trac/mod_python doesn't reconnect to postgresql after db restart

[andrewdied@…]

This may be a reopening of #3394. I am using trac 0.10.3, python 2.5, apache 2.2.3, Suse 10.2, mod_python 3.2.10, postgresql 8.1.5, Pypgsql 2.5.1.

If I restart postgres while apache/trac is running, trac does not automatically reconnect once the database is back up.

Steps to reproduce:

1. Have a running apache/mod_python/trac environment.
2. Restart postgres, like "sudo /etc/init.d/postgres restart"
3. Try to run a report, like ​http://example.com/trac/instancename/report/3

Expected results:

1. The page would take slightly longer to display as trac reconnected to the database. Alternately, See one error message telling the user to reload the page, then trac would function normally.

Actual results:
The on-screen oops message is:

Python Traceback
Traceback (most recent call last):
  File "/usr/lib/python2.5/site-packages/trac/web/main.py", line 387, in dispatch_request
    dispatcher.dispatch(req)
  File "/usr/lib/python2.5/site-packages/trac/web/main.py", line 183, in dispatch
    req.perm = PermissionCache(self.env, req.authname)
  File "/usr/lib/python2.5/site-packages/trac/perm.py", line 263, in __init__
    self.perms = PermissionSystem(env).get_user_permissions(username)
  File "/usr/lib/python2.5/site-packages/trac/perm.py", line 227, in get_user_permissions
    for perm in self.store.get_user_permissions(username):
  File "/usr/lib/python2.5/site-packages/trac/perm.py", line 110, in get_user_permissions
    cursor = db.cursor()
  File "/usr/lib/python2.5/site-packages/trac/db/util.py", line 78, in cursor
    return IterableCursor(self.cnx.cursor())
  File "/usr/lib/python2.5/site-packages/trac/db/util.py", line 78, in cursor
    return IterableCursor(self.cnx.cursor())
  File "/usr/local/lib/python2.5/site-packages/pyPgSQL/PgSQL.py", line 2599, in cursor
    return Cursor(self, name, isRefCursor)
  File "/usr/local/lib/python2.5/site-packages/pyPgSQL/PgSQL.py", line 2718, in __init__
    self.conn._Connection__setupTransaction()
  File "/usr/local/lib/python2.5/site-packages/pyPgSQL/PgSQL.py", line 2510, in __setupTransaction
    self.conn.query("BEGIN WORK")
OperationalError: FATAL:  terminating connection due to administrator command
server closed the connection unexpectedly
	This probably means the server terminated abnormally
	before or while processing the request.

In the trac log file:

2007-03-20 08:11:21,499 Trac[main] ERROR: FATAL:  terminating connection due to administrator command
server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.
Traceback (most recent call last):
  File "/usr/lib/python2.5/site-packages/trac/web/main.py", line 387, in dispatch_request
    dispatcher.dispatch(req)
  File "/usr/lib/python2.5/site-packages/trac/web/main.py", line 183, in dispatch
    req.perm = PermissionCache(self.env, req.authname)
  File "/usr/lib/python2.5/site-packages/trac/perm.py", line 263, in __init__
    self.perms = PermissionSystem(env).get_user_permissions(username)
  File "/usr/lib/python2.5/site-packages/trac/perm.py", line 227, in get_user_permissions
    for perm in self.store.get_user_permissions(username):
  File "/usr/lib/python2.5/site-packages/trac/perm.py", line 110, in get_user_permissions
    cursor = db.cursor()
  File "/usr/lib/python2.5/site-packages/trac/db/util.py", line 78, in cursor
    return IterableCursor(self.cnx.cursor())
  File "/usr/lib/python2.5/site-packages/trac/db/util.py", line 78, in cursor
    return IterableCursor(self.cnx.cursor())
  File "/usr/local/lib/python2.5/site-packages/pyPgSQL/PgSQL.py", line 2599, in cursor
    return Cursor(self, name, isRefCursor)
  File "/usr/local/lib/python2.5/site-packages/pyPgSQL/PgSQL.py", line 2718, in __init__
    self.conn._Connection__setupTransaction()
  File "/usr/local/lib/python2.5/site-packages/pyPgSQL/PgSQL.py", line 2510, in __setupTransaction
    self.conn.query("BEGIN WORK")
OperationalError: FATAL:  terminating connection due to administrator command
server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.

[cboos]

Agreed, we should handle this kind of error more gracefully.

[cboos]

#7797 was closed as duplicate.

[anonymous]

Has anyone had the time to look at this bug?

I can confirm that it is still happening in Debian Lenny.

[tlk]

postgresql 8.3, psycopg2, trac 0.11.4 - running through tracd

Restarting postgresql, and then visiting trac results in an error message like the reporter described. In addition, tracd also outputs the following on a single line:

Exception psycopg2.InterfaceError: 
'connection already closed' in 
<bound method PooledConnection.__del__ of 
<trac.db.pool.PooledConnection object at 
0x2aaaabd09290>> ignored

However, if the page is reloaded it works and subsequent http requests also works as expected.

[tlk]

Can reproduce running through mod_python. The error shows up at random times.

It looks like a problem with ConnectionPoolBackend?._pool still holding the PostgreSQLConnection(s) that was closed during database restart.

[tlk@…]

do not add failing connections to the pool (0.11-stable)

[tlk]

The patch wont hide connection failures but it will prevent the pool from reusing connections already know to fail.

[cboos]

The patch looks good, thanks. I'd like jonas to have a look on this.

Also, I wonder if we couldn't try an auto-reconnect once before failing.

[anonymous]

Agreed, it would be nice to be able to auto-reconnect once before failing. We could create a new connection in the cursor method if an exception is thrown, but currently the PooledConnection? does not have any knowledge about what kind of database connection it holds, so it would be necessary to add information about that. Also, we need to make sure not messing up _pool in ConnectionPoolBackend?.

Perhaps a cleaner solution is to add another class e.g. ReliableConnection?(ConnectionWrapper?) encapsulating a PooledConnection?. Then everything related to database error handling can be kept inside the ReliableConnection? class.

[tlk]

Another issue is how database errors are presented to the user. My suggestion is to introduce a DatabaseError?(Exception) and handle these kind of exceptions in the user interface layers.

[tlk]

also see #6348 (Catch database exceptions in a backend neutral way)

[cboos]

I'd like to get an "ack" from jonas on this patch. The change itself might also interfere with #8443.

[cboos]

Doing self.close() in PooledConnection seems a bit too much, we might recover from a failed query in the user code and retry another query
The close should instead be done when we decide to not reuse the connection.

As mentioned in comment:11, the changes here are also a good step in direction of #6348.

[cboos]

Postponed.

[anonymous]

This issue still happens on 11.6 version. We need a solution.

Regards.

[anonymous]

This problem still exists in Trac 0.12.2 using mod_wsgi 3.3, and is incredibly annoying.