2

I am not sure why django is not logging anything less than "WARNING" level. I have this code in the view:

logger = logging.getLogger(__name__)

def profile_data(request):
    logging.info("INFO PROFILE DATA!!")
    logging.debug("DEBUG PROFILE DATA!!")
    logging.warning("WARNING PROFILE DATA!!")
    logging.error("ERROR PROFILE DATA!!")

and this in my settings.py:

# Logging
LOGGING = {
    'version': 1,
    # Version of logging
    'disable_existing_loggers': False,

    'filters': {
        # information regarding filters
    },

    'formatters': {
        '<simple_format>': {
            'format': '{levelname} {message}',
            'style': '{',
        }
    },

    'handlers': {
        'file': {
            'level': 'DEBUG',
            'class': 'logging.FileHandler',
            'filename': '/logs/log_file1.log',
        },

        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler'
        },
    },

    'loggers': {
        'django': {
            'handlers': ['file', 'console'],
            'level': 'DEBUG',
        },
        'root': {
            'handlers': ['file', 'console'],
            'level': 'DEBUG',
        }
    }
    }

As you can see, I try to set everything to the DEBUG level, it doesn't work, I only see this is the warning and error level in the terminal:

WARNING:root:WARNING PROFILE DATA!!
ERROR:root:ERROR PROFILE DATA!!

EDIT

changed the logger declaration to:

logger = logging.getLogger('app_logger')

the call to:

logger.info("INFO PROFILE DATA!!")

and the settings to the new name, of course:

