Gunicorn logging stopped replacing values

Question

With the default logging config Gunicorn would replace values like the listening ip/port and the worker pid in the template log message. After adding a custom logging config to log in json, it no longer does that replacement.

I can't figure out what I am missing in the custom config to restore that behavior.

Here is what happens now:

{"log_level": "INFO", "msg": "Starting gunicorn %s", "timestamp": "2022-10-11T10:47:50.705102Z"}
{"log_level": "INFO", "msg": "Listening at: %s (%s)", "timestamp": "2022-10-11T10:47:50.705515Z"}
{"log_level": "INFO", "msg": "Using worker: %s", "timestamp": "2022-10-11T10:47:50.705545Z"}
{"log_level": "INFO", "msg": "Booting worker with pid: %s", "timestamp": "2022-10-11T10:47:50.712564Z"}

here is what I had before:

[2022-10-11 11:49:09 +0100] [71004] [INFO] Starting gunicorn 20.1.0
[2022-10-11 11:49:09 +0100] [71004] [INFO] Listening at: http://0.0.0.0:5002 (71004)
[2022-10-11 11:49:09 +0100] [71004] [INFO] Using worker: sync
[2022-10-11 11:49:09 +0100] [71005] [INFO] Booting worker with pid: 71005

Here is the logging config file:

[loggers]
keys=root, gunicorn.error, gunicorn.access

[handlers]
keys=console

[formatters]
keys=json

[logger_root]
level=INFO
handlers=console

[logger_gunicorn.error]
level=INFO
handlers=console
propagate=0
qualname=gunicorn.error

[logger_gunicorn.access]
level=INFO
handlers=console
propagate=0
qualname=gunicorn.access

[handler_console]
class=StreamHandler
formatter=json
args=(sys.stdout, )

[formatter_json]
class=src.logging_helpers.json_log_formatter.GunicornLogFormatter
format='%(log_level)s %(msg)s %(timestamp)s'

And here is the formatter mentioned in it:

class GunicornLogFormatter(JsonFormatter):
    def add_fields(self, log_record, record, message_dict):
        """
        This method allows us to inject gunicorn's args as fields for the formatter
        """
        super(GunicornLogFormatter, self).add_fields(log_record, record, message_dict)

        now = datetime.utcnow().strftime('%Y-%m-%dT%H:%M:%S.%fZ')
        log_record['timestamp'] = now

        if 'r' in record.args:
            log_record['request'] = record.args.get('r')
            log_record['msg'] = None
        if 's' in record.args:
            log_record['status_code'] = record.args.get('s')
        if 'level' in log_record:
            log_record['log_level'] = log_record['level'].upper()
        else:
            log_record['log_level'] = record.levelname

Any help is appreciated.

Answer 1

I found out that the message with replaced values was actually being provided but under the "message" key in the logging message. Under "msg", we got the message without values replaced, hence, this result I was getting.

As a workaround, I added a new formatter in the config, pointing to the same formatter class but with a different pattern, to have access to the "message" key.

Then, in the class code itself, I did the switch around between what was inside "msg" and "message".

This is the final result:

Config file:

[loggers]
keys=root, gunicorn.access, gunicorn.error

[handlers]
keys=console,server

[formatters]
keys=json, server

[logger_root]
level=INFO
handlers=console

[logger_gunicorn.access]
level=INFO
handlers=console
propagate=0
qualname=gunicorn.access

[logger_gunicorn.error]
level=INFO
handlers=server
propagate=0
qualname=gunicorn.error

[handler_console]
class=StreamHandler
formatter=json
args=(sys.stdout, )

[handler_server]
class=StreamHandler
formatter=server
args=(sys.stdout, )

[formatter_json]
class=src.logging.json_log_formatter.GunicornLogFormatter
format='%(log_level)s %(msg)s %(timestamp)s'

[formatter_server]
format='%(log_level)s %(message)s %(msg)s %(timestamp)s'
rename_fields=(message:msg)
class=src.logging.json_log_formatter.GunicornLogFormatter

Formatter class:

from datetime import datetime
from pythonjsonlogger.jsonlogger import JsonFormatter


class GunicornLogFormatter(JsonFormatter):
    def add_fields(self, log_record, record, message_dict):
        super(GunicornLogFormatter, self).add_fields(log_record, record, message_dict)

        now = datetime.utcnow().strftime('%Y-%m-%dT%H:%M:%S.%fZ')
        log_record['timestamp'] = now

        # this 'if-clause' is necessary for us to handle gunicorn's logging in our required format.
        if 'message' in log_record:
            log_record['msg'] = log_record['message']
            log_record.pop('message')

        # here we do some name normalization with what we want and gunicorn default logging provide us
        if 'r' in record.args:
            log_record['request'] = record.args.get('r')
            log_record['msg'] = None

        if 's' in record.args:
            log_record['status_code'] = record.args.get('s')

        if 'level' in log_record:
            log_record['log_level'] = log_record['level'].upper()
        else:
            log_record['log_level'] = record.levelname