How to override Gunicorn's logging config to use a custom formatter

Question

I would like gunicorn.error to use the following key-value based log format instead of the default defined in gunicorn/glogging.py:

'format': 'timestamp=%(asctime)s pid=%(process)d loglevel=%(levelname)s msg=%(message)s'`

In my gunicorn config file:

import logging.config

workers = 2
bind = "127.0.0.1:8000"
loglevel = 'INFO'

LOGGING = {
    'version': 1,
    'disable_existing_loggers': True,
    'formatters': {
        'key_value': {
            'format': 'timestamp=%(asctime)s pid=%(process)d loglevel=%(levelname)s msg=%(message)s'
        },
    },
    'handlers': {
        'console': {
            'level': 'INFO',
            'class': 'logging.StreamHandler',
            'formatter': 'key_value',
            'stream': 'ext://sys.stdout'
        }
    },
    'loggers': {
        'gunicorn.error': {
            'handlers': ['console'],
            'level': 'INFO',
            'propagate': False,
        },
        'flask.app': {
            'handlers': ['console'],
            'level': 'INFO',
            'propagate': False,
        }
    },
}

logging.config.dictConfig(LOGGING)

Gunicorn logs twice, in my custom format and in the default format:

timestamp=2016-12-11 15:20:49,559 pid=22110 loglevel=INFO msg=Starting gunicorn 19.6.0
[2016-12-11 15:20:49 +0000] [22110] [INFO] Starting gunicorn 19.6.0
timestamp=2016-12-11 15:20:49,559 pid=22110 loglevel=INFO msg=Listening at: http://127.0.0.1:8000 (22110)
[2016-12-11 15:20:49 +0000] [22110] [INFO] Listening at: http://127.0.0.1:8000 (22110)
timestamp=2016-12-11 15:20:49,559 pid=22110 loglevel=INFO msg=Using worker: sync
[2016-12-11 15:20:49 +0000] [22110] [INFO] Using worker: sync
timestamp=2016-12-11 15:20:49,560 pid=22115 loglevel=INFO msg=Booting worker with pid: 22115
[2016-12-11 15:20:49 +0000] [22115] [INFO] Booting worker with pid: 22115
timestamp=2016-12-11 15:20:49,595 pid=22115 loglevel=INFO msg=Starting Flask application
timestamp=2016-12-11 15:20:49,659 pid=22120 loglevel=INFO msg=Booting worker with pid: 22120
[2016-12-11 15:20:49 +0000] [22120] [INFO] Booting worker with pid: 22120
timestamp=2016-12-11 15:20:49,693 pid=22120 loglevel=INFO msg=Starting Flask application

I used the logging_tree library to take a look at the configured loggers and I'm seeing 2 gunicorn loggers emitting to the console:

<--""
   Level WARNING
   |
   o<--"flask"
   |   Level NOTSET so inherits level WARNING
   |   |
   |   o   "flask.app"
   |       Level INFO
   |       Propagate OFF
   |       Handler Stream <open file '<stdout>', mode 'w' at 0x7f86676b1150>
   |         Level INFO
   |         Formatter fmt='timestamp=%(asctime)s pid=%(process)d loglevel=%(levelname)s msg=%(message)s' datefmt=None
   |
   o<--"gunicorn"
       Level NOTSET so inherits level WARNING
       |
       o   "gunicorn.access"
       |   Level INFO
       |   Propagate OFF
       |
       o   "gunicorn.error"
       |   Level INFO
       |   Propagate OFF
       |   Handler Stream <open file '<stdout>', mode 'w' at 0x7f86676b1150>
       |     Level INFO
       |     Formatter fmt='timestamp=%(asctime)s pid=%(process)d loglevel=%(levelname)s msg=%(message)s' datefmt=None
       |   Handler Stream <open file '<stderr>', mode 'w' at 0x7f86676b11e0>
       |     Formatter fmt='%(asctime)s [%(process)d] [%(levelname)s] %(message)s' datefmt='[%Y-%m-%d %H:%M:%S %z]'
       |
       o<--"gunicorn.http"
           Level NOTSET so inherits level WARNING
           |
           o<--"gunicorn.http.wsgi"
               Level NOTSET so inherits level WARNING

Gunicorn's docs say it's possible to specify the logger class to use, but I don't know how to do this.

Barmecide

Answer 1

I have had very good luck by specifying my own custom logging class. You can do this by making a class that inherits from Gunicorn's gunicorn.glogging.Logger class, and then override the setup(self, cfg) method of this class.

For example:

import logging
from gunicorn import glogging


class CustomLogger(glogging.Logger):
    """Custom logger for Gunicorn log messages."""

    def setup(self, cfg):
        """Configure Gunicorn application logging configuration."""
        super().setup(cfg)

        # Override Gunicorn's `error_log` configuration.
        self._set_handler(
            self.error_log, cfg.errorlog, logging.Formatter(
                fmt=('timestamp=%(asctime)s pid=%(process)d '
                     'loglevel=%(levelname)s msg=%(message)s')))

Now, depending upon how you launch Gunicorn, you can either provide the full path to this class; IE: program.app.CustomLogger via the --logger-class option, or you can directly pass it in via your own customer Gunicorn application class like so:

from gunicorn.app import base
from program.app import app, CustomLogger


class WebServer(base.BaseApplication):
    """Gunicorn WSGI Web Server."""

    def __init__(self, app, options):
        """Initialize server object."""
        self.options = options or {}
        self.application = app
        super().__init__()

    def load():
        """Return WSGI application."""
        return self.application

    def load_config():
        """Load configuration into Gunicorn."""
        self.cfg.set('logger_class', CustomLogger)


if __name__ == '__main__':
    WebServer(app, {}).run()

This should accomplish your desired goal without any yucky INI files being required and it is a completely supported configuration style.

Passmore

Answer 2

The problem with gunicorn's logging is that it normally runs in the same Python process before your code, configures logging on its own and logs some messages before any of your WSGI-related code runs and you have a chance to configure logging your way. Fortunately, as already mentioned its "logger" (gunicorn.glogging.Logger by default) is configurable.

$ gunicorn --help | grep logger
  --logger-class STRING
                        The logger you want to use to log events in Gunicorn.

Note that incremental configuration (i.e. dictConfig called once by gunicorn then by you) is not recommended and likely not what you want:

[...] there is not a compelling case for arbitrarily altering the object graph of loggers, handlers, filters, formatters at run-time, once a configuration is set up; the verbosity of loggers and handlers can be controlled just by setting levels (and, in the case of loggers, propagation flags). Changing the object graph arbitrarily in a safe way is problematic in a multi-threaded environment; while not impossible, the benefits are not worth the complexity it adds to the implementation.

Hence, my suggests it to treat gunicorn as a regular library with regards to logging and completely disable its logging configuration (in favour of you application's).

This is a trivial application which has HTTP and console entry points that should have the same logging configuration for both:

logging_cfg = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'KeyValueFormatter': {
            'format': (
                'timestamp=%(asctime)s pid=%(process)d '
                'loglevel=%(levelname)s msg=%(message)s'
            )
        },
    },
    'handlers': {
        'console': {
            'level': 'INFO',
            'class': 'logging.StreamHandler',
            'formatter': 'KeyValueFormatter',
        }
    },
    'loggers': {
        'gunicorn.access': {
            'propagate': True,
        },
        'gunicorn.error': {
            'propagate': True,
        },
    },
    'root': {
        'level': 'INFO',
        'handlers': ['console'],
    }
}

And here its implementation, app.py.

import logging.config

from gunicorn import glogging


logger = logging.getLogger(__name__)

def get_result():
    logger.info('Calculating result')
    return b'Hello world!'

def wsgi_app(environ, start_response):
    result = get_result()
    start_response('200 OK', [('Content-Type', 'text/html')])
    return [result]

def configure_logging():
    logging.config.dictConfig(logging_cfg)

class UniformLogger(glogging.Logger):

    def setup(self, cfg):
        configure_logging()


if __name__ == '__main__':
    configure_logging()
    print(get_result())

If you run python app.py you should get:

timestamp=2021-07-25 12:09:04,488 pid=4599 loglevel=INFO msg=Calculating result
b'Hello world!'

And if you run gunicorn --logger-class=app.UniformLogger app:wsgi_app followed by curl localhost:8000:

timestamp=2021-07-25 12:16:56,892 pid=4874 loglevel=INFO msg=Starting gunicorn 20.1.0
timestamp=2021-07-25 12:16:56,892 pid=4874 loglevel=INFO msg=Listening at: http://127.0.0.1:8000 (4874)
timestamp=2021-07-25 12:16:56,893 pid=4874 loglevel=INFO msg=Using worker: sync
timestamp=2021-07-25 12:16:56,894 pid=4876 loglevel=INFO msg=Booting worker with pid: 4876
timestamp=2021-07-25 12:17:06,926 pid=4876 loglevel=INFO msg=Calculating result

Forsaken

In case anyone is looking, I'd like to highlight something: this particular answer shows how to point gunicorn to your logging class if invoked from the terminal. Thank you. – Sidra

Indeed. This allows overriding gunicorn logger! Amazing answer. – Contralto

Answer 3

Gunicorn uses a custom logger called glogger glogger code which internally has a Logger class, you could change the format your messages with attributes that are already available to the logger.

The gunicorn_config file with custom format may look like this (the attributes are self explanatory)

from gunicorn import glogging    
glogging.Logger.error_fmt = '{"AppName": "%(name)s", "logLevel": "%(levelname)s", "Timestamp": "%(created)f", "Class_Name":"%(module)s", "Method_name": "%(funcName)s", "process_id":%(process)d, "message": "%(message)s"}'
glogging.Logger.datefmt = ""

glogging.Logger.access_fmt = '{"AppName": "%(name)s", "logLevel": "%(levelname)s", "Timestamp": "%(created)f","Class_Name":"%(module)s", "Method_name": "%(funcName)s", "process_id":%(process)d, "message": "%(message)s"}'
glogging.Logger.syslog_fmt = '{"AppName": "%(name)s", "logLevel": "%(levelname)s", "Timestamp": "%(created)f","Class_Name":"%(module)s", "Method_name": "%(funcName)s", "process_id":%(process)d, "message": "%(message)s"}'

I hope this helps, in my opinion it is one of the clean way of overriding the logger format.

but if you want add custom attributes in the logs you may have to create a new instance of the logger class as this logger class doesn't support filter. and assigning a logger instance wont help either.

Industrialize

Answer 4

I recently run into this myself, with gunicorn, as well as some other python packages that do not honor existing logging configuration when they are imported.

The following function resets all existing logging configuration and loads the new configuration from a dictionary. See logging.config.dictConfig for more information on the configuration dictionary schema.

Just call reset_logging_configuration() after you have imported all offending modules.

import logging
import logging.config

from my_logging_config import CONFIG  # see `logging.config.dictConfig`

def reset_logging_configuration():
    logging._acquireLock()
    for logger in logging.Logger.manager.loggerDict.values():
        if not isinstance(logger, logging.Logger):
            continue
        logger.handlers.clear()        # unset all logger handlers
        logger.filters.clear()         # unset all logger filters
        logger.level = logging.NOTSET  # unset logger level
        logger.propagate = True        # enable logger propagation
    logging._releaseLock()
    logging.config.dictConfig(CONFIG)  # load actual config

Beaware: this method messes with logging internals and is more of a work-around than an actual solution. However, many modules blindly overwrite existing logging configuration when they are imported, leaving you with no choice but to overwrite their configuration after they are loaded. Use with caution!

This code is based on a code-snippet found in logging/config.py.

Saith

Answer 5

I think you only need to give the configuration file (.ini or .conf) with your own configuration. Make sure you override the default.

There is a examples/logging.conf in the examples directory.

Crenation

yes this method works, however only .ini (fileConfig) format is supported, but you cant use custom filters in the .ini. – Barmecide

The only solution I know, is to implement your own handler which creates the filtering you need. – Crenation