options='-c statement_timeout=5000' not honoured with SSL timeout

[stefanknechtDBE]

We hung over 15 minutes, despite there being a statement timeout in effect of 5 seconds.

Connect call:
psycopg2.connect( dbname = databaseName, user = userName, host = hostName, port = 5432, connect_timeout = 5, options='-c statement_timeout=5000')

Yet, the logs show:

2019-07-08 06:00:13,932 Connection check for xyz succeeded. Sleeping..
2019-07-08 06:00:44,327 Connection check for xyz succeeded. Sleeping..
2019-07-08 06:01:15,256 Connection check for xyz succeeded. Sleeping..
2019-07-08 06:17:17,580 Failed to execute query select current_user;: (<class 'psycopg2.DatabaseError'>, DatabaseError('SSL SYSCALL error: Connection timed out\n',), <traceback object at 0x7f95f185e748>)
2019-07-08 06:17:17,780 Connected to database postgres at xyz.x.rds.amazonaws.com after 0.0245s
2019-07-08 06:17:17,793 Connection check for xyz succeeded. Sleeping..

At 06:01 Amazon RDS initiated a failover. We failed to detect that the connection is dead for over 15 minutes, while waiting for "select current user;" to return, which was set to a 5 second statement timeout.

Should the statement timeout not override the ssl timeout?

[stefanknechtDBE]

This is on Ubuntu 16.04.5 LTS 4.4.0-1072-aws #82-Ubuntu
psycopg2-binary 2.7.5
Python 3.6.6

[dvarrazzo]

Psycopg just passes down the parameters to the libpq. If you find they don't make sense you should mention to a postgres mailing list such as pgsql-bugs.

[bobergj]

When a wait_callback is set (psyco_green is true) PQconnectStart and PQconnectPoll is used to setup the connection.

psycopg2/psycopg/connection_int.c

Line 724 in e14e338

self->pgconn = PQconnectStart(dsn);

Now, https://www.postgresql.org/docs/current/libpq-connect.html says

The connect_timeout connection parameter is ignored when using PQconnectPoll; it is the application's responsibility to decide whether an excessive amount of time has elapsed. Otherwise, PQconnectStart followed by a PQconnectPoll loop is equivalent to PQconnectdb.

Now, it's the first time I look at this code, but my impression is that psycopg doesn't setup any connection timeout-timer in the psyco_green configuration. Maybe it should?

[dvarrazzo]

Thank you @bobergj, good catch.

I guess we can do something around the idea of checking explicitly if the timeout had expired at every poll. It's not a minor change, it's a sort of small feature.

It's also weird how to interface. I don't feel like adding a new connection parameter, as it would create an asymmetry between sync and async/green code. We could parse the options but it's tricky as they can also come from the PGOPTIONS end var. If PQconninfo works at half connection too that's doable anyway.

Reopening to jam around that. Ideas?