PostgreSQL server "idle in transaction"

Hello,

We face with our application servers (ESQL/C written) and a 14.1 server
on Linux, the situation that the PostgreSQL backend for servers are
saying "idle in transaction". One can see this in the table
pg_stat_activity and also on the shell:

$ ps -ef | grep transaction
postgres  6979 24002  0 11:05 ?  00:00:00 postgres: sisis testdb 127.0.0.1(58620) idle in transaction

testdb=# select * from pg_stat_activity where pid=6979;
 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_id |                    query                     |  backend_type
 

 734526 | testdb  | 6979 |            |    16384 | sisis   | SunRise DBCALL V7.3 (pid=6978) | 127.0.0.1   |
   |       58620 | 15.11.2022 11:05:50.153359 CET | 15.11.2022 11:05:50.173748 CET | 15.11.2022 11:05:50.174322 CET |
15.11.202211:05:50.174346 CET | Client          | ClientRead | idle in transaction |             |     17444593 |
  | select name from pg_cursors where name = $1  | client backend
 

The application server itself has done some initializations, updated a
table about the fact that it was started, commited the update and waits
for work to do (which would be come as commands over some network
socket). The last PostgreSQL related action was looking into the table
'pg_cursors' to see if some used CURSOR is still open, which was not the
case. This last query is still visible in pg_stat_activity.query.

I have below the full ESQL/C log and do not understand, why the
PostgreSQL server is thinking "idle in transaction". For me with the
"COMMIT" on the line below marked with ^^^^^ the transaction was closed.
Am I wrong?

[6978] [15.11.2022 11:05:50:152]: ECPGdebug: set to 1
[6978] [15.11.2022 11:05:50:152]: ECPGdebug: proc argv0 is Z39Targetd
[6978] [15.11.2022 11:05:50:152]: ECPGconnect: opening database testdb on localhost port 5432 with options
application_name=SunRiseDBCALL V7.3 (pid=6978) for user sisis
 
[6978] [15.11.2022 11:05:50:157]: ecpg_execute on line 859: query: select current_date; with 0 parameter(s) on
connectiontestdb
 
[6978] [15.11.2022 11:05:50:157]: ecpg_execute on line 859: using PQexec
[6978] [15.11.2022 11:05:50:157]: ecpg_process_output on line 859: correctly got 1 tuples with 1 fields
[6978] [15.11.2022 11:05:50:157]: ecpg_get_data on line 859: RESULT: 15.11.2022 offset: 80; array: no
[6978] [15.11.2022 11:05:50:159]: ecpg_execute on line 1191: query: declare sisisinst_seq cursor with hold for SELECT
ctid,* from sisisinst WHERE version  = $1; with 1 parameter(s) on connection testdb
 
[6978] [15.11.2022 11:05:50:160]: ecpg_execute on line 1191: using PQexecParams
[6978] [15.11.2022 11:05:50:160]: ecpg_free_params on line 1191: parameter 1 = V7.3
[6978] [15.11.2022 11:05:50:160]: ecpg_process_output on line 1191: OK: DECLARE CURSOR
[6978] [15.11.2022 11:05:50:160]: ecpg_execute on line 1678: query: fetch sisisinst_seq; with 0 parameter(s) on
connectiontestdb
 
[6978] [15.11.2022 11:05:50:160]: ecpg_execute on line 1678: using PQexec
[6978] [15.11.2022 11:05:50:160]: ecpg_process_output on line 1678: correctly got 1 tuples with 7 fields
[6978] [15.11.2022 11:05:50:160]: ecpg_get_data on line 1678: RESULT: (1,10) offset: 19; array: no
[6978] [15.11.2022 11:05:50:160]: ecpg_get_data on line 1678: RESULT: 10.03.2022 offset: 137; array: no
[6978] [15.11.2022 11:05:50:160]: ecpg_get_data on line 1678: RESULT: srap51dxr1-20220310       offset: 137; array: no
[6978] [15.11.2022 11:05:50:160]: ecpg_get_data on line 1678: RESULT: Upgrade V7.2 -> V7.3
 offset: 137; array: no
 
[6978] [15.11.2022 11:05:50:160]: ecpg_get_data on line 1678: RESULT: sisisbase                 offset: 137; array: no
[6978] [15.11.2022 11:05:50:160]: ecpg_get_data on line 1678: RESULT:  offset: 137; array: no
[6978] [15.11.2022 11:05:50:160]: ecpg_get_data on line 1678: RESULT: V7.3       offset: 137; array: no
[6978] [15.11.2022 11:05:50:160]: ecpg_execute on line 1208: query: declare z39t_user_seq cursor with hold for SELECT
ctid,* from z39t_user WHERE groupid  = $1 AND loginid  = $2; with 2 parameter(s) on connection testdb
 
