Re: client waits for end of update operation and server proc is idle - Mailing list pgsql-general

El día domingo, abril 25, 2021 a las 11:51:45a. m. -0400, Tom Lane escribió:

> Matthias Apitz <guru@unixarea.de> writes:
> > At the end of the day, it turned out that out client caused the problem.
> > Because we were hunting some other issue, the client was logging some
> > message with fprintf(stderr, ...) but the fd=2 was not stderr, fd=2 was the
> > connection to the socket of the PostgreSQL server. And ofc the Pos
> > server could not understand our human message.
> 
> Hmph.  So why wasn't this visible in the tcpdump trace?

It was visible. That's why I detected it while looking up the TCP
packages before the UPDATE:

10:57:16.051326 IP 127.0.0.1.52288 > 127.0.0.1.5432: Flags [P.], seq 14280:14407, ack 120304, win 512, options
[nop,nop,TSval 3424445708 ecr 3424445708], length 127
 
        0x0000:  4500 00b3 b84e 4000 4006 83f4 7f00 0001  E....N@.@.......
        0x0010:  7f00 0001 cc40 1538 d9b9 44bb fcd1 afb7  .....@.8..D.....
        0x0020:  8018 0200 fea7 0000 0101 080a cc1c e50c  ................
        0x0030:  cc1c e50c 5352 502d 3236 3937 363a 2072  ....SRP-26976:.r
        0x0040:  6573 746f 7265 6420 7374 7275 6374 206b  estored.struct.k
        0x0050:  6574 7465 7361 747a 2066 6f72 2073 6574  ettesatz.for.set
        0x0060:  6964 3a32 2c20 6465 736b 3a33 3831 3832  id:2,.desk:38182
        0x0070:  3038 302c 2066 656c 646e 723a 362c 206b  080,.feldnr:6,.k
        0x0080:  6174 6b65 793a 3136 3839 3532 3937 392c  atkey:168952979,
        0x0090:  206b 6574 7465 7361 747a 2e66 7265 693a  .kettesatz.frei:
        0x00a0:  302c 206b 6574 7465 7361 747a 2e61 6e7a  0,.kettesatz.anz
        0x00b0:  3235 0a                                  25.
10:57:16.051388 IP 127.0.0.1.52288 > 127.0.0.1.5432: Flags [P.], seq 14407:14812, ack 120304, win 512, options
[nop,nop,TSval 3424445708 ecr 3424445708], length 405
 
        0x0000:  4500 01c9 b84f 4000 4006 82dd 7f00 0001  E....O@.@.......
        0x0010:  7f00 0001 cc40 1538 d9b9 453a fcd1 afb7  .....@.8..E:....
        0x0020:  8018 0200 ffbd 0000 0101 080a cc1c e50c  ................
        0x0030:  cc1c e50c 5000 0000 7e00 7570 6461 7465  ....P...~.update
        0x0040:  2070 6572 5f6b 6574 7465 2073 6574 2064  .per_kette.set.d
        0x0050:  6573 6b6e 7220 3d20 2431 2020 2c20 6672  esknr.=.$1..,.fr

> 
> My initial thought was that the server process should log a message
> and drop the connection once it received something that didn't look
> like a valid Postgres-protocol message, on the assumption that
> message-boundary sync could never be recovered reliably.  But on
> further thought, it would start by taking the second through fifth
> bytes of the input as a message length, and it wouldn't really do
> anything interesting until it had collected that much input ---
> and, if those bytes were text, that would look like a large number.
> So what the server is really doing is waiting for the rest of the
> imaginary message, which will never arrive.
> 
> Maybe we should have more sanity checking on alleged message lengths.
> I recall there is some checking of that sort in libpq, but I'm less
> sure about the server.

Yes, this would make sense.

    matthias

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