Cannot close a connection joined to a transaction

[takyon]

The following error can happen randomly when using any action:

Exception type: ZODB.POSException.ConnectionStateError?
Exception message: Cannot close a connection joined to a transaction
Traceback:

File "/usr/lib/python2.4/site-packages/cds_indico-0.97_rc1-py2.4.egg/MaKaC/webinterface/rh/base.py", line 484, in process

DBMgr.getInstance().endRequest( True )

File "/usr/lib/python2.4/site-packages/cds_indico-0.97_rc1-py2.4.egg/MaKaC/common/db.py", line 131, in endRequest

self._getConnObject().close()

File "/usr/lib/python2.4/site-packages/ZODB3-3.9.3-py2.4-linux-i686.egg/ZODB/Connection.py", line 284, in close

raise ConnectionStateError?("Cannot close a connection joined to "

Request handler: RHConferenceDisplay
URL: ​http://XXX.XXX.XXX.XXX/indico/conferenceDisplay.py?confId=2
Params: detailLevel = contribution
showSession = all
showDate = all
confId = 2
HTTP headers:

Host: XXX.XXX.XXX.XXX
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 6.0; en-US; rv:1.9.2.8) Gecko/20100722 Firefox/3.6.8 ( .NET CLR 3.5.30729; .NET4.0E)
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: fr,en;q=0.7,en-us;q=0.3
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Keep-Alive: 115
Connection: keep-alive
Referer: ​http://XXX.XXX.XXX.XXX/indico/categoryDisplay.py?categId=1
Cookie: MAKACSESSION=FC9FE16A1A75CC26

Logged user: -- none --

[pferreir]

Could you please check the DB log? Is there any warning/error?

[takyon]

Replying to pferreir:

Could you please check the DB log? Is there any warning/error?

No error in zeo.log, indico.log reports the same error as above.
Is there other logs to check?

It seems that restarting zdaemon is solving the problem for some time...

[pferreir]

Is your Apache server configured to use mpm_prefork or mpm_worker?
Could you please paste the lines that precede the failure (from indico.log)? There should be some indico.dbmgr line...

[pferreir]

Is your Apache server configured to use mpm_prefork or mpm_worker?
Could you please paste the lines that precede the failure (from indico.log)? There should be some indico.dbmgr line...

[takyon]

Here is the copy of log:

%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
2010-10-05 12:51:00,011 indico.dbmgr : DEBUG - Allocated connection for thread -1208695024 - table size is 1
2010-10-05 12:51:00,011 indico.requestHandler: INFO - [pid=18057] Request 175278676 started (/indico/categoryDisplay.py?categId=1)
2010-10-05 12:51:00,013 indico.requestHandler: INFO - [pid=18057] from host 150.183.234.132
2010-10-05 12:51:00,015 indico.i18n : DEBUG - lang:en_US
2010-10-05 12:51:00,104 indico.requestHandler: INFO - Request 175278676 successful
2010-10-05 12:51:00,138 indico.dbmgr : DEBUG - Allocated connection for thread -1208695024 - table size is 1
2010-10-05 12:51:00,139 indico.requestHandler: INFO - [pid=18063] Request 175221228 started (/indico/JSContent.py/getVars)
2010-10-05 12:51:00,140 indico.requestHandler: INFO - [pid=18063] from host 150.183.234.132
2010-10-05 12:51:00,142 indico.i18n : DEBUG - lang:en_US
2010-10-05 12:51:00,159 indico.requestHandler: INFO - Request 175221228 successful
2010-10-05 12:51:01,619 indico.dbmgr : DEBUG - Allocated connection for thread -1208695024 - table size is 1
2010-10-05 12:51:01,621 indico.requestHandler: INFO - [pid=17851] Request 175232684 started (/indico/conferenceDisplay.py?confId=1)
2010-10-05 12:51:01,622 indico.requestHandler: INFO - [pid=17851] from host 150.183.234.132
2010-10-05 12:51:01,626 indico.i18n : DEBUG - lang:en_US
2010-10-05 12:51:01,799 indico.requestHandler: INFO - Request 175232684 successful
2010-10-05 12:51:01,838 indico.dbmgr : DEBUG - Allocated connection for thread -1208695024 - table size is 1
2010-10-05 12:51:01,838 indico.requestHandler: INFO - [pid=18059] Request 175188668 started (/indico/JSContent.py/getVars)
2010-10-05 12:51:01,840 indico.requestHandler: INFO - [pid=18059] from host 150.183.234.132
2010-10-05 12:51:01,842 indico.i18n : DEBUG - lang:en_US
2010-10-05 12:51:01,842 indico.requestHandler: INFO - Request 175188668 successful
2010-10-05 12:51:05,617 indico.dbmgr : DEBUG - Allocated connection for thread -1208695024 - table size is 1
2010-10-05 12:51:05,617 indico.requestHandler: INFO - [pid=18062] Request 175270796 started (/indico/categoryDisplay.py?categId=1)
2010-10-05 12:51:05,619 indico.requestHandler: INFO - [pid=18062] from host 150.183.234.132
2010-10-05 12:51:05,621 indico.i18n : DEBUG - lang:en_US
2010-10-05 12:51:05,853 indico.requestHandler: INFO - Request 175270796 successful
2010-10-05 12:51:05,889 indico.dbmgr : DEBUG - Allocated connection for thread -1208695024 - table size is 1
2010-10-05 12:51:05,889 indico.requestHandler: INFO - [pid=18058] Request 175221124 started (/indico/JSContent.py/getVars)
2010-10-05 12:51:05,891 indico.requestHandler: INFO - [pid=18058] from host 150.183.234.132
2010-10-05 12:51:05,892 indico.i18n : DEBUG - lang:en_US
2010-10-05 12:51:05,893 indico.requestHandler: INFO - Request 175221124 successful
2010-10-05 12:51:07,313 indico.dbmgr : DEBUG - Reused connection for thread -1208695024 - table size is 1
2010-10-05 12:51:07,313 indico.requestHandler: INFO - [pid=18087] Request 175893180 started (/indico/index.py)
2010-10-05 12:51:07,313 indico.requestHandler: INFO - [pid=18087] from host 150.183.234.132
2010-10-05 12:51:07,317 indico.i18n : DEBUG - lang:en_US
2010-10-05 12:51:07,328 indico.cache/upcoming_events: DEBUG - Checking /opt/indico/cache/upcoming_events/e/events...
2010-10-05 12:51:07,329 indico.cache/upcoming_events: DEBUG - HIT
2010-10-05 12:51:07,341 indico.requestHandler: ERROR - Request 175893180 failed: "Cannot close a connection joined to a transaction"