[6978] [15.11.2022 11:05:50:164]: ecpg_execute on line 1208: using PQexecParams
[6978] [15.11.2022 11:05:50:164]: ecpg_free_params on line 1208: parameter 1 = gast
[6978] [15.11.2022 11:05:50:164]: ecpg_free_params on line 1208: parameter 2 = gast
[6978] [15.11.2022 11:05:50:164]: ecpg_process_output on line 1208: OK: DECLARE CURSOR
[6978] [15.11.2022 11:05:50:164]: ecpg_execute on line 1709: query: fetch z39t_user_seq; with 0 parameter(s) on
connectiontestdb
 
[6978] [15.11.2022 11:05:50:165]: ecpg_execute on line 1709: using PQexec
[6978] [15.11.2022 11:05:50:165]: ecpg_process_output on line 1709: correctly got 1 tuples with 4 fields
[6978] [15.11.2022 11:05:50:165]: ecpg_get_data on line 1709: RESULT: (0,1) offset: 19; array: no
[6978] [15.11.2022 11:05:50:166]: ecpg_get_data on line 1709: RESULT: gast                 offset: 93; array: no
[6978] [15.11.2022 11:05:50:166]: ecpg_get_data on line 1709: RESULT: gast                 offset: 93; array: no
[6978] [15.11.2022 11:05:50:166]: ecpg_get_data on line 1709: RESULT: gast
offset: 93; array: no
 
[6978] [15.11.2022 11:05:50:167]: ecpg_execute on line 1161: query: declare z39t_report_seq cursor with hold for SELECT
ctid,* from z39t_report WHERE associd  = $1; with 1 parameter(s) on connection testdb
 
[6978] [15.11.2022 11:05:50:168]: ecpg_execute on line 1161: using PQexecParams
[6978] [15.11.2022 11:05:50:168]: ecpg_free_params on line 1161: parameter 1 = 1
[6978] [15.11.2022 11:05:50:168]: ecpg_process_output on line 1161: OK: DECLARE CURSOR
[6978] [15.11.2022 11:05:50:168]: ecpg_execute on line 1634: query: fetch z39t_report_seq; with 0 parameter(s) on
connectiontestdb
 
[6978] [15.11.2022 11:05:50:170]: ecpg_execute on line 1634: using PQexec
[6978] [15.11.2022 11:05:50:170]: ecpg_process_output on line 1634: correctly got 1 tuples with 7 fields
[6978] [15.11.2022 11:05:50:170]: ecpg_get_data on line 1634: RESULT: (0,39) offset: 19; array: no
[6978] [15.11.2022 11:05:50:170]: ecpg_get_data on line 1634: RESULT: 1 offset: 168; array: no
[6978] [15.11.2022 11:05:50:170]: ecpg_get_data on line 1634: RESULT: gast;gast;gast
                                                                      offset: 168; array: no
 
[6978] [15.11.2022 11:05:50:170]: ecpg_get_data on line 1634: RESULT: 0 offset: 168; array: no
[6978] [15.11.2022 11:05:50:170]: ecpg_get_data on line 1634: RESULT: 0 offset: 168; array: no
[6978] [15.11.2022 11:05:50:170]: ecpg_get_data on line 1634: RESULT: 3 offset: 168; array: no
[6978] [15.11.2022 11:05:50:170]: ecpg_get_data on line 1634: RESULT: 0 offset: 168; array: no
[6978] [15.11.2022 11:05:50:170]: ecpg_execute on line 2310: query: select currtid2 ( 'z39t_report' :: text , $1  ::
tid); with 1 parameter(s) on connection testdb
 
[6978] [15.11.2022 11:05:50:171]: ecpg_execute on line 2310: using PQexecParams
[6978] [15.11.2022 11:05:50:171]: ecpg_free_params on line 2310: parameter 1 = (0,39)
[6978] [15.11.2022 11:05:50:171]: ecpg_process_output on line 2310: correctly got 1 tuples with 1 fields
[6978] [15.11.2022 11:05:50:171]: ecpg_get_data on line 2310: RESULT: (0,39) offset: 80; array: no
[6978] [15.11.2022 11:05:50:171]: ecpg_execute on line 1427: query: declare hc_z39t_report cursor for SELECT * FROM
z39t_reportWHERE ctid = $1 FOR UPDATE; with 1 parameter(s) on connection testdb
 
