Bad stack trace during rollback after bulk create

[Gordon Wrigley]

The value of connection.rollback_exc is being set in one transaction and then raised in a different later, unrelated transaction.

with these models

class Firm(Model):
    name = models.CharField(max_length=255, unique=True)

class Lender(Model):
    name = models.CharField(max_length=255, unique=True)
    override_svr = models.DecimalField(max_digits=6, decimal_places=2)

this code

def bob():
    try:
        with transaction.atomic():
            Firm.objects.create(name="bob")
            Firm.objects.create(name="bob")
    except Exception as e:
        pass # safely ignoring e

def fred():
    with transaction.atomic():
        try:
            l = Lender(name="fred", override_svr = "bobit")
            Lender.objects.bulk_create([l])
        except Exception as e:
            pass # unsafely ignoring e

        Lender.objects.count() # will fail because we're in a broken transaction

def main():
    try:
        bob()
        Lender.objects.count() # demonstrate we can make queries
        fred()
    except Exception as e:
        import traceback
        traceback.print_exc()


main()

yields this exception

Traceback (most recent call last):
  django/db/backends/utils.py", line 89, in _execute
    return self.cursor.execute(sql, params)
psycopg2.errors.UniqueViolation: duplicate key value violates unique constraint "retain_firm_name_key"
DETAIL:  Key (name)=(bob) already exists.


