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

[err]

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`;

[Aymeric Augustin]

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?

[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')

[err]

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

[Aymeric Augustin]

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.

[Aymeric Augustin]

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

tests/transactions/tests.py

@@ -3 +3 @@
 import sys
 from unittest import skipIf, skipUnless
 
-from django.db import connection, transaction, DatabaseError, IntegrityError
+from django.conf import settings
+from django.db import (connection, DEFAULT_DB_ALIAS,
+    DatabaseError, IntegrityError, transaction)
+from django.db.utils import ConnectionHandler
 from django.test import TransactionTestCase, skipIfDBFeature
 from django.utils import six
 
@@ -333 +336 @@
         self.assertEqual(Reporter.objects.get(pk=r1.pk).last_name, "Calculus")
 
 
+@skipUnless(connection.vendor == 'mysql', "MySQL-specific behaviors")
+class AtomicMeetsMySQLTests(TransactionTestCase):
+
+    available_apps = ['transactions']
+
+    def setUp(self):
+        # Create a second connection to the default database.
+        new_connections = ConnectionHandler(settings.DATABASES)
+        self.conn2 = new_connections[DEFAULT_DB_ALIAS]
+        self.conn2.set_autocommit(False)
+
+    def tearDown(self):
+        # Close down the second connection.
+        self.conn2.rollback()
+        self.conn2.close()
+
+    def test_implicit_savepoint_rollback(self):
+        """MySQL implicitly rolls back savepoints when it deadlocks (#22291)."""
+        with self.conn2.cursor() as cursor2:
+            cursor2.execute("INSERT INTO transactions_reporter (id, first_name) VALUES (1, 'Tintin');")
+            # Double atomic to enter a transaction and create a savepoint.
+            with transaction.atomic():
+                with transaction.atomic():
+                    Reporter.objects.create(id=1, first_name="Tintin")
+                    cursor2.execute("UPDATE transactions_reporter SET id = 2 WHERE NOT id = 1;")
+                    self.conn2.commit()
+                    # At this point, there's a deadlock on the main connection?
+
 class AtomicMiscTests(TransactionTestCase):
 
     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

[Aymeric Augustin]

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.)

[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 :)

[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.

[Aymeric Augustin]

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

[Aymeric Augustin <aymeric.augustin@…>]

In 58161e4e93d1fc796fc804c943028d4433f4813c:

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

Thanks err for the report.

[Aymeric Augustin <aymeric.augustin@…>]

In ee837b9a22220d08fea1e499bec3b094851a1bbe:

Increased robustness of 58161e4e. Refs #22291.

[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.

[Aymeric Augustin <aymeric.augustin@…>]

In 80f6cbbadbd33574c8b949a8fbc77a5e94398e54:

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

Backport of ee837b9a from master

[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.

[Aymeric Augustin <aymeric.augustin@…>]

In 1bcc8eb0f64831b24c2769e033a10e530c8ed140:

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

Backport of ee837b9a from master