Strange: the registrar only uses the formatting of the first handler for exceptions

Question

I am watching how the registration module works in a funny way. Did I miss something?

I do the usual thing with two handlers: StreamHandler for logging only INFO and higher for the console and FileHandler, which will also handle all DEBUG information.

This worked until I decided that I had a different format for exceptions. I wanted to get the full stack in the file, but only the type of exception and value on the console. Since handlers have a setFormatter function, and since it seems easy to write a subclass of logging.Formatter, I thought it would work.

The console handler and file handler have their own formatter. Print statements in code prove this. However, when calling logger.exception, only the Exception format will be used for the first handler added => the exception is logged in a file with the format that it should have in the console. Reorder the line order of logger.addHandler and then the formatException of the file handler that is used everywhere.

import logging import sys class ConsoleFormatter(logging.Formatter): def formatException(self, exc_info): # Ugly but obvious way to see who talking. return "CONSOLE EXCEPTION %s: %s" % exc_info[:2] def setup(path): logger = logging.getLogger() # file_handler = logging.FileHandler(path, mode='w') if __debug__: file_handler.setLevel(logging.DEBUG) else: file_handler.setLevel(logging.INFO) formatter = logging.Formatter("%(asctime)s %(levelname)-8s " "%(name)-16s %(message)s " "[%(filename)s@%(lineno)d in %(funcName)s]") file_handler.setFormatter(formatter) # console_handler = logging.StreamHandler(sys.stderr) console_handler.setLevel(logging.INFO) console_formatter = ConsoleFormatter("%(levelname)-8s - %(message)s") console_handler.setFormatter(console_formatter) # >>> FUN HAPPENS HERE <<< # Only the formatter of the first handler is used ! Both on the console # and in the file. Change the order of these two lines to see. logger.addHandler(console_handler) logger.addHandler(file_handler) # # Proof that the two handlers have different formatters: print logger.handlers print file_handler.formatter.formatException print console_formatter.formatException # logger.setLevel(logging.DEBUG) logger.info("Logger ready.") setup('test.log') logger = logging.getLogger() logger.debug("Only visible in the file.") try: 1/0 except ZeroDivisionError: logger.exception("boom") 

What's happening?

EDIT: By the way, I'm using python 2.6. EDIT: Assign code in code with the variable name "console_formatter".

Answer 1

I found your problem! If you look at logger/__init__.py in the source code for Formatter.format , on line 440 (for py2.6) you will see the following:

  if record.exc_info: # Cache the traceback text to avoid converting it multiple times # (it constant anyway) if not record.exc_text: record.exc_text = self.formatException(record.exc_info) 

This is not true in your case, since you are overriding formatException . If you comment out if not record.exc_text (and correct the indent accordingly), it seems to work as expected.

It seems that the error here is being reported: http://bugs.python.org/issue6435

Answer 2

This is the code I came up with. It does the job :).

 class CachelessFormatter(logging.Formatter): # I came up with that after reading the answers to # http://stackoverflow.com/questions/5875225/ # which pointed me to # http://bugs.python.org/issue6435 # I still think Vinay Sajip has a bit of an attitude :p. def format(self, record): # Disable the caching of the exception text. backup = record.exc_text record.exc_text = None s = logging.Formatter.format(self, record) record.exc_text = backup return s class ConsoleFormatter(CachelessFormatter): def formatException(self, exc_info): return " %s: %s" % exc_info[:2] def setup(path): file_handler = logging.FileHandler(path, mode='w') file_handler.setLevel(logging.DEBUG) formatter = CachelessFormatter("%(asctime)s %(levelname)-8s " "%(name)-16s %(message)s " "[%(filename)s@%(lineno)d in %(funcName)s]") file_handler.setFormatter(formatter) console_handler = logging.StreamHandler(sys.stderr) console_handler.setLevel(logging.INFO) formatter = ConsoleFormatter("%(levelname)-8s - %(message)s") console_handler.setFormatter(formatter) logger = logging.getLogger() logger.addHandler(file_handler) logger.addHandler(console_handler) if __debug__: logger.setLevel(logging.DEBUG) else: logger.setLevel(logging.INFO) logger.info("Logger ready.") if __name__ == '__main__': setup('test.log') logger = logging.getLogger() logger.debug("Only shows in the file") try: 1 / 0 except ZeroDivisionError: pass logger.exception("boom") 

Answer 3

The first time you run your code, I have a trace:

 Traceback (most recent call last): File "logger.py", line 42, in <module> setup('test.log') File "logger.py", line 37, in setup print console_formatter.formatException NameError: global name 'console_formatter' is not defined 

This is probably the source of the problem. The formats were correct when I changed the console_handler code:

 console_handler = logging.StreamHandler(sys.stderr) console_handler.setLevel(logging.INFO) console_formatter = ConsoleFormatter("%(levelname)-8s - %(message)s") console_handler.setFormatter(console_formatter)