Multi-line logging in Python

It seems that I made a small typo when defining my LogFormatter string: by accidentally escaping the newline character, I wrongly assumed that writing multi-line output to a log file was not possible.

Cheers to @Barafu for pointing this out (which is why I assigned him the correct answer).

Here's the sample code:

import logging
lf = logging.Formatter('%(levelname)-8s - %(message)s\n%(detail)s')
lh = logging.FileHandler(filename=r'c:\temp\test.log')
lh.setFormatter(lf)
log = logging.getLogger()
log.setLevel(logging.DEBUG)
log.addHandler(lh)
log.debug('test', extra={'detail': 'This is a multi-line\ncomment to test the formatter'})

The resulting output would look like this:

DEBUG    - test
This is a multi-line
comment to test the formatter

Caveat:

If there is no detail information to log, and you pass an empty string, the logger will still output a newline. Thus, the remaining question is: how can we make this conditional?

One approach would be to update the logging formatter before actually logging the information, as described here.

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)

i'm using a simple line splitter in my smaller applications:

for line in logmessage.splitlines():
            writemessage = logtime + " - " + line + "\n"
            logging.info(str(writemessage))

Note that this is not thread-safe and should probably only be used in log-volume logging applications.

However you can output to log almost anything, as it will preserve your formatting. I have used it for example to output JSON API responses formatted using: json.dumps(parsed, indent=4, sort_keys=True)

I just add \n symbols to the output text.