You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@airflow.apache.org by "t oo (JIRA)" <ji...@apache.org> on 2019/05/10 21:19:00 UTC
[jira] [Updated] (AIRFLOW-4498) sql metastore/scheduler deadlock
[ https://issues.apache.org/jira/browse/AIRFLOW-4498?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
t oo updated AIRFLOW-4498:
--------------------------
Description:
see late comments in AIRFLOW-2511, issue still occurring in 1.10.3 release
17/Apr/19 14:44
We're still seeing deadlocking issues within 1.10.3 with this change applied, it appears that for this specific condition (subdagoperator) it has no effect:
[2019-04-17 14:01:33,423] {{__init__.py:1580}} 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(2019, 4, 17, 14, 1, 18, 249580, tzinfo=<Timezone [UTC]>), 'subdag_task_instance', 'subdag_dag.move_data', datetime.datetime(2019, 4, 17, 11, 35, 56, 625793, tzinfo=<Timezone [UTC]>))] (Background on this error at: http://sqlalche.me/e/e3q8)
Traceback (most recent call last):
File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1236, in _execute_context
cursor, statement, parameters, context
File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/default.py", line 536, in do_execute
cursor.execute(statement, parameters)
File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 255, in execute
self.errorhandler(self, exc, value)
File "/usr/lib64/python3.6/site-packages/MySQLdb/connections.py", line 50, in defaulterrorhandler
raise errorvalue
File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 252, in execute
res = self._query(query)
File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 378, in _query
db.query(q)
File "/usr/lib64/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 "/usr/lib/python3.6/site-packages/airflow/models/__init__.py", line 1441, in _run_raw_task
result = task_copy.execute(context=context)
File "/usr/lib/python3.6/site-packages/airflow/operators/subdag_operator.py", line 102, in execute
executor=self.executor)
File "/usr/lib/python3.6/site-packages/airflow/models/__init__.py", line 4030, in run
job.run()
File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 209, in run
self._execute()
File "/usr/lib/python3.6/site-packages/airflow/utils/db.py", line 73, in wrapper
return func(*args, **kwargs)
File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 2475, in _execute
session=session)
File "/usr/lib/python3.6/site-packages/airflow/utils/db.py", line 69, in wrapper
return func(*args, **kwargs)
File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 2421, in _execute_for_run_dates
session=session)
File "/usr/lib/python3.6/site-packages/airflow/utils/db.py", line 69, in wrapper
return func(*args, **kwargs)
File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 2310, in _process_backfill_task_instances
_per_task_process(task, key, ti)
File "/usr/lib/python3.6/site-packages/airflow/utils/db.py", line 73, in wrapper
return func(*args, **kwargs)
File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 2273, in _per_task_process
session.commit()
File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 1023, in commit
self.transaction.commit()
File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 487, in commit
self._prepare_impl()
File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 466, in _prepare_impl
self.session.flush()
File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 2446, in flush
self._flush(objects)
File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 2584, in _flush
transaction.rollback(_capture_exception=True)
File "/usr/lib64/python3.6/site-packages/sqlalchemy/util/langhelpers.py", line 67, in __exit__
compat.reraise(exc_type, exc_value, exc_tb)
File "/usr/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 277, in reraise
raise value
File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 2544, in _flush
flush_context.execute()
File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/unitofwork.py", line 416, in execute
rec.execute(self)
File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/unitofwork.py", line 583, in execute
uow,
File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/persistence.py", line 236, in save_obj
update,
File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/persistence.py", line 976, in _emit_update_statements
statement, multiparams
File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 980, in execute
return meth(self, multiparams, params)
File "/usr/lib64/python3.6/site-packages/sqlalchemy/sql/elements.py", line 273, in _execute_on_connection
return connection._execute_clauseelement(self, multiparams, params)
File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1099, in _execute_clauseelement
distilled_params,
File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1240, in _execute_context
e, statement, parameters, cursor, context
File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1458, in _handle_dbapi_exception
util.raise_from_cause(sqlalchemy_exception, exc_info)
File "/usr/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 296, in raise_from_cause
reraise(type(exception), exception, tb=exc_tb, cause=cause)
File "/usr/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 276, in reraise
raise value.with_traceback(tb)
File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1236, in _execute_context
cursor, statement, parameters, context
File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/default.py", line 536, in do_execute
cursor.execute(statement, parameters)
File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 255, in execute
self.errorhandler(self, exc, value)
File "/usr/lib64/python3.6/site-packages/MySQLdb/connections.py", line 50, in defaulterrorhandler
raise errorvalue
File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 252, in execute
res = self._query(query)
File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 378, in _query
db.query(q)
File "/usr/lib64/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(2019, 4, 17, 14, 1, 18, 249580, tzinfo=<Timezone [UTC]>), 'subdag_task_instance', 'subdag_dag.move_data', datetime.datetime(2019, 4, 17, 11, 35, 56, 625793, tzinfo=<Timezone [UTC]>))] (Background on this error at: http://sqlalche.me/e/e3q8)
[2019-04-17 14:01:33,437] {{__init__.py:1611}} INFO - Marking task as FAILED.
[2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data Traceback (most recent call last):
[2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1236, in _execute_context
[2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data cursor, statement, parameters, context
[2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/default.py", line 536, in do_execute
[2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data cursor.execute(statement, parameters)
[2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 255, in execute
[2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data self.errorhandler(self, exc, value)
[2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/connections.py", line 50, in defaulterrorhandler
[2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data raise errorvalue
[2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 252, in execute
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data res = self._query(query)
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 378, in _query
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data db.query(q)
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/connections.py", line 280, in query
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data _mysql.connection.query(self, query)
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data _mysql_exceptions.OperationalError: (1213, 'Deadlock found when trying to get lock; try restarting transaction')
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data The above exception was the direct cause of the following exception:
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data Traceback (most recent call last):
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/bin/airflow", line 32, in <module>
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data args.func(args)
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/utils/cli.py", line 74, in wrapper
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data return f(*args, **kwargs)
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/bin/cli.py", line 523, in run
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data _run(args, dag, ti)
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/bin/cli.py", line 442, in _run
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data pool=args.pool,
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/utils/db.py", line 73, in wrapper
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data return func(*args, **kwargs)
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/models/__init__.py", line 1441, in _run_raw_task
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data result = task_copy.execute(context=context)
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/operators/subdag_operator.py", line 102, in execute
[2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data executor=self.executor)
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/models/__init__.py", line 4030, in run
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data job.run()
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 209, in run
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data self._execute()
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/utils/db.py", line 73, in wrapper
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data return func(*args, **kwargs)
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 2475, in _execute
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data session=session)
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/utils/db.py", line 69, in wrapper
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data return func(*args, **kwargs)
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 2421, in _execute_for_run_dates
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data session=session)
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/utils/db.py", line 69, in wrapper
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data return func(*args, **kwargs)
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 2310, in _process_backfill_task_instances
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data _per_task_process(task, key, ti)
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/utils/db.py", line 73, in wrapper
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data return func(*args, **kwargs)
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 2273, in _per_task_process
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data session.commit()
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 1023, in commit
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data self.transaction.commit()
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 487, in commit
[2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data self._prepare_impl()
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 466, in _prepare_impl
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data self.session.flush()
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 2446, in flush
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data self._flush(objects)
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 2584, in _flush
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data transaction.rollback(_capture_exception=True)
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/util/langhelpers.py", line 67, in __exit__
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data compat.reraise(exc_type, exc_value, exc_tb)
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 277, in reraise
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data raise value
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 2544, in _flush
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data flush_context.execute()
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/unitofwork.py", line 416, in execute
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data rec.execute(self)
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/unitofwork.py", line 583, in execute
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data uow,
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/persistence.py", line 236, in save_obj
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data update,
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/persistence.py", line 976, in _emit_update_statements
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data statement, multiparams
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 980, in execute
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data return meth(self, multiparams, params)
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/sql/elements.py", line 273, in _execute_on_connection
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data return connection._execute_clauseelement(self, multiparams, params)
[2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1099, in _execute_clauseelement
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data distilled_params,
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1240, in _execute_context
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data e, statement, parameters, cursor, context
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1458, in _handle_dbapi_exception
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data util.raise_from_cause(sqlalchemy_exception, exc_info)
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 296, in raise_from_cause
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data reraise(type(exception), exception, tb=exc_tb, cause=cause)
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 276, in reraise
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data raise value.with_traceback(tb)
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1236, in _execute_context
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data cursor, statement, parameters, context
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/default.py", line 536, in do_execute
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data cursor.execute(statement, parameters)
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 255, in execute
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data self.errorhandler(self, exc, value)
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/connections.py", line 50, in defaulterrorhandler
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data raise errorvalue
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 252, in execute
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data res = self._query(query)
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 378, in _query
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data db.query(q)
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/connections.py", line 280, in query
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data _mysql.connection.query(self, query)
[2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data 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(2019, 4, 17, 14, 1, 18, 249580, tzinfo=<Timezone [UTC]>), 'subdag_task_instance', 'subdag_dag.move_data', datetime.datetime(2019, 4, 17, 11, 35, 56, 625793, tzinfo=<Timezone [UTC]>))] (Background on this error at: http://sqlalche.me/e/e3q8)
[2019-04-17 14:01:34,250] {{logging_mixin.py:95}} INFO - [2019-04-17 14:01:34,249] {{jobs.py:2562}} INFO - Task exited with return code 1
Permalink
jbonjean Julien Bonjean added a comment - 4 days ago
I can see the exact same issue in 1.10.3, but with BranchPythonOperator and DockerOperator.
Permalink Edit Delete
toopt4 t oo added a comment - 3 days ago
still getting this issue in 1.10.3!
was:
I am using subdag and sometimes main dag marked failed because of the following error. In this case, tasks in the subdag stopped.
{code:java}
hourly_dag = DAG(
hourly_dag_name,
default_args=dag_default_args,
params=dag_custom_params,
schedule_interval=config_values.hourly_job_interval,
max_active_runs=2)
hourly_subdag = SubDagOperator(
task_id='s3_to_hive',
subdag=LoadFromS3ToHive(
hourly_dag,
's3_to_hive'),
dag=hourly_dag)
{code}
I got this error in main dag. bug in scheduler?
{code:java}
[2018-05-22 21:52:19,683] {models.py:1595} ERROR - This Session's transaction has been rolled back due to a previous exception during flush. To begin a new transaction with this Session, first issue Session.rollback(). Original exception was: (_mysql_exceptions.OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') [SQL: '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: ('queued', 'transfer_from_tmp_table_into_cleaned_table', 'rfid_warehouse_carton_wh_g_dl_dwh_csv_uqjp_1h.s3_to_hive', datetime.datetime(2018, 5, 7, 5, 2))] (Background on this error at: http://sqlalche.me/e/e3q8)
Traceback (most recent call last):
sqlalchemy.exc.InvalidRequestError: This Session's transaction has been rolled back due to a previous exception during flush. To begin a new transaction with this Session, first issue Session.rollback(). Original exception was: (_mysql_exceptions.OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') [SQL: '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: ('queued', 'transfer_from_tmp_table_into_cleaned_table', 'rfid_warehouse_carton_wh_g_dl_dwh_csv_uqjp_1h.s3_to_hive', datetime.datetime(2018, 5, 7, 5, 2))] (Background on this error at: http://sqlalche.me/e/e3q8)
[2018-05-22 21:52:19,687] {models.py:1624} INFO - Marking task as FAILED.
[2018-05-22 21:52:19,688] {base_task_runner.py:98} INFO - Subtask: [2018-05-22 21:52:19,688] {slack_hook.py:143} INFO - Message is prepared:
[2018-05-22 21:52:19,688] {base_task_runner.py:98} INFO - Subtask: {"attachments": [{"color": "danger", "text": "", "fields": [{"title": "DAG", "value": "<https://data-platform-airflow-tokyo.data.fastretailing.com:8080/admin/airflow/tree?dag_id=rfid_warehouse_carton_wh_g_dl_dwh_csv_uqjp_1h|rfid_warehouse_carton_wh_g_dl_dwh_csv_uqjp_1h>", "short": true}, {"title": "Owner", "value": "airflow", "short": true}, {"title": "Task", "value": "s3_to_hive", "short": false}, {"title": "Status", "value": "FAILED", "short": false}, {"title": "Execution Time", "value": "2018-05-07T05:02:00", "short": true}, {"title": "Duration", "value": "826.305929", "short": true}, {"value": "<https://data-platform-airflow-tokyo.data.fastretailing.com:8080/admin/airflow/log?dag_id=rfid_warehouse_carton_wh_g_dl_dwh_csv_uqjp_1h&task_id=s3_to_hive&execution_date=2018-05-07T05:02:00|View Task Log>", "short": false}]}]}
[2018-05-22 21:52:19,688] {models.py:1638} ERROR - Failed at executing callback
[2018-05-22 21:52:19,688] {models.py:1639} ERROR - This Session's transaction has been rolled back due to a previous exception during flush. To begin a new transaction with this Session, first issue Session.rollback(). Original exception was: (_mysql_exceptions.OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') [SQL: '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: ('queued', 'transfer_from_tmp_table_into_cleaned_table', 'rfid_warehouse_carton_wh_g_dl_dwh_csv_uqjp_1h.s3_to_hive', datetime.datetime(2018, 5, 7, 5, 2))] (Background on this error at: http://sqlalche.me/e/e3q8)
{code}
> sql metastore/scheduler deadlock
> --------------------------------
>
> Key: AIRFLOW-4498
> URL: https://issues.apache.org/jira/browse/AIRFLOW-4498
> Project: Apache Airflow
> Issue Type: Bug
> Affects Versions: 1.9.0
> Reporter: t oo
> Assignee: Feng Lu
> Priority: Major
> Fix For: 1.10.3
>
>
> see late comments in AIRFLOW-2511, issue still occurring in 1.10.3 release
> 17/Apr/19 14:44
> We're still seeing deadlocking issues within 1.10.3 with this change applied, it appears that for this specific condition (subdagoperator) it has no effect:
> [2019-04-17 14:01:33,423] {{__init__.py:1580}} 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(2019, 4, 17, 14, 1, 18, 249580, tzinfo=<Timezone [UTC]>), 'subdag_task_instance', 'subdag_dag.move_data', datetime.datetime(2019, 4, 17, 11, 35, 56, 625793, tzinfo=<Timezone [UTC]>))] (Background on this error at: http://sqlalche.me/e/e3q8)
> Traceback (most recent call last):
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1236, in _execute_context
> cursor, statement, parameters, context
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/default.py", line 536, in do_execute
> cursor.execute(statement, parameters)
> File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 255, in execute
> self.errorhandler(self, exc, value)
> File "/usr/lib64/python3.6/site-packages/MySQLdb/connections.py", line 50, in defaulterrorhandler
> raise errorvalue
> File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 252, in execute
> res = self._query(query)
> File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 378, in _query
> db.query(q)
> File "/usr/lib64/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 "/usr/lib/python3.6/site-packages/airflow/models/__init__.py", line 1441, in _run_raw_task
> result = task_copy.execute(context=context)
> File "/usr/lib/python3.6/site-packages/airflow/operators/subdag_operator.py", line 102, in execute
> executor=self.executor)
> File "/usr/lib/python3.6/site-packages/airflow/models/__init__.py", line 4030, in run
> job.run()
> File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 209, in run
> self._execute()
> File "/usr/lib/python3.6/site-packages/airflow/utils/db.py", line 73, in wrapper
> return func(*args, **kwargs)
> File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 2475, in _execute
> session=session)
> File "/usr/lib/python3.6/site-packages/airflow/utils/db.py", line 69, in wrapper
> return func(*args, **kwargs)
> File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 2421, in _execute_for_run_dates
> session=session)
> File "/usr/lib/python3.6/site-packages/airflow/utils/db.py", line 69, in wrapper
> return func(*args, **kwargs)
> File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 2310, in _process_backfill_task_instances
> _per_task_process(task, key, ti)
> File "/usr/lib/python3.6/site-packages/airflow/utils/db.py", line 73, in wrapper
> return func(*args, **kwargs)
> File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 2273, in _per_task_process
> session.commit()
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 1023, in commit
> self.transaction.commit()
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 487, in commit
> self._prepare_impl()
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 466, in _prepare_impl
> self.session.flush()
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 2446, in flush
> self._flush(objects)
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 2584, in _flush
> transaction.rollback(_capture_exception=True)
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/util/langhelpers.py", line 67, in __exit__
> compat.reraise(exc_type, exc_value, exc_tb)
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 277, in reraise
> raise value
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 2544, in _flush
> flush_context.execute()
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/unitofwork.py", line 416, in execute
> rec.execute(self)
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/unitofwork.py", line 583, in execute
> uow,
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/persistence.py", line 236, in save_obj
> update,
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/persistence.py", line 976, in _emit_update_statements
> statement, multiparams
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 980, in execute
> return meth(self, multiparams, params)
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/sql/elements.py", line 273, in _execute_on_connection
> return connection._execute_clauseelement(self, multiparams, params)
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1099, in _execute_clauseelement
> distilled_params,
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1240, in _execute_context
> e, statement, parameters, cursor, context
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1458, in _handle_dbapi_exception
> util.raise_from_cause(sqlalchemy_exception, exc_info)
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 296, in raise_from_cause
> reraise(type(exception), exception, tb=exc_tb, cause=cause)
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 276, in reraise
> raise value.with_traceback(tb)
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1236, in _execute_context
> cursor, statement, parameters, context
> File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/default.py", line 536, in do_execute
> cursor.execute(statement, parameters)
> File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 255, in execute
> self.errorhandler(self, exc, value)
> File "/usr/lib64/python3.6/site-packages/MySQLdb/connections.py", line 50, in defaulterrorhandler
> raise errorvalue
> File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 252, in execute
> res = self._query(query)
> File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 378, in _query
> db.query(q)
> File "/usr/lib64/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(2019, 4, 17, 14, 1, 18, 249580, tzinfo=<Timezone [UTC]>), 'subdag_task_instance', 'subdag_dag.move_data', datetime.datetime(2019, 4, 17, 11, 35, 56, 625793, tzinfo=<Timezone [UTC]>))] (Background on this error at: http://sqlalche.me/e/e3q8)
> [2019-04-17 14:01:33,437] {{__init__.py:1611}} INFO - Marking task as FAILED.
> [2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data Traceback (most recent call last):
> [2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1236, in _execute_context
> [2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data cursor, statement, parameters, context
> [2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/default.py", line 536, in do_execute
> [2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data cursor.execute(statement, parameters)
> [2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 255, in execute
> [2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data self.errorhandler(self, exc, value)
> [2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/connections.py", line 50, in defaulterrorhandler
> [2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data raise errorvalue
> [2019-04-17 14:01:33,733] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 252, in execute
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data res = self._query(query)
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 378, in _query
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data db.query(q)
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/connections.py", line 280, in query
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data _mysql.connection.query(self, query)
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data _mysql_exceptions.OperationalError: (1213, 'Deadlock found when trying to get lock; try restarting transaction')
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data The above exception was the direct cause of the following exception:
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data Traceback (most recent call last):
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/bin/airflow", line 32, in <module>
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data args.func(args)
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/utils/cli.py", line 74, in wrapper
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data return f(*args, **kwargs)
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/bin/cli.py", line 523, in run
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data _run(args, dag, ti)
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/bin/cli.py", line 442, in _run
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data pool=args.pool,
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/utils/db.py", line 73, in wrapper
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data return func(*args, **kwargs)
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/models/__init__.py", line 1441, in _run_raw_task
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data result = task_copy.execute(context=context)
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/operators/subdag_operator.py", line 102, in execute
> [2019-04-17 14:01:33,734] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data executor=self.executor)
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/models/__init__.py", line 4030, in run
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data job.run()
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 209, in run
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data self._execute()
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/utils/db.py", line 73, in wrapper
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data return func(*args, **kwargs)
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 2475, in _execute
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data session=session)
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/utils/db.py", line 69, in wrapper
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data return func(*args, **kwargs)
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 2421, in _execute_for_run_dates
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data session=session)
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/utils/db.py", line 69, in wrapper
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data return func(*args, **kwargs)
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 2310, in _process_backfill_task_instances
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data _per_task_process(task, key, ti)
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/utils/db.py", line 73, in wrapper
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data return func(*args, **kwargs)
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib/python3.6/site-packages/airflow/jobs.py", line 2273, in _per_task_process
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data session.commit()
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 1023, in commit
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data self.transaction.commit()
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 487, in commit
> [2019-04-17 14:01:33,735] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data self._prepare_impl()
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 466, in _prepare_impl
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data self.session.flush()
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 2446, in flush
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data self._flush(objects)
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 2584, in _flush
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data transaction.rollback(_capture_exception=True)
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/util/langhelpers.py", line 67, in __exit__
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data compat.reraise(exc_type, exc_value, exc_tb)
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 277, in reraise
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data raise value
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 2544, in _flush
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data flush_context.execute()
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/unitofwork.py", line 416, in execute
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data rec.execute(self)
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/unitofwork.py", line 583, in execute
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data uow,
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/persistence.py", line 236, in save_obj
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data update,
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/persistence.py", line 976, in _emit_update_statements
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data statement, multiparams
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 980, in execute
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data return meth(self, multiparams, params)
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/sql/elements.py", line 273, in _execute_on_connection
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data return connection._execute_clauseelement(self, multiparams, params)
> [2019-04-17 14:01:33,736] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1099, in _execute_clauseelement
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data distilled_params,
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1240, in _execute_context
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data e, statement, parameters, cursor, context
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1458, in _handle_dbapi_exception
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data util.raise_from_cause(sqlalchemy_exception, exc_info)
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 296, in raise_from_cause
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data reraise(type(exception), exception, tb=exc_tb, cause=cause)
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 276, in reraise
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data raise value.with_traceback(tb)
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1236, in _execute_context
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data cursor, statement, parameters, context
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/default.py", line 536, in do_execute
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data cursor.execute(statement, parameters)
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 255, in execute
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data self.errorhandler(self, exc, value)
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/connections.py", line 50, in defaulterrorhandler
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data raise errorvalue
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 252, in execute
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data res = self._query(query)
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/cursors.py", line 378, in _query
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data db.query(q)
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data File "/usr/lib64/python3.6/site-packages/MySQLdb/connections.py", line 280, in query
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data _mysql.connection.query(self, query)
> [2019-04-17 14:01:33,737] {{base_task_runner.py:101}} INFO - Job 942670: Subtask move_data 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(2019, 4, 17, 14, 1, 18, 249580, tzinfo=<Timezone [UTC]>), 'subdag_task_instance', 'subdag_dag.move_data', datetime.datetime(2019, 4, 17, 11, 35, 56, 625793, tzinfo=<Timezone [UTC]>))] (Background on this error at: http://sqlalche.me/e/e3q8)
> [2019-04-17 14:01:34,250] {{logging_mixin.py:95}} INFO - [2019-04-17 14:01:34,249] {{jobs.py:2562}} INFO - Task exited with return code 1
> Permalink
> jbonjean Julien Bonjean added a comment - 4 days ago
> I can see the exact same issue in 1.10.3, but with BranchPythonOperator and DockerOperator.
> Permalink Edit Delete
> toopt4 t oo added a comment - 3 days ago
> still getting this issue in 1.10.3!
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)