Why does Python logging throw an error when a handler name starts with `s`?-CodePudding

The Problem

When I run main.py below, it prints out HELLO WORLD (everything works). However, if I rename console in LOGGING_CONFIG to s, python throws this error: AttributeError: 'ConvertingDict' object has no attribute 'handle'. Why does changing a handler name cause this to happen and how can I fix it?

Background

I have an asyncio application that requires logging, but "the logging module uses blocking I/O when emitting records." Python's logging.handlers.QueueHandler was built for this and I'm trying to implement the QueueHandler with dictConfig. I used the links in the references section at the bottom to put main.py together.

Code

This is main.py. Note that the filename main.py is important because main.QueueListenerHandler references it in LOGGING_CONFIG.

# main.py
import logging
import logging.config
import logging.handlers
import queue
import atexit


# This function resolves issues when using `cfg://handlers.[name]` where
# QueueListenerHandler complains that `cfg://handlers.[name]` isn't a handler.
def _resolve_handlers(myhandlers):
    if not isinstance(myhandlers, logging.config.ConvertingList):
        return myhandlers

    # Indexing the list performs the evaluation.
    return [myhandlers[i] for i in range(len(myhandlers))]


class QueueListenerHandler(logging.handlers.QueueHandler):
    def __init__(
        self,
        handlers,
        respect_handler_level=False,
        auto_run=True,
        queue=queue.Queue(-1),
    ):
        super().__init__(queue)
        handlers = _resolve_handlers(handlers)
        self._listener = logging.handlers.QueueListener(
            self.queue, *handlers, respect_handler_level=respect_handler_level
        )
        if auto_run:
            self.start()
            atexit.register(self.stop)

    def start(self):
        self._listener.start()

    def stop(self):
        self._listener.stop()

    def emit(self, record):
        return super().emit(record)


LOGGING_CONFIG = {
    "version": 1,
    "handlers": {
        "console": {
            "class": "logging.StreamHandler",
        },
        "queue_listener": {
            "class": "main.QueueListenerHandler",
            "handlers": [
                "cfg://handlers.console"
            ],
        },
    },
    "loggers": {
        "server": {
            "handlers": ["queue_listener"],
            "level": "DEBUG",
            "propagate": False,
        },
    },
}

if __name__ == "__main__":
    logging.config.dictConfig(LOGGING_CONFIG)
    logger = logging.getLogger("server")
    logger.debug("HELLO WORLD")

If I modify LOGGING_CONFIG["handlers"] to this:

"handlers": {
        "s": {
            "class": "logging.StreamHandler",
        },
        "queue_listener": {
            "class": "main.QueueListenerHandler",
            "handlers": [
                "cfg://handlers.s"
            ],
        },
    },

python will throw this error:

sh-3.2$ pyenv exec python main.py 
Exception in thread Thread-1 (_monitor):
Traceback (most recent call last):
  File "/Users/zion.perez/.pyenv/versions/3.10.6/lib/python3.10/threading.py", line 1016, in _bootstrap_inner
    self.run()
  File "/Users/zion.perez/.pyenv/versions/3.10.6/lib/python3.10/threading.py", line 953, in run
    self._target(*self._args, **self._kwargs)
  File "/Users/zion.perez/.pyenv/versions/3.10.6/lib/python3.10/logging/handlers.py", line 1548, in _monitor
    self.handle(record)
  File "/Users/zion.perez/.pyenv/versions/3.10.6/lib/python3.10/logging/handlers.py", line 1529, in handle
    handler.handle(record)
AttributeError: 'ConvertingDict' object has no attribute 'handle'

Notes

Interestingly only s causes this issue. Any other letter works. If s is the first letter of the handler name (e.g. sconsole, shandler), Python will throw the exception above.
Tested and confirmed the same behavior on MacOS with Python 3.11.1, 3.10.6, 3.9.16
Tested on Ubuntu 22.04 with Python 3.10.6 and 3.11.0rc1
Regarding the _resolve_handlers func, if the handler is console (does not start with s) the func returns [<StreamHandler <stderr> (NOTSET)>] and everything works. If the handler is sconsole (starts with s), the func returns [{'class': 'logging.StreamHandler'}]. For more background on _resolve_handlers, this article explains why this function is needed.

