Re: client waits for end of update operation and server proc is idle

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

> Matthias Apitz <guru(at)unixarea(dot)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,TS val 3424445708 ecr 3424445708], length 127
0x0000: 4500 00b3 b84e 4000 4006 83f4 7f00 0001 E(dot)(dot)(dot)(dot)N(at)(dot)@.......
0x0010: 7f00 0001 cc40 1538 d9b9 44bb fcd1 afb7 (dot)(dot)(dot)(dot)(dot)(at)(dot)8(dot)(dot)D(dot)(dot)(dot)(dot)(dot)
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,TS val 3424445708 ecr 3424445708], length 405
0x0000: 4500 01c9 b84f 4000 4006 82dd 7f00 0001 E(dot)(dot)(dot)(dot)O(at)(dot)@.......
0x0010: 7f00 0001 cc40 1538 d9b9 453a fcd1 afb7 (dot)(dot)(dot)(dot)(dot)(at)(dot)8(dot)(dot)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(at)unixarea(dot)de, http://www.unixarea.de/ +49-176-38902045
Public GnuPG key: http://www.unixarea.de/key.pub