Opened 13 months ago

Closed 13 months ago

Last modified 13 months ago

#22291 closed Uncategorized (fixed)

transactions.atomic (with savepoints) doesn't work correctly with deadlocks in mysql

Reported by: err Owned by: nobody
Component: Database layer (models, ORM) Version: 1.6
Severity: Normal Keywords:
Cc: Triage Stage: Unreviewed
Has patch: no Needs documentation: no
Needs tests: no Patch needs improvement: no
Easy pickings: no UI/UX: no

Description

In mysql on deadlock occurance all savepoints will be deleted. so trying to rollback to previous savepoint will cause error: SAVEPOINT ... does not exist;

here is example:

		1 Query create table user2(id int primary key) engine=innodb;
		1 Query	set autocommit=0;INSERT INTO `user2` (`id`) VALUES (222);
		2 Query	set autocommit=0;SAVEPOINT `xxx`;INSERT INTO `user2` (`id`) VALUES (222);
		1 Query	UPDATE `user2` SET `id` = 111 WHERE NOT (`user2`.`id` = 222 );commit;  -- after commit there will be deadlock in transaction 2
		2 Query	ROLLBACK TO SAVEPOINT `xxx`;

Change History (15)

comment:1 Changed 13 months ago by aaugustin

  • Needs documentation unset
  • Needs tests unset
  • Patch needs improvement unset
  • Resolution set to needsinfo
  • Status changed from new to closed

I assume Django raises an exception when trying to rollback to the savepoint that no longer exists, which eventually leads to the entire transaction being rolled back. This appears to be the correct behavior.

What do you suggest Django should do instead?

comment:2 Changed 13 months ago by err

I thing Django should rollback whole transaction and raise normal error django.db.utils.OperationalError: (1213, 'Deadlock found when trying to get lock; try restarting transaction') not django.db.utils.OperationalError: (1305, 'SAVEPOINT s139640098436864_x1 does not exist')

comment:3 Changed 13 months ago by err

  • Resolution needsinfo deleted
  • Status changed from closed to new

I assume Django raises an exception when trying to rollback to the savepoint that no longer exists

the problem is that Django is trying to rollback to the savepoint. this is incorrect in mysql

comment:4 Changed 13 months ago by aaugustin

OK, so this is about not masking the original exception when rolling back to a savepoint fails.

This problem only affects Python 2, which lacks the exception chaining automatically provided by Python 3.

comment:5 Changed 13 months ago by aaugustin

I've written a test that reproduces the sequence of queries you're describing. Here's the diff:

  • tests/transactions/tests.py

    a b from __future__ import unicode_literals 
    33import sys
    44from unittest import skipIf, skipUnless
    55
    6 from django.db import connection, transaction, DatabaseError, IntegrityError
     6from django.conf import settings
     7from django.db import (connection, DEFAULT_DB_ALIAS,
     8    DatabaseError, IntegrityError, transaction)
     9from django.db.utils import ConnectionHandler
    710from django.test import TransactionTestCase, skipIfDBFeature
    811from django.utils import six
    912
    class AtomicErrorsTests(TransactionTestCase): 
    333336        self.assertEqual(Reporter.objects.get(pk=r1.pk).last_name, "Calculus")
    334337
    335338
     339@skipUnless(connection.vendor == 'mysql', "MySQL-specific behaviors")
     340class AtomicMeetsMySQLTests(TransactionTestCase):
     341
     342    available_apps = ['transactions']
     343
     344    def setUp(self):
     345        # Create a second connection to the default database.
     346        new_connections = ConnectionHandler(settings.DATABASES)
     347        self.conn2 = new_connections[DEFAULT_DB_ALIAS]
     348        self.conn2.set_autocommit(False)
     349
     350    def tearDown(self):
     351        # Close down the second connection.
     352        self.conn2.rollback()
     353        self.conn2.close()
     354
     355    def test_implicit_savepoint_rollback(self):
     356        """MySQL implicitly rolls back savepoints when it deadlocks (#22291)."""
     357        with self.conn2.cursor() as cursor2:
     358            cursor2.execute("INSERT INTO transactions_reporter (id, first_name) VALUES (1, 'Tintin');")
     359            # Double atomic to enter a transaction and create a savepoint.
     360            with transaction.atomic():
     361                with transaction.atomic():
     362                    Reporter.objects.create(id=1, first_name="Tintin")
     363                    cursor2.execute("UPDATE transactions_reporter SET id = 2 WHERE NOT id = 1;")
     364                    self.conn2.commit()
     365                    # At this point, there's a deadlock on the main connection?
     366
    336367class AtomicMiscTests(TransactionTestCase):
    337368
    338369    available_apps = []

