Gunicorn is not logging on start-up while using custom logging config-CodePudding

I am creating a Flask app to run on Gunicorn and needed the logs to be in JSON format and with a specific format. As such, I created a custom "logging config" file.

Gunicorn is correctly logging, in JSON, when a request is received, but I lost the default "start-up logging" that Gunicorn used to be doing before.

I am launching the application like this:

gunicorn -w 2 --log-config resources/gunicorn_logging.config 'wsgi:app'

Here are the "gunicorn_logging.config" contents:

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

[handlers]
keys=console

[formatters]
keys=json

[logger_root]
level=INFO
handlers=console

[logger_gunicorn.error]
level=ERROR
handlers=console
propagate=1
qualname=gunicorn.error

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

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

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

Here is the formatter code:

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

        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

This is what I get when a request comes to the application, which is great:

{"log_level": "INFO", "msg": null, "timestamp": "2022-10-10T22:32:40.663159Z", "request": "GET /_/health HTTP/1.1", "status_code": "200"}

And this is what I lost and would like to get back, but in json format:

[2022-10-10 23:42:47  0100] [95107] [INFO] Starting gunicorn 20.1.0
[2022-10-10 23:42:47  0100] [95107] [INFO] Listening at: http://127.0.0.1:8000 (95107)
[2022-10-10 23:42:47  0100] [95107] [INFO] Using worker: sync
[2022-10-10 23:42:47  0100] [95108] [INFO] Booting worker with pid: 95108
[2022-10-10 23:42:47  0100] [95109] [INFO] Booting worker with pid: 95109

I've tried adding prints inside the formatter "add_field" function to see if it was called on start-up, but it isn't so it doesn't look like I am losing the messages there somehow.

Any help is highly appreciated.

CodePudding user response：

I solved this issue, which was simply a matter of having the logger for gunicorn.error at INFO logging level as such:

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

Had no idea that the start-up logs end up in gunicorn.error, but here we are...

That being said, I now have a new problem, which is the fact that the logging doesn't dynamically replace the values for version, running port, etc. as it does by default without custom configuration.

I detail it here, in case you are having the same issue:

Gunicorn logging stopped replacing values