Re: PostgreSQL client hangs sometimes on 'EXEC SQL PREPAREsid_sisisinst FROM :select_anw;'

El día Dienstag, April 28, 2020 a las 10:10:18 +0200, Matthias Apitz escribió:

> 
> I've added the proposed log line to the server code in src/backend/libpq/pqcomm.c
> and restarted the server with this. In the log file /data/postgresql11/data/serverlog
> are other messages about length of packages, like:
> 
> 2020-04-28 09:49:49.877 CEST [16229] LOG:  invalid length of startup packet
> 2020-04-28 09:49:50.117 CEST [16231] LOG:  invalid length of startup packet
> 
> They're coming from:
> 
> grep 'invalid length of startup packet' src/backend/*/*.c
> src/backend/postmaster/postmaster.c:                             errmsg("invalid length of startup packet")));
> 
> I will change the code there to to get the 'len' printed with the
> message
> 
> ...
>         if (len < (int32) sizeof(ProtocolVersion) ||
>                 len > MAX_STARTUP_PACKET_LENGTH)
>         {
>                 ereport(COMMERROR,
>                                 (errcode(ERRCODE_PROTOCOL_VIOLATION),
>                                  errmsg("invalid length %d of startup packet", len)));
>                 return STATUS_ERROR;
>         }

I'm still trying to catch from where (i.e. from which client connection) the above
message are originated. Over the actual weeken(!), I see the following
picture:

# egrep 'bogus|incomplete message from|invalid length' /data/postgresql11/data/serverlog
...
2020-05-09 05:35:20.124 CEST [6905] LOG:  invalid length 33554940 of startup packet
2020-05-09 05:35:20.368 CEST [6907] LOG:  invalid length 33554940 of startup packet
2020-05-09 05:38:14.381 CEST [7186] LOG:  invalid length 33554940 of startup packet
2020-05-09 05:38:14.669 CEST [7246] LOG:  invalid length 33554940 of startup packet
2020-05-10 05:34:56.716 CEST [13241] LOG:  invalid length 33554940 of startup packet
2020-05-10 05:34:56.942 CEST [13243] LOG:  invalid length 33554940 of startup packet
2020-05-10 05:37:46.599 CEST [13921] LOG:  invalid length 33554940 of startup packet
2020-05-10 05:37:49.577 CEST [14017] LOG:  invalid length 33554940 of startup packet

i.e. the messages only appear short after 5:3x am; this is exactly the
time when (based on cronjobs) our software is deployed to this server
and all servers (the clients for PostgreSQL) are started. Following
questions:

1. In addition to the above code, can I get somehow the connecting client's PID? If
   so, I could get from its PID its command line from the /proc file
   system. This would help to instrument the client side with logging.
   There are some hundred clients of different server types booting up
   at this time frame after the deployment. 

2. Can I get something out of the buffer of the startup packet? For
   example, with adding to the above change something like:

   {
   char buf[1024+1];
   memset (buf, 0, sizeof(buf));
   pq_getbytes(buf, 1024);
   buf[1024] = '\0';
   ereport(COMMERROR, (errcode(ERRCODE_PROTOCOL_VIOLATION),
          errmsg("first 1024 bytes of startup packet [%s]", buf)));
   }

Thanks

    matthias

-- 
Matthias Apitz, ✉ guru@unixarea.de, http://www.unixarea.de/ +49-176-38902045
Public GnuPG key: http://www.unixarea.de/key.pub