Since I want the deadlock to happen on the main connection, connection 1 in your original report is self.conn2 in the test and connection 2 is the main connection.

Unfortunately, I cannot reproduce the results you're seeing, because I'm reaching the point where you say MySQL should deadlock.

(django-dev)myk@mYk tests % ./runtests.py --settings=test_mysql transactions.tests.AtomicMeetsMySQLTests
Testing against Django installed in '/Users/myk/Documents/dev/django/django'
Creating test database for alias 'default'...
Creating test database for alias 'other'...
E
======================================================================
ERROR: test_implicit_savepoint_rollback (transactions.tests.AtomicMeetsMySQLTests)
MySQL implicitly rolls back savepoints when it deadlocks (#22291).
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/myk/Documents/dev/django/tests/transactions/tests.py", line 362, in test_implicit_savepoint_rollback
    Reporter.objects.create(id=1, first_name="Tintin")
  File "/Users/myk/Documents/dev/django/django/db/models/manager.py", line 84, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/Users/myk/Documents/dev/django/django/db/models/query.py", line 367, in create
    obj.save(force_insert=True, using=self.db)
  File "/Users/myk/Documents/dev/django/django/db/models/base.py", line 603, in save
    force_update=force_update, update_fields=update_fields)
  File "/Users/myk/Documents/dev/django/django/db/models/base.py", line 631, in save_base
    updated = self._save_table(raw, cls, force_insert, force_update, using, update_fields)
  File "/Users/myk/Documents/dev/django/django/db/models/base.py", line 712, in _save_table
    result = self._do_insert(cls._base_manager, using, fields, update_pk, raw)
  File "/Users/myk/Documents/dev/django/django/db/models/base.py", line 745, in _do_insert
    using=using, raw=raw)
  File "/Users/myk/Documents/dev/django/django/db/models/manager.py", line 84, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/Users/myk/Documents/dev/django/django/db/models/query.py", line 916, in _insert
    return query.get_compiler(using=using).execute_sql(return_id)
  File "/Users/myk/Documents/dev/django/django/db/models/sql/compiler.py", line 914, in execute_sql
    cursor.execute(sql, params)
  File "/Users/myk/Documents/dev/django/django/db/backends/utils.py", line 59, in execute
    return self.cursor.execute(sql, params)
  File "/Users/myk/Documents/dev/django/django/db/utils.py", line 94, in __exit__
    six.reraise(dj_exc_type, dj_exc_value, traceback)
  File "/Users/myk/Documents/dev/django/django/db/backends/utils.py", line 59, in execute
    return self.cursor.execute(sql, params)
  File "/Users/myk/Documents/dev/django/django/db/backends/mysql/base.py", line 128, in execute
    return self.cursor.execute(query, args)
  File "/Users/myk/.virtualenvs/django-dev/lib/python2.7/site-packages/MySQLdb/cursors.py", line 201, in execute
    self.errorhandler(self, exc, value)
  File "/Users/myk/.virtualenvs/django-dev/lib/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
    raise errorclass, errorvalue
OperationalError: (1205, 'Lock wait timeout exceeded; try restarting transaction')

----------------------------------------------------------------------
Ran 1 test in 50.990s

FAILED (errors=1)
Destroying test database for alias 'default'...
Destroying test database for alias 'other'...

Here's the MySQL log, where connection 7 is your connection 1 and connection 3 is your connection 2.

		    7 Query	set autocommit=0
		    7 Query	INSERT INTO transactions_reporter (id, first_name) VALUES (1, 'Tintin')
		    7 Query	SHOW WARNINGS
		    3 Query	set autocommit=0
		    3 Query	SAVEPOINT `s140735313277712_x1`
		    3 Query	INSERT INTO `transactions_reporter` (`id`, `first_name`, `last_name`, `email`) VALUES (1, 'Tintin', '', '')

