Problem with logging module

[Steve Erickson]

I have a logger class that uses the Python logging module. When I
call it within a program using the unittest module, I get one line in
the log file for the first test, two identical ones for the second,
etc. I'm using local variables, which should go out of context with
each test. Setting the 'propagate' property to False doesn't have any
affect.

import logging, os, signal, sys
from datetime import datetime

class Logger:
def __init__(self, dir, name):
self.dir = dir
self.name = name

self.logger = logging.getLogger(name)
self.logger.propagate = False
handler = logging.FileHandler(dir + '/' + name + '.log')
self.logger.addHandler(handler)
self.logger.setLevel(logging.INFO)

def log(self, text):
msg = datetime.utcnow().isoformat(' ') + ' ' + sys.argv[0] + ' -- '
+ text
self.logger.info(msg)

import os, sys, unittest
import log

class Test(unittest.TestCase):

def test_1(self):
homedir = sys.path[0]
logger = log.Logger(homedir, "test")
logger.log("Test 1")

def test_2(self):
homedir = sys.path[0]
logger = log.Logger(homedir, "test")
logger.log("Test 2")

def test_3(self):
homedir = sys.path[0]
logger = log.Logger(homedir, "test")
logger.log("Test 3")

def test_4(self):
homedir = sys.path[0]
logger = log.Logger(homedir, "test")
logger.log("Test 4")

def test_5(self):
homedir = sys.path[0]
logger = log.Logger(homedir, "test")
logger.log("Test 5")

if __name__ == '__main__':
unittest.main()

And the output file looks like:

2004-10-13 15:54:08.321112 test.py -- Test 1
2004-10-13 15:54:08.326594 test.py -- Test 2
2004-10-13 15:54:08.326594 test.py -- Test 2
2004-10-13 15:54:08.329742 test.py -- Test 3
2004-10-13 15:54:08.329742 test.py -- Test 3
2004-10-13 15:54:08.329742 test.py -- Test 3
2004-10-13 15:54:08.333411 test.py -- Test 4
2004-10-13 15:54:08.333411 test.py -- Test 4
2004-10-13 15:54:08.333411 test.py -- Test 4
2004-10-13 15:54:08.333411 test.py -- Test 4
2004-10-13 15:54:08.336997 test.py -- Test 5
2004-10-13 15:54:08.336997 test.py -- Test 5
2004-10-13 15:54:08.336997 test.py -- Test 5
2004-10-13 15:54:08.336997 test.py -- Test 5
2004-10-13 15:54:08.336997 test.py -- Test 5

 

[Diez B. Roggisch]

self.logger = logging.getLogger(name)

self.logger.propagate = False
handler = logging.FileHandler(dir + '/' + name + '.log')
self.logger.addHandler(handler)

^^^^
Thats your problem - only set the handler once for the runtime of your
program.

 

[Jeff Shannon]

I have a logger class that uses the Python logging module. When I
call it within a program using the unittest module, I get one line in
the log file for the first test, two identical ones for the second,
etc. I'm using local variables, which should go out of context with
each test. Setting the 'propagate' property to False doesn't have any
affect.

import logging, os, signal, sys
from datetime import datetime

class Logger:
def __init__(self, dir, name):
self.dir = dir
self.name = name

self.logger = logging.getLogger(name)
self.logger.propagate = False
handler = logging.FileHandler(dir + '/' + name + '.log')
self.logger.addHandler(handler)
self.logger.setLevel(logging.INFO)

def log(self, text):
msg = datetime.utcnow().isoformat(' ') + ' ' + sys.argv[0] + ' -- '
+ text
self.logger.info(msg)

As I understand it, logging uses internal (global/"static") data
structures to keep track of all instantiated loggers. Thus, each time
you create an instance of your logger class, it gets the (pre-existing)
logging.Logger instance named "test" and adds a *new* FileHandler to
it. Thus, you end up with an ever-growing list of (identical) handlers
on the same logging.Logger instance.

You can fix this either by using a global log.Logger object, or by
having a separate initialize() method for it that's called only once and
which adds the handler and sets the logging level.

By the way, you can also set a formatter on the handler which will
automatically include the time (and probably sys.argv[0] as well). With
that done, you could do away with your class. Just initialize the
logger once, and then in each test case, you can do

logging.getLogger("test").info(text)

The logging module will keep track of all of the handler and formatting
details for you.

Jeff Shannon
Technician/Programmer
Credit International

 

[Steve Erickson]

^^^^
Thats your problem - only set the handler once for the runtime of your
program.

Thanks. Coming from C++, I thought that the local logger instance in
each test method would go away when I went out of the context of the
method. Sounds like the logging class in Python maintains artifacts
that affect instantiations in other methods. Or maybe I'm confused
about how Python handles local versus class variables.

 

[Diez B. Roggisch]

Thanks. Coming from C++, I thought that the local logger instance in
each test method would go away when I went out of the context of the
method. Sounds like the logging class in Python maintains artifacts
that affect instantiations in other methods. Or maybe I'm confused
about how Python handles local versus class variables.

Nothing to do with python - its the way logging is designed, and it makes
sense: if at one place you attach the logger named foo.bar to a handler,
and at another place obtain a reference to foo.bar to log some stuff, you
don't want to reiterate the whole handler-attaching stuff.

So you simply abused the logging module - just set up the logger once, and
then obtain a reference to it using logging.getLogger whenever you need it
- that totally rids you of your logger class, that so far doesn't do much
anyway. Like this:

------
logger = logging.getLogger(name)
logger.propagate = False
handler = logging.FileHandler(dir + '/' + name + '.log')
logger.addHandler(handler)

class Test:

def test_me(self):
logger = logging.getLogger(name)
logger.debug("test_me")

 

[Steve Erickson]

Thanks a bunch for your patience and explanations. It would be nice
if there was a method of checking the logger or handler for an
instance of it:

logger = logging.getLogger(name)
if not logger.handler(dir + '/' + name + '.log'):
logger.propagate = False
handler = logging.FileHandler(dir + '/' + name + '.log')
logger.addHandler(handler)

 

[Diez B. Roggisch]

Thanks a bunch for your patience and explanations. It would be nice
if there was a method of checking the logger or handler for an
instance of it:

logger = logging.getLogger(name)
if not logger.handler(dir + '/' + name + '.log'):
logger.propagate = False
handler = logging.FileHandler(dir + '/' + name + '.log')
logger.addHandler(handler)

There is the (unfortunately undocumented) property "handlers" on a Logger
insnstance that you can use:

if not fname in [h.stream.name for h in logger.handlers]:
...

 

[Vinay Sajip]

[Steve]

if not logger.handler(dir + '/' + name + '.log'):

[Diez]
There is the (unfortunately undocumented) property "handlers" on a Logger
insnstance that you can use:

The handlers property is not documented because it is not normally
meant to be used by clients of the logging package. Since handlers can
include third party handlers, the answer to 'what is an existing
handler?' is not in general known to the logging package. This is why
something like the functionality suggested by Steve is not provided in
the box.

Regards,


Vinay Sajip

 

[Steve Erickson]

Thanks a bunch for your patience and explanations. It would be nice
if there was a method of checking the logger or handler for an
instance of it:

logger = logging.getLogger(name)
if not logger.handler(dir + '/' + name + '.log'):
logger.propagate = False
handler = logging.FileHandler(dir + '/' + name + '.log')
logger.addHandler(handler)

There is the (unfortunately undocumented) property "handlers" on a Logger
insnstance that you can use:

if not fname in [h.stream.name for h in logger.handlers]:
...

Excellent!! Thanks.