Horton

Re: libpq debug log

Kyotaro Horiguchi <horikyota.ntt@gmail.com>

View thread View on postgr.es
From: Kyotaro Horiguchi <horikyota.ntt@gmail.com>
To: tsunakawa.takay@fujitsu.com
Cc: iwata.aya@fujitsu.com, k.jamison@fujitsu.com, alvherre@alvh.no-ip.org, pgsql-hackers@lists.postgresql.org
Date: 2021-02-26T07:12:39Z
Lists: pgsql-hackers 
At Fri, 26 Feb 2021 06:21:15 +0000, "tsunakawa.takay@fujitsu.com" <tsunakawa.takay@fujitsu.com> wrote in 
> From: Álvaro Herrera <alvherre@alvh.no-ip.org>
> > It appears that something is still wrong.  I applied lipq pipeline v27 from [1] and ran src/test/modules/test_libpq/pipeline singlerow, after patching it to do PQtrace() after PQconn(). Below is the output I get from that. The noteworthy point is that "ParseComplete" messages appear multiple times for some reason ... but that's quite odd, because if I look at the network traffic with Wireshark I certainly do not see the ParseComplete message being sent three times.
> 
> < CommandComplete 13 "SELECT 3"
> < ParseComplete 4
> < ParseComplete 4
> < ParseComplete 4
> < BindComplete 4
> 
> Hmm, that's mysterious.  I'm not sure if this explains why, but some places such as pqTraceOutputBeByte1() and pqTraceOutputString() appears to forget to update LogCursor.
> 
> In addition, in pqTraceOutputBeInt(),
> 
> +        bool                     logfinish = 0;
> 
> 0 should be false instead.
> 
> +                                    logfinish = pqTraceMaybeBreakLine(0, conn);
> 
> "length" should be passed instead of 0, shouldn't it?

The reason is be_msg->length is set with the value already subtracted
length.  Perhaps the following change allows the Assert() to
resurrect.

 +		case LOG_LENGTH:
 +			fprintf(conn->Pfdebug, "%d", v);
-+			conn->be_msg->length = v - length;
++			conn->be_msg->length = v;
 +			/* Next, log the message contents */
 +			conn->be_msg->state = LOG_CONTENTS;
-+			logfinish = pqTraceMaybeBreakLine(0, conn);
++			logfinish = pqTraceMaybeBreakLine(length, conn);

However, This doesn't seem cause the phenomenon.

+	if (!logfinish)
+		conn->be_msg->logCursor = conn->inCursor - conn->inStart;

This inhibits logCursor being updated. What is worse, I find that
logCursor movement is quite dubious.

  pqTraceOutputBeByte1 donsn't move logCursor for LOG_FIRST_BYTE
  pqTraceOutputBeInt doesn't move logCursor if the messages *does* end.

So it repeats the same message if the previous message consists of
<type, length=4>.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

Commits

  1. Rename PQtraceSetFlags() to PQsetTraceFlags().

  2. Suppress length of Notice/Error msgs in PQtrace regress mode

  3. Strip file names reported in error messages on Windows, too.

  4. Fix setvbuf()-induced crash in libpq_pipeline

  5. libpq_pipeline: Must strdup(optarg) to avoid crash

  6. Remove setvbuf() call from PQtrace()

  7. Initialize conn->Pfdebug to NULL when creating a connection

  8. Disable force_parallel_mode in libpq_pipeline

  9. libpq_pipeline: add PQtrace() support and tests

  10. Improve PQtrace() output format

  11. Re-simplify management of inStart in pqParseInput3's subroutines.