# long wait here...

140323 14:01:20	    3 Query	ROLLBACK TO SAVEPOINT `s140735313277712_x1`
		    3 Query	rollback

comment:6 Changed 13 months ago by aaugustin

I don't understand why deadlocks aren't detected in my tests. I tried another example based on http://www.xaprb.com/blog/2006/08/08/how-to-deliberately-cause-a-deadlock-in-mysql/ and MySQL also timeouts instead of detecting the deadlock:

        with transaction.atomic():
            Reporter.objects.create(first_name="Tintin")
            with self.conn2.cursor() as cursor2:
                cursor2.execute("SELECT * FROM transactions_reporter FOR UPDATE;")
            Reporter.objects.create(first_name="Archibald", last_name="Haddock")
		   29 Query	set autocommit=0
		   25 Query	set autocommit=0
		   25 Query	INSERT INTO `transactions_reporter` (`first_name`, `last_name`, `email`) VALUES ('Tintin', '', '')
		   29 Query	SELECT * FROM transactions_reporter FOR UPDATE
# timeout after innodb_lock_wait_timeout (50 seconds)

All the information I can find about InnoDB says that deadlocks should always be detected. innodb_table_locks is enabled and autocommit is explicitly set to 0 as shown in the query log.

Can you provide an example of Python code that triggers the issue you're reporting? If I can't reproduce the issue, I can't fix it.

(Given that MySQL's transaction handling is an unreliable, bolted-on mess that doesn't make much sense in general, I'm not surprised to see inconsistent behavior. If you care about transactions, you should use a database that actually works.)

comment:7 Changed 13 months ago by err

I guess the problem is here

+                    Reporter.objects.create(id=1, first_name="Tintin")
+                    cursor2.execute("UPDATE transactions_reporter SET id = 2 WHERE NOT id = 1;")

This two lines should run in parallel. I'll give you more info tomorrow. thanks for patience :)

Last edited 13 months ago by err (previous) (diff)

comment:8 Changed 13 months ago by err

https://github.com/errx/django/compare/django:stable%2F1.6.x...ticket_22291

I've created branch with working test and possible attempt to fix it. I'am not sure that this is a best way to fix this problem.

Last edited 13 months ago by err (previous) (diff)

comment:9 Changed 13 months ago by aaugustin

Aaaah, of course, I need another thread! Thank you, hopefully I'll be able to reproduce now.

comment:10 Changed 13 months ago by Aymeric Augustin <aymeric.augustin@…>

  • Resolution set to fixed
  • Status changed from new to closed

In 58161e4e93d1fc796fc804c943028d4433f4813c:

Fixed #22291 -- Avoided shadowing deadlock exceptions on MySQL.

Thanks err for the report.

comment:11 Changed 13 months ago by Aymeric Augustin <aymeric.augustin@…>

In ee837b9a22220d08fea1e499bec3b094851a1bbe:

Increased robustness of 58161e4e. Refs #22291.

comment:12 Changed 13 months ago by Aymeric Augustin <aymeric.augustin@…>

In 9afedbef4207a86d17d9525664bcd06f403cc6f9:

[1.6.x] Fixed #22291 -- Avoided shadowing deadlock exceptions on MySQL.

Thanks err for the report.

Backport of 58161e4e from master.

comment:13 Changed 13 months ago by Aymeric Augustin <aymeric.augustin@…>

In 80f6cbbadbd33574c8b949a8fbc77a5e94398e54:

[1.6.x] Increased robustness of 58161e4e. Refs #22291.

Backport of ee837b9a from master

comment:14 Changed 13 months ago by Aymeric Augustin <aymeric.augustin@…>

In 7e89434084d7952d107aef1c41f2019a73310634:

[1.7.x] Fixed #22291 -- Avoided shadowing deadlock exceptions on MySQL.

Thanks err for the report.

Backport of 58161e4e from master.

comment:15 Changed 13 months ago by Aymeric Augustin <aymeric.augustin@…>

In 1bcc8eb0f64831b24c2769e033a10e530c8ed140:

[1.7.x] Increased robustness of 58161e4e. Refs #22291.

Backport of ee837b9a from master

Note: See TracTickets for help on using tickets.
Back to Top