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
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 |