MySQL Commands out of sync on attempt to rollback

[voidfiles@…]

I have newest code as of this ticket. This only happens when I run django through a fastCGI on dreamhost. I have built my own python, and mysqlDB so its not dreamhosts stuff. Followed the directions in the django tutorial. Happened after a checkout so that is why I think this might be a bug, and not a support issue.

Here is the Error dump.

 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr: Traceback (most recent call last):
 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr:   File "build/bdist.linux-i686/egg/flup/server/fcgi_base.py", line 558, in run
 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr:     protocolStatus, appStatus = self.server.handler(self)
 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr:   File "build/bdist.linux-i686/egg/flup/server/fcgi_base.py", line 1112, in handler
 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr:     result = self.application(environ, start_response)
 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr:   File "/home/varius_2/opt/lib/python2.5/site-packages/django/core/handlers/wsgi.py", line 216, in __call__
 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr:     response = self.get_response(request)
 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr:   File "/home/varius_2/opt/lib/python2.5/site-packages/django/core/handlers/base.py", line 124, in get_response
 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr:     receivers = signals.got_request_exception.send(sender=self.__class__, request=request)
 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr:   File "/home/varius_2/opt/lib/python2.5/site-packages/django/dispatch/dispatcher.py", line 132, in send
 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr:     response = receiver(signal=self, sender=sender, **named)
 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr:   File "/home/varius_2/opt/lib/python2.5/site-packages/django/db/__init__.py", line 56, in _rollback_on_exception
 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr:     transaction.rollback_unless_managed()
 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr:   File "/home/varius_2/opt/lib/python2.5/site-packages/django/db/transaction.py", line 157, in rollback_unless_managed
 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr:     connection._rollback()
 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr:   File "/home/varius_2/opt/lib/python2.5/site-packages/django/db/backends/mysql/base.py", line 227, in _rollback
 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr:     BaseDatabaseWrapper._rollback(self)
 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr:   File "/home/varius_2/opt/lib/python2.5/site-packages/django/db/backends/__init__.py", line 32, in _rollback
 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr:     return self.connection.rollback()
 /home/varius_2/loudfarm.tastestalkr.com/dispatch.fcgi" stderr: ProgrammingError: (2014, "Commands out of sync; you can't run this command now")

[Karen Tracey <kmtracey@…>]

Specifics beyond 'not dreamhosts stuff' could be helpful here. What MySQLdb & MySQL levels exactly? I assume you are using InnoDB since the error sounds transaction-related? What exactly triggers the error? Any attempt to access any url on your site?

[voidfiles@…]

Yea thanks for the response.

So here is what I get mysql
mysql Ver 14.12 Distrib 5.0.16, for pc-linux-gnu (i386) using readline 5.0

MySQL-python-1.2.2

I get the error when I try and access admin, and one other url

I am using MyISAM, not InnoDB

Thanks for telling me what elese to include I have never filled a ticket before.

[Karen Tracey]

I think there are a couple of problems interacting here. First there is something weird causing ill-described "crashes" going on with sessions/cookies, see #8314 and various reports on the user's list today. The reason I think that is related to this report is that I just hit this traceback when I:

• changed my settings.py to point to my test DB instead of my production DB

• used the same browser I had been using to access my production DB to instead access the test DB, this caused a commands out of sync error/traceback

• I then managed to avoid the traceback by clearing cookies from my browser, once I did that I could access the test DB admin

So the cookies/session oddness is one problem and is I think being looked into separately. The fact that the exception it caused resulted in a MySQL "Commands out of sync" error is a different problem which I will try looking into.

To voidfiles: try clearing cookies in your browser and see if that fixes the problem.

To anyone with trac superpowers: Could you fix the original description formatting? (Or if that is something mere mortals can do please tell me how, 'cause I don't know how to do it and this one is hurting my eyes.)

[Karen Tracey]

Meant to change the triage stage, not assign to myself.

[Malcolm Tredinnick]

Fixed description to stop Karen's eyes from hurting.

[voidfiles]

clearing my cookies did allow me to get into the admin section.

[Karen Tracey]

Catch ProgrammingError on attempt to rollback

[Karen Tracey]

