If creation of a db cursor fails, the resulting traceback is misleading

[Jerome Leclanche]

When a schema is out of sync (eg. running tests for a project where a model has fields not present in the migration).

The creation of a cursor involves a sql query which includes all of the field names. Creating that cursor will fail.
However, the exception is currently caught by a try/except which always attempts to *close* the cursor. Closing the cursor is not try/excepted, which results in that particular query failing and a traceback that looks like "ERROR: cursor "_django_curs_140260213699904_6" does not exist".

Patch:

commit 7c7a1f53acbf7d94f0a9b360f973711a7c9fbfbd (HEAD -> refs/heads/master)
Author: Jerome Leclanche <jerome@leclan.ch>
Date:   Tue Mar 20 09:57:26 2018 +0200

    Raise outer exception when failing to close a cursor after an error

diff --git a/django/db/models/sql/compiler.py b/django/db/models/sql/compiler.py
index 1fdbd156b6..f96be3c4ea 100644
--- a/django/db/models/sql/compiler.py
+++ b/django/db/models/sql/compiler.py
@@ -1051,10 +1051,15 @@ class SQLCompiler:
             cursor = self.connection.cursor()
         try:
             cursor.execute(sql, params)
-        except Exception:
+        except Exception as e:
             # Might fail for server-side cursors (e.g. connection closed)
-            cursor.close()
-            raise
+            try:
+                cursor.close()
+            except Exception:
+                # If we got an error creating the cursor, then closing it
+                # will always fail. Raise the outer exception instead of the
+                # obscure "cursor _django_curs_xxxx does not exist".
+                raise e from None
 
         if result_type == CURSOR:
             # Give the caller the cursor to process and close.

[Chetan Khanna]

Hi.
Upon applying the patch, the following Traceback occurs since the asserted output didn't match the new error raised. Just wanted to know the correct way to proceed from here (Sorry am very new here). Particularly, is a new regression test required here? Or we just need to re-write these tests?

Traceback:

======================================================================
ERROR [0.006s]: test_atomic_prevents_queries_in_broken_transaction (transactions.tests.AtomicErrorsTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/unittest/case.py", line 59, in testPartExecutor
    yield
  File "/usr/local/lib/python3.6/unittest/case.py", line 605, in run
    testMethod()
  File "/tests/django/tests/transactions/tests.py", line 327, in test_atomic_prevents_queries_in_broken_transaction
    r2.save(force_update=True)
  File "/tests/django/django/db/models/base.py", line 743, in save
    force_update=force_update, update_fields=update_fields)
  File "/tests/django/django/db/models/base.py", line 781, in save_base
    force_update, using, update_fields,
  File "/tests/django/django/db/models/base.py", line 863, in _save_table
    raise DatabaseError("Forced update did not affect any rows.")
django.db.utils.DatabaseError: Forced update did not affect any rows.

======================================================================
ERROR [0.160s]: test_content_type_rename_conflict (contenttypes_tests.test_operations.ContentTypeOperationsTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/unittest/case.py", line 59, in testPartExecutor
    yield
  File "/usr/local/lib/python3.6/unittest/case.py", line 605, in run
    testMethod()
  File "/tests/django/tests/contenttypes_tests/test_operations.py", line 77, in test_content_type_rename_conflict
    call_command('migrate', 'contenttypes_tests', database='default', interactive=False, verbosity=0)
  File "/tests/django/django/core/management/__init__.py", line 168, in call_command
    return command.execute(*args, **defaults)
  File "/tests/django/django/core/management/base.py", line 369, in execute
    output = self.handle(*args, **options)
  File "/tests/django/django/core/management/base.py", line 83, in wrapped
    res = handle_func(*args, **kwargs)
  File "/tests/django/django/core/management/commands/migrate.py", line 233, in handle
    fake_initial=fake_initial,
  File "/tests/django/django/db/migrations/executor.py", line 117, in migrate
    state = self._migrate_all_forwards(state, plan, full_plan, fake=fake, fake_initial=fake_initial)
  File "/tests/django/django/db/migrations/executor.py", line 147, in _migrate_all_forwards
    state = self.apply_migration(state, migration, fake=fake, fake_initial=fake_initial)
  File "/tests/django/django/db/migrations/executor.py", line 245, in apply_migration
    state = migration.apply(state, schema_editor)
  File "/tests/django/django/db/migrations/migration.py", line 124, in apply
    operation.database_forwards(self.app_label, schema_editor, old_state, project_state)
  File "/tests/django/django/db/migrations/operations/special.py", line 190, in database_forwards
    self.code(from_state.apps, schema_editor)
  File "/tests/django/django/contrib/contenttypes/management/__init__.py", line 39, in rename_forward
    self._rename(apps, schema_editor, self.old_model, self.new_model)
  File "/tests/django/django/contrib/contenttypes/management/__init__.py", line 27, in _rename
    content_type.save(using=db, update_fields={'model'})
  File "/tests/django/django/db/models/base.py", line 743, in save
    force_update=force_update, update_fields=update_fields)
  File "/tests/django/django/db/models/base.py", line 781, in save_base
    force_update, using, update_fields,
  File "/tests/django/django/db/models/base.py", line 865, in _save_table
    raise DatabaseError("Save with update_fields did not affect any rows.")
django.db.utils.DatabaseError: Save with update_fields did not affect any rows.

