[ https://issues.apache.org/jira/browse/AIRFLOW-1873?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16281857#comment-16281857 ]
ASF subversion and git services commented on AIRFLOW-1873: ---------------------------------------------------------- Commit 9a552c4fe88d362f79d644ec04340b7b63af795f in incubator-airflow's branch refs/heads/v1-9-test from [~ashb] [ https://git-wip-us.apache.org/repos/asf?p=incubator-airflow.git;h=9a552c4 ] [AIRFLOW-1873] Set TI.try_number to right value depending TI state Rather than having try_number+1 in various places, try_number will now automatically contain the right value for when the TI will next be run, and handle the case where try_number is accessed when the task is currently running. This showed up as a bug where the logs from running operators would show up in the next log file (2.log for the first try) Closes #2832 from ashb/AIRFLOW-1873-task-operator- log-try-number (cherry picked from commit 4b4e504eeae81e48f3c9d796a61dd9e86000c663) Signed-off-by: Bolke de Bruin <bo...@xs4all.nl> > Task operator logs appear in wrong numbered log file > ---------------------------------------------------- > > Key: AIRFLOW-1873 > URL: https://issues.apache.org/jira/browse/AIRFLOW-1873 > Project: Apache Airflow > Issue Type: Bug > Affects Versions: 1.9.0 > Reporter: Ash Berlin-Taylor > Fix For: 1.9.0 > > > The logs for the running operators appear in the "next" task number. > For example, for the first try for a given task instance the "collecting dag" > etc appear in 1.log, but log messages from the operator itself appear in > 2.log. > 1.log: > {noformat} > [2017-11-30 23:14:44,189] {cli.py:374} INFO - Running on host 4f1698e8ae61 > [2017-11-30 23:14:44,254] {models.py:1173} INFO - Dependencies all met for > <TaskInstance: tests.test-logging 2017-11-20 00:00:00 [queued]> > [2017-11-30 23:14:44,265] {models.py:1173} INFO - Dependencies all met for > <TaskInstance: tests.test-logging 2017-11-20 00:00:00 [queued]> > [2017-11-30 23:14:44,266] {models.py:1383} INFO - > -------------------------------------------------------------------------------- > Starting attempt 1 of 1 > -------------------------------------------------------------------------------- > [2017-11-30 23:14:44,290] {models.py:1404} INFO - Executing > <Task(PythonOperator): test-logging> on 2017-11-20 00:00:00 > [2017-11-30 23:14:44,291] {base_task_runner.py:115} INFO - Running: ['bash', > '-c', 'airflow run tests test-logging 2017-11-20T00:00:00 --job_id 4 --raw > -sd /usr/local/airflow/dags/example/csv_to_parquet.py'] > [2017-11-30 23:14:50,054] {base_task_runner.py:98} INFO - Subtask: > [2017-11-30 23:14:50,052] {configuration.py:206} WARNING - section/key > [celery/celery_ssl_active] not found in config > [2017-11-30 23:14:50,056] {base_task_runner.py:98} INFO - Subtask: > [2017-11-30 23:14:50,052] {default_celery.py:41} WARNING - Celery Executor > will run without SSL > [2017-11-30 23:14:50,058] {base_task_runner.py:98} INFO - Subtask: > [2017-11-30 23:14:50,054] {__init__.py:45} INFO - Using executor > CeleryExecutor > [2017-11-30 23:14:50,529] {base_task_runner.py:98} INFO - Subtask: > [2017-11-30 23:14:50,529] {models.py:189} INFO - Filling up the DagBag from > /usr/local/airflow/dags/example/csv_to_parquet.py > [2017-11-30 23:14:50,830] {base_task_runner.py:98} INFO - Subtask: > [2017-11-30 23:14:50,825] {python_operator.py:90} INFO - Done. Returned value > was: None > {noformat} > 2.log: > {noformat} > [2017-11-30 23:14:50,749] {cli.py:374} INFO - Running on host 4f1698e8ae61 > [2017-11-30 23:14:50,820] {logging_mixin.py:84} INFO - Hi from > /usr/local/airflow/dags/example/csv_to_parquet.py > [2017-11-30 23:14:50,824] {csv_to_parquet.py:21} ERROR - Hello > {noformat} > Notice the timestamps - the contents of 2.log appear just before the last > line of 1.log, and should be in the same log file (there is only a single run > of this task instance) -- This message was sent by Atlassian JIRA (v6.4.14#64029)