Problem with logging module

[Jeff Shannon]

Steve Erickson wrote:

>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