'loggers': {
    'app_logger': {
        'handlers': ['file', 'console'],
        'level': 'DEBUG',
    },

But it still prints only WARNING and above. When am I declaring a new logger? shouldn't logging.getLogger() get the logger declared in the settings? how should I import that logger in my views?

Also, tried adding the logger to the top level of the dict key as suggested by an answer below ('app_logger': {"level": "DEBUG", "handler": "console"},) it didn't work.

Alejandro Veintimilla
  • 10,743
  • 23
  • 91
  • 180
  • You constructed a *new* logger, and by default this is set to `Warning`. – Willem Van Onsem Dec 18 '20 at 19:22
  • *"tried adding the logger to the top level of the dict key as suggested by an answer below"* - I didn't suggest that. I said, to configure the *root logger* you must use the key "root" at the top level of the dictConfig. It doesn't work for any logger, only for the root logger. Hmm, ok, I'll clarify - I see that isn't very clear. –  Dec 20 '20 at 20:35

2 Answers2

3

You constructed a new logger with:

logger = logging.getLogger(__name__)

__name__ has value [geeksforgeeks.org]:

If the source file is executed as the main program, the interpreter sets the __name__ variable to have a value "__main__". If this file is being imported from another module, __name__ will be set to the module's name.

So you will either construct a logger with the name __main__, or one with the name of a module. But these are not the loggers you defined in the settings.py, this is a new logger.

Another problem is: you do not use the logger, you use logging, so the "root" logger, you thus should replace:

    logging.info('INFO PROFILE DATA!!')

with:

    logger.info('INFO PROFILE DATA!!')

We can for example make use of the root logger with:

import logging

logger = logging.getLogger('root')

def profile_data(request):
    logger.info('INFO PROFILE DATA!!')
    logger.debug('DEBUG PROFILE DATA!!')
    logger.warning('WARNING PROFILE DATA!!')
    logger.error('ERROR PROFILE DATA!!')
Willem Van Onsem
  • 443,496
  • 30
  • 428
  • 555
  • New loggers should go to the root logger, for which he did set a config. So even in the case of using logging.info(), it should log it. –  Dec 18 '20 at 19:37
  • @Melvyn: but the root logger is not `'root'`, but `None`. You get the root logger with `logging.getLogger(None)`, or just leave it blank (`logging.getLogger()`.) – Willem Van Onsem Dec 18 '20 at 19:39
  • @Melvyn: that is why using `root` as name for a logger is "asking for trouble". You can also specify a logger in the Django settings that uses `None` as key, then you are altering the root logger, but a logger with `'root'` as name is not the "root logger", it is just a custom logger that *happens* to have `'root'` as name. – Willem Van Onsem Dec 18 '20 at 19:41
  • @Melvyn: take for example `l = logging.getLogger('root')` and `l2 = logging.getLogger(None)`, then `l.level` will return `10` whereas `l2.level` will return 30. – Willem Van Onsem Dec 18 '20 at 19:42
  • It's actually not `None`, but ['root' at the top level](https://docs.python.org/3/library/logging.config.html#dictionary-schema-details). But still, names that are not configured, go to root. So the problem was that his "root" logger was inside the logger config, instead of "root" key at top level. I had to look it up, cause I keep forgetting :( –  Dec 18 '20 at 19:44
  • @Melvyn: no that is a misunderstanding between the *name* of a logger and the identifier. You can run the following test `l = getLogger('root')` then `l.parent` will give you *another* logger, whereas `l2 = getLogger(None)` will give `l2.parent` as `None`. Furthermore `l.parent == l2` holds (so the logger with `None` as identifier is the parent of the one with `root` as identifier). The confusion is that the `.name` of both loggers is `'root'`, but these are different loggers. – Willem Van Onsem Dec 18 '20 at 19:49
  • @Melvyn: see for example: https://repl.it/talk/share/log-confusion/87569 As you can see there are two loggers with `root` as *name*, but the one with `None` is the *parent* of the `'root'`-logger, and you can specify different log levels. Furthermore `l.parent == l2`, but `l2.parent != l`. – Willem Van Onsem Dec 18 '20 at 19:52
  • @Melvyn: if I set it to `INFO`, and create a logger in the Django shell, it says `l.level` is `20`, and for `DEBUG` it is `10`, for `'WARN'` it is `30`. The handler of course also has a log level, so if the handler has a higher log level, it will refuse to log that (whereas another handler for the same logger will log it). – Willem Van Onsem Dec 18 '20 at 20:37
  • Yeah, I got confused for a sec, because it seems that new loggers get level 0 and that's probably a mechanism to defer? parent = root. Both string and logging.DEBUG work to set to root logger to DEBUG, but it's where the key is in the dictConfig. –  Dec 18 '20 at 20:41
  • Thanks for the answer! @WillemVanOnsem added an Edit, corrected what you suggested but it still doesn't work. – Alejandro Veintimilla Dec 20 '20 at 19:39
  • @AlejandroVeintimilla: what does it print with `print(logger.handlers)` and `print(logging.filters)`? – Willem Van Onsem Dec 20 '20 at 19:47
  • @WillemVanOnsem `logger.handlers` and `logger.filters` print an empty array. – Alejandro Veintimilla Dec 20 '20 at 19:59
  • @AlejandroVeintimilla: then it looks there is still a mismatch between your `settings.py` and the logger, since normally the `handlers` should include a `StreamHandler`. – Willem Van Onsem Dec 20 '20 at 20:01
  • @WillemVanOnsem thanks for your comments! They helped me find that this line was the source of the problem: `django_heroku.settings(locals())` . – Alejandro Veintimilla Dec 20 '20 at 22:00
2

So the following config:

LOGGING = {
    "version": 1,
    "root": {"level": "DEBUG", "handlers": ["console"]},
    "loggers": {"oldname": {"level": "WARNING", "handlers": ["console"],}},
    "handlers": {
        "console": {"class": "logging.StreamHandler", "stream": "ext://sys.stdout"}
    },
}

Yields:

IPython 7.19.0 -- An enhanced Interactive Python. Type '?' for help.

In [1]: import logging

In [2]: logging.warning("open stdout")
WARNING:root:open stdout

In [3]: root = logging.getLogger(None)

In [4]: old = logging.getLogger("oldname")

In [5]: new = logging.getLogger("newname")

In [6]: print(root.level, old.level, new.level)
10 30 0

In [7]: root.debug("test")
DEBUG:root:test

In [8]: old.debug("test")

In [9]: new.debug("test")
DEBUG:newname:test

So moving your "root" key from inside "loggers" to the top-level of the LOGGING dict, solves your problem.

Note: The name "root" at top level is a reserved name to configure the root logger, a key with any other name at the top level won't work. And because undefined loggers inherit settings from root, your undefined logger will work.

With a defined logger

There's something else interfering with your configuration. Reduce your configuration to only this, then start adding stuff one by one until it breaks.

LOGGING = {
    "version": 1,
    "loggers": {"app_logger": {"level": "DEBUG", "handlers": ["console",]}},
    "handlers": {"console": {"class": "logging.StreamHandler",}},
}

Also, this lives in settings.py of your django project and it only applies if you open up a Django shell via python manage.py shell. Just using this in the standard interpreter won't load the config (just to cover the basics).