References

CodePudding user response：

This is a partial answer because I haven't found a "proper" solution, just an explanation for the issue and how to fix it with light hackery.

The issue you're seeing occurs because:

Handlers are initialized in alphabetical order by name
There is some ugly and hacky (literally inspects the stringified form of the chained exception for a specific substring) code used to handle deferred initialization when one handler relies upon another, which your code doesn't trigger properly
Due to #1 and #2, whenever a dependent handler appears after the handler it depends on, alphabetically, your attempt to resolve the handlers resolves to the dictionary that handler name maps to, not the actual handler class it is supposed to construct

A more minimalist reproducer (without all the queues and threads involved) is:

import logging
import logging.config
import logging.handlers

# Minimalist handler that just delegates to contained handler
class PassThroughHandler:
    def __init__(
        self,
        handler,
    ):
        self._handler = handler
        print(type(handler))  # Will print either the resolved handler object type, or ConfiguringDict when it hasn't resolved

    def __getattr__(self, name):
        return getattr(self._handler, name)

LOGGING_CONFIG = {
    "version": 1,
    "handlers": {
        "q": {   # Fails as "q" (and anything alphabetically after "passthrough"), works as "p" (and anything else alphabetically before "passthrough")
            "class": "logging.StreamHandler",
        },
        "passthrough": {
            "class": __name__   ".PassThroughHandler",
            "handler": "cfg://handlers.q", # Change to match "q" or "p" above
        },
    },
    "loggers": {
        "server": {
            "handlers": ["passthrough"],
            "level": "DEBUG",
            "propagate": False,
        },
    },
}

if __name__ == "__main__":
    logging.config.dictConfig(LOGGING_CONFIG)
    logger = logging.getLogger("server")
    logger.debug("HELLO WORLD")

Try it online!

As written it fails, but change the "q" handler name to "p" (or anything else that alphabetically precedes "passthrough") and it works.

Right now, the best solution I can come up with is to ensure that the handler dependency is fully resolved first. This just means that, if handler A relies on handler B, you must give handler B a name that alphabetically precedes handler A's name. So anything that alphabetically precedes "queue_listener" will work (like the original "console"), and anything following it will now.

On the bright side, while hacky, this appears to be an intentional design decision; the code comments at the point where it is configuring handlers include:

          # Next, do handlers - they refer to formatters and filters
          # As handlers can refer to other handlers, sort the keys
          # to allow a deterministic order of configuration

That same code has an insanely hacky approach to trying to handle cross-handler dependencies, by allowing for a single layer of deferred handling if exceptions are raised in exactly the right way, but my attempts to hook into it have not been successful. I can raise an exception of the form it wants (with raise Exception() from ValueError('target not configured yet')) when I detect that the dependent handler is not resolved yet, and the handler is then deferred for a second pass, but some state is broken when the second pass occurs (a string that used to be validly parsable ends up being parsed incorrectly and the resulting None object breaks when the code tries to split it up by dots), leading to an exception later on. Looking at what some of the existing classes have to do to work with this (saving off copies of pre-parsing state to restore if the configuration fails so it can revert to the original state before raising the hacky exception) makes me think it's not worth the trouble.

The docs on this cfg:// feature seem to indicate what you're doing should work (their example has handlers.custom reference handlers.file, and custom is alphabetically earlier than file in this design, so it seems like it should still have the problem), so either we're missing something, or the docs are misleading.

CodePudding user response：

This seems to be Error when initializing queue listener from config file #92929 which is closed as not planned, because a mechanism for configuring QueueListener / QueueHandler together was added in #93269.

There is more context and configuration advice in Allow using QueueHandler and QueueListener in logging.dictConfig #93162.

It won't help you on Python 3.10.6, where I guess you just have to dodge the issue by using alphabetically chosen names in your config, but you can review the new mechanism in the Python 3.12 docs:

Configuring QueueHandler and QueueListener