Re: libpq debug log

(we had better avoid top-posting:p)

At Fri, 26 Feb 2021 02:52:49 +0000, "iwata(dot)aya(at)fujitsu(dot)com" <iwata(dot)aya(at)fujitsu(dot)com> wrote in
> Alvaro san,
>
> Thank you very much for your updating and organizing this patch.
>
> 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.
>
> I will search this cause. Please wait a minuets.
> I thought I could avoid multiple such outputs by using conn->LogCursor…

I found a bug of the patch.

- Tweaked psql to enable tracing. (attached)

- Connect to a server using SSL.

- Restart the server.
<many ":::Invalid Protocol" are emitted>

- Reconnect to the server by just entering ';<ret>' on the psql
command line. I saw the following log lines.

2021-02-26 14:29:40.434749 > Query 6 ";"
2021-02-26 14:29:40.435948 < ErrorResponse 116 S "FATAL" V "FATAL" C "57P01" M "terminating connection due to administrator command" F "postgres.c" L "3129" R "ProcessInterrupts" \x00
2021-02-26 14:29:40.438298 > SSLRequest 8 '\x04\xffffffd2\x16/'
2021-02-26 14:29:40.443155 < ParameterStatus 2021-02-26 14:29:40.468186 > StartupMessage 84 '\x00\x03\x00\x00user\x00horiguti\x00database\x00postgres\x00application_name\x00psql\x00client_encoding\x00UTF8\x00\x00'
< :::Invalid Protocol
< :::Invalid Protocol

1. It seems to have desynced.
2. ":::Invalid Protocol" looks somewhat odd?
3. ":::Invalid Protocol" lines missing a timestamp.

- type "select 1;<ret>"
<several ":::Invalid Protocols" then psql crashes>

I haven't looked further, though.

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center