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: iwata.aya@fujitsu.com
Cc: alvherre@alvh.no-ip.org, k.jamison@fujitsu.com, tsunakawa.takay@fujitsu.com, pgsql-hackers@lists.postgresql.org
Date: 2021-02-26T05:33:26Z
Lists: pgsql-hackers

Attachments

(we had better avoid top-posting:p)

At Fri, 26 Feb 2021 02:52:49 +0000, "iwata.aya@fujitsu.com" <iwata.aya@fujitsu.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

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.