Log exception with traceback
Use logging.exception
from within the except:
handler/block to log the current exception along with the trace information, prepended with a message.
import logging
LOG_FILENAME = '/tmp/logging_example.out'
logging.basicConfig(filename=LOG_FILENAME, level=logging.DEBUG)
logging.debug('This message should go to the log file')
try:
run_my_stuff()
except:
logging.exception('Got exception on main handler')
raise
Now looking at the log file, /tmp/logging_example.out
:
DEBUG:root:This message should go to the log file
ERROR:root:Got exception on main handler
Traceback (most recent call last):
File "/tmp/teste.py", line 9, in <module>
run_my_stuff()
NameError: name 'run_my_stuff' is not defined
Use exc_info
options may be better, remains warning or error title:
try:
# coode in here
except Exception as e:
logging.error(e, exc_info=True)
My job recently tasked me with logging all the tracebacks/exceptions from our application. I tried numerous techniques that others had posted online such as the one above but settled on a different approach. Overriding traceback.print_exception
.
I have a write up at http://www.bbarrows.com/ That would be much easier to read but Ill paste it in here as well.
When tasked with logging all the exceptions that our software might encounter in the wild I tried a number of different techniques to log our python exception tracebacks. At first I thought that the python system exception hook, sys.excepthook would be the perfect place to insert the logging code. I was trying something similar to:
import traceback
import StringIO
import logging
import os, sys
def my_excepthook(excType, excValue, traceback, logger=logger):
logger.error("Logging an uncaught exception",
exc_info=(excType, excValue, traceback))
sys.excepthook = my_excepthook
This worked for the main thread but I soon found that the my sys.excepthook would not exist across any new threads my process started. This is a huge issue because most everything happens in threads in this project.
After googling and reading plenty of documentation the most helpful information I found was from the Python Issue tracker.
The first post on the thread shows a working example of the sys.excepthook
NOT persisting across threads (as shown below). Apparently this is expected behavior.
import sys, threading
def log_exception(*args):
print 'got exception %s' % (args,)
sys.excepthook = log_exception
def foo():
a = 1 / 0
threading.Thread(target=foo).start()
The messages on this Python Issue thread really result in 2 suggested hacks. Either subclass Thread
and wrap the run method in our own try except block in order to catch and log exceptions or monkey patch threading.Thread.run
to run in your own try except block and log the exceptions.
The first method of subclassing Thread
seems to me to be less elegant in your code as you would have to import and use your custom Thread
class EVERYWHERE you wanted to have a logging thread. This ended up being a hassle because I had to search our entire code base and replace all normal Threads
with this custom Thread
. However, it was clear as to what this Thread
was doing and would be easier for someone to diagnose and debug if something went wrong with the custom logging code. A custome logging thread might look like this:
class TracebackLoggingThread(threading.Thread):
def run(self):
try:
super(TracebackLoggingThread, self).run()
except (KeyboardInterrupt, SystemExit):
raise
except Exception, e:
logger = logging.getLogger('')
logger.exception("Logging an uncaught exception")
The second method of monkey patching threading.Thread.run
is nice because I could just run it once right after __main__
and instrument my logging code in all exceptions. Monkey patching can be annoying to debug though as it changes the expected functionality of something. The suggested patch from the Python Issue tracker was:
def installThreadExcepthook():
"""
Workaround for sys.excepthook thread bug
From
http://spyced.blogspot.com/2007/06/workaround-for-sysexcepthook-bug.html
(https://sourceforge.net/tracker/?func=detail&atid=105470&aid=1230540&group_id=5470).
Call once from __main__ before creating any threads.
If using psyco, call psyco.cannotcompile(threading.Thread.run)
since this replaces a new-style class method.
"""
init_old = threading.Thread.__init__
def init(self, *args, **kwargs):
init_old(self, *args, **kwargs)
run_old = self.run
def run_with_except_hook(*args, **kw):
try:
run_old(*args, **kw)
except (KeyboardInterrupt, SystemExit):
raise
except:
sys.excepthook(*sys.exc_info())
self.run = run_with_except_hook
threading.Thread.__init__ = init
It was not until I started testing my exception logging I realized that I was going about it all wrong.
To test I had placed a
raise Exception("Test")
somewhere in my code. However, wrapping a a method that called this method was a try except block that printed out the traceback and swallowed the exception. This was very frustrating because I saw the traceback bring printed to STDOUT but not being logged. It was I then decided that a much easier method of logging the tracebacks was just to monkey patch the method that all python code uses to print the tracebacks themselves, traceback.print_exception. I ended up with something similar to the following:
def add_custom_print_exception():
old_print_exception = traceback.print_exception
def custom_print_exception(etype, value, tb, limit=None, file=None):
tb_output = StringIO.StringIO()
traceback.print_tb(tb, limit, tb_output)
logger = logging.getLogger('customLogger')
logger.error(tb_output.getvalue())
tb_output.close()
old_print_exception(etype, value, tb, limit=None, file=None)
traceback.print_exception = custom_print_exception
This code writes the traceback to a String Buffer and logs it to logging ERROR. I have a custom logging handler set up the 'customLogger' logger which takes the ERROR level logs and send them home for analysis.