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

Hello,

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)

# psql -Usisis -dsisis
psql (11.4, server 13.1)
WARNING: psql major version 11, server major version 13.
Some psql features might not work.
Type "help" for help.

sisis=# select * from pg_stat_activity where client_port = 49518;

datid | datname | pid | leader_pid | usesysid | usename | application_name | client_addr | client_hostname | client_port | backend_start | xact_start | query_start | state_change | wait_event_type | wait_event | state | backend_xid | backend_xmin | query | backend_type
--------+---------+-------+------------+----------+---------+---------------------------------+-------------+-----------------+-------------+---------------------------------+---------------------------------+---------------------------------+---------------------------------+-----------------+------------+---------------------+-------------+--------------+---------------------+----------------
951941 | sisis | 27106 | | 16384 | sisis | SunRise DBCALL V7.2 (pid=27074) | ::1 | | 49518 | 23.04.2021 05:57:19.536206 CEST | 23.04.2021 05:57:19.562102 CEST | 23.04.2021 05:57:19.664471 CEST | 23.04.2021 05:57:19.664495 CEST | Client | ClientRead | idle in transaction | 18228156 | 18228156 | fetch per_kette_seq | client backend
(1 row)

i.e. the server is in '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
#11 0x00007f1e67e091c6 in update_record () at per_kette.pgc:1968
#12 0x00007f1e67e04d16 in per_kette (zugriff=10, scroll=-20000, lock=-20000, key=-20000,
sto=-20000, p_daten=0x7fff4e6db9b0, sel_anw=0x0, where_anw=0x0, p_btw_daten=0x0,
order_by=0x0, auf_ab=0x0, group_by=0x0, having=0x0, into_temp=0x0,
count=0x7fff4e6da6d0) at per_kette.pgc:497
#13 0x00007f1e67d7d70f in DB_rewr (tabmodul=0x7f1e67e047ca <per_kette>,
p_daten=0x7fff4e6db9b0) at dbcall.pgc:3274
#14 0x00007f1e68ade821 in BKDeskInsert (setid=FSTAB_Personen, kette=...,
katkey=168952979) at ./BKDesk.c:1447
#15 0x00007f1e68ae79c1 in InvAufnehmen (setid=FSTAB_Personen, katkey=168952979)
#16 0x00007f1e68ae6e17 in BKBearbeiteIndexAuftrag (setid=FSTAB_Personen, auftrag=...)
at ./BKInvert.c:109
#17 0x0000000000405384 in main (argc=3, argv=0x7fff4e6ec1d8) at ./INDEX.c:525

i.e. our client issued ECPGdo() and now waits on finish; the provided
data looks fine:

(gdb) p hrec_per_kette.desknr
$2 = 1384118
(gdb) p hrec_per_kette.katlist
value requires 130000 bytes, which is more than max-value-size

(gdb) x/1s hrec_per_kette.katlist
0x7f1e6864af6e <hrec_per_kette+14>: "\\xee9e01001eaf010057af010005ce010082d20100d4f801008e0a0200af340200253a0200a58e0200ae8e020044a602003ea7020020f1030024f1030054170400a04304003f670400ba8904003bed000005490100925201007454010083600100828301"...

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 ()
#8 0x00007f54fec14780 in ?? ()
#9 0x00007ffffec148a0 in ?? ()
#10 0x00007ffffec14780 in ?? ()
#11 0x00000053008d3b1b in ?? ()
#12 0x00007ffffec14780 in ?? ()
#13 0x00000000008d5482 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?

Thanks

matthias
--
Matthias Apitz, ✉ guru(at)unixarea(dot)de, http://www.unixarea.de/ +49-176-38902045
Public GnuPG key: http://www.unixarea.de/key.pub