Обсуждение: Print logical WAL message content

Hi,
Right now pg_waldump just prints whether the message is transactional
or not and its size. That doesn't help much to understand the message
itself. If it prints the contents of a logical WAL message, it helps
debugging logical replication related problems. Prefix is a
null-terminated ASCII string, so no problem printing that. Even the
contents can be printed as a series of hex bytes. Here's a patch to do
that.

I tested this manually as below

postgres=# select pg_logical_emit_message(false, 'some_prefix', 'some
message'::text);
 pg_logical_emit_message
-------------------------
 0/1570658
(1 row)

$> pg_waldump --start 0/1570600 -p data/
first record is after 0/1570600, at 0/1570608, skipping over 8 bytes
rmgr: LogicalMessage len (rec/tot):     74/    74, tx:          0,
lsn: 0/01570608, prev 0/015705D0, desc: MESSAGE nontransactional
message size 12 bytes, prefix some_prefix; mesage: 73 6F 6D 65 20 6D
65 73 73 61 67 65
rmgr: Standby     len (rec/tot):     50/    50, tx:          0, lsn:
0/01570658, prev 0/01570608, desc: RUNNING_XACTS nextXid 504
latestCompletedXid 503 oldestRunningXid 504
pg_waldump: fatal: error in WAL record at 0/1570658: invalid record
length at 0/1570690: wanted 24, got 0

I didn't find any tests for pg_waldump to test its output, so haven't
added one in the patch.

-- 
Best Wishes,
Ashutosh Bapat

On 2020-Aug-18, Ashutosh Bapat wrote:

> Right now pg_waldump just prints whether the message is transactional
> or not and its size. That doesn't help much to understand the message
> itself. If it prints the contents of a logical WAL message, it helps
> debugging logical replication related problems. Prefix is a
> null-terminated ASCII string, so no problem printing that. Even the
> contents can be printed as a series of hex bytes. Here's a patch to do
> that.

Looks like a good idea.

I didn't like that you're documenting the message format in the new
function:

>          xl_logical_message *xlrec = (xl_logical_message *) rec;
> +        /*
> +         * Per LogLogicalMessage() actual logical message follows a null-terminated prefix of length
> +         * prefix_size.

I would prefer to remove this comment, and instead add a comment atop
xl_logical_message's struct definition in message.h to say that the
message has a valid C-string as prefix, whose length is prefix_size, and
please see logicalmesg_desc() if you change this.
This way, you don't need to blame LogLogicalMessage for this
restriction, but it's actually part of the definition of the WAL
message.

> +        /*
> +         * Per LogLogicalMessage() actual logical message follows a null-terminated prefix of length
> +         * prefix_size.
> +         */
> +        char   *prefix = xlrec->message;
> +        char   *message = xlrec->message + xlrec->prefix_size;
> +        int        cnt;
> +        char   *sep = "";

This would cause a crash if the message actually fails to follow the
rule.  Let's test that prefix[xlrec->prefix_size] is a trailing zero,
and if not, avoid printing it.  Although, just Assert()'ing that it's a
trailing zero would seem to suffice.

> +        appendStringInfo(buf, "%s message size %zu bytes, prefix %s; mesage: ",
>                           xlrec->transactional ? "transactional" : "nontransactional",
> -                         xlrec->message_size);
> +                         xlrec->message_size, prefix);

Misspelled "message", but also the line looks a bit repetitive -- the
word "message" would appear three times:

> lsn: 0/01570608, prev 0/015705D0, desc: MESSAGE nontransactional message size 12 bytes, prefix some_prefix; mesage:
736F 6D 65 20 6D 65 73 73 61 67 65
 

I would reduce it to

> lsn: 0/01570608, prev 0/015705D0, desc: MESSAGE nontransactional, prefix "some_prefix"; payload (12 bytes): 73 6F 6D
6520 6D 65 73 73 61 67 65
 

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Thanks Alvaro for review.

On Wed, Aug 19, 2020 at 3:21 AM Alvaro Herrera <alvherre@2ndquadrant.com> wrote:
>
> I didn't like that you're documenting the message format in the new
> function:
>
> >               xl_logical_message *xlrec = (xl_logical_message *) rec;
> > +             /*
> > +              * Per LogLogicalMessage() actual logical message follows a null-terminated prefix of length
> > +              * prefix_size.
>
> I would prefer to remove this comment, and instead add a comment atop
> xl_logical_message's struct definition in message.h to say that the
> message has a valid C-string as prefix, whose length is prefix_size, and
> please see logicalmesg_desc() if you change this.

It's documented in the struct definition. Added a note about logicalmesg_desc().

> This way, you don't need to blame LogLogicalMessage for this
> restriction, but it's actually part of the definition of the WAL
> message.
>
> > +             /*
> > +              * Per LogLogicalMessage() actual logical message follows a null-terminated prefix of length
> > +              * prefix_size.
> > +              */
> > +             char   *prefix = xlrec->message;
> > +             char   *message = xlrec->message + xlrec->prefix_size;
> > +             int             cnt;
> > +             char   *sep = "";
>
> This would cause a crash if the message actually fails to follow the
> rule.  Let's test that prefix[xlrec->prefix_size] is a trailing zero,
> and if not, avoid printing it.  Although, just Assert()'ing that it's a
> trailing zero would seem to suffice.

Added an Assert.

>
> > +             appendStringInfo(buf, "%s message size %zu bytes, prefix %s; mesage: ",
> >                                                xlrec->transactional ? "transactional" : "nontransactional",
> > -                                              xlrec->message_size);
> > +                                              xlrec->message_size, prefix);
>
> Misspelled "message", but also the line looks a bit repetitive -- the
> word "message" would appear three times:
>
> > lsn: 0/01570608, prev 0/015705D0, desc: MESSAGE nontransactional message size 12 bytes, prefix some_prefix; mesage:
736F 6D 65 20 6D 65 73 73 61 67 65
 
>
> I would reduce it to
>
> > lsn: 0/01570608, prev 0/015705D0, desc: MESSAGE nontransactional, prefix "some_prefix"; payload (12 bytes): 73 6F
6D65 20 6D 65 73 73 61 67 65
 

I like this format as well. Done.

PFA the patch attached with your comments addressed.

Thanks for your review.

-- 
Best Wishes,
Ashutosh Bapat

On 2020-Aug-19, Ashutosh Bapat wrote:

> I like this format as well. Done.
> 
> PFA the patch attached with your comments addressed.

Pushed, thanks!

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services