Celery loses connection when processing scans
I have observed the following in celery logs. The scans seem to die; requires further investigation.
Traceback
[2023-11-08 08:43:01,494: INFO/MainProcess] Task zesje.scans.process_scan[01ed0eca-4eaa-4ac2-98f5-c61888ccbda3] received
[2023-11-08 08:43:04,190: ERROR/ForkPoolWorker-2] Task zesje.scans.process_scan[210e63fd-788e-426e-980b-cbe2f6d39c24] raised unexpected: PendingRollbackError("Can't reconnect until invalid transaction is rolled back.")
Traceback (most recent call last):
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1910, in _execute_context
self.dialect.do_execute(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/engine/default.py", line 736, in do_execute
cursor.execute(statement, parameters)
File "/opt/conda/lib/python3.9/site-packages/pymysql/cursors.py", line 153, in execute
result = self._query(query)
File "/opt/conda/lib/python3.9/site-packages/pymysql/cursors.py", line 322, in _query
conn.query(q)
File "/opt/conda/lib/python3.9/site-packages/pymysql/connections.py", line 558, in query
self._affected_rows = self._read_query_result(unbuffered=unbuffered)
File "/opt/conda/lib/python3.9/site-packages/pymysql/connections.py", line 822, in _read_query_result
result.read()
File "/opt/conda/lib/python3.9/site-packages/pymysql/connections.py", line 1200, in read
first_packet = self.connection._read_packet()
File "/opt/conda/lib/python3.9/site-packages/pymysql/connections.py", line 739, in _read_packet
packet_header = self._read_bytes(4)
File "/opt/conda/lib/python3.9/site-packages/pymysql/connections.py", line 795, in _read_bytes
raise err.OperationalError(
pymysql.err.OperationalError: (2013, 'Lost connection to MySQL server during query')
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/app/zesje/scans.py", line 100, in _process_scan
report_progress(f"Processing page {number} / {total}")
File "/app/zesje/scans.py", line 187, in write_scan_status
scan = Scan.query.get(scan_id)
File "<string>", line 2, in get
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/util/deprecations.py", line 468, in warned
return fn(*args, **kwargs)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/query.py", line 947, in get
return self._get_impl(ident, loading.load_on_pk_identity)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/query.py", line 951, in _get_impl
return self.session._get_impl(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 2942, in _get_impl
instance = self._identity_lookup(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 2220, in _identity_lookup
return loading.get_from_identity(self, mapper, key, passive)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 379, in get_from_identity
state._load_expired(state, passive)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/state.py", line 712, in _load_expired
self.manager.expired_attribute_loader(self, toload, passive)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 1451, in load_scalar_attributes
result = load_on_ident(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 407, in load_on_ident
return load_on_pk_identity(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 530, in load_on_pk_identity
session.execute(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 1717, in execute
result = conn._execute_20(statement, params or {}, execution_options)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1710, in _execute_20
return meth(self, args_10style, kwargs_10style, execution_options)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/sql/elements.py", line 334, in _execute_on_connection
return connection._execute_clauseelement(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1577, in _execute_clauseelement
ret = self._execute_context(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1953, in _execute_context
self._handle_dbapi_exception(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 2134, in _handle_dbapi_exception
util.raise_(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/util/compat.py", line 211, in raise_
raise exception
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1910, in _execute_context
self.dialect.do_execute(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/engine/default.py", line 736, in do_execute
cursor.execute(statement, parameters)
File "/opt/conda/lib/python3.9/site-packages/pymysql/cursors.py", line 153, in execute
result = self._query(query)
File "/opt/conda/lib/python3.9/site-packages/pymysql/cursors.py", line 322, in _query
conn.query(q)
File "/opt/conda/lib/python3.9/site-packages/pymysql/connections.py", line 558, in query
self._affected_rows = self._read_query_result(unbuffered=unbuffered)
File "/opt/conda/lib/python3.9/site-packages/pymysql/connections.py", line 822, in _read_query_result
result.read()
File "/opt/conda/lib/python3.9/site-packages/pymysql/connections.py", line 1200, in read
first_packet = self.connection._read_packet()
File "/opt/conda/lib/python3.9/site-packages/pymysql/connections.py", line 739, in _read_packet
packet_header = self._read_bytes(4)
File "/opt/conda/lib/python3.9/site-packages/pymysql/connections.py", line 795, in _read_bytes
raise err.OperationalError(
sqlalchemy.exc.OperationalError: (pymysql.err.OperationalError) (2013, 'Lost connection to MySQL server during query')
[SQL: SELECT scan.id AS scan_id, scan.exam_id AS scan_exam_id, scan.name AS scan_name, scan.status AS scan_status, scan.message AS scan_message
FROM scan
WHERE scan.id = %(pk_1)s]
[parameters: {'pk_1': 99}]
(Background on this error at: https://sqlalche.me/e/14/e3q8)
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/app/zesje/scans.py", line 62, in process_scan
_process_scan(scan_id, ExamLayout(scan_type))
File "/app/zesje/scans.py", line 117, in _process_scan
report_error(f"Failed to read file {scan.name}: {e}")
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/attributes.py", line 487, in __get__
return self.impl.get(state, dict_)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/attributes.py", line 959, in get
value = self._fire_loader_callables(state, key, passive)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/attributes.py", line 990, in _fire_loader_callables
return state._load_expired(state, passive)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/state.py", line 712, in _load_expired
self.manager.expired_attribute_loader(self, toload, passive)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 1451, in load_scalar_attributes
result = load_on_ident(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 407, in load_on_ident
return load_on_pk_identity(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 530, in load_on_pk_identity
session.execute(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 1717, in execute
result = conn._execute_20(statement, params or {}, execution_options)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1710, in _execute_20
return meth(self, args_10style, kwargs_10style, execution_options)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/sql/elements.py", line 334, in _execute_on_connection
return connection._execute_clauseelement(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1577, in _execute_clauseelement
ret = self._execute_context(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1808, in _execute_context
conn = self._revalidate_connection()
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 650, in _revalidate_connection
self._invalid_transaction()
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 622, in _invalid_transaction
raise exc.PendingRollbackError(
sqlalchemy.exc.PendingRollbackError: Can't reconnect until invalid transaction is rolled back. (Background on this error at: https://sqlalche.me/e/14/8s2b)
uring handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/opt/conda/lib/python3.9/site-packages/celery/app/trace.py", line 477, in trace_task
R = retval = fun(*args, **kwargs)
File "/app/zesje/factory.py", line 74, in __call__
return TaskBase.__call__(self, *args, **kwargs)
File "/opt/conda/lib/python3.9/site-packages/celery/app/trace.py", line 760, in __protected_call__
return self.run(*args, **kwargs)
File "/app/zesje/scans.py", line 67, in process_scan
write_scan_status(scan_id, "error", "Unexpected error: " + str(error))
File "/app/zesje/scans.py", line 187, in write_scan_status
scan = Scan.query.get(scan_id)
File "<string>", line 2, in get
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/util/deprecations.py", line 468, in warned
return fn(*args, **kwargs)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/query.py", line 947, in get
return self._get_impl(ident, loading.load_on_pk_identity)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/query.py", line 951, in _get_impl
return self.session._get_impl(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 2942, in _get_impl
instance = self._identity_lookup(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 2220, in _identity_lookup
return loading.get_from_identity(self, mapper, key, passive)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 379, in get_from_identity
state._load_expired(state, passive)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/state.py", line 712, in _load_expired
self.manager.expired_attribute_loader(self, toload, passive)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 1451, in load_scalar_attributes
result = load_on_ident(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 407, in load_on_ident
return load_on_pk_identity(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 530, in load_on_pk_identity
session.execute(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 1717, in execute
result = conn._execute_20(statement, params or {}, execution_options)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1710, in _execute_20
return meth(self, args_10style, kwargs_10style, execution_options)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/sql/elements.py", line 334, in _execute_on_connection
return connection._execute_clauseelement(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1577, in _execute_clauseelement
ret = self._execute_context(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1808, in _execute_context
conn = self._revalidate_connection()
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 650, in _revalidate_connection
self._invalid_transaction()
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 622, in _invalid_transaction
raise exc.PendingRollbackError(
sqlalchemy.exc.PendingRollbackError: Can't reconnect until invalid transaction is rolled back. (Background on this error at: https://sqlalche.me/e/14/8s2b)
[2023-11-08 08:43:04,193: ERROR/ForkPoolWorker-1] Task zesje.scans.process_scan[8af7ecc8-d1c2-4632-9cda-7943366758c9] raised unexpected: InvalidRequestError("This session is in 'prepared' state; no further SQL can be emitted within this transaction.")
Traceback (most recent call last):
File "/app/zesje/scans.py", line 100, in _process_scan
report_progress(f"Processing page {number} / {total}")
File "/app/zesje/scans.py", line 187, in write_scan_status
scan = Scan.query.get(scan_id)
File "<string>", line 2, in get
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/util/deprecations.py", line 468, in warned
return fn(*args, **kwargs)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/query.py", line 947, in get
return self._get_impl(ident, loading.load_on_pk_identity)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/query.py", line 951, in _get_impl
return self.session._get_impl(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 2942, in _get_impl
instance = self._identity_lookup(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 2220, in _identity_lookup
return loading.get_from_identity(self, mapper, key, passive)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 379, in get_from_identity
state._load_expired(state, passive)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/state.py", line 712, in _load_expired
self.manager.expired_attribute_loader(self, toload, passive)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 1451, in load_scalar_attributes
result = load_on_ident(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 407, in load_on_ident
return load_on_pk_identity(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 530, in load_on_pk_identity
session.execute(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 1716, in execute
conn = self._connection_for_bind(bind)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 1555, in _connection_for_bind
return self._transaction._connection_for_bind(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 724, in _connection_for_bind
self._assert_active()
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 597, in _assert_active
raise sa_exc.InvalidRequestError(
sqlalchemy.exc.InvalidRequestError: This session is in 'prepared' state; no further SQL can be emitted within this transaction.
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/app/zesje/scans.py", line 62, in process_scan
_process_scan(scan_id, ExamLayout(scan_type))
File "/app/zesje/scans.py", line 117, in _process_scan
report_error(f"Failed to read file {scan.name}: {e}")
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/attributes.py", line 487, in __get__
return self.impl.get(state, dict_)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/attributes.py", line 959, in get
value = self._fire_loader_callables(state, key, passive)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/attributes.py", line 990, in _fire_loader_callables
return state._load_expired(state, passive)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/state.py", line 712, in _load_expired
self.manager.expired_attribute_loader(self, toload, passive)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 1451, in load_scalar_attributes
result = load_on_ident(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 407, in load_on_ident
return load_on_pk_identity(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 530, in load_on_pk_identity
session.execute(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 1716, in execute
conn = self._connection_for_bind(bind)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 1555, in _connection_for_bind
return self._transaction._connection_for_bind(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 724, in _connection_for_bind
self._assert_active()
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 597, in _assert_active
raise sa_exc.InvalidRequestError(
sqlalchemy.exc.InvalidRequestError: This session is in 'prepared' state; no further SQL can be emitted within this transaction.
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/opt/conda/lib/python3.9/site-packages/celery/app/trace.py", line 477, in trace_task
R = retval = fun(*args, **kwargs)
File "/app/zesje/factory.py", line 74, in __call__
return TaskBase.__call__(self, *args, **kwargs)
File "/opt/conda/lib/python3.9/site-packages/celery/app/trace.py", line 760, in __protected_call__
return self.run(*args, **kwargs)
File "/app/zesje/scans.py", line 67, in process_scan
write_scan_status(scan_id, "error", "Unexpected error: " + str(error))
File "/app/zesje/scans.py", line 187, in write_scan_status
scan = Scan.query.get(scan_id)
File "<string>", line 2, in get
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/util/deprecations.py", line 468, in warned
return fn(*args, **kwargs)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/query.py", line 947, in get
return self._get_impl(ident, loading.load_on_pk_identity)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/query.py", line 951, in _get_impl
return self.session._get_impl(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 2942, in _get_impl
instance = self._identity_lookup(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 2220, in _identity_lookup
return loading.get_from_identity(self, mapper, key, passive)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 379, in get_from_identity
state._load_expired(state, passive)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/state.py", line 712, in _load_expired
self.manager.expired_attribute_loader(self, toload, passive)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 1451, in load_scalar_attributes
result = load_on_ident(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 407, in load_on_ident
return load_on_pk_identity(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/loading.py", line 530, in load_on_pk_identity
session.execute(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 1716, in execute
conn = self._connection_for_bind(bind)
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 1555, in _connection_for_bind
return self._transaction._connection_for_bind(
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 724, in _connection_for_bind
self._assert_active()
File "/opt/conda/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 597, in _assert_active
raise sa_exc.InvalidRequestError(
sqlalchemy.exc.InvalidRequestError: This session is in 'prepared' state; no further SQL can be emitted within this transaction.