search

digitalfabrik / integreat-cms

Simplified content management back end for the Integreat App - a multilingual information platform for newcomers
https://digitalfabrik.github.io/integreat-cms/
Apache License 2.0
55 stars 33 forks source link

Deadlock during page move #1716

Open timobrembeck opened 1 year ago

timobrembeck commented 1 year ago

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 commented 1 year ago

This is probably also related to #1518 and ultimately https://github.com/django-treebeard/django-treebeard/issues/53.

timobrembeck commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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

svenseeberg commented 1 year ago

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

Yes.