Gunicorn: Unable to configure root logger

Created on 27 Jan 2020 · 8Comments · Source: benoitc/gunicorn

Hi, everyone!

I have a problem with root logger: Error: Unable to configure root logger.

Run command: gunicorn project:create_app -c gunicorn.config.py,

create_app is a coroutine that is returned the instance of aiohttp.web.Application (aiohttp v3.6.2).

Gunicorn config file (gunicorn.config.py):

from multiprocessing import cpu_count
from os import getenv as env

from project import log, settings

# The number of pending connections.
backlog = env("GUNICORN_BACKLOG", 2048)

# The socket to bind.
bind = env("GUNICORN_BIND", f"0.0.0.0:{settings.PORT}")

# Check the configuration.
check_config = env("GUNICORN_CHECK_CONFIG", False)

# The number of worker processes that this server
# should keep alive for handling requests.
workers = env("GUNICORN_WORKERS", cpu_count() * 2 + 1)

# The type of workers to use.
worker_class = env("GUNICORN_WORKER_CLASS", "aiohttp.GunicornUVLoopWebWorker")

# The maximum number of requests a worker will process before restarting.
# Any value greater than zero will limit the number of requests
# a work will process before automatically restarting.
max_requests = env("GUNICORN_MAX_REQUESTS", 1000)

# If a worker does not notify the master process in this number of
# seconds it is killed and a new worker is spawned to replace it.
timeout = env("GUNICORN_TIMEOUT", 30)

# Timeout for graceful workers restart.
graceful_timeout = env("GUNICORN_GRACEFUL_TIMEOUT", 5)

# The number of seconds to wait for the next
# request on a Keep-Alive HTTP connection.
keepalive = env("GUNICORN_KEEPALIVE", 5)

# Install a trace function that spews every line of Python
# that is executed when running the server.
# This is the nuclear option.
spew = env("GUNICORN_SPEW", False)

# Detach the main Gunicorn process from the controlling
# terminal with a standard fork sequence.
daemon = env("GUNICORN_DAEMON", False)

# The path to a log file to write to.
logfile = env("GUNICORN_LOGFILE", "-")

# The granularity of log output.
loglevel = env("GUNICORN_LOGLEVEL", log.level)

# The Error log file to write to.
errorlog = env("GUNICORN_ERRORLOG", "-")

# The Access log file to write to.
accesslog = env("GUNICORN_ACCESSLOG", "-")

# The access log format.
access_log_format = log.access_log_message_format

# The log config dictionary to use, using the standard Python
# logging module’s dictionary configuration format.
logconfig_dict = log.config

My project/log.py file:

import logging.config

from project.app import context
from project.settings import env

__all__ = (
    "access_logger",
    "app_logger",
    "config",
    "install",
    "level",
    "datetime_format",
    "log_format",
    "access_log_format",
    "access_log_message_format",
)

level = "INFO"
datetime_format = "%Y-%m-%d %H:%M:%S"

access_logger = logging.getLogger("access")
app_logger = logging.getLogger("app")

log_format = (
    'time="%(asctime)s" '
    'level="%(levelname)s" '
    'logger="%(name)s" '
    'service_name="%(service_name)s" '
    'pid="%(process)d" '
    'request_id="%(request_id)s" '
    'message="%(message)s" '
)

access_log_format = (
    'time="%(asctime)s" '
    'level="%(levelname)s" '
    'logger="%(name)s" '
    'service_name="%(service_name)s" '
    'pid="%(process)d" '
    "%(message)s "
)

access_log_message_format = (
    'request_id="%{X-Request-Id}i" '
    'remote_addr="%a" '
    'referer="%{Referer}i" '
    'user_agent="%{User-Agent}i" '
    'protocol="%r" '
    'response_code="%s" '
    'request_time="%Tf" '
)


class ServiceNameFilter(logging.Filter):
    """Adds custom log attribute: service_name"""

    def filter(self, record: logging.LogRecord):
        service_name = env("SERVICE_NAME", "statistics")
        setattr(record, "service_name", service_name)
        return super().filter(record)


class RequestIDFilter(logging.Filter):
    """Adds custom log attribute: request_id"""

    def filter(self, record: logging.LogRecord):
        request_id = context.REQUEST_ID.get("-")
        setattr(record, "request_id", request_id)
        return super().filter(record)


