Airflow 1.10.7+ suppresses Operator logs

[kaxil]

First reported at https://issues.apache.org/jira/browse/AIRFLOW-6904 by Rahul Jain.

After upgrading from 1.10.2 to 1.10.9, we noticed that the Operator logs are no longer printed.

1.10.2:

1.10.9:

This worked fine with Airflow <=1.10.6 and was most likely caused by our change to using os.fork (#6627).

[jeffolsi]

also https://issues.apache.org/jira/browse/AIRFLOW-6236

[rahulj51]

Steps to reproduce:

1. Create a simple DAG with a PythonOperator.
2. In the Python function, print some logs. For ex.

for i in range(1,10):
        time.sleep(2)
        logging.info("running job..")

logging.info("job completed")

1. Run this with Airflow 1.10.6. Logs will be printed.

1. Run again with 1.10.9. Logs will not be printed.

[davido912]

Did you manage to find resolution to this?
@rahulj51 We ended up wiping up our remote Airflow instance and setting up a new one, this solved the problem (for now). I didn't manage to find the reason behind this, but if you check your scheduler, you will see that the logs are being fired into the scheduler, however, not into the log file itself.

[rahulj51]

Interesting. I actually tried this on a fresh docker container and it still didn't print the logs.

[ewjmulder]

We experienced a similar issue after upgrading from 1.10.3 to 1.10.9: no more task logging visible in the UI. In our case it was specifically for the KubernetesPodOperator, but not for the BashOperator for instance. We fixed it by adding a logger for the airflow.contrib package (in the main airflow logging configuration file, see snippet below), since the KubernetesPodOperator lives there. So if the operator you're missing logs from is also from the contrib package, you can try this fix to see if it re-appears. Probably it also works for other operators, as long as you specify the right package they are in as extra logger.

My guess is that the combination of forking instead of starting a whole new process + having no specific logger for the package triggered this particular issue.

Added log config snippet:

        'airflow.contrib': {
            'handlers': bucket_handler,
            'level': LOG_LEVEL,
            'propagate': True,
        }

[davido912]

@ewjmulder You added this to airflow_local_settings.py?

And, for airflow.contrib, did you import something on there? because I'm failing to find where and what you did to be honest. Would appreciate if you could be a bit more specific.

[ewjmulder]

@davido912 In the Airflow project the example config is in the airflow_local_settings.py file indeed. But you can customize this with the logging_config_class = ... setting in airflow.cfg (as we have done). Either way, it boils down to a dictionary variable called something like (DEFAULT_)LOGGING_CONFIG that contains (among others) the formatters, handlers and loggers properties. Inside that loggers property the various loggers are defined and that is where you should add one with as key the Airflow package name for which you are missing the logging (for instance airflow.contrib), see the example snippet in my comment above.

[davido912]

@ewjmulder seems to work, nice job!
we have 3 remote airflow instances and I basically wiped out one and installed without using any custom logging configs, that worked as well.

[ewjmulder]

Yes, I guess the issue is related to an upgrade from an older version where you also (try to) migrate the log config but somehow they are not fully compatible and this issue appears. If someone does a deep dive into the diffs on the logging config and code between 1.10.6 and 1.10.7 I'm sure some underlying reason will pop up. But I'm happy with the resolution that we have found :)

[jhtimmins]

Could you all share the different operators where you've seen this happen? Looks like it's an issue on KubernetesPodOperator?

I was unable to attempted to replicate with PythonOperator.

[ewjmulder]

Indeed for us it was a problem for the KubernetesPodOperator but not for the PythonOperator. Looking at the top post it also affects the DataprocOperator, which also lives in the contrib package. So it seems the direction to look in is loggers for certain packages and default behavior if no logger is configured for a package.

[rahulj51]

For us, it's happening across all operators. I have seen this with pythonoperator ( see above steps) and also with dataprocoperator and a few others. I have tried this with a fresh airflow installation in a container and it's still behaved the same way.

…

