You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@airflow.apache.org by "sanjayp (Jira)" <ji...@apache.org> on 2020/12/03 06:24:00 UTC
[jira] [Commented] (AIRFLOW-2516) Deadlock found when trying to
update task_instance table
[ https://issues.apache.org/jira/browse/AIRFLOW-2516?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17242949#comment-17242949 ]
sanjayp commented on AIRFLOW-2516:
----------------------------------
i am getting this issue on version 1.10.12 while running the example_subdag_operator from the examples. it is a clean deployment, and this is the only DAG configured.
it is happening pretty consistently.
Environment:
Airflow Version: 1.10.12
Database: MySQL 8.0.22
Deployed on Kubernetes with CeleryExecutor using airflow-helm/charts
{code:java}
// code placeholder
*** Log file does not exist: /opt/airflow/logs/example_subdag_operator/section-2/2020-12-03T05:55:04.861187+00:00/1.log
*** Fetching from: http://airflow-demo-worker-0.airflow-demo-worker.airflow.svc.cluster.local:8793/log/example_subdag_operator/section-2/2020-12-03T05:55:04.861187+00:00/1.log
[2020-12-03 05:56:13,403] {taskinstance.py:670} INFO - Dependencies all met for <TaskInstance: example_subdag_operator.section-2 2020-12-03T05:55:04.861187+00:00 [queued]>
[2020-12-03 05:56:13,430] {taskinstance.py:670} INFO - Dependencies all met for <TaskInstance: example_subdag_operator.section-2 2020-12-03T05:55:04.861187+00:00 [queued]>
[2020-12-03 05:56:13,430] {taskinstance.py:880} INFO -
--------------------------------------------------------------------------------
[2020-12-03 05:56:13,430] {taskinstance.py:881} INFO - Starting attempt 1 of 1
[2020-12-03 05:56:13,430] {taskinstance.py:882} INFO -
--------------------------------------------------------------------------------
[2020-12-03 05:56:13,459] {taskinstance.py:901} INFO - Executing <Task(SubDagOperator): section-2> on 2020-12-03T05:55:04.861187+00:00
[2020-12-03 05:56:13,461] {standard_task_runner.py:54} INFO - Started process 1540 to run task
[2020-12-03 05:56:13,481] {standard_task_runner.py:77} INFO - Running: ['airflow', 'run', 'example_subdag_operator', 'section-2', '2020-12-03T05:55:04.861187+00:00', '--job_id', '39', '--pool', 'default_pool', '--raw', '-sd', 'DAGS_FOLDER/example_subdag_operator.py', '--cfg_path', '/tmp/tmpkdem7boi']
[2020-12-03 05:56:13,483] {standard_task_runner.py:78} INFO - Job 39: Subtask section-2
[2020-12-03 05:56:13,658] {logging_mixin.py:112} INFO - Running %s on host %s <TaskInstance: example_subdag_operator.section-2 2020-12-03T05:55:04.861187+00:00 [running]> airflow-demo-worker-0.airflow-demo-worker.airflow.svc.cluster.local
[2020-12-03 05:56:14,265] {base_executor.py:58} INFO - Adding to queue: ['airflow', 'run', 'example_subdag_operator.section-2', 'section-2-task-1', '2020-12-03T05:55:04.861187+00:00', '--local', '--pool', 'default_pool', '-sd', 'DAGS_FOLDER/example_subdag_operator.py', '--cfg_path', '/tmp/tmp8kky3o06']
[2020-12-03 05:56:14,539] {base_executor.py:58} INFO - Adding to queue: ['airflow', 'run', 'example_subdag_operator.section-2', 'section-2-task-2', '2020-12-03T05:55:04.861187+00:00', '--local', '--pool', 'default_pool', '-sd', 'DAGS_FOLDER/example_subdag_operator.py', '--cfg_path', '/tmp/tmp3uhiaf8x']
[2020-12-03 05:56:14,820] {base_executor.py:58} INFO - Adding to queue: ['airflow', 'run', 'example_subdag_operator.section-2', 'section-2-task-3', '2020-12-03T05:55:04.861187+00:00', '--local', '--pool', 'default_pool', '-sd', 'DAGS_FOLDER/example_subdag_operator.py', '--cfg_path', '/tmp/tmpjwipf0vo']
[2020-12-03 05:56:14,836] {sequential_executor.py:54} INFO - Executing command: ['airflow', 'run', 'example_subdag_operator.section-2', 'section-2-task-1', '2020-12-03T05:55:04.861187+00:00', '--local', '--pool', 'default_pool', '-sd', 'DAGS_FOLDER/example_subdag_operator.py', '--cfg_path', '/tmp/tmp8kky3o06']
[2020-12-03 05:56:22,546] {sequential_executor.py:54} INFO - Executing command: ['airflow', 'run', 'example_subdag_operator.section-2', 'section-2-task-2', '2020-12-03T05:55:04.861187+00:00', '--local', '--pool', 'default_pool', '-sd', 'DAGS_FOLDER/example_subdag_operator.py', '--cfg_path', '/tmp/tmp3uhiaf8x']
[2020-12-03 05:56:35,125] {sequential_executor.py:54} INFO - Executing command: ['airflow', 'run', 'example_subdag_operator.section-2', 'section-2-task-3', '2020-12-03T05:55:04.861187+00:00', '--local', '--pool', 'default_pool', '-sd', 'DAGS_FOLDER/example_subdag_operator.py', '--cfg_path', '/tmp/tmpjwipf0vo']
[2020-12-03 05:56:42,893] {taskinstance.py:1150} ERROR - (_mysql_exceptions.OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction')
[SQL: UPDATE task_instance SET state=%s, queued_dttm=%s WHERE task_instance.task_id = %s AND task_instance.dag_id = %s AND task_instance.execution_date = %s]
[parameters: ('queued', datetime.datetime(2020, 12, 3, 5, 56, 14, 601700), 'section-2-task-3', 'example_subdag_operator.section-2', datetime.datetime(2020, 12, 3, 5, 55, 4, 861187))]
(Background on this error at: http://sqlalche.me/e/13/e3q8)
Traceback (most recent call last):
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1277, in _execute_context
cursor, statement, parameters, context
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 593, in do_execute
cursor.execute(statement, parameters)
File "/home/airflow/.local/lib/python3.6/site-packages/MySQLdb/cursors.py", line 255, in execute
self.errorhandler(self, exc, value)
File "/home/airflow/.local/lib/python3.6/site-packages/MySQLdb/connections.py", line 50, in defaulterrorhandler
raise errorvalue
File "/home/airflow/.local/lib/python3.6/site-packages/MySQLdb/cursors.py", line 252, in execute
res = self._query(query)
File "/home/airflow/.local/lib/python3.6/site-packages/MySQLdb/cursors.py", line 378, in _query
db.query(q)
File "/home/airflow/.local/lib/python3.6/site-packages/MySQLdb/connections.py", line 280, in query
_mysql.connection.query(self, query)
_mysql_exceptions.OperationalError: (1213, 'Deadlock found when trying to get lock; try restarting transaction')
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/home/airflow/.local/lib/python3.6/site-packages/airflow/models/taskinstance.py", line 984, in _run_raw_task
result = task_copy.execute(context=context)
File "/home/airflow/.local/lib/python3.6/site-packages/airflow/operators/subdag_operator.py", line 102, in execute
executor=self.executor)
File "/home/airflow/.local/lib/python3.6/site-packages/airflow/models/dag.py", line 1432, in run
job.run()
File "/home/airflow/.local/lib/python3.6/site-packages/airflow/jobs/base_job.py", line 218, in run
self._execute()
File "/home/airflow/.local/lib/python3.6/site-packages/airflow/utils/db.py", line 74, in wrapper
return func(*args, **kwargs)
File "/home/airflow/.local/lib/python3.6/site-packages/airflow/jobs/backfill_job.py", line 787, in _execute
session=session)
File "/home/airflow/.local/lib/python3.6/site-packages/airflow/utils/db.py", line 70, in wrapper
return func(*args, **kwargs)
File "/home/airflow/.local/lib/python3.6/site-packages/airflow/jobs/backfill_job.py", line 717, in _execute_for_run_dates
session=session)
File "/home/airflow/.local/lib/python3.6/site-packages/airflow/utils/db.py", line 70, in wrapper
return func(*args, **kwargs)
File "/home/airflow/.local/lib/python3.6/site-packages/airflow/jobs/backfill_job.py", line 586, in _process_backfill_task_instances
_per_task_process(task, key, ti)
File "/home/airflow/.local/lib/python3.6/site-packages/airflow/utils/db.py", line 74, in wrapper
return func(*args, **kwargs)
File "/home/airflow/.local/lib/python3.6/site-packages/airflow/jobs/backfill_job.py", line 509, in _per_task_process
session.commit()
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/orm/session.py", line 1042, in commit
self.transaction.commit()
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/orm/session.py", line 504, in commit
self._prepare_impl()
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/orm/session.py", line 483, in _prepare_impl
self.session.flush()
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/orm/session.py", line 2523, in flush
self._flush(objects)
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/orm/session.py", line 2664, in _flush
transaction.rollback(_capture_exception=True)
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/util/langhelpers.py", line 69, in __exit__
exc_value, with_traceback=exc_tb,
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 182, in raise_
raise exception
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/orm/session.py", line 2624, in _flush
flush_context.execute()
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/orm/unitofwork.py", line 422, in execute
rec.execute(self)
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/orm/unitofwork.py", line 589, in execute
uow,
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/orm/persistence.py", line 236, in save_obj
update,
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/orm/persistence.py", line 995, in _emit_update_statements
statement, multiparams
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1011, in execute
return meth(self, multiparams, params)
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/sql/elements.py", line 298, in _execute_on_connection
return connection._execute_clauseelement(self, multiparams, params)
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1130, in _execute_clauseelement
distilled_params,
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1317, in _execute_context
e, statement, parameters, cursor, context
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1511, in _handle_dbapi_exception
sqlalchemy_exception, with_traceback=exc_info[2], from_=e
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 182, in raise_
raise exception
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1277, in _execute_context
cursor, statement, parameters, context
File "/home/airflow/.local/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 593, in do_execute
cursor.execute(statement, parameters)
File "/home/airflow/.local/lib/python3.6/site-packages/MySQLdb/cursors.py", line 255, in execute
self.errorhandler(self, exc, value)
File "/home/airflow/.local/lib/python3.6/site-packages/MySQLdb/connections.py", line 50, in defaulterrorhandler
raise errorvalue
File "/home/airflow/.local/lib/python3.6/site-packages/MySQLdb/cursors.py", line 252, in execute
res = self._query(query)
File "/home/airflow/.local/lib/python3.6/site-packages/MySQLdb/cursors.py", line 378, in _query
db.query(q)
File "/home/airflow/.local/lib/python3.6/site-packages/MySQLdb/connections.py", line 280, in query
_mysql.connection.query(self, query)
sqlalchemy.exc.OperationalError: (_mysql_exceptions.OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction')
[SQL: UPDATE task_instance SET state=%s, queued_dttm=%s WHERE task_instance.task_id = %s AND task_instance.dag_id = %s AND task_instance.execution_date = %s]
[parameters: ('queued', datetime.datetime(2020, 12, 3, 5, 56, 14, 601700), 'section-2-task-3', 'example_subdag_operator.section-2', datetime.datetime(2020, 12, 3, 5, 55, 4, 861187))]
(Background on this error at: http://sqlalche.me/e/13/e3q8)
[2020-12-03 05:56:42,899] {taskinstance.py:1194} INFO - Marking task as FAILED. dag_id=example_subdag_operator, task_id=section-2, execution_date=20201203T055504, start_date=20201203T055613, end_date=20201203T055642
[2020-12-03 05:56:43,465] {local_task_job.py:102} INFO - Task exited with return code 1
{code}
h3.
> Deadlock found when trying to update task_instance table
> --------------------------------------------------------
>
> Key: AIRFLOW-2516
> URL: https://issues.apache.org/jira/browse/AIRFLOW-2516
> Project: Apache Airflow
> Issue Type: Bug
> Components: DagRun
> Affects Versions: 1.8.0, 1.9.0, 1.10.0, 1.10.1, 1.10.2, 1.10.3, 1.10.4, 1.10.5, 1.10.6, 1.10.7
> Reporter: Jeff Liu
> Assignee: Jarek Potiuk
> Priority: Major
> Fix For: 1.10.11
>
> Attachments: Screenshot 2019-12-30 at 10.42.52.png, image-2019-12-30-10-48-41-313.png, image-2019-12-30-10-58-02-610.png, jobs.py, jobs_fixed_deadlock_possibly_1.9.py, scheduler_job_fixed_deadlock_possibly_1.10.6.py
>
>
>
>
> {code:java}
> [2018-05-23 17:59:57,218] {base_task_runner.py:98} INFO - Subtask: [2018-05-23 17:59:57,217] {base_executor.py:49} INFO - Adding to queue: airflow run production_wipeout_wipe_manager.Carat Carat_20180227 2018-05-23T17:41:18.815809 --local -sd DAGS_FOLDER/wipeout/wipeout.py
> [2018-05-23 17:59:57,231] {base_task_runner.py:98} INFO - Subtask: Traceback (most recent call last):
> [2018-05-23 17:59:57,232] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/bin/airflow", line 27, in <module>
> [2018-05-23 17:59:57,232] {base_task_runner.py:98} INFO - Subtask: args.func(args)
> [2018-05-23 17:59:57,232] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/lib/python2.7/site-packages/airflow/bin/cli.py", line 392, in run
> [2018-05-23 17:59:57,232] {base_task_runner.py:98} INFO - Subtask: pool=args.pool,
> [2018-05-23 17:59:57,233] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/lib/python2.7/site-packages/airflow/utils/db.py", line 50, in wrapper
> [2018-05-23 17:59:57,233] {base_task_runner.py:98} INFO - Subtask: result = func(*args, **kwargs)
> [2018-05-23 17:59:57,233] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/lib/python2.7/site-packages/airflow/models.py", line 1532, in _run_raw_task
> [2018-05-23 17:59:57,234] {base_task_runner.py:98} INFO - Subtask: self.handle_failure(e, test_mode, context)
> [2018-05-23 17:59:57,234] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/lib/python2.7/site-packages/airflow/models.py", line 1641, in handle_failure
> [2018-05-23 17:59:57,234] {base_task_runner.py:98} INFO - Subtask: session.merge(self)
> [2018-05-23 17:59:57,235] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1920, in merge
> [2018-05-23 17:59:57,235] {base_task_runner.py:98} INFO - Subtask: _resolve_conflict_map=_resolve_conflict_map)
> [2018-05-23 17:59:57,235] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1974, in _merge
> [2018-05-23 17:59:57,236] {base_task_runner.py:98} INFO - Subtask: merged = self.query(mapper.class_).get(key[1])
> [2018-05-23 17:59:57,236] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 882, in get
> [2018-05-23 17:59:57,236] {base_task_runner.py:98} INFO - Subtask: ident, loading.load_on_pk_identity)
> [2018-05-23 17:59:57,236] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 952, in _get_impl
> [2018-05-23 17:59:57,237] {base_task_runner.py:98} INFO - Subtask: return db_load_fn(self, primary_key_identity)
> [2018-05-23 17:59:57,237] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/loading.py", line 247, in load_on_pk_i
> dentity
> [2018-05-23 17:59:57,237] {base_task_runner.py:98} INFO - Subtask: return q.one()
> [2018-05-23 17:59:57,238] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2884, in one
> [2018-05-23 17:59:57,238] {base_task_runner.py:98} INFO - Subtask: ret = self.one_or_none()
> [2018-05-23 17:59:57,238] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2854, in one_or_none
> [2018-05-23 17:59:57,238] {base_task_runner.py:98} INFO - Subtask: ret = list(self)
> [2018-05-23 17:59:57,239] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2925, in __iter__
> [2018-05-23 17:59:57,239] {base_task_runner.py:98} INFO - Subtask: return self._execute_and_instances(context)
> [2018-05-23 17:59:57,239] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2946, in _execute_and_instances
> [2018-05-23 17:59:57,240] {base_task_runner.py:98} INFO - Subtask: close_with_result=True)
> [2018-05-23 17:59:57,240] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2955, in _get_bind_ar
> s
> [2018-05-23 17:59:57,240] {base_task_runner.py:98} INFO - Subtask: **kw
> [2018-05-23 17:59:57,240] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2937, in _connection_f
> rom_session
> [2018-05-23 17:59:57,241] {base_task_runner.py:98} INFO - Subtask: conn = self.session.connection(**kw)
> [2018-05-23 17:59:57,241] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1035, in connection
> [2018-05-23 17:59:57,241] {base_task_runner.py:98} INFO - Subtask: execution_options=execution_options)
> [2018-05-23 17:59:57,241] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1040, in _connection
> _for_bind
> [2018-05-23 17:59:57,242] {base_task_runner.py:98} INFO - Subtask: engine, execution_options)
> [2018-05-23 17:59:57,242] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 388, in _connection_
> for_bind
> [2018-05-23 17:59:57,242] {base_task_runner.py:98} INFO - Subtask: self._assert_active()
> [2018-05-23 17:59:57,243] {base_task_runner.py:98} INFO - Subtask: File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 276, in _assert_acti
> ve
> [2018-05-23 17:59:57,243] {base_task_runner.py:98} INFO - Subtask: % self._rollback_exception
> [2018-05-23 17:59:57,244] {base_task_runner.py:98} INFO - Subtask: sqlalchemy.exc.InvalidRequestError: This Session's transaction has been rolled back due to a previou
> s exception during flush. To begin a new transaction with this Session, first issue Session.rollback(). Original exception was: (_mysql_exceptions.OperationalError) (1
> 213, 'Deadlock found when trying to get lock; try restarting transaction') [SQL: u'UPDATE task_instance SET state=%s WHERE task_instance.task_id = %s AND task_instance
> .dag_id = %s AND task_instance.execution_date = %s'] [parameters: (u'queued', 'Carat_20180227', 'production_wipeout_wipe_manager.Carat', datetime.datetime(2018, 5, 23,
> 17, 41, 18, 815809))] (Background on this error at: http://sqlalche.me/e/e3q8){code}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)