PostgreSQL authentication error throws cryptic exception

[gabrtv]

After issuing a GET to /trac, Apache/mod-python return the following cryptic error message:

Traceback (most recent call last):
  File "/usr/local/lib/python2.6/dist-packages/Trac-0.12.1dev_r10109-py2.6.egg/trac/web/api.py", line 436, in send_error
    data, 'text/html')
  File "/usr/local/lib/python2.6/dist-packages/Trac-0.12.1dev_r10109-py2.6.egg/trac/web/chrome.py", line 803, in render_template
    message = req.session.pop('chrome.%s.%d' % (type_, i))
  File "/usr/local/lib/python2.6/dist-packages/Trac-0.12.1dev_r10109-py2.6.egg/trac/web/api.py", line 212, in __getattr__
    value = self.callbacks[name](self)
  File "/usr/local/lib/python2.6/dist-packages/Trac-0.12.1dev_r10109-py2.6.egg/trac/web/main.py", line 300, in _get_session
    return Session(self.env, req)
  File "/usr/local/lib/python2.6/dist-packages/Trac-0.12.1dev_r10109-py2.6.egg/trac/web/session.py", line 166, in __init__
    self.promote_session(sid)
  File "/usr/local/lib/python2.6/dist-packages/Trac-0.12.1dev_r10109-py2.6.egg/trac/web/session.py", line 225, in promote_session
    @self.env.with_transaction()
  File "/usr/local/lib/python2.6/dist-packages/Trac-0.12.1dev_r10109-py2.6.egg/trac/db/api.py", line 82, in transaction_wrapper
    ldb.rollback()
  File "/usr/local/lib/python2.6/dist-packages/Trac-0.12.1dev_r10109-py2.6.egg/trac/db/util.py", line 102, in __getattr__
    return getattr(self.cnx, name)
AttributeError: 'tuple' object has no attribute 'rollback'

The error should probably be a bit more descriptive. Environment is Ubuntu 10.04 x64 with a generic trac 0.12 install.

[osimons]

I just looked at this briefly when it appeard on IRC, and according to user the error was a Postgres authentication error - which is then a typical database error that can occur for various reasons. Some assumption inside transaction_wrapper does not hold in such circumstances.

[Christian Boos]

I wonder if we still have a similar error with 0.12-stable, as the pool code has changed quite a bit. Would someone mind testing? (or I'll test it myself on some innocent 0.12-stable instance, like … Bitten! :-) ).

[Christian Boos]

This can actually happen as a secondary error, if a database connection couldn't be created (the ('create', None) entry is kept in the _active dict). I have already fixed that in the forthcoming changes in the db layer for 0.13dev, need to backport this specific fix.

[Christian Boos]

Specifically this hunk:

trac/db/pool.py

@@ -113 +98 @@
             elif op == 'close':
                 cnx.close()
             if op in ('close', 'create'):
-                cnx = connector.get_connection(**kwargs)
-
+                try:
+                    cnx = connector.get_connection(**kwargs)
+                except Exception: # couldn't create a new connection
+                    with self._available:
+                        del self._active[(tid, key)]
+                    raise
+        

[Christian Boos]

more robust deferred operations when taking a connection from the pool.

[Christian Boos]

Ok, I backported and refined the patch above. Please test 9623-active.patch​. I think it's a safe fix but more review can't hurt, especially that close to release ;-)

[Remy Blank]

The patch works fine here on Linux, OS X and Windows 7. But I have to admit that you have lost me long ago with the logic in the DB pool…

[Christian Boos]

Replying to rblank:

The patch works fine here on Linux, OS X and Windows 7.

Thanks for testing! Ideally, we should also test what's happening when Trac is running fine with PostgreSQL or MySQL and the DB is suddenly shut down…

But I have to admit that you have lost me long ago with the logic in the DB pool…

Well, the story goes like that:

• jonas produces a simple, nice and clean pool mechanism
• some corner cases appear
• cboos tries to handle them all and makes the whole thing overly complex…

Repeat. So let's wait for the next iteration from jonas ;-)

[Christian Boos]

Ok, as I was surprised to get again a TimeoutError when testing the patch, I realized this was because the database I attempted to connect to was no longer existing. So the 'create' deferred step failed, but we didn't show why.

I added that to the error message (appended, because of the string freeze), in addition to the previous changes from 9623-active.patch​.

Fix committed in r10151.