Changes between Version 1 and Version 2 of Ticket #36318


Ignore:
Timestamp:
Apr 11, 2025, 9:40:19 AM (5 months ago)
Author:
Gordon Wrigley
Comment:

Legend:

Unmodified
Added
Removed
Modified

  • Ticket #36318

    • Property Summary Bad stack trace during rollback → Bad stack trace during rollback after bulk create

  • Ticket #36318 – Description

    v1 v2  
    1 I'M REWRITING ALL OF THIS
     1The value of `connection.rollback_exc` is being set in one transaction and then raised in a different later, unrelated transaction.
    22
    3 TL;DNR the value of `connection.rollback_exc` is being set in one celery task and then raised in another later celery task.
     3with these models
     4{{{
     5class Firm(Model):
     6    name = models.CharField(max_length=255, unique=True)
    47
    5 I'm on 4.2.20 and I got this stack trace from a celery worker
     8class Lender(Model):
     9    name = models.CharField(max_length=255, unique=True)
     10    override_svr = models.DecimalField(max_digits=6, decimal_places=2)
     11}}}
     12
     13this code
     14{{{
     15def bob():
     16    try:
     17        with transaction.atomic():
     18            Firm.objects.create(name="bob")
     19            Firm.objects.create(name="bob")
     20    except Exception as e:
     21        pass # safely ignoring e
     22
     23def fred():
     24    with transaction.atomic():
     25        try:
     26            l = Lender(name="fred", override_svr = "bobit")
     27            Lender.objects.bulk_create([l])
     28        except Exception as e:
     29            pass # unsafely ignoring e
     30
     31        Lender.objects.count() # will fail because we're in a broken transaction
     32
     33def main():
     34    try:
     35        bob()
     36        Lender.objects.count() # demonstrate we can make queries
     37        fred()
     38    except Exception as e:
     39        import traceback
     40        traceback.print_exc()
     41
     42
     43main()
     44}}}
     45
     46yields this exception
     47{{{
     48Traceback (most recent call last):
     49  django/db/backends/utils.py", line 89, in _execute
     50    return self.cursor.execute(sql, params)
     51psycopg2.errors.UniqueViolation: duplicate key value violates unique constraint "retain_firm_name_key"
     52DETAIL:  Key (name)=(bob) already exists.
     53
     54
     55The above exception was the direct cause of the following exception:
     56
     57Traceback (most recent call last):
     58  File "<ipython-input-6-729c3e87d98c>", line 9, in bob
     59    Firm.objects.create(name="bob")
     60  django/db/models/manager.py", line 87, in manager_method
     61    return getattr(self.get_queryset(), name)(*args, **kwargs)
     62  django/db/models/query.py", line 658, in create
     63    obj.save(force_insert=True, using=self.db)
     64  django/db/models/base.py", line 814, in save
     65    self.save_base(
     66  django/db/models/base.py", line 877, in save_base
     67    updated = self._save_table(
     68  django/db/models/base.py", line 1020, in _save_table
     69    results = self._do_insert(
     70  django/db/models/base.py", line 1061, in _do_insert
     71    return manager._insert(
     72  django/db/models/manager.py", line 87, in manager_method
     73    return getattr(self.get_queryset(), name)(*args, **kwargs)
     74  django/db/models/query.py", line 1805, in _insert
     75    return query.get_compiler(using=using).execute_sql(returning_fields)
     76  django/db/models/sql/compiler.py", line 1822, in execute_sql
     77    cursor.execute(sql, params)
     78  django/db/backends/utils.py", line 102, in execute
     79    return super().execute(sql, params)
     80  django/db/backends/utils.py", line 67, in execute
     81    return self._execute_with_wrappers(
     82  django/db/backends/utils.py", line 80, in _execute_with_wrappers
     83    return executor(sql, params, many, context)
     84  django/db/backends/utils.py", line 84, in _execute
     85    with self.db.wrap_database_errors:
     86  django/db/utils.py", line 91, in __exit__
     87    raise dj_exc_value.with_traceback(traceback) from exc_value
     88  django/db/backends/utils.py", line 89, in _execute
     89    return self.cursor.execute(sql, params)
     90django.db.utils.IntegrityError: duplicate key value violates unique constraint "retain_firm_name_key"
     91DETAIL:  Key (name)=(bob) already exists.
     92
     93
     94The above exception was the direct cause of the following exception:
     95
     96Traceback (most recent call last):
     97  File "<ipython-input-6-729c3e87d98c>", line 27, in main
     98    fred()
     99  File "<ipython-input-6-729c3e87d98c>", line 21, in fred
     100    Lender.objects.count() # will fail because we're in a broken transaction
     101  django/db/models/manager.py", line 87, in manager_method
     102    return getattr(self.get_queryset(), name)(*args, **kwargs)
     103  django/db/models/query.py", line 608, in count
     104    return self.query.get_count(using=self.db)
     105  django/db/models/sql/query.py", line 568, in get_count
     106    return obj.get_aggregation(using, {"__count": Count("*")})["__count"]
     107  django/db/models/sql/query.py", line 554, in get_aggregation
     108    result = compiler.execute_sql(SINGLE)
     109  django/db/models/sql/compiler.py", line 1562, in execute_sql
     110    cursor.execute(sql, params)
     111  django/db/backends/utils.py", line 102, in execute
     112    return super().execute(sql, params)
     113  django/db/backends/utils.py", line 67, in execute
     114    return self._execute_with_wrappers(
     115  django/db/backends/utils.py", line 80, in _execute_with_wrappers
     116    return executor(sql, params, many, context)
     117  django/db/backends/utils.py", line 83, in _execute
     118    self.db.validate_no_broken_transaction()
     119  django/db/backends/base/base.py", line 531, in validate_no_broken_transaction
     120    raise TransactionManagementError(
     121django.db.transaction.TransactionManagementError: An error occurred in the current transaction. You can't execute queries until the end of the 'atomic' block.
     122}}}
     123
     124I 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.
     125
     126What'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
    6127
    7128{{{
    8 UniqueViolation: duplicate key value violates unique constraint "retain_consumer_firm_id_email_hash_3f1266dc_uniq"
    9 DETAIL:  Key (firm_id, email_hash)=(ac90f753-3f10-44f2-af43-b851371c5572, 863397f56c061afbaa0822c9c16ece2b55f2e972) already exists.
    10 
    11   File "django/db/backends/utils.py", line 89, in _execute
    12     return self.cursor.execute(sql, params)
    13 
    14 IntegrityError: duplicate key value violates unique constraint "retain_consumer_firm_id_email_hash_3f1266dc_uniq"
    15 DETAIL:  Key (firm_id, email_hash)=(ac90f753-3f10-44f2-af43-b851371c5572, 863397f56c061afbaa0822c9c16ece2b55f2e972) already exists.
    16 
    17   File "data_import/import_from_csv.py", line 1692, in _consumer_from_row
    18     consumer.save()
    19   File "core/models/consumer.py", line 615, in save
    20     return super().save(*args, **kwargs)
    21   File "core/models/firm_user.py", line 197, in save
    22     super().save(update_fields=update_fields, **kwargs)
    23   File "common/models.py", line 900, in save
    24     super().save(*args, **kwargs)
    25   File "django/contrib/auth/base_user.py", line 76, in save
    26     super().save(*args, **kwargs)
    27   File "django/db/models/base.py", line 814, in save
    28     self.save_base(
    29   File "django/db/models/base.py", line 877, in save_base
    30     updated = self._save_table(
    31   File "django/db/models/base.py", line 1020, in _save_table
    32     results = self._do_insert(
    33   File "django/db/models/base.py", line 1061, in _do_insert
    34     return manager._insert(
    35   File "django/db/models/manager.py", line 87, in manager_method
    36     return getattr(self.get_queryset(), name)(*args, **kwargs)
    37   File "django/db/models/query.py", line 1805, in _insert
    38     return query.get_compiler(using=using).execute_sql(returning_fields)
    39   File "django/db/models/sql/compiler.py", line 1822, in execute_sql
    40     cursor.execute(sql, params)
    41   File "django/db/backends/utils.py", line 67, in execute
    42     return self._execute_with_wrappers(
    43   File "django/db/backends/utils.py", line 80, in _execute_with_wrappers
    44     return executor(sql, params, many, context)
    45   File "django/db/backends/utils.py", line 84, in _execute
    46     with self.db.wrap_database_errors:
    47   File "django/db/utils.py", line 91, in __exit__
    48     raise dj_exc_value.with_traceback(traceback) from exc_value
    49   File "django/db/backends/utils.py", line 89, in _execute
    50     return self.cursor.execute(sql, params)
    51 
    52 TransactionManagementError: An error occurred in the current transaction. You can't execute queries until the end of the 'atomic' block.
    53   File "celery/app/trace.py", line 760, in __protected_call__
    54     return self.run(*args, **kwargs)
    55   File "common/tasks.py", line 19, in wrapper
    56     return func(*args, **kwargs)
    57   File "contextlib.py", line 81, in inner
    58     return func(*args, **kwds)
    59   File "product_selection/tasks.py", line 129, in try_product_import
    60     product_import.save()
    61   File "common/models.py", line 900, in save
    62     super().save(*args, **kwargs)
    63   File "django/db/models/base.py", line 814, in save
    64     self.save_base(
    65   File "django/db/models/base.py", line 877, in save_base
    66     updated = self._save_table(
    67   File "django/db/models/base.py", line 990, in _save_table
    68     updated = self._do_update(
    69   File "django/db/models/base.py", line 1054, in _do_update
    70     return filtered._update(values) > 0
    71   File "django/db/models/query.py", line 1231, in _update
    72     return query.get_compiler(self.db).execute_sql(CURSOR)
    73   File "django/db/models/sql/compiler.py", line 1984, in execute_sql
    74     cursor = super().execute_sql(result_type)
    75   File "django/db/models/sql/compiler.py", line 1562, in execute_sql
    76     cursor.execute(sql, params)
    77   File "django/db/backends/utils.py", line 67, in execute
    78     return self._execute_with_wrappers(
    79   File "django/db/backends/utils.py", line 80, in _execute_with_wrappers
    80     return executor(sql, params, many, context)
    81   File "django/db/backends/utils.py", line 83, in _execute
    82     self.db.validate_no_broken_transaction()
    83   File "django/db/backends/base/base.py", line 531, in validate_no_broken_transaction
    84     raise TransactionManagementError(
     129django.core.exceptions.ValidationError: ['“bobit” value must be a decimal number.']
    85130}}}
    86131
    87 There's two related problems with this. First the lines around `File "data_import/import_from_csv.py", line 1692, in _consumer_from_row` look like this
    88 {{{
    89             try:
    90                 with transaction.atomic():
    91                     consumer.save()
    92                 if change_log:
    93                     self.record_log(consumer, change_log)
    94             except IntegrityError:
    95 }}}
    96 So that has been well handled and the transaction is good again.
     132My understanding is that this validation error should have been captured into `rollback_exc` when `needs_rollback` was set to True
     133`needs_rollback` is getting set in `Atomic.__exit__` when `exc_type` is set and `connection.needs_rollback` is False
    97134
    98 Secondly there is no relationship between the `File "product_selection/tasks.py", line 129, in try_product_import` code path from the `TransactionManagementError` and the `File "data_import/import_from_csv.py", line 1692` in _consumer_from_row` code path from the `IntegrityError` and `UniqueViolation`, these are totally unrelated celery tasks.
     135Alternatively maybe there's some error handling missing in bulk_create. Although even if that's the case it seems bad that
     136`Atomic.__exit__`  can turn on `needs_rollback` without setting `rollback_exc`. Also perhaps `rollback_exc` should be getting cleared when `needs_rollback` is cleared.
    99137
    100 It looks for all intents as if the stack for the `IntegrityError`/`UniqueViolation` has been captured in one celery task and then raised in a different later celery task.
    101 
    102 Digging through the code and adding prints supports this view.
    103 1. `connection.rollback_exc` is never cleared anywhere
    104 2. `Atomic.__exit__` can set `connection.needs_rollback = True` when it wasn't true already and without setting `connection.rollback_exc` this creates the possibility for the observed behaviour.
    105 
    106 I'm not sure how critical it is to reproduction, but the actual error that killed the transaction looks like this
    107 {{{
    108 decimal.InvalidOperation: [<class 'decimal.ConversionSyntax'>]
    109   File "django/db/models/fields/__init__.py", line 1741, in to_python
    110     decimal_value = decimal.Decimal(value)
    111 
    112 django.core.exceptions.ValidationError: ['“3 3 3 2 1” value must be a decimal number.']
    113   File "product_selection/tasks.py", line 123, in try_product_import
    114     Product.objects.bulk_create(new_products, skip_save_logic=True)
    115   File "django/db/models/manager.py", line 87, in manager_method
    116     return getattr(self.get_queryset(), name)(*args, **kwargs)
    117   File "common/models.py", line 772, in bulk_create
    118     return super().bulk_create(*args, **kwargs)
    119   File "django/db/models/query.py", line 786, in bulk_create
    120     returned_columns = self._batched_insert(
    121   File "django/db/models/query.py", line 1831, in _batched_insert
    122     self._insert(
    123   File "django/db/models/query.py", line 1805, in _insert
    124     return query.get_compiler(using=using).execute_sql(returning_fields)
    125   File "django/db/models/sql/compiler.py", line 1821, in execute_sql
    126     for sql, params in self.as_sql():
    127   File "django/db/models/sql/compiler.py", line 1747, in as_sql
    128     self.prepare_value(field, self.pre_save_val(field, obj))
    129   File "django/db/models/sql/compiler.py", line 1686, in prepare_value
    130     return field.get_db_prep_save(value, connection=self.connection)
    131   File "django/db/models/fields/__init__.py", line 1760, in get_db_prep_save
    132     self.to_python(value), self.max_digits, self.decimal_places
    133   File "django/db/models/fields/__init__.py", line 1743, in to_python
    134     raise exceptions.ValidationError(
    135 }}}
    136 
    137 My understanding is this should have been captured into `rollback_exc` when `needs_rollback` was set to True
    138 That happens in `Atomic.__exit__` when `exc_type` is set and `connection.needs_rollback` is False
    139138I can't test this on 5.2 but `Atomic.__exit__` looks unchanged.
Back to Top