rgrizzell commented on issue #10024: URL: https://github.com/apache/airflow/issues/10024#issuecomment-678469071
A further deep dive into this issue, I believe this is the result of default behavior in the Python logging module. When utilizing the [PercentStyle Formatter](https://github.com/python/cpython/blob/3.8/Lib/logging/__init__.py#L413) (as the [JSONFormatter](https://github.com/apache/airflow/blob/master/airflow/utils/log/json_formatter.py#L29) does by default with `style='%'`), if `fmt` is `None` when the class is instantiated, the PercentStyle Formatter uses `"%(levelname)s:%(name)s:%(message)s"` as its default logging format. This is important because if `%(asctime)s` is not included in the logging format, [the function responsible for generating the `asctime` field is never called](https://github.com/python/cpython/blob/3.8/Lib/logging/__init__.py#L665). _But wait, if the `asctime` field doesn't exists why does it show up in the log messages as `null`?_ Well, in the case because `asctime` exists in the `json_fields` object, the `JSONFormatter.format()` merges the `json_fields` object with the LogRecord object and `asctime` is set to `None`. Workaround The following patch is a workaround for this issue that demonstrates the behavior of the standard logging library. ``` Index: airflow/utils/log/json_formatter.py IDEA additional info: Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP <+>UTF-8 =================================================================== --- airflow/utils/log/json_formatter.py (revision c35a01037ad4bb03d39a0319d37bc36b08ccf766) +++ airflow/utils/log/json_formatter.py (date 1598039818218) @@ -25,6 +25,7 @@ from airflow.utils.helpers import merge_dicts +JSON_FMT = "%(asctime)s:%(levelname)s:%(name)s:%(message)s" class JSONFormatter(logging.Formatter): """ @@ -32,6 +33,8 @@ """ # pylint: disable=too-many-arguments def __init__(self, fmt=None, datefmt=None, style='%', json_fields=None, extras=None): + if fmt is None: + fmt = JSON_FMT super().__init__(fmt, datefmt, style) if extras is None: extras = {} ``` This patch generates the following log message: ``` {"asctime": "2020-08-21 18:42:33,625", "filename": "bash.py", "lineno": 162, "levelname": "INFO", "message": "Command exited with return code 0", "dag_id": "example_bash_operator", "task_id": "run_after_loop", "execution_date": "2020_08_20T00_00_00_000000", "try_number": "1"} ``` ---------------------------------------------------------------- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. For queries about this service, please contact Infrastructure at: [email protected]
