Deadlock during page move

[timobrembeck]

Describe the Bug

In some edge cases, a deadlock can occur during moving pages.

Steps to Reproduce

Not sure how to reproduce

Expected Behavior

The page should be moved

Actual Behavior

An internal server error occurs:

django.db.utils.OperationalError: deadlock detected
DETAIL:  Process 2031290 waits for ShareLock on transaction 13447834; blocked by process 2031285.
Process 2031285 waits for ShareLock on transaction 13447835; blocked by process 2031290.
HINT:  See server log for query details.
CONTEXT:  while updating tuple (2,47) in relation "cms_page"

Additional Information

Traceback

  return self.cursor.execute(sql, params)
psycopg2.errors.DeadlockDetected: deadlock detected
DETAIL:  Process 2031290 waits for ShareLock on transaction 13447834; blocked by process 2031285.
Process 2031285 waits for ShareLock on transaction 13447835; blocked by process 2031290.
HINT:  See server log for query details.
CONTEXT:  while updating tuple (2,47) in relation "cms_page"


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

Traceback (most recent call last):
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/core/handlers/exception.py", line 47, in inner
  response = get_response(request)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/core/handlers/base.py", line 181, in _get_response
  response = wrapped_callback(request, *callback_args, **callback_kwargs)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/views/decorators/http.py", line 40, in inner
  return func(request, *args, **kwargs)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/contrib/auth/decorators.py", line 21, in _wrapped_view
  return view_func(request, *args, **kwargs)
File "/usr/lib/python3.9/contextlib.py", line 79, in inner
  return func(*args, **kwds)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/integreat_cms/cms/views/pages/page_actions.py", line 490, in move_page
  page.move(target, position)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/integreat_cms/cms/models/pages/page.py", line 303, in move
  super().move(target, pos)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/integreat_cms/cms/models/abstract_tree_node.py", line 285, in move
  super().move(target=target, pos=pos)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/treebeard/ns_tree.py", line 432, in move
  cursor.execute(sql, params)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/cacheops/transaction.py", line 98, in execute
  result = self._no_monkey.execute(self, sql, params)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/backends/utils.py", line 66, in execute
  return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/backends/utils.py", line 75, in _execute_with_wrappers
  return executor(sql, params, many, context)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/backends/utils.py", line 84, in _execute
  return self.cursor.execute(sql, params)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/utils.py", line 90, in __exit__
  raise dj_exc_value.with_traceback(traceback) from exc_value
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/backends/utils.py", line 84, in _execute
  return self.cursor.execute(sql, params)
django.db.utils.OperationalError: deadlock detected
DETAIL:  Process 2031290 waits for ShareLock on transaction 13447834; blocked by process 2031285.
Process 2031285 waits for ShareLock on transaction 13447835; blocked by process 2031290.
HINT:  See server log for query details.
CONTEXT:  while updating tuple (2,47) in relation "cms_page"

[timobrembeck]

This is probably also related to #1518 and ultimately django-treebeard/django-treebeard#53.

[timobrembeck]

A similar issue occured on March 14 when acquiring the db mutex:

Traceback

Mar 14 12:43:53 ERROR   django.request - 500 Internal Server Error: /landkreis-konstanz/pages/de/14907/edit/
Traceback (most recent call last):
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/backends/utils.py", line 84, in _execute
  return self.cursor.execute(sql, params)
psycopg2.errors.DeadlockDetected: deadlock detected
DETAIL:  Process 1054249 waits for ShareLock on transaction 18359673; blocked by process 1054250.
Process 1054250 waits for ShareLock on transaction 18359675; blocked by process 1054249.
HINT:  See server log for query details.
CONTEXT:  while inserting index tuple (0,11) in relation "db_mutex_dbmutex_lock_id_key"


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

Traceback (most recent call last):
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/core/handlers/exception.py", line 47, in inner
  response = get_response(request)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/core/handlers/base.py", line 181, in _get_response
  response = wrapped_callback(request, *callback_args, **callback_kwargs)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/views/generic/base.py", line 70, in view
  return self.dispatch(request, *args, **kwargs)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/utils/decorators.py", line 43, in _wrapper
  return bound_method(*args, **kwargs)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/contrib/auth/decorators.py", line 21, in _wrapped_view
  return view_func(request, *args, **kwargs)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/views/generic/base.py", line 98, in dispatch
  return handler(request, *args, **kwargs)
File "/usr/lib/python3.9/contextlib.py", line 79, in inner
  return func(*args, **kwds)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/integreat_cms/cms/views/pages/page_form_view.py", line 324, in post
  page_translation_form.instance.page = page_form.save()
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/integreat_cms/cms/forms/custom_model_form.py", line 133, in save
  return super().save(commit=commit)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/treebeard/forms.py", line 153, in save
  self.instance.move(reference_node, pos=position_type)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/integreat_cms/cms/models/pages/page.py", line 327, in move
  super().move(target, pos)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/integreat_cms/cms/models/abstract_tree_node.py", line 270, in move
  with db_mutex(self.__class__.__name__):
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/db_mutex/db_mutex.py", line 93, in __enter__
  self.start()
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/db_mutex/db_mutex.py", line 107, in start
  self.lock = DBMutex.objects.create(lock_id=self.lock_id)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/models/manager.py", line 85, in manager_method
  return getattr(self.get_queryset(), name)(*args, **kwargs)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/models/query.py", line 453, in create
  obj.save(force_insert=True, using=self.db)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/models/base.py", line 739, in save
  self.save_base(using=using, force_insert=force_insert,
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/models/base.py", line 776, in save_base
  updated = self._save_table(
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/models/base.py", line 881, in _save_table
  results = self._do_insert(cls._base_manager, using, fields, returning_fields, raw)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/models/base.py", line 919, in _do_insert
  return manager._insert(
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/models/manager.py", line 85, in manager_method
  return getattr(self.get_queryset(), name)(*args, **kwargs)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/models/query.py", line 1270, in _insert
  return query.get_compiler(using=using).execute_sql(returning_fields)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/models/sql/compiler.py", line 1416, in execute_sql
  cursor.execute(sql, params)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/cacheops/transaction.py", line 98, in execute
  result = self._no_monkey.execute(self, sql, params)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/backends/utils.py", line 66, in execute
  return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/backends/utils.py", line 75, in _execute_with_wrappers
  return executor(sql, params, many, context)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/backends/utils.py", line 84, in _execute
  return self.cursor.execute(sql, params)
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/utils.py", line 90, in __exit__
  raise dj_exc_value.with_traceback(traceback) from exc_value
File "/opt/integreat-cms/.venv/lib/python3.9/site-packages/django/db/backends/utils.py", line 84, in _execute
  return self.cursor.execute(sql, params)
django.db.utils.OperationalError: deadlock detected

[svenseeberg]

Now that we have the mutex, I think we can definitely say that we can barely see a difference to before. We currently have 18 duplicate key violations in our log files. AFAICT this is roughly the same amount we had before we introduced the locking mechanism. I think we should remove the mutex and need to rethink the cause of the duplicate key violations.

[timobrembeck]

@svenseeberg yes, I agree. Very strange...
But this relates mostly to issue #1518, right?

[svenseeberg]

@svenseeberg yes, I agree. Very strange... But this relates mostly to issue #1518, right?

Yes.