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

On Fri, 2021-04-23 at 10:15 +0200, Matthias Apitz wrote:
> We face (somehow reproducible) the following situation with a 13.1
> server and a client written in ESQL/C:
>
> # ps ax | grep post
> ...
> 27106 ? Ss 0:00 postgres: sisis sisis ::1(49518) idle in transaction
>
> # lsof | grep 49518
> INDEX 27074 sisis 2u IPv6 26465150 0t0 TCP localhost:49518->localhost:postgresql (ESTABLISHED)
> postmaste 27106 postgres 9u IPv6 26464149 0t0 TCP localhost:postgresql->localhost:49518 (ESTABLISHED)
>
> sisis=# select * from pg_stat_activity where client_port = 49518;
>
> [...] ClientRead | idle in transaction [...]
>
> The ESQL/C code the client is executing at this moment is:
>
> /*
> * update the actual row
> */
> posDebug(POSDEBUG_FLOW, "ES UPDATE per_kette set .. WHERE CURRENT OF hc_per_kette");
> EXEC SQL UPDATE per_kette
> SET desknr =:hrec_per_kette.desknr,
> frei =:hrec_per_kette.frei,
> modif =:hrec_per_kette.modif,
> anz =:hrec_per_kette.anz,
> katlist =:hrec_per_kette.katlist
> WHERE CURRENT OF hc_per_kette;
>
> An attached GDB shows:
>
> # gdb /opt/lib/sisis/catserver/bin/INDEX 27074
>
> #0 0x00007f1e65c1b5c4 in poll () from /lib64/libc.so.6
> #1 0x00007f1e648ac22f in pqSocketPoll () from /usr/local/sisis-pap/pgsql/lib/libpq.so.5
> #2 0x00007f1e648ac0ff in pqSocketCheck () from /usr/local/sisis-pap/pgsql/lib/libpq.so.5
> #3 0x00007f1e648abf83 in pqWaitTimed () from /usr/local/sisis-pap/pgsql/lib/libpq.so.5
> #4 0x00007f1e648abf55 in pqWait () from /usr/local/sisis-pap/pgsql/lib/libpq.so.5
> #5 0x00007f1e648a7d3a in PQgetResult () from /usr/local/sisis-pap/pgsql/lib/libpq.so.5
> #6 0x00007f1e648a8478 in PQexecFinish () from /usr/local/sisis-pap/pgsql/lib/libpq.so.5
> #7 0x00007f1e648a812e in PQexecParams () from /usr/local/sisis-pap/pgsql/lib/libpq.so.5
> #8 0x00007f1e65818216 in ecpg_execute ()
> from /usr/local/sisis-pap/pgsql/lib/libecpg.so.6
> #9 0x00007f1e658195de in ecpg_do () from /usr/local/sisis-pap/pgsql/lib/libecpg.so.6
> #10 0x00007f1e658196ef in ECPGdo () from /usr/local/sisis-pap/pgsql/lib/libecpg.so.6
>
> i.e. our client issued ECPGdo() and now waits on finish; the provided
> data looks fine:
>
> the server pocess is in epoll_pwait():
>
> # gdb /usr/local/sisis-pap/pgsql-13.0/bin/postmaster 27106
> ...
> (gdb) bt
> #0 0x00007fe7ee953fe0 in epoll_pwait () from /lib64/libc.so.6
> #1 0x00000000008acf10 in WaitEventSetWaitBlock ()
> #2 0x00000000008acde9 in WaitEventSetWaitBlock ()
> #3 0x000000000073c5a5 in check_ssl_key_file_permissions ()
> #4 0x000000000074636e in RemoveSocketFiles ()
> #5 0x000000000074662b in pq_getbyte_if_available ()
> #6 0x000000000074697b in pq_getmessage ()
> #7 0x00000000008d543b in pg_analyze_and_rewrite_params ()
>
> The client has a log file for this update which shows the actual time of
> this operation:
>
> # ls -l --full-time /var/spool/sisis/catserver/tmp/.lock_index-A.sisis.2
> -rw-rw---- 1 sisis sisis 6 2021-04-23 05:57:19.529476471 +0200 /var/spool/sisis/catserver/tmp/.lock_index-A.sisis.2
>
>
> The serverlog has around this time (sorry for German):
>
> 2021-04-23 05:55:23.591 CEST [2317] LOG: unvollständige Message vom Client
> 2021-04-23 05:55:23.593 CEST [2317] FEHLER: Speicher aufgebraucht
> 2021-04-23 05:55:23.593 CEST [2317] DETAIL: Kann Zeichenkettenpuffer mit 0 Bytes nicht um 1380986158 Bytes vergrößern.
> 2021-04-23 05:55:23.593 CEST [2317] LOG: konnte Daten nicht an den Client senden: Datenübergabe unterbrochen (broken pipe)
> 2021-04-23 05:55:23.593 CEST [2317] FATAL: Verbindung zum Client wurde verloren
> 2021-04-23 05:57:20.339 CEST [27190] LOG: unerwartetes EOF auf Client-Verbindung mit einer offenen Transaktion
> 2021-04-23 05:59:17.419 CEST [26827] LOG: unerwartetes EOF auf Client-Verbindung mit einer offenen Transaktion
>
> What else could be checked for this? Any hints about this issue?

It seems pretty clear that both the client and the server are waiting for each other.

The server is of the opinion that it has completed the query, while the client is
still waiting for the response.

I would look for the problem in the network between both. The error messages
(unexpected EOF on client connection, broken pipe) seem to point in the same direction.

Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com