ExceptionReporter may re-evaluate error-causing queryset, leading to a later DatabaseError that masks the original one

[aaron]

I'm using PostgreSQL and the TransactionMiddleware , and I'm not sure if this error occurs with other database engines. Here's the error that pops up:

DatabaseError at /blah/

current transaction is aborted, commands ignored until end of transaction block

Traceback:
File ".../lib/django-1.3/django/core/handlers/base.py" in get_response
  178.                 response = middleware_method(request, response)
File ".../lib/django-1.3/django/contrib/sessions/middleware.py" in process_response
  36.                 request.session.save()
File ".../lib/django-1.3/django/contrib/sessions/backends/db.py" in save
  61.         sid = transaction.savepoint(using=using)
File ".../lib/django-1.3/django/db/transaction.py" in savepoint
  162.     return connection.savepoint()
File ".../lib/django-1.3/django/db/backends/__init__.py" in savepoint
  223.         self._savepoint(sid)
File ".../lib/django-1.3/django/db/backends/__init__.py" in _savepoint
  70.         self.cursor().execute(self.ops.savepoint_create_sql(sid))
File ".../lib/django-1.3/django/db/backends/util.py" in execute
  34.             return self.cursor.execute(sql, params)
File ".../lib/django-1.3/django/db/backends/postgresql_psycopg2/base.py" in execute
  44.             return self.cursor.execute(query, args)

The cause seems to be a QuerySet that causes an error, for example, it refers to a table that doesn't exist or is missing a column. This would be fine, except that there are two lines in django/views/debug.py around line 117, in ExceptionReporter.get_traceback_html() (in django 1.3 release version) that looks like this:

if 'vars' in frame:
    frame['vars'] = [(k, force_escape(pprint(v))) for k, v in frame['vars']]

In this case, v is the QuerySet. Running the pprint template filter on it evaluates it, and since it caused an error the first time (and never got _result_cache filled in) it causes an error the second time too. This error is caught by the filter, which returns an error string. However, the running of the SQL query puts the DB in a bad state, so any SQL commands run after this point also return an error, and saving the current user's session is one such command. This new error masks the original one, which is annoying. It's still possible to find the original error by looking at the database log, but that's defeating the point of this otherwise beautiful error page.

I'm not sure of the best way to fix this. One way, I guess, is to set a transaction savepoint before calling this method and roll it back after, but that seems to be a hack. Maybe we could check for querysets that have not been evaluated, and leave them unevaluated, printing out something like "(Unevaluated QuerySet) %s" % qs.query instead. It seems to make sense that the error reporting page renderer should not touch the database at all, since it should be as robust as possible.

I think that ideally QuerySet.__repr__ wouldn't have any side effects, but its behaviour has been around for so long and so many people are used to not needing list(qs) in an interactive shell that this would not be an easy change to make. I wonder if it would be possible to add a hook into manage.py shell that evaluates querysets as a substitute?

[aaron]

Another idea -- perhaps it would make sense to add a global toggle that determines whether QuerySet.repr evaluates them, and leave it on at all times except when rendering the error page.

[Luke Plant]

Regarding a hook in manage.py shell - that wouldn't be acceptable, because it is far from the only way that Django code is run from an interactive Python session.

Here are some other options for stopping this happening:

• For your second idea, instead of a global toggle, we could simply monkey patch QuerySet.__repr__ when rendering the error page.
• We could just do isinstance checks for QuerySet.
• QuerySet.__repr__ is potentially just one source of DB activity, so a fuller solution might be to turn the DB code into 'don't do anything' mode. This could be via some global, or by some monkey patching.

[aaron]

What about adding a method to QuerySet? Something like QuerySet.safe_repr(), which acts the way I described above, and then we can do an isinstance check and call that method instead of pprint. That way if this issue comes up in other places there will be a clear way to fix it, and anyone modifying QuerySet will be aware that this use case exists.

Monkey patching always has the issue that it's hard to notice when changing the original code.

For the DB don't-do-anything mode idea, what would the behaviour be? Return empty results, or raise an exception? Raising a special exception would be nice, perhaps, because the template code could catch it and display a clear message.

[Luke Plant]

For the DB-level switch, it should throw some exception. The hard part is find the right point to do it.

So I think for now, your 'safe_repr' idea is the best one. Perhaps even __safe_repr__, to avoid accidental conflicts, and to make it obviously similar to __repr__. The exception handling will call this method, perhaps via a new saferepr function that encapsulates the checking for __safe_repr__ attribute. We can avoid isinstance checks entirely this way.

[Aymeric Augustin]

Since Django now uses autocommit by default, it's impossible to end up in "current transaction is aborted, commands ignored until end of transaction block" — unless you're building your own transaction management, in which case it's up to you to rollback.

[lgfausak@…]

In my opinion this is not fixed. Auto-commit is not a reasonable way to run a database. Often a database performs more than one operation at the same time. The database's job is to insure that either all operations work, or all operations fail. With auto-commit that would leave you in an inconsistent state. I think this bug was reported incorrectly. It isn't that 'current transaction is aborted, commands ignored until end' is the real problem. The real problem is finding out what the error was that caused this state. Is that possible? I can only do so by looking through the postgres logs. Maybe I am using the transaction incorrectly, or maybe this is fixed in 1.6???

[Aymeric Augustin]

Please review the transaction management documentation.

Auto-commit is the *default* mode, but Django *also* supports transactions.