Opened 10 years ago

Closed 10 years ago

Last modified 10 years 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 by Aymeric Augustin, 10 years ago

Resolution: needsinfo
Status: newclosed

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 by err, 10 years ago

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 by err, 10 years ago

Resolution: needsinfo
Status: closednew

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 by Aymeric Augustin, 10 years ago

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 by Aymeric Augustin, 10 years ago

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 by Aymeric Augustin, 10 years ago

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 by err, 10 years ago

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 10 years ago by err (previous) (diff)

comment:8 by err, 10 years ago

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 10 years ago by err (previous) (diff)

comment:9 by Aymeric Augustin, 10 years ago

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

comment:10 by Aymeric Augustin <aymeric.augustin@…>, 10 years ago

Resolution: fixed
Status: newclosed

In 58161e4e93d1fc796fc804c943028d4433f4813c:

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

Thanks err for the report.

comment:11 by Aymeric Augustin <aymeric.augustin@…>, 10 years ago

In ee837b9a22220d08fea1e499bec3b094851a1bbe:

Increased robustness of 58161e4e. Refs #22291.

comment:12 by Aymeric Augustin <aymeric.augustin@…>, 10 years ago

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 by Aymeric Augustin <aymeric.augustin@…>, 10 years ago

In 80f6cbbadbd33574c8b949a8fbc77a5e94398e54:

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

Backport of ee837b9a from master

comment:14 by Aymeric Augustin <aymeric.augustin@…>, 10 years ago

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 by Aymeric Augustin <aymeric.augustin@…>, 10 years ago

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