How to output additional information when logging with python's logging module

Introduction

A story about changing the representation of the log output by the python logging module. There are roughly three ways

--Additional log output to the extent supported by default --Log output by passing additional information when passing log output --Log output with specific information added to all log output

Additional log output to the extent supported by default

Output when nothing is set

In the python logging module, you can change the representation of the output by changing the format.

import logging
logger = logging.getLogger(__name__)

logging.basicConfig(level=logging.DEBUG)

logger.info("hello")
logger.info("bye")

If you use logging.basicConfig () without setting anything, the output will be as follows.

INFO:__main__:hello
INFO:__main__:bye

When the formatter used for log output is changed

You can change the display by changing the formatter. The change itself can also be done by adding the format option to basicConfig.

import logging
logger = logging.getLogger(__name__)

fmt = "%(asctime)s %(levelname)s %(name)s :%(message)s"
logging.basicConfig(level=logging.DEBUG, format=fmt)
# logging.root.handlers[0].setFormatter(logging.Formatter(fmt=fmt))


logger.info("hello")
logger.info("bye")

The output will be as follows.

2016-10-10 19:49:50,692 INFO __main__ :hello
2016-10-10 19:49:50,693 INFO __main__ :bye

You can do what you can by default. The following information can be added.

--asctime --current time --levelname --Log level (e.g. DEBUG, INFO, ERROR, ...) --message --Message (string passed to logger.info () etc.) --pathname --The physical path (absolute path) from which the log was called --funcName --The name of the function from which the log was called

See below for details.

http://docs.python.jp/3/library/logging.html#logrecord-attributes

Log output by passing additional information when passing log output

It is possible to add additional information at the time of output by passing additional information each time the log is output. Specifically, specify the extra option. The value in the dict specified by the extra option will be touched from the formatter of the log output. (To be exact, it will be held in __dict__ of the LogRecord object)

For example, let's update the information of who and cost as follows. Approximately format string mini-language notation can be used to format strings.

import logging
import random
logger = logging.getLogger(__name__)

fmt = "%(message)10s [who=%(who)s cost=%(cost).5f]"
logging.basicConfig(level=logging.DEBUG, format=fmt)

logger.info("hello", extra={"who": "foo", "cost": random.random() * 5})
logger.info("bye", extra={"who": "foo", "cost": random.random() * 5})

The output will be as follows.

     hello [who=foo cost=2.48451]
       bye [who=foo cost=0.79263]

By the way, note that KeyError will occur if there is missing information.

logger.info("noop")  # KeyError: 'who'

Log output with specific information added to all log output

There are times when you want to always add certain information instead of passing it each time. In this case, it is better to change LogRecordFactory.

For example, let's display the same message (counted by fmt character string) called call_count with the number of log outputs added.

import logging
from collections import defaultdict
logger = logging.getLogger(__name__)


class Extension:
    def __init__(self):
        self.c = defaultdict(int)


class LogRecordExtension(logging.LogRecord):
    extension = Extension()

    def __init__(self, *args, **kwargs):
        super().__init__(*args, **kwargs)
        self.extension.c[self.msg] += 1
        self.call_count = self.extension.c[self.msg]


if __name__ == "__main__":
    logging.basicConfig(level=logging.DEBUG, format="%(asctime)s %(levelname)s %(message)s[%(call_count)d]")
    logging.setLogRecordFactory(LogRecordExtension)

    logger.info("hello")
    logger.info("hello")

    logger.info("%s: hello", "foo")
    logger.info("%s: hello", "bar")

The output will be as follows.

2016-10-10 20:01:33,337 INFO hello[1]
2016-10-10 20:01:33,338 INFO hello[2]
2016-10-10 20:01:33,338 INFO foo: hello[1]
2016-10-10 20:01:33,338 INFO bar: hello[2]