Unable to configure root logger

[rugleb]

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.

[jamadden]

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

[rugleb]

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.

[danieljacobs1]

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).

[berkerpeksag]

6da84c6 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.

[rugleb]

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

[jtrh]

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.

gunicorn/gunicorn/glogging.py

Lines 229 to 231 in 5d0c778

	if cfg.logconfig_dict:
	config = CONFIG_DEFAULTS.copy()
	config.update(cfg.logconfig_dict)

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"]}.

gunicorn/gunicorn/glogging.py

Lines 48 to 52 in 5d0c778

	CONFIG_DEFAULTS = dict(
	version=1,
	disable_existing_loggers=False,
	root={"level": "INFO", "handlers": ["console"]},

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'],
}

[tilgovi]

If anyone would like to contribute a PR to add some documentation language around this, please tag me and I'll review! There's an examples/logging.conf file and a section about logging in docs/source/deploy.rst.

[CaichaoGitHub]

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.

gunicorn/gunicorn/glogging.py

Lines 229 to 231 in 5d0c778

	if cfg.logconfig_dict:
	config = CONFIG_DEFAULTS.copy()
	config.update(cfg.logconfig_dict)

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"]}.

gunicorn/gunicorn/glogging.py

Lines 48 to 52 in 5d0c778

	CONFIG_DEFAULTS = dict(
	version=1,
	disable_existing_loggers=False,
	root={"level": "INFO", "handlers": ["console"]},

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'],
}

it helped me

[default-work]

the main reason that file basef loggin handled failed is that they can't be reused, so if y setup it on a root level, u cant reuse the same file in another handler as well as the same handler in another than root logger