unexpected log entry when logging configured with dictConfig

[maszczyn]

Depending on which mechanism is used to configure logging, the log entries are different. Following is a sample application that configures logging either using dictConfig or equivalent "manual" configuration (addHandler).

import logging
import json_logging
import datetime
import flask


config = {
    'version': 1,
    'disable_existing_loggers': True,
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'stream': 'ext://sys.stdout',
        },
    },
    'root': {
        'level': 'DEBUG',
        'handlers': ['console']
    },
}

USE_DICT_CONFIG=False
if USE_DICT_CONFIG:
    logging.config.dictConfig(config)
    logger = logging.getLogger('test-logger')
else:
    logger = logging.getLogger('test-logger')
    logger.setLevel(logging.DEBUG)
    logger.addHandler(logging.StreamHandler(sys.stdout))

app = flask.Flask(__name__)
json_logging.init_flask(enable_json=True)
json_logging.init_request_instrument(app)


@app.route('/')
def home():
    logger.info("test log statement")
    return "Hello world : " + str(datetime.datetime.now())


if __name__ == "__main__":
    app.run(host='0.0.0.0', port=int(5000), use_reloader=False)

Expected behavior

When configured "manually" (with USE_DICT_CONFIG=False) the output is as follows:

{"written_at": "2020-07-19T07:17:35.408Z", "written_ts": 1595143055408875000, "msg": "test log statement", "type": "log", "logger": "test-logger", "thread": "Thread-1", "level": "INFO", "module": "bug", "line_no": 39, "correlation_id": "eb573ed4-c98f-11ea-b8b9-d7d66ca74b30"}
{"written_at": "2020-07-19T07:17:35.409Z", "written_ts": 1595143055409613000, "type": "request", "correlation_id": "eb573ed4-c98f-11ea-b8b9-d7d66ca74b30", "remote_user": "-", "request": "/", "referer": "-", "x_forwarded_for": "-", "protocol": "HTTP/1.1", "method": "GET", "remote_ip": "127.0.0.1", "request_size_b": -1, "remote_host": "127.0.0.1", "remote_port": 36044, "request_received_at": "2020-07-19T07:17:35.408Z", "response_time_ms": 0, "response_status": 200, "response_size_b": 40, "response_content_type": "text/html; charset=utf-8", "response_sent_at": "2020-07-19T07:17:35.409Z"}

Actual behavior

When configured with dictConfig (USE_DICT_CONFIG=True) the output contains an additional entry:

{"written_at": "2020-07-19T07:18:03.828Z", "written_ts": 1595143083828308000, "msg": "test log statement", "type": "log", "logger": "test-logger", "thread": "Thread-1", "level": "INFO", "module": "bug", "line_no": 39, "correlation_id": "fc47b462-c98f-11ea-b8b9-d7d66ca74b30"}
{"written_at": "2020-07-19T07:18:03.829Z", "written_ts": 1595143083829026000, "type": "request", "correlation_id": "fc47b462-c98f-11ea-b8b9-d7d66ca74b30", "remote_user": "-", "request": "/", "referer": "-", "x_forwarded_for": "-", "protocol": "HTTP/1.1", "method": "GET", "remote_ip": "127.0.0.1", "request_size_b": -1, "remote_host": "127.0.0.1", "remote_port": 36046, "request_received_at": "2020-07-19T07:18:03.828Z", "response_time_ms": 0, "response_status": 200, "response_size_b": 40, "response_content_type": "text/html; charset=utf-8", "response_sent_at": "2020-07-19T07:18:03.828Z"}
{"written_at": "2020-07-19T07:18:03.829Z", "written_ts": 1595143083829292000, "msg": "", "type": "log", "logger": "flask-request-logger", "thread": "Thread-1", "level": "INFO", "module": "__init__", "line_no": 54, "correlation_id": "fc47b462-c98f-11ea-b8b9-d7d66ca74b30"}

I believe the last entry shouldn't be there at all, and I am wondering whether using dictConfig with json-logging causes any other, perhaps more serious, logging misconfiguration.

[bobbui]

will investigate this

[bobbui]

@maszczyn fix on 1.2.4

[maszczyn]

@thangbn seems ok, thanks!