puckel / docker-airflow

Docker Apache Airflow
Apache License 2.0
3.77k stars 542 forks source link

Python is not logging in the task logs #517

Open AxelFurlanF opened 4 years ago

AxelFurlanF commented 4 years ago

Context

I'm using Airflow Celery. I'm trying to move from BashOperator executing python script.py to the actual PythonOperator but I'm running into a logging error.

I have the following DAG to test this:

import logging

logger = logging.getLogger('dag')
logger.setLevel(logging.INFO)

import os
from airflow import DAG
from airflow.operators.python_operator import PythonOperator
from airflow.operators.latest_only_operator import LatestOnlyOperator
from datetime import datetime, timedelta

default_args = {
    'owner': 'axelfurlan',
    'depends_on_past': False,
    'start_date': datetime(2019, 9, 23),
    'email_on_failure': True,
    'email_on_retry': False,
    'retries': 1,
    'retry_delay': timedelta(minutes=5)
}

dag = DAG(
    'test', catchup=False, default_args=default_args, schedule_interval='@daily')

scriptdir = os.environ.get('HOME', '/usr/local/airflow')

latest_only = LatestOnlyOperator(task_id='latest_only', dag=dag)

test_log = PythonOperator(
    task_id='test_log',
    python_callable=lambda: logger.info("this works"),
    dag=dag
)

latest_only >> test_log

Missing INFO log

The task test_log logs appear to be:

[2020-03-11 18:43:08,045] {{standard_task_runner.py:52}} INFO - Started process 234 to run task
[2020-03-11 18:43:08,166] {{python_operator.py:105}} INFO - Exporting the following env vars:
AIRFLOW_CTX_DAG_EMAIL=
AIRFLOW_CTX_DAG_OWNER=axelfurlan
AIRFLOW_CTX_DAG_ID= test
AIRFLOW_CTX_TASK_ID= test
AIRFLOW_CTX_EXECUTION_DATE=2020-03-11T18:42:51.521606+00:00
AIRFLOW_CTX_DAG_RUN_ID=manual__2020-03-11T18:42:51.521606+00:00
[2020-03-11 18:43:08,166] {{python_operator.py:114}} INFO - Done. Returned value was: None

But in the docker logs worker I can see my statement as follows:

Running %s on host %s <TaskInstance: test. test_log 2020-03-11T15:23:42.080673+00:00 [queued]> 168afb73b515
INFO this works
INFO Task exited with return code 0

My airflow.cfg has:

# Logging level
logging_level = INFO
fab_logging_level = WARN

This is happening with other DAGs as well. I'd appreciate some insight

AxelFurlanF commented 4 years ago

This works using local executor with the Puckel's docker-compose.yml

BrainMonkey commented 4 years ago

Did you ever get this figured out, as far as I knew the PythonOperator did log out like the BashOperator does.

AxelFurlanF commented 4 years ago

Did you ever get this figured out, as far as I knew the PythonOperator did log out like the BashOperator does.

@BrainMonkey nope, never came up with a solution. I'm still using the bash operator sadly