Logging does not work as expected

Using Django Forms & APIs
1

Hi,

I’m trying to understand logging. I’m following How to configure and use logging | Django documentation | Django and it shows there how to configure a logger that logs everything (logger "") to a file.

I tried that and added the setting below to my settings.py, which made me notice some unexpected behaviour.

LOGGING = {
    "version": 1,  # the dictConfig format version
    "disable_existing_loggers": False,  # retain the default loggers
    "formatters": {
        "verbose": {
            "format": "{asctime} {levelname:<8} {module:<12} | {message}",
            "style": "{",
        },
        "simple": {
            "format": "{levelname} {message}",
            "style": "{",
        },
    },
    "handlers": {
        "file": {
            "class": "logging.FileHandler",
            "filename": "general.log",
            "formatter": "verbose",
        },
    },
    "loggers": {
        "": {
            "handlers": ["file"],
            "level": "DEBUG",
        },
    },
}

In my view I am logging the following.

import logging
logger = logging.getLogger(__name__)
logger.debug("MY LOGGER: DEBUG")
logger.info("MY LOGGER: INFO")
logger.warning("MY LOGGER: WARNING")
logger.error("MY LOGGER: ERROR")
logger.critical("MY LOGGER: CRITICAL")

Without the setting, the following gets logged:

Console

MY LOGGER: WARNING
MY LOGGER: ERROR
MY LOGGER: CRITICAL
[23/Apr/2024 22:57:17] "GET / HTTP/1.1" 200 9515

general.log

But with the setting, the following gets logged:

Console

[23/Apr/2024 22:58:43] "GET / HTTP/1.1" 200 9515

general.log

2024-04-23 22:58:43,653 DEBUG    views        | MY LOGGER: DEBUG
2024-04-23 22:58:43,653 INFO     views        | MY LOGGER: INFO
2024-04-23 22:58:43,653 WARNING  views        | MY LOGGER: WARNING
2024-04-23 22:58:43,653 ERROR    views        | MY LOGGER: ERROR
2024-04-23 22:58:43,653 CRITICAL views        | MY LOGGER: CRITICAL

Now my understanding is that the setting I added is additive. The docs state that “a logger can forward messages to multiple handlers, so the relation between loggers and handlers is many-to-many.” And the logger name does not override an existing named logger, such as django.server.

So why does my setting remove the logs from the console logger? I was expecting my five test log messages to appear in both, the console and the file.

2

Maybe try to set propagate on your "" logger.

"loggers": {
        "": {
            "handlers": ["file"],
            "level": "DEBUG",
            "propagate": True,
        },
    },

Also, there’s this excellent video by mCoding about setting up logging, this video helped me a lot to better understand the inner behavior of the python’s logging module.

3

Thanks for the suggestion. The video does not reveal any new information, that was not discussed in the docs.

The propagation does not change anything, and why would it? It’s a top-level logger. A message cannot be propagated any higher than “”.

4

What logger are you testing? (What’s the __name__ being used in your tests?)

The only loggers defined by name by default are for “django” and “django.server”. If __name__ is not either of those, then it would be logged using the implicit "" default - and that’s what you’re overriding with your configuration.

5

__name__ is myapp.views. Your note about the name helps. What I don’t get is the sentence I quoted. The default logging definition does not have a logger "" configured, so there’s nothing there that I could override.

6

It doesn’t need to be defined. It’s the implict default (root) used in the absence of an explicit logger being referenced.

If you use the logging facility without providing any definitions, you will still get logs, regardless of the name being used.

As you note, the DEFAULT_LOGGING only defines loggers for "django" and "django.server". If there wasn’t an implicit default, then those would be the only names causing logs to be written.

So by adding the null string key, “”, you’re overriding the default root.

Note: You’ll see the docs referencing a top-level key named “root”. It is an effective synonym to the blank key in the “loggers” dict.

7

Well, it should be defined! There is a default config showing me what is configured by default. Why is the root logger and it’s configuration not included in there? How is it better to have it implicit instead of explicit? How am I supposed to know that I am overwriting something, if nothing - not even the docs tells me this?

And nowhere is written that the unnamed logger “” is the same as “root” (which is on the same level as “loggers”). That’s not only very confusing,but also in transparent. I also find that atypical on how loggers are defined.

Thanks, Ken. I may raise an issue in the Bug tracker about this.

8

Because it’s part of the underlying Python logging module. Quoting directly from Logging | Django documentation | Django

Django uses and extends Python’s builtin logging module to perform system logging. This module is discussed in detail in Python’s own documentation; this section provides a quick overview.

The LOGGING configuration is passed directly to the Python logging module. All the implications of how things are used is based solely on it.

Having said that, I definitely agree that the Python docs for this could be made more clear. I definitely get the impression that not only is the Python logger “styled” in a manner similar to Java’s log4j, but it also presumes some knowledge of it

9

Hmm, got it. I didn’t grasp the importance of that statement. It sounded more like a deep-dive, that would not be important to know for basic logging setups. I guess it is…

Will look at this when I have time, but thanks already for making that clear.