wulczer/txpostgres — Issue #18: Unhandled errors on TCP connection timeout
Author: woodrow
Created: 2012-01-23 06:40:36+00:00
State: open

I've been testing txpostgres' response to connection failures/timeouts, and I've run into issues where, during a connection failure or timeout, exceptions occur that are not caught/do not fire an errback and so it's not possible to handle them by i.e. closing the connection and reopening it.

There are two slightly different failure modes. If a tcp_keepalive timeout is allowed to occur, then no errbacks are fired. If a tcp_retries or TCP_USER_TIMEOUT occurs, one errback fires but an unhandled exception still occurs. This happens both with SSL and non-SSL connections -- both are psycopg2.OperationalError exceptions, but the error messages are slightly different (see below).

## The tracebacks

```pytb
Unhandled Error
Traceback (most recent call last):
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/python/log.py", line 84, in callWithLogger
return callWithContext({"system": lp}, func, *args, **kw)
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/python/log.py", line 69, in callWithContext
return context.call({ILogContext: newCtx}, func, *args, **kw)
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/python/context.py", line 118, in callWithContext
return self.currentContext().callWithContext(ctx, func, *args, **kw)
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/python/context.py", line 81, in callWithContext
return func(*args,**kw)
--- ---
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/internet/posixbase.py", line 581, in _doReadOrWrite
why = selectable.doRead()
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/txpostgres/txpostgres.py", line 584, in doRead
_PollingMixin.doRead(self)
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/txpostgres/txpostgres.py", line 151, in doRead
self.continuePolling()
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/txpostgres/txpostgres.py", line 123, in continuePolling
state = self.pollable().poll()
psycopg2.OperationalError: SSL SYSCALL error: EOF detected
```

```pytb
Unhandled Error
Traceback (most recent call last):
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/python/log.py", line 84, in callWithLogger
return callWithContext({"system": lp}, func, *args, **kw)
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/python/log.py", line 69, in callWithContext
return context.call({ILogContext: newCtx}, func, *args, **kw)
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/python/context.py", line 118, in callWithContext
return self.currentContext().callWithContext(ctx, func, *args, **kw)
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/python/context.py", line 81, in callWithContext
return func(*args,**kw)
--- ---
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/internet/posixbase.py", line 581, in _doReadOrWrite
why = selectable.doRead()
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/txpostgres/txpostgres.py", line 584, in doRead
_PollingMixin.doRead(self)
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/txpostgres/txpostgres.py", line 151, in doRead
self.continuePolling()
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/txpostgres/txpostgres.py", line 123, in continuePolling
state = self.pollable().poll()
psycopg2.OperationalError: could not receive data from server: Connection timed out
```

## Reproducing this error

I created a program to reproduce this: https://gist.github.com/1661012. Apologies if it's not very idiomatic Twisted, but hopefully it does the job.

This must be run on a Linux machine as it requires iptables to simulate connection failures. Having TCP fail quickly using the TCP_USER_TIMEOUT socket option requires running this with kernel >= 2.6.37. Further, the python modules twisted, txpostgres and psycopg2 are required. Finally, a PostgreSQL database listening on 127.0.0.1 with no password needed to access the 'postgres' database from localhost is required.

The program will provide prompts to add and remove an iptables rule -- you can just start the program and follow along.

You can run the program with or without an 'ssl' argument to enable or disable SSL on the connection.

If you don't want to run the program yourself, both failure modes are shown below (which include the tracebacks already shown above):

`$ python demo_conn.py ssl` (sslmode=require)

An Errback is called (`ERRBACK: (, SSL SYSCALL error: Connection timed out)`) but an unhandled error still occurs:

```pytb
Unhandled Error
Traceback (most recent call last):
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/python/log.py", line 84, in callWithLogger
return callWithContext({"system": lp}, func, *args, **kw)
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/python/log.py", line 69, in callWithContext
return context.call({ILogContext: newCtx}, func, *args, **kw)
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/python/context.py", line 118, in callWithContext
return self.currentContext().callWithContext(ctx, func, *args, **kw)
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/python/context.py", line 81, in callWithContext
return func(*args,**kw)
--- ---
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/internet/posixbase.py", line 581, in _doReadOrWrite
why = selectable.doRead()
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/txpostgres/txpostgres.py", line 584, in doRead
_PollingMixin.doRead(self)
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/txpostgres/txpostgres.py", line 151, in doRead
self.continuePolling()
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/txpostgres/txpostgres.py", line 123, in continuePolling
state = self.pollable().poll()
psycopg2.OperationalError: SSL SYSCALL error: EOF detected
```

`$ python demo_conn.py` (sslmode=disable)

An Errback is called (`ERRBACK: (, could not receive data from server: Connection timed out)` but an unhandled error still occurs:

```pytb
Unhandled Error
Traceback (most recent call last):
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/python/log.py", line 84, in callWithLogger
return callWithContext({"system": lp}, func, *args, **kw)
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/python/log.py", line 69, in callWithContext
return context.call({ILogContext: newCtx}, func, *args, **kw)
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/python/context.py", line 118, in callWithContext
return self.currentContext().callWithContext(ctx, func, *args, **kw)
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/python/context.py", line 81, in callWithContext
return func(*args,**kw)
--- ---
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/twisted/internet/posixbase.py", line 581, in _doReadOrWrite
why = selectable.doRead()
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/txpostgres/txpostgres.py", line 584, in doRead
_PollingMixin.doRead(self)
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/txpostgres/txpostgres.py", line 151, in doRead
self.continuePolling()
File "/home/woodrow/tmp/txpostgres_noerrback/virt-python/lib/python2.7/site-packages/txpostgres/txpostgres.py", line 123, in continuePolling
state = self.pollable().poll()
psycopg2.OperationalError: could not receive data from server: Connection timed out
```

## My Environment:

```
Python 2.7.2 (default, Nov 21 2011, 17:25:27)
>>> import txpostgres
>>> print(txpostgres.__version__)
(1, 0, 0)
>>> import twisted
>>> print(twisted.__version__)
11.1.0
>>> import psycopg2
>>> print(psycopg2.__version__)
2.4.4 (dt dec pq3 ext)
```