url: ​http://134.75.123.49/indico/index.py

parameters: {}

Traceback (most recent call last):

File "/usr/lib/python2.4/site-packages/cds_indico-0.97_rc1-py2.4.egg/MaKaC/webinterface/rh/base.py", line 484, in process

DBMgr.getInstance().endRequest( True )

File "/usr/lib/python2.4/site-packages/cds_indico-0.97_rc1-py2.4.egg/MaKaC/common/db.py", line 131, in endRequest

self._getConnObject().close()

File "/usr/lib/python2.4/site-packages/ZODB3-3.9.3-py2.4-linux-i686.egg/ZODB/Connection.py", line 284, in close

raise ConnectionStateError?("Cannot close a connection joined to "

ConnectionStateError?: Cannot close a connection joined to a transaction
2010-10-05 12:51:07,409 indico.dbmgr : DEBUG - Reused connection for thread -1208695024 - table size is 1
2010-10-05 12:51:07,409 indico.requestHandler: INFO - [pid=18061] Request 175844132 started (/indico/JSContent.py/getVars)
2010-10-05 12:51:07,409 indico.requestHandler: INFO - [pid=18061] from host 150.183.234.132
2010-10-05 12:51:07,413 indico.i18n : DEBUG - lang:en_US
2010-10-05 12:51:07,413 indico.requestHandler: ERROR - Request 175844132 failed: "Cannot close a connection joined to a transaction"

url: ​http://134.75.123.49/indico/JSContent.py/getVars

parameters: {}

Traceback (most recent call last):

File "/usr/lib/python2.4/site-packages/cds_indico-0.97_rc1-py2.4.egg/MaKaC/webinterface/rh/base.py", line 484, in process

DBMgr.getInstance().endRequest( True )

File "/usr/lib/python2.4/site-packages/cds_indico-0.97_rc1-py2.4.egg/MaKaC/common/db.py", line 131, in endRequest

self._getConnObject().close()

File "/usr/lib/python2.4/site-packages/ZODB3-3.9.3-py2.4-linux-i686.egg/ZODB/Connection.py", line 284, in close

raise ConnectionStateError?("Cannot close a connection joined to "

ConnectionStateError?: Cannot close a connection joined to a transaction
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%

I have the following configuration for MPM:
<IfModule? prefork.c>
StartServers? 8
MinSpareServers? 5
MaxSpareServers? 20
ServerLimit? 256
MaxClients? 256
MaxRequestsPerChild? 4000
</IfModule?>

<IfModule? worker.c>
StartServers? 2
MaxClients? 150
MinSpareThreads? 25
MaxSpareThreads? 75
ThreadsPerChild? 25
MaxRequestsPerChild? 0
</IfModule?>

[pferreir]

OK, there is something suspicious:

2010-10-05 12:51:05,889 indico.dbmgr : DEBUG - Allocated connection for thread -1208695024 - table size is 1

Which suggests our thread table may be going berserk.

Regarding the Apache config, there must be some place where either prefork or worker is being included.

[takyon]

#httpd -l
Compiled in modules:

core.c
prefork.c
http_core.c
mod_so.c

so it seems that prefork is included.

[pferreir]

Patch for possible database threading issues

[pferreir]

Ok, the only way I can see it failing using prefork is having two processes that assign the same thread id to their main threads. I don't know how probable that is (never happened to us, as we restart the DB every day), but seems likely to happen.

Could you please apply the patch that I have attached to the ticket (then restart apache), and let us know if the problem goes away?
This is definitely an issue that we want to get rid of ASAP.

[takyon]

I successfully applied the patch. It seems to work correctly for the moment but we have to wait few days to see if the error come back or not.

[takyon]

the problem is back since this morning...

[pferreir]

Patch for possible database threading issues (2)

[pferreir]

Could you then please try version 2?

[takyon]

patch version 2 successfully applied.

[pferreir]

Any updates on this? Does it still happen?

[takyon]

The situation seems to be better: still no errors until now.
I guess we can close the ticket now and if the error come back in the futur, I can open a new ticket.

[Pedro Ferreira <jose.pedro.ferreira@…>]

In [53540050ec252234cb232dca7ccde8ac05c68f34]:

[FIX] Fix for threading issues

• Let ZEO handle thead connections;
• Apparently fixes #540;

[Pedro Ferreira <jose.pedro.ferreira@…>]

In [53540050ec252234cb232dca7ccde8ac05c68f34]:

[FIX] Fix for threading issues

• Let ZEO handle thead connections;
• Apparently fixes #540;