Help me understand this logging config

[Roy Smith]

I'm using django 1.3 and python 2.6.

My logging config is:


LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'formatters': {
'verbose': {
'format': '%(asctime)s: %(name)s %(levelname)s %
(funcName)s %(message)s'
}
},
'handlers': {
'mail_admins': {
'level': 'ERROR',
'class': 'django.utils.log.AdminEmailHandler'
},
'console': {
'level': 'DEBUG',
'class': 'logging.StreamHandler',
'formatter': 'verbose',
},
},
'loggers': {
'django.request': {'handlers': ['mail_admins'],
'level': 'ERROR',
'propagate': True,
},
'djfront': {'handlers': ['console'],
'propagate': True,
},
'djfront.view': {'level': 'INFO'},
'djfront.auth': {'level': 'INFO'},
'djfront.auth.user': {'level': 'INFO'},
'djfront.api': {'level': 'WARN'},
}
}

In my code, I do:

logger = logging.getLogger('djfront.auth.facebook')

Since I haven't configured a 'djfront.auth.facebook' logger, it should
inherit the 'djfront.auth' config, which means the logging level
should be set to INFO. But, when I do:

logger.debug('redirecting to "%s"' % url)

it emits a message:

2011-08-29 13:31:03,321: djfront.auth.facebook DEBUG oauth_init
redirecting to [...]

I'm confused. Why is the debug level message not getting filtered
out?

 

[Peter Otten]

I'm using django 1.3 and python 2.6.

Isn't dictConfig() new in 2.7? It looks like that is what you are using...

My logging config is:


LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'formatters': {
'verbose': {
'format': '%(asctime)s: %(name)s %(levelname)s %
(funcName)s %(message)s'
}
},
'handlers': {
'mail_admins': {
'level': 'ERROR',
'class': 'django.utils.log.AdminEmailHandler'
},
'console': {
'level': 'DEBUG',
'class': 'logging.StreamHandler',
'formatter': 'verbose',
},
},
'loggers': {
'django.request': {'handlers': ['mail_admins'],
'level': 'ERROR',
'propagate': True,
},
'djfront': {'handlers': ['console'],
'propagate': True,
},
'djfront.view': {'level': 'INFO'},
'djfront.auth': {'level': 'INFO'},
'djfront.auth.user': {'level': 'INFO'},
'djfront.api': {'level': 'WARN'},
}
}

In my code, I do:

logger = logging.getLogger('djfront.auth.facebook')

Since I haven't configured a 'djfront.auth.facebook' logger, it should
inherit the 'djfront.auth' config, which means the logging level
should be set to INFO. But, when I do:

logger.debug('redirecting to "%s"' % url)

it emits a message:

2011-08-29 13:31:03,321: djfront.auth.facebook DEBUG oauth_init
redirecting to [...]

I'm confused. Why is the debug level message not getting filtered
out?

I tried your setup with the django-specific handler replaced by another
StreamHandler

$ cat tmp_logging.py
import logging
import logging.config

LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'formatters': {
'verbose': {
'format': '%(asctime)s: %(name)s %(levelname)s %(funcName)s
%(message)s'
}
},
'handlers': {
'mail_admins': {
'level': 'ERROR',
'class': 'logging.StreamHandler'
#'django.utils.log.AdminEmailHandler'
},
'console': {
'level': 'DEBUG',
'class': 'logging.StreamHandler',
'formatter': 'verbose',
},
},
'loggers': {
'django.request': {'handlers': ['mail_admins'],
'level': 'ERROR',
'propagate': True,
},
'djfront': {'handlers': ['console'],
'propagate': True,
},
'djfront.view': {'level': 'INFO'},
'djfront.auth': {'level': 'INFO'},
'djfront.auth.user': {'level': 'INFO'},
'djfront.api': {'level': 'WARN'},
}
}

logging.config.dictConfig(LOGGING)

logger = logging.getLogger('djfront.auth.facebook')
logger.info("info-test")
logger.debug("debug-test")