config = {
    "version": 1,
    "disable_existing_loggers": True,
    "loggers": {
        "root": {
            "level": level,
            "handlers": ["default_handler"],
        },
        app_logger.name: {
            "level": level,
            "handlers": ["default_handler"],
            "propagate": False,
        },
        access_logger.name: {
            "level": level,
            "handlers": ["access_handler"],
            "propagate": False,
        },
        "gunicorn.error": {
            "level": level,
            "handlers": ["default_handler"],
            "propagate": False,
        },
        "gunicorn.access": {
            "level": level,
            "handlers": ["access_handler"],
            "propagate": False,
        },
    },
    "handlers": {
        "default_handler": {
            "class": "logging.StreamHandler",
            "formatter": "default_formatter",
            "stream": "ext://sys.stdout",
            "filters": [
                "service_name_filter",
                "request_id_filter",
            ],
        },
        "access_handler": {
            "class": "logging.StreamHandler",
            "formatter": "access_formatter",
            "stream": "ext://sys.stdout",
            "filters": [
                "service_name_filter",
                "request_id_filter",
            ],
        },
    },
    "formatters": {
        "default_formatter": {
            "format": log_format,
            "datefmt": datetime_format,
            "class": "logging.Formatter",
        },
        "access_formatter": {
            "format": access_log_format,
            "datefmt": datetime_format,
            "class": "logging.Formatter",
        },
    },
    "filters": {
        "request_id_filter": {
            "()": "project.log.RequestIDFilter",
        },
        "service_name_filter": {
            "()": "project.log.ServiceNameFilter",
        },
    },
}


def install() -> None:
    logging.config.dictConfig(config)

This problem appears on versions 19.10 and 20.* (by pip), on different workers. On version 19.8, everything works well.
I tried to configure logs in different ways, change workers, aiohttp versions, but all in vain. I think the problem is in logconfig_dict.
Python 3.6, 3.7, 3.8.
Please help solve the problem. Thank you in advance!

PS: I apologize for my English.

Source

rugleb

Most helpful comment

I experienced this issue today when I upgraded from v19.9.0 to v20.0.4.

I think it's related to the way the _default_ and the _user_ log configuration dictionaries are merged (see below), which may sometimes result in an invalid configuration.

https://github.com/benoitc/gunicorn/blob/5d0c7783008d4df87d579a576d19182c4a95caf7/gunicorn/glogging.py#L229-L231

Let me explain this in detail.

First, here's my logging configuration, which fails with Error: Unable to configure root logger:

logconfig_dict = {
    'version': 1,
    'formatters': {
        'web_standard': {
            'format': '%(asctime)s %(name)s[%(process)d]: [%(levelname)s] %(message)s',
            'datefmt': None,
            'style': '%',
        },
    },
    'handlers': {
        'web_console': {
            'class': 'logging.StreamHandler',
            'level': 'DEBUG',
            'formatter': 'web_standard',
        },
    },
    'loggers': {
        'gunicorn': {
            'level': 'WARNING',
            'propagate': False,
            'handlers': ['web_console'],
        },
    },
    'incremental': False,
    'disable_existing_loggers': False,
}

We also know that gunicorn.glogging.CONFIG_DEFAULTS['root'] is {"level": "INFO", "handlers": ["console"]}.

https://github.com/benoitc/gunicorn/blob/5d0c7783008d4df87d579a576d19182c4a95caf7/gunicorn/glogging.py#L48-L52

If we add that to my configuration it will result in an invalid configuration because there's no handler named console there.

For my configuration, adding a handler named console (or renaming web_console to console) fixed the issue.

Alternatively, explicitly configuring the root logger also worked (see example below). Remember to use a handler that is defined in your configuration.

logconfig_dict['root'] = {
    'level': 'WARNING',
    'handlers': ['web_console'],
}

jtrh on 5 Feb 2020

👍8 🎉4 🚀3

All 8 comments

Can you provide the full traceback and error message you're getting?

jamadden on 27 Jan 2020

Can you provide the full traceback and error message you're getting?

Unfortunately, this is already a full traceback.

Just Error: Unable to configure root logger and no more.

rugleb on 27 Jan 2020

I had the same problem; this seems to be new with gunicorn (specifically using 20.0.4). I got rid of the error by adding

      "root": {
          "level": "WARNING",
          "handlers": ["default_handler", ]
      },

to the config dictionary. Note that this has to be at the same level the "version" at the root of the dictionary (excuse the pun). I suppose that this is more a workaround than a fix?

I read the Python docs on the logging config dict as saying that this "root" key/value pair is optional; I'm pretty sure we didn't need this extra "root" key for gunicorn 19.9.0 (since I copied gunicorn config from a project that used 19.9.0 which didn't have that).

danieljacobs1 on 31 Jan 2020

https://github.com/benoitc/gunicorn/commit/6da84c614d5a5b60ebed146301e4ac7c436f8fb3 might be related. I can see that the change has also been backported to 19.10.

It seems to me that we need to document this in the changelog.

berkerpeksag on 1 Feb 2020

I had the same problem; this seems to be new with gunicorn (specifically using 20.0.4). I got rid of the error by adding
      "root": {
          "level": "WARNING",
          "handlers": ["default_handler", ]
      },
to the config dictionary. Note that this has to be at the same level the "version" at the root of the dictionary (excuse the pun). I suppose that this is more a workaround than a fix?

I read the Python docs on the logging config dict as saying that this "root" key/value pair is optional; I'm pretty sure we didn't need this extra "root" key for gunicorn 19.9.0 (since I copied gunicorn config from a project that used 19.9.0 which didn't have that).

Alas, this doesn't work either

rugleb on 4 Feb 2020