======================================================================
FAIL [0.008s]: test_select_on_save_lying_update (basic.tests.SelectOnSaveTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/unittest/case.py", line 59, in testPartExecutor
    yield
  File "/usr/local/lib/python3.6/unittest/case.py", line 605, in run
    testMethod()
  File "/tests/django/tests/basic/tests.py", line 666, in test_select_on_save_lying_update
    asos.save(update_fields=['pub_date'])
  File "/usr/local/lib/python3.6/contextlib.py", line 99, in __exit__
    self.gen.throw(type, value, traceback)
  File "/tests/django/django/test/testcases.py", line 655, in _assert_raises_or_warns_cm
    self.assertIn(expected_message, str(getattr(cm, cm_attr)))
  File "/usr/local/lib/python3.6/unittest/case.py", line 1089, in assertIn
    self.fail(self._formatMessage(msg, standardMsg))
  File "/usr/local/lib/python3.6/unittest/case.py", line 670, in fail
    raise self.failureException(msg)
AssertionError: "An error occurred in the current transaction. You can't execute queries until the end of the 'atomic' block." not found in 'Save with update_fields did not affect any rows.'

======================================================================
FAIL [0.004s]: test_migrate_with_existing_target_permission (auth_tests.test_migrations.ProxyModelWithSameAppLabelTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/unittest/case.py", line 59, in testPartExecutor
    yield
  File "/usr/local/lib/python3.6/unittest/case.py", line 605, in run
    testMethod()
  File "/tests/django/tests/auth_tests/test_migrations.py", line 179, in test_migrate_with_existing_target_permission
    self.assertIn('A problem arose migrating proxy model permissions', stdout.getvalue())
  File "/usr/local/lib/python3.6/unittest/case.py", line 1089, in assertIn
    self.fail(self._formatMessage(msg, standardMsg))
  File "/usr/local/lib/python3.6/unittest/case.py", line 670, in fail
    raise self.failureException(msg)
AssertionError: 'A problem arose migrating proxy model permissions' not found in ''

----------------------------------------------------------------------
Ran 13026 tests in 230.826s

FAILED (failures=2, errors=2, skipped=779, expected failures=4)

[ChillarAnand]

Hi Chetan Khanna,

The broken tests need to be fixed and a new regression test for this patch should suffice.

[Chetan Khanna]

Hey!

Sorry I forgot about this one. So I fixed a patch a bit by adding an else clause to the try block in the proposed patch, and all tests pass on current master. However, I am not sure how would one go testing about this patch. The way I reproduced this issue was by creating a test app and then intentionally making the schema out of sync. I don't think it's possible to imitate that when running the test suite.

[Chetan Khanna]

patch_without_test

[Jacob Walls]

What about something like this? With postgres you can disable server side cursors and then attempt to use them. I haven't made it as far as to set up postgres so I can run this test, but if you decide to give it a shot let me know what you see.

Also I don't know what type of error we are expecting to get back.

diff --git a/tests/backends/postgresql/test_server_side_cursors.py b/tests/backends/postgresql/test_server_side_cursors.py
index 0cc3423a9b..1b0e4484a3 100644
--- a/tests/backends/postgresql/test_server_side_cursors.py
+++ b/tests/backends/postgresql/test_server_side_cursors.py
@@ -4,6 +4,7 @@ from collections import namedtuple
 from contextlib import contextmanager
 
 from django.db import connection, models
+from django.db.utils import DatabaseError
 from django.test import TestCase
 
 from ..models import Person
@@ -87,3 +88,9 @@ class ServerSideCursorsPostgres(TestCase):
 
         with self.override_db_setting(DISABLE_SERVER_SIDE_CURSORS=True):
             self.asserNotUsesCursor(Person.objects.iterator())
+
+    def test_close_nonexistent_cursor(self):
+        persons = Person.objects.iterator()
+        with self.override_db_setting(DISABLE_SERVER_SIDE_CURSORS=True):
+            # Attempt to create server-side cursor
+            self.assertRaises(DatabaseError, next(persons))

[Michal Mládek]

I will do some research tommorow.

[Michal Mládek]

I don't think this is a bug. It seems more like a code style consideration — specifically, how to handle exceptions when cursor.close() itself raises an error.

In practice, cursor closure can fail for many reasons, and seeing the original exception with full traceback is often more helpful than hiding it behind secondary issues.

Some possible reasons why closing the cursor might fail:

1. Lost connection to the database
2. Exceeding the connection limit
3. Transaction-related inconsistencies
4. Bugs in the DB driver
5. Insufficient DB permissions
6. System resource exhaustion
7. Misconfiguration on the Django or DB side

Given that, I believe the current behavior is appropriate, and this ticket could be closed as “not a bug” or “works as intended.”
Happy to hear if others see a concrete problem that this change would solve.

[Jacob Walls]

Thanks for digging in! (Also please ignore my rough test in comment:5; there are better tests in the ​pull request for django 1.11.) Some more related tickets I found:

The cursor close exception was intentionally masked in Django 1.11 (6b6be692fcd102436c7abef1d7b3fa1d37ad4bdf) because Python 2 did not chain exceptions -- with a note that in Python 3, the default exception chaining would either be superior to masking or at least not worth maintaining a workaround. This fix was adjusted in #28091.

Then on the python 3 upgrade, this was removed as promised in d170c63351944fd91b2206d10f89e7ff75b53b76.

Then this ticket was accepted, which goes the other way.

Then a dupe of this ticket was closed as needsinfo: #33331, with the latest response in ticket:33331#comment:11 being:

You're then asking for a change in behaviour to remove information from the traceback. Maybe that's OK if there's a good reason, but otherwise the presumption would be wontfix.

My 2¢, we have multiple reports finding this confusing, and I do see this in my dev workflow from time to time. An ugly message about cursors is too much noise for beginners. So I think we could consider masking the cursor close exception as proposed in #33331.

In practice, cursor closure can fail for many reasons, and seeing the original exception with full traceback is often more helpful than hiding it behind secondary issues.

I follow in the general case, but do you have a view on whether here, inside exception handling, the cursor failure info would be relevant? (I'm struggling to see why it would be anything but noise.)