Multi-line logging in Python

Question

I'm using Python 3.3.5 and the logging module to log information to a local file (from different threads). There are cases where I'd like to output some additional information, without knowing exactly what that information will be (e.g. it might be one single line of text or a dict).

What I'd like to do is add this additional information to my log file, after the log record has been written. Furthermore, the additional info is only necessary when the log level is error (or higher).

Ideally, it would look something like:

2014-04-08 12:24:01 - INFO     - CPU load not exceeded
2014-04-08 12:24:26 - INFO     - Service is running
2014-04-08 12:24:34 - ERROR    - Could not find any active server processes
Additional information, might be several lines.
Dict structured information would be written as follows:
key1=value1
key2=value2
2014-04-08 12:25:16 - INFO     - Database is responding

Short of writing a custom log formatter, I couldn't find much which would fit my requirements. I've read about filters and contexts, but again this doesn't seem like a good match.

Alternatively, I could just write to a file using the standard I/O, but most of the functionality already exists in the Logging module, and moreover it's thread-safe.

Any input would be greatly appreciated. If a custom log formatter is indeed necessary, any pointers on where to start would be fantastic.

Answer 1

Keeping in mind that many people consider a multi-line logging message a bad practice (understandably so, since if you have a log processor like DataDog or Splunk which are very prepared to handle single line logs, multi-line logs will be very hard to parse), you can play with the extra parameter and use a custom formatter to append stuff to the message that is going to be shown (take a look to the usage of 'extra' in the logging package documentation).

import logging

class CustomFilter(logging.Filter):
    def filter(self, record):
        if hasattr(record, 'dct') and len(record.dct) > 0:
            for k, v in record.dct.iteritems():
                record.msg = record.msg + '\n\t' + k + ': ' + v
        return super(CustomFilter, self).filter(record)
        
if __name__ == "__main__":
    logging.getLogger().setLevel(logging.DEBUG)
    extra_logger = logging.getLogger('extra_logger')
    extra_logger.setLevel(logging.INFO)
    extra_logger.addFilter(CustomFilter())
    logging.debug("Nothing special here... Keep walking")
    extra_logger.info("This shows extra",
                      extra={'dct': {"foo": "bar", "baz": "loren"}})
    extra_logger.debug("You shouldn't be seeing this in the output")
    extra_logger.setLevel(logging.DEBUG)
    extra_logger.debug("Now you should be seeing it!")
    

That code outputs:

DEBUG:root:Nothing special here... Keep walking
INFO:extra_logger:This shows extra
        foo: bar
        baz: loren
DEBUG:extra_logger:Now you should be seeing it!

I still recommend calling the super's filter function in your custom filter, mainly because that's the function that decides whether showing the message or not (for instance, if your logger's level is set to logging.INFO, and you log something using extra_logger.debug, that message shouldn't be seen, as shown in the example above)