Using LoggingConfig with custom loggers?

[tomschr]

Thank you for this wonderful project! Really like it. 👍

I have some difficulties with logging, in particular the LoggingConfig class. It seems such an easy endeavor, but I'm kind of stuck.

I've read the Logging section in the documentation. Apart from a little warning with the my_router_handler function (there is an missing async), the code works fine.

Maybe it's a misunderstanding on my side, but I try to configure additional loggers and would like to define them with LoggingConfig. However, that part is missing in the documentation. So with the help of the API, I've tried to create an example and added some arguments into LoggingConfig:

logging_config = LoggingConfig(
        # configure_root_logger=False,
        # disable_existing_loggers=True,
        handlers={
            'foo': {
                'class': 'logging.StreamHandler', # 'litestar.logging.standard.QueueListenerHandler',
                'level': 'DEBUG',
                'formatter': 'foo'
            },
        formatters={
            'foo':
                {'format': '[%(levelname)s] - %(asctime)s - %(name)s - %(module)s - %(message)s'},
            # Disabling the "standard" formatter crashes with an exception (see below):
            'standard':
                {'format': '%(levelname)s - %(asctime)s - %(name)s - %(module)s - %(message)s'},
        },
        loggers={
                 'foo': {'level': 'DEBUG',
                          'handlers': ['foo'],
                          'propagate': False}
                },
    )

What's a bit strange is that I have to provide a "standard" formatter otherwise I get a KeyError:

KeyError when omitting the "standard" formatter

$ litestar run --reload
Using Litestar app from app:app
Starting server process ──────────────────────────────────────────────────────────────────────────────────────────────────────
┌──────────────────────────────┬──────────────────────┐
│ Litestar version             │ 2.8.3                │
│ Debug mode                   │ Enabled              │
│ Python Debugger on exception │ Disabled             │
│ CORS                         │ Disabled             │
│ CSRF                         │ Disabled             │
│ OpenAPI                      │ Enabled path=/schema │
│ Compression                  │ Disabled             │
└──────────────────────────────┴──────────────────────┘
INFO:     Will watch for changes in these directories: ['/tmp/litestar-test']
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
INFO:     Started reloader process [30274] using WatchFiles
INFO:     Started server process [30276]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
WARNING:  WatchFiles detected changes in 'app.py'. Reloading...
INFO:     Shutting down
INFO:     Waiting for application shutdown.
INFO:     Application shutdown complete.
INFO:     Finished server process [30276]
Process SpawnProcess-2:
Traceback (most recent call last):
  File "/usr/lib64/python3.11/logging/config.py", line 722, in configure_handler
    formatter = self.config['formatters'][formatter]
                ~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^
  File "/usr/lib64/python3.11/logging/config.py", line 336, in __getitem__
    value = dict.__getitem__(self, key)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^
KeyError: 'standard'

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/lib64/python3.11/logging/config.py", line 573, in configure
    handler = self.configure_handler(handlers[name])
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.11/logging/config.py", line 724, in configure_handler
    raise ValueError('Unable to set formatter '
ValueError: Unable to set formatter 'standard'

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/lib64/python3.11/multiprocessing/process.py", line 314, in _bootstrap
    self.run()
  File "/usr/lib64/python3.11/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "/tmp/litestar-test/.venv311/lib64/python3.11/site-packages/uvicorn/_subprocess.py", line 78, in subprocess_started
    target(sockets=sockets)
  File "/tmp/litestar-test/.venv311/lib64/python3.11/site-packages/uvicorn/server.py", line 65, in run
    return asyncio.run(self.serve(sockets=sockets))
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.11/asyncio/runners.py", line 190, in run
    return runner.run(main)
           ^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.11/asyncio/runners.py", line 118, in run
    return self._loop.run_until_complete(task)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "uvloop/loop.pyx", line 1517, in uvloop.loop.Loop.run_until_complete
  File "/tmp/litestar-test/.venv311/lib64/python3.11/site-packages/uvicorn/server.py", line 69, in serve
    await self._serve(sockets)
  File "/tmp/litestar-test/.venv311/lib64/python3.11/site-packages/uvicorn/server.py", line 76, in _serve
    config.load()
  File "/tmp/litestar-test/.venv311/lib64/python3.11/site-packages/uvicorn/config.py", line 433, in load
    self.loaded_app = import_from_string(self.app)
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/tmp/litestar-test/.venv311/lib64/python3.11/site-packages/uvicorn/importer.py", line 19, in import_from_string
    module = importlib.import_module(module_str)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.11/importlib/__init__.py", line 126, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "<frozen importlib._bootstrap>", line 1204, in _gcd_import
  File "<frozen importlib._bootstrap>", line 1176, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1147, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 690, in _load_unlocked
  File "<frozen importlib._bootstrap_external>", line 940, in exec_module
  File "<frozen importlib._bootstrap>", line 241, in _call_with_frames_removed
  File "/tmp/litestar-test/app.py", line 68, in <module>
    loggerfunc = logging_config.configure()
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/tmp/litestar-test/.venv311/lib64/python3.11/site-packages/litestar/logging/config.py", line 259, in configure
    config.dictConfig(values)
  File "/usr/lib64/python3.11/logging/config.py", line 823, in dictConfig
    dictConfigClass(config).configure()
  File "/usr/lib64/python3.11/logging/config.py", line 580, in configure
    raise ValueError('Unable to configure handler '
ValueError: Unable to configure handler 'queue_listener'

But that's a minor issue. When I trigger the my_router_handler() with curl, I get this output:

INFO:     127.0.0.1:33524 - "GET / HTTP/1.1" 200 OK
INFO - 2024-05-09 14:06:51,181 - root - app - an info
WARNING - 2024-05-09 14:06:51,181 - root - app - a warning
ERROR - 2024-05-09 14:06:51,181 - root - app - an error
CRITICAL - 2024-05-09 14:06:51,181 - root - app - a critical message

My questions to this:

1. How is LoggingConfig suppose to be used correctly? What is missing in my example?
2. Is the argument disable_existing_loggers really functional? Search in logging.config and you will notice it appears only one time. Seems the logic behind isn't implemented yet, is it?
3. Should I just omit LoggingConfig at all and use my own logging setup?
4. In my handler function my_router_handler, the request.logger object points to the root logger. Is there a way to use my own defined "foo" logger? Or is the preferred way to use logging.getLogger("foo")?

Hope that makes sense. Thanks for your ideas and suggestions. Much appreciated!

[peterschutt]

Sorry for not directly answering your questions just yet, but this may be of interest to you: #2858

[tomschr]

Thank you for taking the time! I searched the discussion and issue pages, but I didn't find this issue. Many thanks! 👍

[peterschutt]

The point of interest in that linked issue is that it's looking like litestar will remove logging configuration via the application object in a future version.

[tomschr]

That would be fine. Thanks for the hint. Have a great day! 🙂

[peterschutt]

That would be fine. Thanks for the hint. Have a great day! 🙂

You're very welcome!

[jderrien]

How is LoggingConfig suppose to be used correctly? What is missing in my example?

LoggingConfig will configure the root logger and a litestar logger. It uses some default handlers and formatters. If you configure your formatted, the default formatter (standard) won't be defined. So you have to define it as you did, or update the handler to not use it. I worked on a fix for that a few weeks/months ago but I haven't had time to open a PR.

My advice would be to stick with the current config, just re-use or override what you need. In your case you could just redefine the standardformatter with the format you want.

I haven't tested it, but I guess something like that would work:

logging_config = LoggingConfig(
    log_exceptions='always',
    formatters={
        'standard': {'format': '[%(levelname)s] - %(asctime)s - %(name)s - %(module)s - %(message)s'},
    },
    loggers={
        'foo': {
            'level': 'DEBUG',
            'handlers': ['queue_listener'],
            'propagate': False
        },
    },
)

Is the argument disable_existing_loggers really functional? Search in logging.config and you will notice it appears only one time. Seems the logic behind isn't implemented yet, is it?

This is passed to logging.config.dictConfig().

Should I just omit LoggingConfig at all and use my own logging setup?

LoggingConfig is mostly a wrapper around logging.config.dictConfig(). It might work but I haven't tested it.

In my handler function my_router_handler, the request.logger object points to the root logger. Is there a way to use my own defined "foo" logger? Or is the preferred way to use logging.getLogger("foo")?

I guess the prefered way is to use logging.getLogger("foo"). Or just use the root logger.

[tomschr]

Thank you so much for your detailed answer! Very appreciated! 👍

[dbrnz]

I've defined a simple logging configuration class so that Litestar will use a preconfigured Python logger. First use logging.dictConfig() to define a logger called litestar and then use the following when creating the app:

import logging
import typing

from litestar.logging import BaseLoggingConfig
from litestar.types import GetLogger, Logger

class LoggingConfig(BaseLoggingConfig):
    def configure(self) -> GetLogger:
        return typing.cast(GetLogger, logging.getLogger)

    @staticmethod
    def set_level(logger: Logger, level: int) -> None:
        logger.setLevel(level)

app = Litestar(
    route_handlers=[],
    logging_config=LoggingConfig()
)

[dbrnz]

In fact, and in order to log exceptions, I needed:

from dataclasses import dataclass
import logging
import typing

from litestar.logging import LoggingConfig as LitestarLoggingConfig
from litestar.types import GetLogger

@dataclass
class LoggingConfig(LitestarLoggingConfig):
    def configure(self) -> GetLogger:
        return typing.cast(GetLogger, logging.getLogger)

app = Litestar(
    route_handlers=[],
    logging_config=LoggingConfig(log_exceptions="always")
)