strange behavious of the logging module?

[Christian Meesters]

Hi,

having the following code:

import logging
logging.basicConfig(level=logging.ERROR,
format='%(levelname)-8s %(message)s',
filename='mc_rigid.log',
filemode='w')
# define a Handler which writes INFO messages or higher to the sys.stderr
console = logging.StreamHandler()
console.setLevel(logging.INFO)
# set a format which is simpler for console use
formatter = logging.Formatter('%(message)s')
# tell the handler to use this format
console.setFormatter(formatter)
# add the handler to the root logger
logging.getLogger('').addHandler(console)

I observe nothing printed on the console. However if I change the level
(just after the import) from logging.ERROR to logging.DEBUG I do see all
info lines on the console as intended.

Can anybody tell my mistake? I thought changing the level in basicConfig
would have no impact on the following StreamHandler instance.
Also, adding %(funcName)-8s to the formatter in basigConfig does not work
for me: instead of the functions name the level in lower case gets inserted
into the logfile.

My python:
Python 2.5.1 (r251:54863, May 2 2007, 16:56:35)
[GCC 4.1.2 (Ubuntu 4.1.2-0ubuntu4)] on linux2

TIA
Christian

 

[Gabriel Genellina]

En Sun, 23 Sep 2007 18:53:53 -0300, Christian Meesters

import logging
logging.basicConfig(level=logging.ERROR,
format='%(levelname)-8s %(message)s',
filename='mc_rigid.log',
filemode='w')
# define a Handler which writes INFO messages or higher to the sys.stderr
console = logging.StreamHandler()
console.setLevel(logging.INFO)
# set a format which is simpler for console use
formatter = logging.Formatter('%(message)s')
# tell the handler to use this format
console.setFormatter(formatter)
# add the handler to the root logger
logging.getLogger('').addHandler(console)

I observe nothing printed on the console. However if I change the level
(just after the import) from logging.ERROR to logging.DEBUG I do see all
info lines on the console as intended.

basicConfig sets the root logger level; if it's ERROR, nothing below ERROR
will pass. Your handler does not have a chance to get the message.

Can anybody tell my mistake? I thought changing the level in basicConfig
would have no impact on the following StreamHandler instance.

basicConfig sets the overall verbosity of your application.

Also, adding %(funcName)-8s to the formatter in basigConfig does not work
for me: instead of the functions name the level in lower case gets
inserted
into the logfile.

Looks like a bug...

 

[Peter Otten]

Also, adding %(funcName)-8s to the formatter in basigConfig does not work
for me: instead of the functions name the level in lower case gets inserted
into the logfile.

When you call logging.info(...), "info" actually is the function name. As a
workaround use logging.getLogger(...).info(...).

It would still be a good idea to file a bug report.

Peter

 

[Christian Meesters]

Thanks Peter and Gabriel,

I see, so I should provide the application with an additional handler for
the file in order to gain maximum independence of the two handlers (console
& file stream).

Looks like a bug...

Well, the documentation -- as far as I understand it ;-) -- says the
behaviour should be different, you two basically agree ... think I should
file a report.

Thanks,
Christian

 

[Vinay Sajip]

It would still be a good idea to file a bug report.

Not sure where the bug is. The script below, when called, prints
"Information" to the console and "INFO some_func Information" to
mc_rigid.log, as I would expect. (Python 2.5.1)

Best regards,

Vinay

import logging
logging.basicConfig(level=logging.DEBUG,
format='%(levelname)-8s %(funcName)-8s %
(message)s',
filename='mc_rigid.log',
filemode='w')
# define a Handler which writes INFO messages or higher to the
sys.stderr
console = logging.StreamHandler()
console.setLevel(logging.INFO)
# set a format which is simpler for console use
formatter = logging.Formatter('%(message)s')
# tell the handler to use this format
console.setFormatter(formatter)
# add the handler to the root logger
logging.getLogger('').addHandler(console)

def some_func():
logging.info("Information")

if __name__ == "__main__":
some_func()

 

[Peter Otten]

Not sure where the bug is. The script below, when called, prints
"Information" to the console and "INFO some_func Information" to
mc_rigid.log, as I would expect. (Python 2.5.1)

I get

$ python vinaj.py
Information
$ cat mc_rigid.log
INFO info Information

Maybe a platform issue (I'm on Ubuntu 7.04)?

It seems Logger.findCaller() gets puzzled by the following discrepancy:
'/usr/lib/python2.5/logging/__init__.py'

I don't think I have messed with paths manually on that machine, by the
way.

Peter

 

[Vinay Sajip]

I get

$ python vinaj.py
Information
$ cat mc_rigid.log
INFO info Information

Maybe a platform issue (I'm on Ubuntu 7.04)?

It seems Logger.findCaller() gets puzzled by the following discrepancy:


'logging/__init__.py'>>>logging._srcfile

'/usr/lib/python2.5/logging/__init__.py'

I don't think I have messed with paths manually on that machine, by the
way.

This is a known bug, and not specifically related to logging, though
it sometimes manifests itself via logging:

http://bugs.python.org/issue1180193

Regards,

Vinay

 

[Peter Otten]

This is a known bug, and not specifically related to logging, though
it sometimes manifests itself via logging:

http://bugs.python.org/issue1180193

Yup, thanks for looking into it.

Peter

 

[Christian Meesters]

Yup, thanks for looking into it.

Peter

Thanks Vinay, but I am curious how issue 1180193 is related to the "bug"
Peter and me described: I do not have any *.pyc file around. As I kept
changing the file during development I used to call the program directly
using a link in my PATH. Hence no *.pyc file got created at all.

However, does anybody know a suggestion for a work-around?

Christian

 

[Peter Otten]

Thanks Vinay, but I am curious how issue 1180193 is related to the "bug"
Peter and me described: I do not have any *.pyc file around. As I kept
changing the file during development I used to call the program directly
using a link in my PATH. Hence no *.pyc file got created at all.

The problem is not caused by the pyc-file for your script, but by
the logging/__init__.pyc file in your python installation. You
can check if you are affected by the bug by typing
'/usr/lib/python2.5/logging/__init__.py'

in the interpreter. If you get different paths like in "logging" and
"/usr/lib/python2.5/logging" in the above example you are affected.

However, does anybody know a suggestion for a work-around?

You could try setting

logging._srcfile = logging.info.func_code.co_filename

manually, but that might break other things. Or you recreate the pyc-files
of your distribution. Again, I don't know what might break...

Peter

 

[Vinay Sajip]

You could try setting

logging._srcfile =logging.info.func_code.co_filename

manually, but that might break other things. Or you recreate the pyc-files
of your distribution. Again, I don't know what might break...

Recreating .pyc files should not break anything - this will get done
automatically, so deleting the .pyc and/or .pyo files in the Python/
Lib directory tree should be sufficient. See the issues linked to by

http://bugs.python.org/msg24988

In these cases, deleting the .pyc/.pyo files solved the problem.

Best regards,

Vinay

 

[Christian Meesters]

Thanks Peter and Vinay,

I finally understood.
And indeed, removing the pyc-file in questions solves the problem - at least
temporarily.

Christian