Enabling debug_toolbar seems to break logging from management commands

[cancan101]

When I add debug_toolbar to my INSTALLED_APPS, calls to logging logger seems no longer work from within a management command.

[tim-schilling]

Can you please provide us with a test case?

[cancan101]

https://www.dropbox.com/s/oifjoqqxsrizzew/debug_toolbar_issue.zip?dl=0
the management command is check_log. You can see that toggling the debug_toolbar app in the settings.py file changes the logging behavior.

[aaugustin]

This may be related to 7d29b40.

[gfairchild]

I'm not sure if this is related to this issue (I suspect it is), but logging seems completely broken for me with DDT 1.3.0. I have numerous logging.debug calls scattered throughout my code, and DDT is no longer picking them up. I reverted to 1.2.2, and logging resumes working.

I'm using Python 3.4.x and Django 1.7.7.

If you want me to create a new issue, let me know.

[tim-schilling]

@gfairchild Do you know what your root.logging.level is set to?

[gfairchild]

@tim-schilling, I'm sorry, but I googled around and can't find any references to root.logging.level. What is that, and how do I report my value to you?

[gfairchild]

Actually, it looks like logging.getLogger().getEffectiveLevel() gets that value. I missed a SO thread on it. That function returns 0, which tells me my logger's root logging level is NOTSET according to https://docs.python.org/3.4/library/logging.html#levels.

[tim-schilling]

Sorry about that. I meant logging.root.level. I typed it out wrong. I'll try to recreate your scenario.

[gfairchild]

I just updated to Django 1.8, and logging still isn't working, so I'm guessing this is a DDT bug.

[dkrnl]

Yes, i catch similar bug: "No messages logged" in logging panel.
After update from Django 1.7 (logging working well) to 1.8 version.

[tim-schilling]

@gfairchild @dkrnl Can you try adding the following code to your settings file?

import logging
logging.root.setLevel(logging.NOTSET)

[gfairchild]

That seems to have fixed the issue!

[tim-schilling]

Glad it worked for you! That problem is actually different than the original issue which I'm still looking into.

[tim-schilling]

@cancan101 Were you using BasicConfig in your actual code? If so, then I don't think this is a bug with the toolbar. The reason being is that BasicConfig will only add a StreamHandler if there are no other handlers on root. The toolbar adds a handler, thus it doesn't create the StreamHandler and you don't see the output in the console. Here are the docs on it.

You can get the logging to work for your example if you add a django handler for that command. The code is:

import sys
LOGGING = {
    ...
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'stream': sys.stdout,
        }
    },
    'loggers': {
        'app.management.commands.check_log': {
            'handlers': ['console'],
            'level': 'INFO',
            'propagate': True,
        },
    }
}

[cancan101]

Interesting.

I wonder though why I don't see this same issue with other third party apps or even with Django itself. Perhaps the call that django-debug-toolbar makes to add a Hander needs to be deferred?

It appears that the handler is added so early that I no matter where I put the call to logging.basicConfig in my code, it I am have included the django-debug-toolbar, I am always too late.