Repeated output when logging exceptions

[John Gordon]

I wrote some code to handle and log exceptions in my application.
It works well, but it produces double output for each exception.
How can I fix this?

Here's the pared-down code:

----- main.py
import exceptionLogger
import doStuff

exlog = exceptionLogger.exceptionLogger()

stuff = doStuff.doStuff()

try:
stuff.doit()
except Exception,msg:
exlog.logException()


----- exceptionLogger.py
import traceback
import logging
import os

class exceptionLogger:
loggingLevel = ""
logger = None

def __init__(self):
self.logger = logging.getLogger("foo")
self.loggingLevel = "DEBUG"
if self.loggingLevel == "DEBUG":
self.logger.setLevel(logging.DEBUG)
handler = logging.FileHandler("error.txt")
format = "%(asctime)s %(levelname)-8s %(message)s"
formatter = logging.Formatter(format)
handler.setFormatter(formatter)
self.logger.addHandler(handler)

def logMsg(self,message):
try:
if self.loggingLevel == "DEBUG":
self.logger.debug(message)
except:
self.stopLogging()

def logException(self):
"""Write an exception traceback to the logfile."""
# save the stack trace to a file and then copy the contents of that
# file to the log. (traceback.format_exc would allow us to avoid
# using a temporary file, but it is not available in python 2.3)

TMPFILE = os.tmpfile()
traceback.print_exc(None, TMPFILE)
TMPFILE.flush()
self.logMsg(" ************** EXCEPTION BEGINS **************")
self.logMsgFromFile(TMPFILE)
self.logMsg(" ************** EXCEPTION ENDS **************")

TMPFILE.close()

def logMsgFromFile(self,file):
"""Read the contents of a file into a string and log the string."""
file.seek(0)
msg = ""
for line in file:
msg = msg + line
self.logMsg(msg)

def stopLogging(self):
logging.shutdown()

----- doStuff.py
import exceptionLogger

class doStuff:

def doit(self):
exlog = exceptionLogger.exceptionLogger()
try:
raise ValueError, "hi there"
except Exception:
exlog.logException()


And here's the contents of error.txt:

----- errror.txt
2009-09-24 14:22:23,288 DEBUG ************** EXCEPTION BEGINS **************
2009-09-24 14:22:23,288 DEBUG ************** EXCEPTION BEGINS **************
2009-09-24 14:22:23,288 DEBUG Traceback (most recent call last):
File "/home/gordonj/exception/doStuff.py", line 8, in doit
raise ValueError, "hi there"
ValueError: hi there

2009-09-24 14:22:23,288 DEBUG Traceback (most recent call last):
File "/home/gordonj/exception/doStuff.py", line 8, in doit
raise ValueError, "hi there"
ValueError: hi there

2009-09-24 14:22:23,288 DEBUG ************** EXCEPTION ENDS **************
2009-09-24 14:22:23,288 DEBUG ************** EXCEPTION ENDS **************


As you can see, all of the output is doubled. Header lines, footer lines,
and body text.

Why is this happening? I suspect it's because I'm declaring two instances
of the exceptionLogger class, which ends up calling logger.addHandler()
twice. Is that right?

What would be a better way to handle this?

Thanks.

 

[Vinay Sajip]

Why is this happening?  I suspect it's because I'm declaring two instances
of the exceptionLogger class, which ends up calling logger.addHandler()
twice.  Is that right?

Yes, that's why you get duplicated lines in the log.

What would be a better way to handle this?

I'm not sure why you need all the code you've posted. The logging
package allows you to add tracebacks to your logs by using the
exception() method, which logs an ERROR with a traceback and is
specifically intended for use from within exception handlers. All that
stuff with temporary files seems completely unnecessary, even with
Python 2.3.

In general, avoid adding handlers more than once - which you are
almost guaranteed to not avoid if you do this kind of processing in a
constructor. If you write your applications without using the
exceptionLogger class (not really needed, since logging exceptions
with tracebacks is part and parcel of the logging package's
functionality since its introduction with Python 2.3), what
functionality do you lose?

Regards,

Vinay Sajip

 

[John Gordon]

The logging package allows you to add tracebacks to your logs by using
the exception() method, which logs an ERROR with a traceback and is
specifically intended for use from within exception handlers. All that
stuff with temporary files seems completely unnecessary, even with Python
2.3.

I didn't know about the exception() method. Thanks!

In general, avoid adding handlers more than once - which you are
almost guaranteed to not avoid if you do this kind of processing in a
constructor. If you write your applications without using the
exceptionLogger class (not really needed, since logging exceptions
with tracebacks is part and parcel of the logging package's
functionality since its introduction with Python 2.3), what
functionality do you lose?

I'm trying to encapsulate all the setup work that must be done before any
actual logging occurs: setting the debugging level, choosing the output
filename, declaring a format string, adding the handler, etc.

If I didn't do all that in a class, where would I do it?

 

[Simon Forman]

I didn't know about the exception() method.  Thanks!


I'm trying to encapsulate all the setup work that must be done before any
actual logging occurs: setting the debugging level, choosing the output
filename, declaring a format string, adding the handler, etc.

If I didn't do all that in a class, where would I do it?

Put it in a module. :]

 

[Vinay Sajip]

If I didn't do all that in a class, where would I do it?

You could, for example, use the basicConfig() function to do it all
for you.

import logging
logging.basicConfig(filename='/path/to/my/log',level=logging.DEBUG)

logging.debug('This message should go to the log file')

Here's the documentation link for simple examples:

http://docs.python.org/library/logging.html#simple-examples

Here's the link for basicConfig:

http://docs.python.org/library/logging.html#logging.basicConfig

Regards,

Vinay Sajip

 

[Chris Withers]

I'm not sure why you need all the code you've posted. The logging
package allows you to add tracebacks to your logs by using the
exception() method, which logs an ERROR with a traceback and is
specifically intended for use from within exception handlers.

You can also use the exc_info=True parameter with any logging method...

Chris

 

[Chris Withers]

If I didn't do all that in a class, where would I do it?

I find the configureLoggers method of ZConfig most convenient for this:

http://pypi.python.org/pypi/ZConfig

cheers,

Chris