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/14 10:58:00 UTC
[jira] [Created] (AIRFLOW-4514) logging is unclear - 'Taking the
poison pill' and 'terminated with exit code -15' but overall success
t oo created AIRFLOW-4514:
-----------------------------
Summary: logging is unclear - 'Taking the poison pill' and 'terminated with exit code -15' but overall success
Key: AIRFLOW-4514
URL: https://issues.apache.org/jira/browse/AIRFLOW-4514
Project: Apache Airflow
Issue Type: Improvement
Components: logging
Affects Versions: 1.10.3
Reporter: t oo
Can this log message be more clear? Not sure what ''Taking the poison pill'' or 'State of this instance has been externally set' means or if the 'terminated with exit code' responses are a concern.
In the below 3 logs the first 2 tasks end up succeeding and the last task fails (all expected outcomes) but not sure why seeing 'terminated with exit code -15'. Potentially these logs are not relevant, maybe should be DEBUG only not INFO?
Mentioned in:
https://www.mail-archive.com/dev@airflow.apache.org/msg00173.html
https://stackoverflow.com/questions/55517232/warning-state-of-this-instance-has-been-externally-set-to-success-taking-the
cat t3u/COUNT_ttt_/2019-05-10T00:00:00+00:00/1.log
[2019-05-14 09:30:14,755] {__init__.py:1139} INFO - Dependencies all met for <TaskInstance: t3u.COUNT_ttt_ 2019-05-10T00:00:00+00:00 [scheduled]>
[2019-05-14 09:30:14,775] {__init__.py:1139} INFO - Dependencies all met for <TaskInstance: t3u.COUNT_ttt_ 2019-05-10T00:00:00+00:00 [scheduled]>
[2019-05-14 09:30:14,776] {__init__.py:1353} INFO -
--------------------------------------------------------------------------------
[2019-05-14 09:30:14,776] {__init__.py:1354} INFO - Starting attempt 1 of 1
[2019-05-14 09:30:14,776] {__init__.py:1355} INFO -
--------------------------------------------------------------------------------
[2019-05-14 09:30:14,810] {__init__.py:1374} INFO - Executing <Task(BranchPythonOperator): COUNT_ttt_> on 2019-05-10T00:00:00+00:00
[2019-05-14 09:30:14,810] {base_task_runner.py:119} INFO - Running: [u'airflow', u'run', 't3u', 'COUNT_ttt_', '2019-05-10T00:00:00+00:00', u'--job_id', '7818', u'--raw', u'-sd', u'DAGS_FOLDER/s_dag_generation.py', u'--cfg_path', '/tmp/tmpu6_Hda']
[2019-05-14 09:30:19,691] {base_task_runner.py:101} INFO - Job 7818: Subtask COUNT_ttt_ [2019-05-14 09:30:19,691] {settings.py:182} INFO - settings.configure_orm(): Using pool settings. pool_size=5, pool_recycle=1800, pid=13557
[2019-05-14 09:30:20,197] {base_task_runner.py:101} INFO - Job 7818: Subtask COUNT_ttt_ [2019-05-14 09:30:20,196] {__init__.py:51} INFO - Using executor LocalExecutor
[2019-05-14 09:30:20,699] {base_task_runner.py:101} INFO - Job 7818: Subtask COUNT_ttt_ [2019-05-14 09:30:20,698] {__init__.py:305} INFO - Filling up the DagBag from /home/user/airflow/dags/s_dag_generation.py
[2019-05-14 09:30:24,708] {base_task_runner.py:101} INFO - Job 7818: Subtask COUNT_ttt_ [2019-05-14 09:30:24,707] {cli.py:517} INFO - Running <TaskInstance: t3u.COUNT_ttt_ 2019-05-10T00:00:00+00:00 [running]> on host hosthereee
[2019-05-14 09:30:24,832] {python_operator.py:104} INFO - Exporting the following env vars:
AIRFLOW_CTX_TASK_ID=COUNT_ttt_
AIRFLOW_CTX_DAG_ID=t3u
AIRFLOW_CTX_EXECUTION_DATE=2019-05-10T00:00:00+00:00
AIRFLOW_CTX_DAG_RUN_ID=manual__2019-05-10T00:00:00+00:00
[2019-05-14 09:30:24,833] {logging_mixin.py:95} INFO - [2019-05-14 09:30:24,833] {s_dag_generation.py:18} INFO - Exec_date is: 20190510
[2019-05-14 09:30:24,833] {logging_mixin.py:95} INFO - [2019-05-14 09:30:24,833] {s_dag_generation.py:20} INFO - hourstr is:
[2019-05-14 09:30:24,833] {logging_mixin.py:95} INFO - [2019-05-14 09:30:24,833] {s_dag_generation.py:24} INFO - FILE_NAME_TO_LOAD is: fff2.csv.bz2
[2019-05-14 09:30:24,833] {logging_mixin.py:95} INFO - [2019-05-14 09:30:24,833] {s_dag_generation.py:27} INFO - Executing following command: aws s3 ls s3://myfi.csv.bz2
[2019-05-14 09:30:26,419] {logging_mixin.py:95} INFO - [2019-05-14 09:30:26,419] {s_dag_generation.py:30} INFO - 2019-05-14 09:24:41 237 fff2.csv.bz2
[2019-05-14 09:30:26,420] {logging_mixin.py:95} INFO - [2019-05-14 09:30:26,420] {s_dag_generation.py:43} INFO - Getting rowcount from s3: aws s3 cp s3://myfi.csv.bz2 - | bunzip2 -c | cat | wc -l
[2019-05-14 09:30:28,042] {logging_mixin.py:95} INFO - [2019-05-14 09:30:28,042] {s_dag_generation.py:46} INFO - 23
[2019-05-14 09:30:28,043] {logging_mixin.py:95} INFO - [2019-05-14 09:30:28,042] {s_dag_generation.py:52} INFO - Subtracting 1 rows from the count for header row(s)
[2019-05-14 09:30:28,043] {logging_mixin.py:95} INFO - [2019-05-14 09:30:28,043] {s_dag_generation.py:56} INFO - wc -l rowcount from s3 (s3://myfi.csv.bz2) =22.
[2019-05-14 09:30:28,043] {python_operator.py:113} INFO - Done. Returned value was: ttt__ee_INGEST
[2019-05-14 09:30:28,043] {python_operator.py:143} INFO - Following branch [u'ttt__ee_INGEST']
[2019-05-14 09:30:28,043] {python_operator.py:144} INFO - Marking other directly downstream tasks as skipped
[2019-05-14 09:30:28,076] {python_operator.py:163} INFO - Done.
[2019-05-14 09:30:28,433] {logging_mixin.py:95} INFO - [2019-05-14 09:30:28,432] {jobs.py:2632} WARNING - State of this instance has been externally set to success. Taking the poison pill.
[2019-05-14 09:30:28,487] {helpers.py:281} INFO - Sending 15 to GPID 13557
[2019-05-14 09:30:28,487] {helpers.py:263} INFO - Process psutil.Process(pid=13557, status='terminated') (13557) terminated with exit code 0
[2019-05-14 09:30:28,488] {logging_mixin.py:95} INFO - [2019-05-14 09:30:28,487] {jobs.py:2564} INFO - Task exited with return code 0
cat t3g/COUNT_ttt2_/2019-05-12T00:00:00+00:00/1.log
[2019-05-14 09:33:11,039] {__init__.py:1139} INFO - Dependencies all met for <TaskInstance: t3g.COUNT_ttt2_ 2019-05-12T00:00:00+00:00 [scheduled]>
[2019-05-14 09:33:11,052] {__init__.py:1139} INFO - Dependencies all met for <TaskInstance: t3g.COUNT_ttt2_ 2019-05-12T00:00:00+00:00 [scheduled]>
[2019-05-14 09:33:11,052] {__init__.py:1353} INFO -
--------------------------------------------------------------------------------
[2019-05-14 09:33:11,052] {__init__.py:1354} INFO - Starting attempt 1 of 1
[2019-05-14 09:33:11,053] {__init__.py:1355} INFO -
--------------------------------------------------------------------------------
[2019-05-14 09:33:11,111] {__init__.py:1374} INFO - Executing <Task(BranchPythonOperator): COUNT_ttt2_> on 2019-05-12T00:00:00+00:00
[2019-05-14 09:33:11,111] {base_task_runner.py:119} INFO - Running: [u'airflow', u'run', 't3g', 'COUNT_ttt2_', '2019-05-12T00:00:00+00:00', u'--job_id', '7983', u'--raw', u'-sd', u'DAGS_FOLDER/s_dag_generation.py', u'--cfg_path', '/tmp/tmpujYbKF']
[2019-05-14 09:33:17,926] {base_task_runner.py:101} INFO - Job 7983: Subtask COUNT_ttt2_ [2019-05-14 09:33:17,925] {settings.py:182} INFO - settings.configure_orm(): Using pool settings. pool_size=5, pool_recycle=1800, pid=27356
[2019-05-14 09:33:18,574] {base_task_runner.py:101} INFO - Job 7983: Subtask COUNT_ttt2_ [2019-05-14 09:33:18,573] {__init__.py:51} INFO - Using executor LocalExecutor
[2019-05-14 09:33:18,996] {base_task_runner.py:101} INFO - Job 7983: Subtask COUNT_ttt2_ [2019-05-14 09:33:18,995] {__init__.py:305} INFO - Filling up the DagBag from /home/user/airflow/dags/s_dag_generation.py
[2019-05-14 09:33:24,229] {base_task_runner.py:101} INFO - Job 7983: Subtask COUNT_ttt2_ [2019-05-14 09:33:24,228] {cli.py:517} INFO - Running <TaskInstance: t3g.COUNT_ttt2_ 2019-05-12T00:00:00+00:00 [running]> on host hosthereee
[2019-05-14 09:33:24,331] {python_operator.py:104} INFO - Exporting the following env vars:
AIRFLOW_CTX_TASK_ID=COUNT_ttt2_
AIRFLOW_CTX_DAG_ID=t3g
AIRFLOW_CTX_EXECUTION_DATE=2019-05-12T00:00:00+00:00
AIRFLOW_CTX_DAG_RUN_ID=manual__2019-05-12T00:00:00+00:00
[2019-05-14 09:33:24,332] {logging_mixin.py:95} INFO - [2019-05-14 09:33:24,332] {s_dag_generation.py:18} INFO - Exec_date is: 20190512
[2019-05-14 09:33:24,332] {logging_mixin.py:95} INFO - [2019-05-14 09:33:24,332] {s_dag_generation.py:20} INFO - hourstr is:
[2019-05-14 09:33:24,332] {logging_mixin.py:95} INFO - [2019-05-14 09:33:24,332] {s_dag_generation.py:24} INFO - FILE_NAME_TO_LOAD is: fff.csv.bz2
[2019-05-14 09:33:24,332] {logging_mixin.py:95} INFO - [2019-05-14 09:33:24,332] {s_dag_generation.py:27} INFO - Executing following command: aws s3 ls s3://myfi.csv.bz2
[2019-05-14 09:33:25,907] {logging_mixin.py:95} INFO - [2019-05-14 09:33:25,907] {s_dag_generation.py:30} INFO - 2019-05-14 09:24:23 214 fff.csv.bz2
[2019-05-14 09:33:25,907] {logging_mixin.py:95} INFO - [2019-05-14 09:33:25,907] {s_dag_generation.py:43} INFO - Getting rowcount from s3: aws s3 cp s3://myfi.csv.bz2 - | bunzip2 -c | cat | wc -l
[2019-05-14 09:33:27,885] {logging_mixin.py:95} INFO - [2019-05-14 09:33:27,884] {s_dag_generation.py:46} INFO - 25
[2019-05-14 09:33:27,885] {logging_mixin.py:95} INFO - [2019-05-14 09:33:27,885] {s_dag_generation.py:52} INFO - Subtracting 1 rows from the count for header row(s)
[2019-05-14 09:33:27,885] {logging_mixin.py:95} INFO - [2019-05-14 09:33:27,885] {s_dag_generation.py:56} INFO - wc -l rowcount from s3 (s3://myfi.csv.bz2) =24.
[2019-05-14 09:33:27,885] {python_operator.py:113} INFO - Done. Returned value was: ttt2__hh_INGEST
[2019-05-14 09:33:27,885] {python_operator.py:143} INFO - Following branch [u'ttt2__hh_INGEST']
[2019-05-14 09:33:27,885] {python_operator.py:144} INFO - Marking other directly downstream tasks as skipped
[2019-05-14 09:33:27,918] {python_operator.py:163} INFO - Done.
[2019-05-14 09:33:28,271] {logging_mixin.py:95} INFO - [2019-05-14 09:33:28,271] {jobs.py:2632} WARNING - State of this instance has been externally set to success. Taking the poison pill.
[2019-05-14 09:33:28,365] {helpers.py:281} INFO - Sending 15 to GPID 27356
[2019-05-14 09:33:28,390] {helpers.py:263} INFO - Process psutil.Process(pid=27356, status='terminated') (27356) terminated with exit code -15
[2019-05-14 09:33:28,392] {logging_mixin.py:95} INFO - [2019-05-14 09:33:28,391] {jobs.py:2564} INFO - Task exited with return code 0
cat nn/COUNT_tt_/2019-05-13T06:00:00+00:00/1.log
ValueError: invalid literal for int() with base 10: 'bunzip2: Compressed file ends unexpectedly;\n\tperhaps it is corrupted? *Possible* reason follows.\nbunzip2: Inappropriate ioctl for device\n\tInput file = (stdin), output file = (stdout)\n\nIt is possible '
[2019-05-14 09:30:01,199] {__init__.py:1611} INFO - Marking task as FAILED.
[2019-05-14 09:30:01,246] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ Traceback (most recent call last):
[2019-05-14 09:30:01,247] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ File "/home/user/venv/bin/airflow", line 32, in <module>
[2019-05-14 09:30:01,247] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ args.func(args)
[2019-05-14 09:30:01,247] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ File "/home/user/venv/local/lib/python2.7/site-packages/airflow/utils/cli.py", line 74, in wrapper
[2019-05-14 09:30:01,248] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ return f(*args, **kwargs)
[2019-05-14 09:30:01,248] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ File "/home/user/venv/local/lib/python2.7/site-packages/airflow/bin/cli.py", line 523, in run
[2019-05-14 09:30:01,255] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ _run(args, dag, ti)
[2019-05-14 09:30:01,255] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ File "/home/user/venv/local/lib/python2.7/site-packages/airflow/bin/cli.py", line 442, in _run
[2019-05-14 09:30:01,255] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ pool=args.pool,
[2019-05-14 09:30:01,255] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ File "/home/user/venv/local/lib/python2.7/site-packages/airflow/utils/db.py", line 73, in wrapper
[2019-05-14 09:30:01,256] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ return func(*args, **kwargs)
[2019-05-14 09:30:01,257] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ File "/home/user/venv/local/lib/python2.7/site-packages/airflow/models/__init__.py", line 1441, in _run_raw_task
[2019-05-14 09:30:01,257] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ result = task_copy.execute(context=context)
[2019-05-14 09:30:01,257] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ File "/home/user/venv/local/lib/python2.7/site-packages/airflow/operators/python_operator.py", line 140, in execute
[2019-05-14 09:30:01,257] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ branch = super(BranchPythonOperator, self).execute(context)
[2019-05-14 09:30:01,258] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ File "/home/user/venv/local/lib/python2.7/site-packages/airflow/operators/python_operator.py", line 112, in execute
[2019-05-14 09:30:01,258] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ return_value = self.execute_callable()
[2019-05-14 09:30:01,258] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ File "/home/user/venv/local/lib/python2.7/site-packages/airflow/operators/python_operator.py", line 117, in execute_callable
[2019-05-14 09:30:01,258] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ return self.python_callable(*self.op_args, **self.op_kwargs)
[2019-05-14 09:30:01,258] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ File "/home/user/airflow/dags/st_dag_generation.py", line 48, in count_source_file
[2019-05-14 09:30:01,258] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ if process.returncode != 0 or int(s3count.strip()) < 0:
[2019-05-14 09:30:01,259] {base_task_runner.py:101} INFO - Job 7783: Subtask COUNT_tt_ ValueError: invalid literal for int() with base 10: 'bunzip2: Compressed file ends unexpectedly;\n\tperhaps it is corrupted? *Possible* reason follows.\nbunzip2: Inappropriate ioctl for device\n\tInput file = (stdin), output file = (stdout)\n\nIt is possible '
[2019-05-14 09:30:01,615] {logging_mixin.py:95} INFO - [2019-05-14 09:30:01,614] {jobs.py:2632} WARNING - State of this instance has been externally set to failed. Taking the poison pill.
[2019-05-14 09:30:01,678] {helpers.py:281} INFO - Sending 15 to GPID 2727
[2019-05-14 09:30:01,704] {helpers.py:263} INFO - Process psutil.Process(pid=2727, status='terminated') (2727) terminated with exit code 1
[2019-05-14 09:30:01,706] {logging_mixin.py:95} INFO - [2019-05-14 09:30:01,705] {jobs.py:2564} INFO - Task exited with return code 0
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)