Nicer logging for debusine.server.celery.update_workflows not getting a lock?
When debusine.server.celery.update_workflows cannot get a lock, we get a noisy stack trace in the logs:
Mar 05 10:33:53 <hostname> python3[352730]: Traceback (most recent call last):
Mar 05 10:33:53 <hostname> python3[352730]: File "/usr/lib/python3/dist-packages/django/db/backends/utils.py", line 89, in _execute
Mar 05 10:33:53 <hostname> python3[352730]: return self.cursor.execute(sql, params)
Mar 05 10:33:53 <hostname> python3[352730]: ~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^
Mar 05 10:33:53 <hostname> python3[352730]: File "/usr/lib/python3/dist-packages/psycopg/cursor.py", line 97, in execute
Mar 05 10:33:53 <hostname> python3[352730]: raise ex.with_traceback(None)
Mar 05 10:33:53 <hostname> python3[352730]: psycopg.errors.SerializationFailure: could not serialize access due to concurrent update
Mar 05 10:33:53 <hostname> python3[352730]: The above exception was the direct cause of the following exception:
Mar 05 10:33:53 <hostname> python3[352730]: Traceback (most recent call last):
Mar 05 10:33:53 <hostname> python3[352730]: File "/usr/lib/python3/dist-packages/celery/app/trace.py", line 453, in trace_task
Mar 05 10:33:53 <hostname> python3[352730]: R = retval = fun(*args, **kwargs)
Mar 05 10:33:53 <hostname> python3[352730]: ~~~^^^^^^^^^^^^^^^^^
Mar 05 10:33:53 <hostname> python3[352730]: File "/usr/lib/python3/dist-packages/celery/app/trace.py", line 736, in __protected_call__
Mar 05 10:33:53 <hostname> python3[352730]: return self.run(*args, **kwargs)
Mar 05 10:33:53 <hostname> python3[352730]: ~~~~~~~~^^^^^^^^^^^^^^^^^
Mar 05 10:33:53 <hostname> python3[352730]: File "/usr/lib/python3/dist-packages/pgtransaction/transaction.py", line 113, in inner
Mar 05 10:33:53 <hostname> python3[352730]: return func(*args, **kwds)
Mar 05 10:33:53 <hostname> python3[352730]: File "/usr/lib/python3/dist-packages/debusine/server/celery.py", line 175, in update_workflows
Mar 05 10:33:53 <hostname> python3[352730]: ).lock_workflows_for_update()
Mar 05 10:33:53 <hostname> python3[352730]: ~~~~~~~~~~~~~~~~~~~~~~~~~^^
Mar 05 10:33:53 <hostname> python3[352730]: File "/usr/lib/python3/dist-packages/debusine/db/models/work_requests.py", line 865, in lock_workflows_for_update
Mar 05 10:33:53 <hostname> python3[352730]: bool(
Mar 05 10:33:53 <hostname> python3[352730]: ~~~~^
Mar 05 10:33:53 <hostname> python3[352730]: WorkRequest.objects.select_for_update(nowait=nowait, no_key=True)
Mar 05 10:33:53 <hostname> python3[352730]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Mar 05 10:33:53 <hostname> python3[352730]: ...<12 lines>...
Mar 05 10:33:53 <hostname> python3[352730]: .values("id")
Mar 05 10:33:53 <hostname> python3[352730]: ^^^^^^^^^^^^^
Mar 05 10:33:53 <hostname> python3[352730]: )
Mar 05 10:33:53 <hostname> python3[352730]: ^
Mar 05 10:33:53 <hostname> python3[352730]: File "/usr/lib/python3/dist-packages/django/db/models/query.py", line 414, in __bool__
Mar 05 10:33:53 <hostname> python3[352730]: self._fetch_all()
Mar 05 10:33:53 <hostname> python3[352730]: ~~~~~~~~~~~~~~~^^
Mar 05 10:33:53 <hostname> python3[352730]: File "/usr/lib/python3/dist-packages/django/db/models/query.py", line 1886, in _fetch_all
Mar 05 10:33:53 <hostname> python3[352730]: self._result_cache = list(self._iterable_class(self))
Mar 05 10:33:53 <hostname> python3[352730]: ~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Mar 05 10:33:53 <hostname> python3[352730]: File "/usr/lib/python3/dist-packages/django/db/models/query.py", line 210, in __iter__
Mar 05 10:33:53 <hostname> python3[352730]: for row in compiler.results_iter(
Mar 05 10:33:53 <hostname> python3[352730]: ~~~~~~~~~~~~~~~~~~~~~^
Mar 05 10:33:53 <hostname> python3[352730]: chunked_fetch=self.chunked_fetch, chunk_size=self.chunk_size
Mar 05 10:33:53 <hostname> python3[352730]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Mar 05 10:33:53 <hostname> python3[352730]: ):
Mar 05 10:33:53 <hostname> python3[352730]: ^
Mar 05 10:33:53 <hostname> python3[352730]: File "/usr/lib/python3/dist-packages/django/db/models/sql/compiler.py", line 1513, in results_iter
Mar 05 10:33:53 <hostname> python3[352730]: results = self.execute_sql(
Mar 05 10:33:53 <hostname> python3[352730]: MULTI, chunked_fetch=chunked_fetch, chunk_size=chunk_size
Mar 05 10:33:53 <hostname> python3[352730]: )
Mar 05 10:33:53 <hostname> python3[352730]: File "/usr/lib/python3/dist-packages/django/db/models/sql/compiler.py", line 1562, in execute_sql
Mar 05 10:33:53 <hostname> python3[352730]: cursor.execute(sql, params)
Mar 05 10:33:53 <hostname> python3[352730]: ~~~~~~~~~~~~~~^^^^^^^^^^^^^
Mar 05 10:33:53 <hostname> python3[352730]: File "/usr/lib/python3/dist-packages/django/db/backends/utils.py", line 67, in execute
Mar 05 10:33:53 <hostname> python3[352730]: return self._execute_with_wrappers(
Mar 05 10:33:53 <hostname> python3[352730]: ~~~~~~~~~~~~~~~~~~~~~~~~~~~^
Mar 05 10:33:53 <hostname> python3[352730]: sql, params, many=False, executor=self._execute
Mar 05 10:33:53 <hostname> python3[352730]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Mar 05 10:33:53 <hostname> python3[352730]: )
Mar 05 10:33:53 <hostname> python3[352730]: ^
Mar 05 10:33:53 <hostname> python3[352730]: File "/usr/lib/python3/dist-packages/django/db/backends/utils.py", line 80, in _execute_with_wrappers
Mar 05 10:33:53 <hostname> python3[352730]: return executor(sql, params, many, context)
Mar 05 10:33:53 <hostname> python3[352730]: File "/usr/lib/python3/dist-packages/django/db/backends/utils.py", line 84, in _execute
Mar 05 10:33:53 <hostname> python3[352730]: with self.db.wrap_database_errors:
Mar 05 10:33:53 <hostname> python3[352730]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Mar 05 10:33:53 <hostname> python3[352730]: File "/usr/lib/python3/dist-packages/django/db/utils.py", line 91, in __exit__
Mar 05 10:33:53 <hostname> python3[352730]: raise dj_exc_value.with_traceback(traceback) from exc_value
Mar 05 10:33:53 <hostname> python3[352730]: File "/usr/lib/python3/dist-packages/django/db/backends/utils.py", line 89, in _execute
Mar 05 10:33:53 <hostname> python3[352730]: return self.cursor.execute(sql, params)
Mar 05 10:33:53 <hostname> python3[352730]: ~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^
Mar 05 10:33:53 <hostname> python3[352730]: File "/usr/lib/python3/dist-packages/psycopg/cursor.py", line 97, in execute
Mar 05 10:33:53 <hostname> python3[352730]: raise ex.with_traceback(None)
Mar 05 10:33:53 <hostname> python3[352730]: django.db.utils.OperationalError: could not serialize access due to concurrent updateIt looks to me like an expected condition for a task that aims at eventual consistency: would it make sense to catch the OperationalError and log only one line like "update_workflows() deferred due to a concurrent update"?