Re: Log prefix missing for subscriber log messages received from publisher - Mailing list pgsql-hackers

On 2025/07/16 19:45, vignesh C wrote:
> If we don't trim the trailing newline, an extra blank line will appear
> after the message is printed, like this:
> 2025-07-16 12:44:20.076 IST [534376] LOG:  logical replication table
> synchronization worker for subscription "sub1", table "t2" has started
> 2025-07-16 12:44:20.294 IST [534374] LOG:  received message via
> replication: WARNING:  could not remove directory
> "pg_replslot/pg_16396_sync_16384_7527574647116269356.tmp"
> 
> 2025-07-16 12:44:20.294 IST [534374] LOG:  logical replication table
> synchronization worker for subscription "sub1", table "t1" has
> finished
> 
> This occurs because a newline is appended to the message in
> pqBuildErrorMessage3, which is called when the message is received in
> pqGetErrorNotice3:
> ...
> }
> appendPQExpBufferChar(msg, '\n');
> if (verbosity != PQERRORS_TERSE)
> ...

You're right, the message text passed to the notice processor includes
a trailing newline. I confirmed this is documented in the PQsetNoticeProcessor
docs [1], so I agree it's reasonable to trim the newline for cleaner log output.


Regarding the current implementation:
+       /* Trim trailing newline for cleaner logs */
+       size_t          len = strlen(message);
+
+       if (len > 0 && message[len - 1] == '\n')
+               ereport(LOG,
+                               errmsg("received message via replication: %.*s",
+                                          (int) (len - 1), message));
+       else
+               ereport(LOG,
+                               errmsg("received message via replication: %s", message));

To avoid repeating ereport(), how about refactoring it like this?
I think it's simpler and easier to read:

---------------------------------------
/*
  * Custom notice processor for replication connection.
  */
static void
notice_processor(void *arg, const char *message)
{
    int            len;

    /*
     * Trim the trailing newline from the message text passed to the notice
     * processor, as it always includes one, to produce cleaner log output.
     */
    len = strlen(message);
    if (len > 0 && message[len - 1] == '\n')
        len--;

    ereport(LOG,
            errmsg("received message via replication: %.*s",
                   len, message));
}
---------------------------------------


Also, I suggest adding the prototype for notice_processor() in libpqwalreceiver.c:

---------------------------------------
/* Prototypes for private functions */
static void notice_processor(void *arg, const char *message);
static char *stringlist_to_identifierstr(PGconn *conn, List *strings);
---------------------------------------


Currently, notice_processor() is placed just before libpqrcv_connect(),
but I think it would be better to move it before stringlist_to_identifierstr(),
since the libpqwalreceiver.c seems to follow a structure where private
functions come after the libpqrcv_* functions.


+       PQsetNoticeProcessor(conn->streamConn, notice_processor, NULL);

It might be helpful to add a comment explaining the purpose, such as:

     Set a custom notice processor so that notice, warning, and similar messages
     received via the replication connection are logged in our preferred style,
     instead of just being printed to stderr.

Thought?

>> The phrase "from publisher" could be misleading, since the sender might be
>> a primary in physical replication, not necessarily a logical publisher.
>> Maybe something like "received message via replication" would be clearer?
>> I'd like to hear others' thoughts on a better wording.
> 
> Modified the message to "received message via replication." Will
> update it further if we get any better wording.

+1

Regards,

[1] https://www.postgresql.org/docs/devel/libpq-notice-processing.html

-- 
Fujii Masao
NTT DATA Japan Corporation