On Sat, May 16, 2020, 7:27 AM Erik Mulder ***@***.***> wrote: Indeed for us it was a problem for the KubernetesPodOperator but not for the PythonOperator. Looking at the top post it also affects the DataprocOperator, which also lives in the contrib package. So it seems the direction to look in is loggers for certain packages and default behavior if no logger is configured for a package. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#8484 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAC2PGZADWKJMMD5W7LXSWTRRYP4XANCNFSM4MNHCQDQ> .

[jblakeman]

Had a chance to skim through #6627 and I could be mistaken (have not found the time to grok through all of the moving parts yet) but it seems like using os._exit in the forked child process without first flushing stdio buffers could be a factor:

airflow/airflow/task/task_runner/standard_task_runner.py

Lines 80 to 84 in 8465d66

	try:
	args.func(args, dag=self.dag)
	os._exit(0) # pylint: disable=protected-access
	except Exception: # pylint: disable=broad-except
	os._exit(1) # pylint: disable=protected-access

From the python docs:

Exit the process with status n, without calling cleanup handlers, flushing stdio buffers, etc.

Perhaps what's in order is a flush() of stdout, stderr before calling os._exit?

[ashb]

Is anyone able to make a clean, stand-alone reproduction case that shows this please? (Ideally in the form of a docker image I can pull, or a git repo we can clone)

[kamikaze]

same here, the only way to get logs working - downgrading to 1.10.7, it started to happen since 1.10.9 for us, (we skipped 1.10.8)

[kamikaze]

Is anyone able to make a clean, stand-alone reproduction case that shows this please? (Ideally in the form of a docker image I can pull, or a git repo we can clone)

Here is the DAG you can launch and see by yourself.

import logging.config
import os
from datetime import datetime, timedelta
from time import sleep

from airflow import DAG
from airflow.operators.python_operator import PythonOperator

LOGGING_CONFIG = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'standard': {
            'format': '%(asctime)s [%(levelname)s] PID=%(process)d:TID=%(thread)d '
                      '%(name)s.%(funcName)s:%(lineno)d: %(message)s'
        },
    },
    'handlers': {
        'default': {
            'level': os.getenv('LOGGING_LEVEL', 'INFO'),
            'class': 'logging.StreamHandler',
            'stream': 'ext://sys.stdout',
            'formatter': 'standard'
        },
    },
    'loggers': {
        '': {
            'handlers': ['default'],
            'level': os.getenv('LOGGING_LEVEL', 'INFO'),
            'propagate': True
        }
    }
}
logging.config.dictConfig(LOGGING_CONFIG)
logger = logging.getLogger(__name__)

default_args = {
    'owner': 'airflow',
    'depends_on_past': False,
    'start_date': datetime(2018, 6, 10),
    'catchup': False,
    'email': ['[email protected]'],
    'email_on_failure': False,
    'email_on_retry': False,
    'retries': 3,
    'retry_delay': timedelta(seconds=5),
    'max_retry_delay': timedelta(seconds=60),
    'retry_exponential_backoff': False,
}

dag = DAG(dag_id='aaa_test_logging', catchup=False, default_args=default_args,
          schedule_interval=None, max_active_runs=1)


def aaa_test_logging(**kwargs):
    logger.info('aaa_test_logging START before sleep')
    sleep(5*60)
    logger.info('aaa_test_logging END after sleep')


def generate():
    PythonOperator(
        task_id=f'aaa_test_logging',
        python_callable=aaa_test_logging,
        provide_context=True,
        dag=dag,
    )


generate()

[mik-laj]

Here is workaround: #6627 (comment)

[kaxil]

The fix will be available in 1.10.11

[shanit-saha]

One of the way we could resolve the same problem in our Airflow v 1.10.10 instance is by using a shell script as an extry point to execute the python application. The sys exit is part of the shell script. Earlier we invoked the python application directly from the CMD entry point in docker-image. The logging issue was observed. Please note we also tried both sys.exit() and sys.stdout.flush() in our python modules. Still it did not help. So eventually shell script entry point with sys exit helped.