Python: setup of logging, allowing multiline strings: logging.info('foo\nbar')

Question

Up to now I do simple logging to files, and if I log a multiline string, then the result looks like this:

Emitting log:

logging.info('foo\nbar') 

Logfile:

2018-03-05 10:51:53 root.main +16: INFO     [28302] foo

bar

Up to now all lines which do not contain "INFO" or "DEBUG" get reported to operators.

This means the line bar gets reported. This is a false positive.

Environment: Linux.

How to set up logging in Python to keep the INFO foo\nbar in one string and ignore the whole string since it is only "INFO"?

Note: Yes, you can filter the logging in the interpreter. Unfortunately this is not what the question is about. This question is different. First the logging happens. Then the logs get parsed.

Here is a script to reproduce it:

import sys
import logging


def set_up_logging(level=logging.INFO):
    root_logger = logging.getLogger()
    root_logger.setLevel(level)
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(
        logging.Formatter('%(asctime)s %(name)s: %(levelname)-8s [%(process)d] %(message)s', '%Y-%m-%d %H:%M:%S'))
    root_logger.addHandler(handler)


def main():
    set_up_logging()
    logging.info('foo\nbar')


if __name__ == '__main__':
    main()

After thinking about it again, I think the real question is: Which logging format is feasible? Just removing the newlines in messages which span multiple lines makes some output hard to read for the human eyes. On the other hand the current 1:1 relation between logging.info() and a line in the log file is easy to read. ... I am unsure

Answer 1

I usually have a class to customize logging but you can achieve what you want with a custom logging.Formatter:

import logging

class NewLineFormatter(logging.Formatter):

    def __init__(self, fmt, datefmt=None):
        """
        Init given the log line format and date format
        """
        logging.Formatter.__init__(self, fmt, datefmt)


    def format(self, record):
        """
        Override format function
        """
        msg = logging.Formatter.format(self, record)

        if record.message != "":
            parts = msg.split(record.message)
            msg = msg.replace('\n', '\n' + parts[0])

        return msg

The format() function above splits lines and replicates the timestamp/logging-preamble in each line (after every \n)

Now you need to attach the formatter to the root logger. You can actually attach it to any handler if you build your own logging setup/structure:

# Basic config as usual
logging.basicConfig(level=logging.DEBUG)

# Some globals/consts
DATEFORMAT = '%d-%m-%Y %H:%M:%S'
LOGFORMAT = '%(asctime)s %(process)s %(levelname)-8s %(filename)15s-%(lineno)-4s: %(message)s'

# Create a new formatter
formatter = NewLineFormatter(LOGFORMAT, datefmt=DATEFORMAT)

# Attach the formatter on the root logger
lg = logging.getLogger()

# This is a bit of a hack... might be a better way to do this
lg.handlers[0].setFormatter(formatter)


# test root logger
lg.debug("Hello\nWorld")

# test module logger + JSON
lg = logging.getLogger("mylogger")
lg.debug('{\n    "a": "Hello",\n    "b": "World2"\n}')

The above gives you:

05-03-2018 08:37:34 13065 DEBUG     test_logger.py-47  : Hello
05-03-2018 08:37:34 13065 DEBUG     test_logger.py-47  : World
05-03-2018 08:37:34 13065 DEBUG     test_logger.py-51  : {
05-03-2018 08:37:34 13065 DEBUG     test_logger.py-51  :     "a": "Hello",
05-03-2018 08:37:34 13065 DEBUG     test_logger.py-51  :     "b": "World2"
05-03-2018 08:37:34 13065 DEBUG     test_logger.py-51  : }

Note that I am accessing the .handlers[0] of the root logger which is a bit of a hack but I couldn't find a way around this... Also, note the formatted JSON printing :)