[
https://issues.apache.org/jira/browse/AIRFLOW-2516?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16605348#comment-16605348
]
readme_kylin commented on AIRFLOW-2516:
---------------------------------------
mysql version:5.7
sometimes,it happens.
[2018-09-06 13:13:44,592] \{base_task_runner.py:95} INFO - Subtask: Starting
attempt 1 of 1 [2018-09-06 13:13:44,592] \{base_task_runner.py:95} INFO -
Subtask:
--------------------------------------------------------------------------------
[2018-09-06 13:13:44,592] \{base_task_runner.py:95} INFO - Subtask:
[2018-09-06 13:13:44,612] \{base_task_runner.py:95} INFO - Subtask: Traceback
(most recent call last): [2018-09-06 13:13:44,612] \{base_task_runner.py:95}
INFO - Subtask: File "/usr/local/python2.7/bin/airflow", line 27, in <module>
[2018-09-06 13:13:44,612] \{base_task_runner.py:95} INFO - Subtask:
args.func(args) [2018-09-06 13:13:44,612] \{base_task_runner.py:95} INFO -
Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/airflow/bin/cli.py", line
422, in run [2018-09-06 13:13:44,613] \{base_task_runner.py:95} INFO - Subtask:
pool=args.pool, [2018-09-06 13:13:44,613] \{base_task_runner.py:95} INFO -
Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/airflow/utils/db.py", line
53, in wrapper [2018-09-06 13:13:44,613] \{base_task_runner.py:95} INFO -
Subtask: result = func(*args, **kwargs) [2018-09-06 13:13:44,613]
\{base_task_runner.py:95} INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/airflow/models.py", line
1328, in run [2018-09-06 13:13:44,613] \{base_task_runner.py:95} INFO -
Subtask: session.commit() [2018-09-06 13:13:44,613] \{base_task_runner.py:95}
INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/sqlalchemy/orm/session.py",
line 906, in commit [2018-09-06 13:13:44,619] \{base_task_runner.py:95} INFO -
Subtask: self.transaction.commit() [2018-09-06 13:13:44,619]
\{base_task_runner.py:95} INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/sqlalchemy/orm/session.py",
line 461, in commit [2018-09-06 13:13:44,620] \{base_task_runner.py:95} INFO -
Subtask: self._prepare_impl() [2018-09-06 13:13:44,620]
\{base_task_runner.py:95} INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/sqlalchemy/orm/session.py",
line 441, in _prepare_impl [2018-09-06 13:13:44,620] \{base_task_runner.py:95}
INFO - Subtask: self.session.flush() [2018-09-06 13:13:44,620]
\{base_task_runner.py:95} INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/sqlalchemy/orm/session.py",
line 2171, in flush [2018-09-06 13:13:44,620] \{base_task_runner.py:95} INFO -
Subtask: self._flush(objects) [2018-09-06 13:13:44,620]
\{base_task_runner.py:95} INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/sqlalchemy/orm/session.py",
line 2291, in _flush [2018-09-06 13:13:44,620] \{base_task_runner.py:95} INFO -
Subtask: transaction.rollback(_capture_exception=True) [2018-09-06
13:13:44,621] \{base_task_runner.py:95} INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/sqlalchemy/util/langhelpers.py",
line 66, in __exit__ [2018-09-06 13:13:44,621] \{base_task_runner.py:95} INFO
- Subtask: compat.reraise(exc_type, exc_value, exc_tb) [2018-09-06
13:13:44,621] \{base_task_runner.py:95} INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/sqlalchemy/orm/session.py",
line 2255, in _flush [2018-09-06 13:13:44,621] \{base_task_runner.py:95} INFO -
Subtask: flush_context.execute() [2018-09-06 13:13:44,621]
\{base_task_runner.py:95} INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py",
line 389, in execute [2018-09-06 13:13:44,621] \{base_task_runner.py:95} INFO
- Subtask: rec.execute(self) [2018-09-06 13:13:44,621]
\{base_task_runner.py:95} INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py",
line 548, in execute [2018-09-06 13:13:44,621] \{base_task_runner.py:95} INFO
- Subtask: uow [2018-09-06 13:13:44,622] \{base_task_runner.py:95} INFO -
Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py",
line 177, in save_obj [2018-09-06 13:13:44,622] \{base_task_runner.py:95} INFO
- Subtask: mapper, table, update) [2018-09-06 13:13:44,622]
\{base_task_runner.py:95} INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py",
line 737, in _emit_update_statements [2018-09-06 13:13:44,622]
\{base_task_runner.py:95} INFO - Subtask: execute(statement, multiparams)
[2018-09-06 13:13:44,622] \{base_task_runner.py:95} INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/sqlalchemy/engine/base.py",
line 945, in execute [2018-09-06 13:13:44,622] \{base_task_runner.py:95} INFO -
Subtask: return meth(self, multiparams, params) [2018-09-06 13:13:44,622]
\{base_task_runner.py:95} INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/sqlalchemy/sql/elements.py",
line 263, in _execute_on_connection [2018-09-06 13:13:44,622]
\{base_task_runner.py:95} INFO - Subtask: return
connection._execute_clauseelement(self, multiparams, params) [2018-09-06
13:13:44,622] \{base_task_runner.py:95} INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/sqlalchemy/engine/base.py",
line 1053, in _execute_clauseelement [2018-09-06 13:13:44,622]
\{base_task_runner.py:95} INFO - Subtask: compiled_sql, distilled_params
[2018-09-06 13:13:44,622] \{base_task_runner.py:95} INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/sqlalchemy/engine/base.py",
line 1189, in _execute_context [2018-09-06 13:13:44,623]
\{base_task_runner.py:95} INFO - Subtask: context) [2018-09-06 13:13:44,623]
\{base_task_runner.py:95} INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/sqlalchemy/engine/base.py",
line 1402, in _handle_dbapi_exception [2018-09-06 13:13:44,623]
\{base_task_runner.py:95} INFO - Subtask: exc_info [2018-09-06 13:13:44,623]
\{base_task_runner.py:95} INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/sqlalchemy/util/compat.py",
line 203, in raise_from_cause [2018-09-06 13:13:44,623]
\{base_task_runner.py:95} INFO - Subtask: reraise(type(exception), exception,
tb=exc_tb, cause=cause) [2018-09-06 13:13:44,623] \{base_task_runner.py:95}
INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/sqlalchemy/engine/base.py",
line 1182, in _execute_context [2018-09-06 13:13:44,623]
\{base_task_runner.py:95} INFO - Subtask: context) [2018-09-06 13:13:44,623]
\{base_task_runner.py:95} INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/sqlalchemy/engine/default.py",
line 470, in do_execute [2018-09-06 13:13:44,623] \{base_task_runner.py:95}
INFO - Subtask: cursor.execute(statement, parameters) [2018-09-06 13:13:44,623]
\{base_task_runner.py:95} INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/MySQLdb/cursors.py", line
205, in execute [2018-09-06 13:13:44,623] \{base_task_runner.py:95} INFO -
Subtask: self.errorhandler(self, exc, value) [2018-09-06 13:13:44,624]
\{base_task_runner.py:95} INFO - Subtask: File
"/usr/local/python2.7/lib/python2.7/site-packages/MySQLdb/connections.py", line
36, in defaulterrorhandler [2018-09-06 13:13:44,624] \{base_task_runner.py:95}
INFO - Subtask: raise errorclass, errorvalue [2018-09-06 13:13:44,624]
\{base_task_runner.py:95} INFO - Subtask: sqlalchemy.exc.OperationalError:
(_mysql_exceptions.OperationalError) (1213, 'Deadlock found when trying to get
lock; try restarting transaction') [SQL: u'UPDATE task_instance SET
start_date=%s, state=%s, try_number=%s, hostname=%s, job_id=%s, operator=%s,
pid=%s WHERE task_instance.task_id = %s AND task_instance.dag_id = %s AND
task_instance.execution_date = %s'] [parameters: (datetime.datetime(2018, 9, 6,
13, 13, 44, 583962), u'running', 1L, 'QZ50', '896972', 'BashOperator', 49055,
'realtimeGprpPlay', 'everyTenMinute', datetime.datetime(2018, 9, 6, 13, 2))]
[2018-09-06 13:13:48,014] \{jobs.py:2083} INFO - Task exited with return code 1
> Deadlock found when trying to update task_instance table
> --------------------------------------------------------
>
> Key: AIRFLOW-2516
> URL: https://issues.apache.org/jira/browse/AIRFLOW-2516
> Project: Apache Airflow
> Issue Type: Bug
> Components: DagRun
> Affects Versions: 1.8.0
> Reporter: Jeff Liu
> Priority: Major
>
>
>
> {code:java}
> [2018-05-23 17:59:57,218] {base_task_runner.py:98} INFO - Subtask:
> [2018-05-23 17:59:57,217] {base_executor.py:49} INFO - Adding to queue:
> airflow run production_wipeout_wipe_manager.Carat Carat_20180227
> 2018-05-23T17:41:18.815809 --local -sd DAGS_FOLDER/wipeout/wipeout.py
> [2018-05-23 17:59:57,231] {base_task_runner.py:98} INFO - Subtask: Traceback
> (most recent call last):
> [2018-05-23 17:59:57,232] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/bin/airflow", line 27, in <module>
> [2018-05-23 17:59:57,232] {base_task_runner.py:98} INFO - Subtask:
> args.func(args)
> [2018-05-23 17:59:57,232] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/lib/python2.7/site-packages/airflow/bin/cli.py", line 392, in run
> [2018-05-23 17:59:57,232] {base_task_runner.py:98} INFO - Subtask:
> pool=args.pool,
> [2018-05-23 17:59:57,233] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/lib/python2.7/site-packages/airflow/utils/db.py", line 50, in
> wrapper
> [2018-05-23 17:59:57,233] {base_task_runner.py:98} INFO - Subtask: result =
> func(*args, **kwargs)
> [2018-05-23 17:59:57,233] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/lib/python2.7/site-packages/airflow/models.py", line 1532, in
> _run_raw_task
> [2018-05-23 17:59:57,234] {base_task_runner.py:98} INFO - Subtask:
> self.handle_failure(e, test_mode, context)
> [2018-05-23 17:59:57,234] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/lib/python2.7/site-packages/airflow/models.py", line 1641, in
> handle_failure
> [2018-05-23 17:59:57,234] {base_task_runner.py:98} INFO - Subtask:
> session.merge(self)
> [2018-05-23 17:59:57,235] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line
> 1920, in merge
> [2018-05-23 17:59:57,235] {base_task_runner.py:98} INFO - Subtask:
> _resolve_conflict_map=_resolve_conflict_map)
> [2018-05-23 17:59:57,235] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line
> 1974, in _merge
> [2018-05-23 17:59:57,236] {base_task_runner.py:98} INFO - Subtask: merged =
> self.query(mapper.class_).get(key[1])
> [2018-05-23 17:59:57,236] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 882,
> in get
> [2018-05-23 17:59:57,236] {base_task_runner.py:98} INFO - Subtask: ident,
> loading.load_on_pk_identity)
> [2018-05-23 17:59:57,236] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 952,
> in _get_impl
> [2018-05-23 17:59:57,237] {base_task_runner.py:98} INFO - Subtask: return
> db_load_fn(self, primary_key_identity)
> [2018-05-23 17:59:57,237] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/loading.py", line 247,
> in load_on_pk_i
> dentity
> [2018-05-23 17:59:57,237] {base_task_runner.py:98} INFO - Subtask: return
> q.one()
> [2018-05-23 17:59:57,238] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2884,
> in one
> [2018-05-23 17:59:57,238] {base_task_runner.py:98} INFO - Subtask: ret =
> self.one_or_none()
> [2018-05-23 17:59:57,238] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2854,
> in one_or_none
> [2018-05-23 17:59:57,238] {base_task_runner.py:98} INFO - Subtask: ret =
> list(self)
> [2018-05-23 17:59:57,239] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2925,
> in __iter__
> [2018-05-23 17:59:57,239] {base_task_runner.py:98} INFO - Subtask: return
> self._execute_and_instances(context)
> [2018-05-23 17:59:57,239] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2946,
> in _execute_and_instances
> [2018-05-23 17:59:57,240] {base_task_runner.py:98} INFO - Subtask:
> close_with_result=True)
> [2018-05-23 17:59:57,240] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2955,
> in _get_bind_ar
> s
> [2018-05-23 17:59:57,240] {base_task_runner.py:98} INFO - Subtask: **kw
> [2018-05-23 17:59:57,240] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2937,
> in _connection_f
> rom_session
> [2018-05-23 17:59:57,241] {base_task_runner.py:98} INFO - Subtask: conn =
> self.session.connection(**kw)
> [2018-05-23 17:59:57,241] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line
> 1035, in connection
> [2018-05-23 17:59:57,241] {base_task_runner.py:98} INFO - Subtask:
> execution_options=execution_options)
> [2018-05-23 17:59:57,241] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line
> 1040, in _connection
> _for_bind
> [2018-05-23 17:59:57,242] {base_task_runner.py:98} INFO - Subtask: engine,
> execution_options)
> [2018-05-23 17:59:57,242] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 388,
> in _connection_
> for_bind
> [2018-05-23 17:59:57,242] {base_task_runner.py:98} INFO - Subtask:
> self._assert_active()
> [2018-05-23 17:59:57,243] {base_task_runner.py:98} INFO - Subtask: File
> "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 276,
> in _assert_acti
> ve
> [2018-05-23 17:59:57,243] {base_task_runner.py:98} INFO - Subtask: %
> self._rollback_exception
> [2018-05-23 17:59:57,244] {base_task_runner.py:98} INFO - Subtask:
> sqlalchemy.exc.InvalidRequestError: This Session's transaction has been
> rolled back due to a previou
> s exception during flush. To begin a new transaction with this Session, first
> issue Session.rollback(). Original exception was:
> (_mysql_exceptions.OperationalError) (1
> 213, 'Deadlock found when trying to get lock; try restarting transaction')
> [SQL: u'UPDATE task_instance SET state=%s WHERE task_instance.task_id = %s
> AND task_instance
> .dag_id = %s AND task_instance.execution_date = %s'] [parameters: (u'queued',
> 'Carat_20180227', 'production_wipeout_wipe_manager.Carat',
> datetime.datetime(2018, 5, 23,
> 17, 41, 18, 815809))] (Background on this error at:
> http://sqlalche.me/e/e3q8){code}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
