[jira] [Created] (AIRFLOW-1873) Task operator logs appear in wrong numbered log file

["Ash Berlin-Taylor (JIRA)" <ji...@apache.org>]

Ash Berlin-Taylor created AIRFLOW-1873:
------------------------------------------

             Summary: 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


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)