[6978] [15.11.2022 11:05:50:171]: ecpg_execute on line 1427: using PQexecParams
[6978] [15.11.2022 11:05:50:171]: ecpg_free_params on line 1427: parameter 1 = (0,39)
[6978] [15.11.2022 11:05:50:171]: ecpg_process_output on line 1427: OK: DECLARE CURSOR
[6978] [15.11.2022 11:05:50:171]: ecpg_execute on line 1432: query: fetch hc_z39t_report; with 0 parameter(s) on
connectiontestdb 
[6978] [15.11.2022 11:05:50:171]: ecpg_execute on line 1432: using PQexec
[6978] [15.11.2022 11:05:50:171]: ecpg_process_output on line 1432: correctly got 1 tuples with 6 fields
[6978] [15.11.2022 11:05:50:171]: ecpg_get_data on line 1432: RESULT: 1 offset: 168; array: no
[6978] [15.11.2022 11:05:50:171]: ecpg_get_data on line 1432: RESULT: gast;gast;gast
                                                                      offset: 168; array: no
 
[6978] [15.11.2022 11:05:50:171]: ecpg_get_data on line 1432: RESULT: 0 offset: 168; array: no
[6978] [15.11.2022 11:05:50:171]: ecpg_get_data on line 1432: RESULT: 0 offset: 168; array: no
[6978] [15.11.2022 11:05:50:171]: ecpg_get_data on line 1432: RESULT: 3 offset: 168; array: no
[6978] [15.11.2022 11:05:50:171]: ecpg_get_data on line 1432: RESULT: 0 offset: 168; array: no
[6978] [15.11.2022 11:05:50:171]: ecpg_execute on line 2025: query: update z39t_report set associd = $1  , tuser = $2
,searchrecords = $3  , presentrecords = $4  , assoctime = $5  , assoccost = $6  where current of hc_z39t_report; with 6
parameter(s)on connection testdb
 
[6978] [15.11.2022 11:05:50:172]: ecpg_execute on line 2025: using PQexecParams
[6978] [15.11.2022 11:05:50:172]: ecpg_free_params on line 2025: parameter 1 = 1
[6978] [15.11.2022 11:05:50:172]: ecpg_free_params on line 2025: parameter 2 = gast;gast;gast
[6978] [15.11.2022 11:05:50:172]: ecpg_free_params on line 2025: parameter 3 = 0
[6978] [15.11.2022 11:05:50:172]: ecpg_free_params on line 2025: parameter 4 = 0
[6978] [15.11.2022 11:05:50:172]: ecpg_free_params on line 2025: parameter 5 = 7
[6978] [15.11.2022 11:05:50:172]: ecpg_free_params on line 2025: parameter 6 = 0
[6978] [15.11.2022 11:05:50:172]: ecpg_process_output on line 2025: OK: UPDATE 1
[6978] [15.11.2022 11:05:50:172]: ecpg_execute on line 2310: query: select currtid2 ( 'z39t_report' :: text , $1  ::
tid); with 1 parameter(s) on connection testdb
 
[6978] [15.11.2022 11:05:50:172]: ecpg_execute on line 2310: using PQexecParams
[6978] [15.11.2022 11:05:50:172]: ecpg_free_params on line 2310: parameter 1 = (0,39)
[6978] [15.11.2022 11:05:50:172]: ecpg_process_output on line 2310: correctly got 1 tuples with 1 fields
[6978] [15.11.2022 11:05:50:172]: ecpg_get_data on line 2310: RESULT: (0,41) offset: 80; array: no
[6978] [15.11.2022 11:05:50:172]: ECPGtrans on line 1211: action "commit"; connection "testdb"
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[6978] [15.11.2022 11:05:50:173]: ecpg_execute on line 543: query: select name from pg_cursors where name = $1 ; with 1
parameter(s)on connection testdb
 
[6978] [15.11.2022 11:05:50:174]: ecpg_execute on line 543: using PQexecParams
[6978] [15.11.2022 11:05:50:174]: ecpg_free_params on line 543: parameter 1 = hc_z39t_report
[6978] [15.11.2022 11:05:50:174]: ecpg_process_output on line 543: correctly got 0 tuples with 1 fields
-- 
Matthias Apitz, ✉ guru@unixarea.de, http://www.unixarea.de/ +49-176-38902045
Public GnuPG key: http://www.unixarea.de/key.pub