The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "<ipython-input-6-729c3e87d98c>", line 9, in bob
    Firm.objects.create(name="bob")
  django/db/models/manager.py", line 87, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  django/db/models/query.py", line 658, in create
    obj.save(force_insert=True, using=self.db)
  django/db/models/base.py", line 814, in save
    self.save_base(
  django/db/models/base.py", line 877, in save_base
    updated = self._save_table(
  django/db/models/base.py", line 1020, in _save_table
    results = self._do_insert(
  django/db/models/base.py", line 1061, in _do_insert
    return manager._insert(
  django/db/models/manager.py", line 87, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  django/db/models/query.py", line 1805, in _insert
    return query.get_compiler(using=using).execute_sql(returning_fields)
  django/db/models/sql/compiler.py", line 1822, in execute_sql
    cursor.execute(sql, params)
  django/db/backends/utils.py", line 102, in execute
    return super().execute(sql, params)
  django/db/backends/utils.py", line 67, in execute
    return self._execute_with_wrappers(
  django/db/backends/utils.py", line 80, in _execute_with_wrappers
    return executor(sql, params, many, context)
  django/db/backends/utils.py", line 84, in _execute
    with self.db.wrap_database_errors:
  django/db/utils.py", line 91, in __exit__
    raise dj_exc_value.with_traceback(traceback) from exc_value
  django/db/backends/utils.py", line 89, in _execute
    return self.cursor.execute(sql, params)
django.db.utils.IntegrityError: duplicate key value violates unique constraint "retain_firm_name_key"
DETAIL:  Key (name)=(bob) already exists.


The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "<ipython-input-6-729c3e87d98c>", line 27, in main
    fred()
  File "<ipython-input-6-729c3e87d98c>", line 21, in fred
    Lender.objects.count() # will fail because we're in a broken transaction
  django/db/models/manager.py", line 87, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  django/db/models/query.py", line 608, in count
    return self.query.get_count(using=self.db)
  django/db/models/sql/query.py", line 568, in get_count
    return obj.get_aggregation(using, {"__count": Count("*")})["__count"]
  django/db/models/sql/query.py", line 554, in get_aggregation
    result = compiler.execute_sql(SINGLE)
  django/db/models/sql/compiler.py", line 1562, in execute_sql
    cursor.execute(sql, params)
  django/db/backends/utils.py", line 102, in execute
    return super().execute(sql, params)
  django/db/backends/utils.py", line 67, in execute
    return self._execute_with_wrappers(
  django/db/backends/utils.py", line 80, in _execute_with_wrappers
    return executor(sql, params, many, context)
  django/db/backends/utils.py", line 83, in _execute
    self.db.validate_no_broken_transaction()
  django/db/backends/base/base.py", line 531, in validate_no_broken_transaction
    raise TransactionManagementError(
django.db.transaction.TransactionManagementError: An error occurred in the current transaction. You can't execute queries until the end of the 'atomic' block.

I do not mind that this exceptioned, the problem is the stack trace it produced is leaking stuff between different call paths. In my case it was between unrelated celery tasks.

What's important to note here is the TransactionManagementError is from the fred function but the IntegrityError it shows as the cause is from the bob function. What we should be seeing instead is

django.core.exceptions.ValidationError: ['“bobit” value must be a decimal number.']

My understanding is that this validation error should have been captured into rollback_exc when needs_rollback was set to True
needs_rollback is getting set in Atomic.__exit__ when exc_type is set and connection.needs_rollback is False

Alternatively maybe there's some error handling missing in bulk_create. Although even if that's the case it seems bad that
Atomic.__exit__ can turn on needs_rollback without setting rollback_exc. Also perhaps rollback_exc should be getting cleared when needs_rollback is cleared.

I can't test this on 5.2 but Atomic.__exit__ looks unchanged.

[Adam Johnson]

Thank you for the clear bug report. It would be good to try with main to check if the behaviour persists, but from a quick look at Atomic.__exit__, it seems likely that it does.

[Simon Charette]

I'll point out that we document that weird things can happen when you catch and handle exceptions inside an atomic block

Per ​the docs

Avoid catching exceptions inside atomic!

When exiting an atomic block, Django looks at whether it’s exited normally or with an exception to determine whether to commit or roll back. If you catch and handle exceptions inside an atomic block, you may hide from Django the fact that a problem has happened. This can result in unexpected behavior.

I'm pretty confident we'll be able to avoid surfacing the previous exception message as ​the __cause__ of the TransactionManagementError with

django/db/transaction.py

@@ -195 +195 @@
             # Reset state when entering an outermost atomic block.
             connection.commit_on_exit = True
             connection.needs_rollback = False
+            connection.rollback_exc = None
             if not connection.get_autocommit():
                 # Pretend we're already in an atomic block to bypass the code
                 # that disables autocommit to enter a transaction, and make a

as this is a bug in #23353 (3b4a5b9f97f113ca5151cff744019e39a1ed7475) but I'm afraid we won't able to have the TransactionManagementError provide details about the ValidationError, or any exception raised in an exception handled inside an atomic block for that matter, as it doesn't make it to Atomic.__exit__ and thus it can't be stored anywhere. If it did make it to Atomic.__exit__ it would have overridden rollback_exc and be surfaced appropriately.

[Gordon Wrigley]

I put prints through Atomic.__exit__ and I see the ValidationError in there. One time when it passes through exc_type is the ValidationError, needs_rollback is False and the structure of the logic leads to it setting needs_rollback to True

[Simon Charette]

I think the following might address the issue (for the usage of atomic(savepoint=False) that bulk_create makes)

django/db/transaction.py

@@ -195 +195 @@
             # Reset state when entering an outermost atomic block.
             connection.commit_on_exit = True
             connection.needs_rollback = False
+            connection.rollback_exc = None
             if not connection.get_autocommit():
                 # Pretend we're already in an atomic block to bypass the code
                 # that disables autocommit to enter a transaction, and make a
@@ -278 +279 @@
                     # otherwise.
                     if sid is None:
                         connection.needs_rollback = True
+                        # Avoid shadowing an already assigned rollback exc.
+                        if connection.rollback_exc is None:
+                            connection.rollback_exc = exc_value
                     else:
                         try:
                             connection.savepoint_rollback(sid)

tests/transactions/tests.py

@@ -359 +359 @@
         self.assertIsInstance(cm.exception.__cause__, IntegrityError)
         self.assertEqual(Reporter.objects.get(pk=r1.pk).last_name, "Haddock")
 
+    def test_atomic_prevents_queries_in_broken_transaction_cause_attribution(self):
+        # Trigger a previous atomic rollback to populate cause.
+        with self.assertRaises(Exception), transaction.atomic():
+            raise Exception("First failure")
+
+        with (
+            self.assertRaises(transaction.TransactionManagementError) as ctx,
+            transaction.atomic(),
+        ):
+            try:
+                with transaction.atomic(savepoint=False):
+                    raise Exception("Second failure")
+            except Exception:
+                pass
+            try:
+                with transaction.atomic(savepoint=False):
+                    raise Exception("Third failure")
+            except Exception:
+                pass
+            Reporter.objects.count()
+        self.assertEqual(str(ctx.exception.__cause__), "Second failure")
+
     @skipIfDBFeature("atomic_transactions")
     def test_atomic_allows_queries_after_fixing_transaction(self):
         r1 = Reporter.objects.create(first_name="Archibald", last_name="Haddock")

[JaeHyuckSa]

Thank you, Gordon and Simon, for the detailed explanation. I'll go ahead and prepare a PR with the suggested test and fix.