and got what

$ python2.7 tmp_logging.py
2011-08-30 11:18:33,160: djfront.auth.facebook INFO <module> info-test
$

which seems to be what you expected. So I'm confused, too...

 

[Roy Smith]

Isn't dictConfig() new in 2.7? It looks like that is what you are using...

Oh, my, it turns out that django includes:

# This is a copy of the Python logging.config.dictconfig module,
# reproduced with permission. It is provided here for backwards
# compatibility for Python versions prior to 2.7.

Comparing the django copy to lib/logging/config.py from Python 2.7.2,
they're not identical. It's likely they grabbed something earlier in
the 2.7 series. I'll check 2.7.0 and 2.7.1 to see.

I tried your setup with the django-specific handler replaced by another
StreamHandler
[...]
and got what

$ python2.7 tmp_logging.py
2011-08-30 11:18:33,160: djfront.auth.facebook INFO <module> info-test
$

which seems to be what you expected. So I'm confused, too...

I'll need to dig deeper. Not that I realize this may not be a Python
issue per-se, I'll do some more experimentation and ask on the django
mailing list. Thanks for your help.

 

[Vinay Sajip]

Oh, my, it turns out that django includes:

# This is a copy of the Pythonlogging.config.dictconfig module,
# reproduced with permission. It is provided here for backwards
# compatibility for Python versions prior to 2.7.

Comparing the django copy to lib/logging/config.py from Python 2.7.2,
they're not identical. It's likely they grabbed something earlier in
the 2.7 series. I'll check 2.7.0 and 2.7.1 to see.

They're not identical, but should be functionally equivalent. I'm not
able to reproduce your results: I copied the "loggers" part of your
config into a Django 1.3 project, and from a manage.py shell session:

Python 2.6.5 (r265:79063, Apr 16 2010, 13:09:56)
[GCC 4.4.3] on linux2
Type "help", "copyright", "credits" or "license" for more information.
(InteractiveConsole)
.... as expected.

Since it's Python 2.6, it should be using the dictconfig which ships
with Django 1.3.

Regards,

Vinay Sajip

 

[Vinay Sajip]

Oh, my, it turns out that django includes:

# This is a copy of the Pythonlogging.config.dictconfig module,

# reproduced with permission. It is provided here for backwards

# compatibility for Python versions prior to 2.7.

Comparing the django copy to lib/logging/config.py from Python 2.7.2,
they're not identical. It's likely they grabbed something earlier in
the 2.7 series. I'll check 2.7.0 and 2.7.1 to see.

They're not identical, but should be functionally equivalent. I'm not able to
reproduce your results: I copied the "loggers" part of your config into a Django
1.3 project, and from a manage.py shell session:

Python 2.6.5 (r265:79063, Apr 16 2010, 13:09:56)
[GCC 4.4.3] on linux2
Type "help", "copyright", "credits" or "license" for more information.
(InteractiveConsole)
.... as expected.

Since it's Python 2.6, it should be using the dictconfig which ships with Django
1.3.

Regards,

Vinay Sajip

 

[Vinay Sajip]

Oh, my, it turns out that django includes:

# This is a copy of the Pythonlogging.config.dictconfig module,
# reproduced with permission. It is provided here for backwards
# compatibility for Python versions prior to 2.7.

Comparing the django copy to lib/logging/config.py from Python 2.7.2,
they're not identical. It's likely they grabbed something earlier in
the 2.7 series. I'll check 2.7.0 and 2.7.1 to see.

They're not identical, but should be functionally equivalent. I'm not
able to reproduce your results: I copied the "loggers" part of your
config into a Django 1.3 project, and from a manage.py shell session:

Python 2.6.5 (r265:79063, Apr 16 2010, 13:09:56)
[GCC 4.4.3] on linux2
Type "help", "copyright", "credits" or "license" for more information.
(InteractiveConsole)
.... as expected.

Since it's Python 2.6, it should be using the dictconfig which ships
with Django 1.3.

Regards,

Vinay Sajip