Well, I attached a patch that at least causes the root problem (maximum recursion depth exceeded) to get reported. Attempt to rollback already caught/passed Database.NotSupportedError but did not catch ProgrammingError. I do not know why in this particular case we see ProgrammingError, or if it always correct to catch and ignore it. In this particular case it seems good, since failing to catch it obscured the real error and instead reported something completely unhelpful. But might there be a case where we'd rather want to know rollback reported a ProgrammingError? Someone with more transaction smarts than me maybe knows.

[Karen Tracey <kmtracey@…>]

I've done as much as I can with this one.

[Malcolm Tredinnick]

I'm not completely happy with this (although thanks for working out the problem). A ProgrammingError isn't going to be raised by the database and indicates some kind of real developer-level problem. I'm just about to commit a fix for the root problem (#8314), which should fix the immediate issue. Will leave this open for a bit to think about it. Right now, I'm inclined to not apply it, but I may be missing something.

[Karen Tracey <kmtracey@…>]

I attached an alternative version of the patch that catches the rollback exception within _rollback_on_exception. Here we know we're already dealing with handling an error case, so the question is which error do we want to report? If the answer is we want to report the original exception, not the failure on rollback, then I think we want the patch. I'm more comfortable with this version of the patch since it seems targeted at ensuring the root error is reported without possibly hiding other valid errors that should be raised when a rollback fails. BTW the recursion exception in the case where MySQL is being used seems to be getting hit inside MySQLdb:

File "/home/kmt/django/trunk/django/db/models/sql/query.py" in execute_sql
  1614.         cursor.execute(sql, params)
File "/home/kmt/django/trunk/django/db/backends/util.py" in execute
  19.             return self.cursor.execute(sql, params)
File "/var/lib/python-support/python2.5/MySQLdb/cursors.py" in execute
  166.             self.errorhandler(self, exc, value)
File "/var/lib/python-support/python2.5/MySQLdb/connections.py" in defaulterrorhandler
  File "/home/kmt/django/trunk/django/db/models/sql/query.py" in execute_sql
  1614.         cursor.execute(sql, params)
File "/home/kmt/django/trunk/django/db/backends/util.py" in execute
  19.             return self.cursor.execute(sql, params)
File "/var/lib/python-support/python2.5/MySQLdb/cursors.py" in execute
  166.             self.errorhandler(self, exc, value)
File "/var/lib/python-support/python2.5/MySQLdb/connections.py" in defaulterrorhandler
  35.     raise errorclass, errorvalue

Exception Type: RuntimeError at /admin/
Exception Value: maximum recursion depth exceeded
35.     raise errorclass, errorvalue

Exception Type: RuntimeError at /admin/
Exception Value: maximum recursion depth exceeded

so it may be that the whole connection is left in a state where any attempt to do anything besides close it generates an error? In cases where this has happened I think it will be generally more useful to be told about what caused the first error, not the fact that attempting to rollback failed.

[Karen Tracey <kmtracey@…>]

My center mouse button has developed a bad habit of double-pasting on me. It's supposed to be:

File "/home/kmt/django/trunk/django/db/models/sql/query.py" in execute_sql
  1614.         cursor.execute(sql, params)
File "/home/kmt/django/trunk/django/db/backends/util.py" in execute
  19.             return self.cursor.execute(sql, params)
File "/var/lib/python-support/python2.5/MySQLdb/cursors.py" in execute
  166.             self.errorhandler(self, exc, value)
File "/var/lib/python-support/python2.5/MySQLdb/connections.py" in defaulterrorhandler
  35.     raise errorclass, errorvalue

Exception Type: RuntimeError at /admin/
Exception Value: maximum recursion depth exceeded

which doesn't look quite so insane as the first version.

[Malcolm Tredinnick]

heh. That second paste makes a lot more sense. :-)

I like the second patch better, for the reasons you mention. It doesn't hide the real problem and just feels like it's catching things at the right level (plus it will work for all backends). If I don't get nervous about it in the interim, I'll commit this later today.

[Karen Tracey <kmtracey@…>]

Nervous? What could possibly make you nervous? Perfectly obvious fix, it can't possibly break anything, just like some others this week. :-)

[Malcolm Tredinnick]

(In [8411]) Fixed #8315 -- If an exception is raised whilst trying to rollback a
transaction (after another exception in the code), make sure the original
exception is reported, rather than the rollback-generated one. The latter is
almost certainly a consequence of the former. Patch from Karen Tracey.

[Jacob]

Milestone 1.0 deleted