session: investigate non-closed sessions

[tiborsimko]

Following up from #132, if one issues a large number of ping queries, for example:

$ for i in {{0..100}}; do reana-client ping; done

the DB connections seem to be kept in a rollback-like stage in between requests:

reana=# SELECT * FROM pg_stat_activity;
 datid | datname | 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              
-------+---------+-----+----------+---------+------------------+--------------+-----------------+-------------+-------------------------------+-------------------------------+-------------------------------+-------------------------------+-----------------+------------+--------+-------------+--------------+-----------
----------------------
 16384 | reana   | 145 |    16385 | reana   |                  | 10.244.0.188 |                 |       39692 | 2021-06-08 17:30:41.623811+02 |                               | 2021-06-08 17:37:41.526021+02 | 2021-06-08 17:37:41.526055+02 |                 |            | idle   |             |              | ROLLBACK
 16384 | reana   | 146 |    16385 | reana   |                  | 10.244.0.188 |                 |       39696 | 2021-06-08 17:30:41.636607+02 |                               | 2021-06-08 17:37:41.5263+02   | 2021-06-08 17:37:41.526324+02 |                 |            | idle   |             |              | ROLLBACK
 16384 | reana   |  77 |    16385 | reana   |                  | 10.244.0.180 |                 |       46744 | 2021-06-08 16:59:07.745652+02 |                               | 2021-06-08 17:00:40.988964+02 | 2021-06-08 17:00:40.989008+02 |                 |            | idle   |             |              | ROLLBACK
 16384 | reana   |  78 |    16385 | reana   |                  | 10.244.0.180 |                 |       46746 | 2021-06-08 16:59:09.157766+02 |                               | 2021-06-08 17:00:40.328005+02 | 2021-06-08 17:00:40.328033+02 |                 |            | idle   |             |              | ROLLBACK
 16384 | reana   | 165 |    16385 | reana   | psql             |              |                 |          -1 | 2021-06-08 17:36:37.41503+02  | 2021-06-08 17:39:13.565315+02 | 2021-06-08 17:39:13.565315+02 | 2021-06-08 17:39:13.565317+02 |                 |            | active |             |          694 | SELECT * F
ROM pg_stat_activity;
 16384 | reana   | 169 |    16385 | reana   |                  | 10.244.0.188 |                 |       39698 | 2021-06-08 17:36:50.375506+02 |                               | 2021-06-08 17:37:39.494873+02 | 2021-06-08 17:37:39.49491+02  |                 |            | idle   |             |              | ROLLBACK
 16384 | reana   | 170 |    16385 | reana   |                  | 10.244.0.188 |                 |       39700 | 2021-06-08 17:36:50.388271+02 |                               | 2021-06-08 17:37:39.49519+02  | 2021-06-08 17:37:39.495212+02 |                 |            | idle   |             |              | ROLLBACK
 16384 | reana   |  82 |    16385 | reana   |                  | 10.244.0.180 |                 |       46748 | 2021-06-08 16:59:24.670997+02 |                               | 2021-06-08 17:00:34.618964+02 | 2021-06-08 17:00:34.635221+02 |                 |            | idle   |             |              | COMMIT
 16384 | reana   | 175 |    16385 | reana   |                  | 10.244.0.188 |                 |       39702 | 2021-06-08 17:36:55.998228+02 |                               | 2021-06-08 17:37:41.027987+02 | 2021-06-08 17:37:41.028022+02 |                 |            | idle   |             |              | ROLLBACK
 16384 | reana   | 176 |    16385 | reana   |                  | 10.244.0.188 |                 |       39704 | 2021-06-08 17:36:56.013249+02 |                               | 2021-06-08 17:37:41.028224+02 | 2021-06-08 17:37:41.028243+02 |                 |            | idle   |             |              | ROLLBACK
 16384 | reana   | 185 |    16385 | reana   |                  | 10.244.0.188 |                 |       39706 | 2021-06-08 17:37:01.6228+02   |                               | 2021-06-08 17:37:06.241385+02 | 2021-06-08 17:37:06.241428+02 |                 |            | idle   |             |              | ROLLBACK
 16384 | reana   | 186 |    16385 | reana   |                  | 10.244.0.188 |                 |       39708 | 2021-06-08 17:37:01.635035+02 |                               | 2021-06-08 17:37:06.241714+02 | 2021-06-08 17:37:06.241748+02 |                 |            | idle   |             |              | ROLLBACK
 16384 | reana   | 195 |    16385 | reana   |                  | 10.244.0.188 |                 |       39710 | 2021-06-08 17:37:08.81043+02  |                               | 2021-06-08 17:37:27.607378+02 | 2021-06-08 17:37:27.607413+02 |                 |            | idle   |             |              | ROLLBACK
 16384 | reana   | 196 |    16385 | reana   |                  | 10.244.0.188 |                 |       39712 | 2021-06-08 17:37:08.823103+02 |                               | 2021-06-08 17:37:27.607675+02 | 2021-06-08 17:37:27.607713+02 |                 |            | idle   |             |              | ROLLBACK
(14 rows)

This is possibly related to keeping DB connections open in the Flask app.

Let's investigate whether DB sessions are properly closed/reused in between requests within the connection pool.

Observed on master; does not happen in production.

P.S. See also pool_recycle timeout we may want to set, and pool_pre_ping=True to revive them; see the old issue #58.

[tiborsimko]

Update: seeing this also witth latest maint-0.7.