[
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)
