Re: libpq debug log

From: Kyotaro Horiguchi <horikyota(dot)ntt(at)gmail(dot)com>
To: tsunakawa(dot)takay(at)fujitsu(dot)com
Cc: iwata(dot)aya(at)fujitsu(dot)com, k(dot)jamison(at)fujitsu(dot)com, alvherre(at)alvh(dot)no-ip(dot)org, pgsql-hackers(at)lists(dot)postgresql(dot)org
Subject: Re: libpq debug log
Date: 2021-02-26 07:12:39
Message-ID: 20210226.161239.974671556832294688.horikyota.ntt@gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers

At Fri, 26 Feb 2021 06:21:15 +0000, "tsunakawa(dot)takay(at)fujitsu(dot)com" <tsunakawa(dot)takay(at)fujitsu(dot)com> wrote in
> From: Álvaro Herrera <alvherre(at)alvh(dot)no-ip(dot)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

In response to

Responses

Browse pgsql-hackers by date

  From Date Subject
Next Message Michael Paquier 2021-02-26 07:15:17 Re: pg_attribute.attname inconsistency when renaming primary key columns
Previous Message Peter Eisentraut 2021-02-26 07:05:12 Re: SSL SNI