Learn about logging using Python's logging module ①

Introduction

I'm sure many people have done this by specifying a logger name and using a logger instance (like getLogger (__ name__) in python). I think there are many people who think only of that logger name and the name to be logged. So, I tried to learn how to make a common logging library with simple Python.

Concerns

Here's a quick summary of your concerns when logging. Keep in mind that these are not necessary and sufficient, and that this article does not provide a solution for all of them.

――How do you use the name you set when using logger? --Is logger thread safe? (Isn't it an accident to write in one file from multiple threads?) --Is logger process safe? (Is it possible to write in one file from multiple processes without an accident?) --Is logging a blocking I / O?

Premise

This article is intended for Python and Flask, which I often use to implement validation code. On the other hand, the concerns mentioned above are common to languages and operating systems (commonly used like Linux). In other words, knowing how the language or framework selected this time is approaching / what the programmer should care about when using these can also be used when using other languages or frameworks. I think it might be.

Start studying

The introduction has become longer.

Logger instance and Logger tree

About Logger instance

To understand the logging library, you first need to know about the Logger instance.

When writing logs using the logging package, we ask the Logger instance to do the job. The Logger instance is designed to be the ** only instance ** that takes responsibility for certain logging activities. A good way for programmers to use a Logger instance in their code is to call a logging function attached to the logging module (such as logging.warning ()) or get a Logger instance with getLogger (name = None). Is to call that logging method. (It's not about creating a new instance from the Logger class!)

As you can see by reading the logging module, each logging function in the logging module itself calls the [root logger instance method]. Yes](https://github.com/python/cpython/blob/3.8/Lib/logging/init.py#L2047). The root logger is generated when the logging module is loaded and is kept within the scope of the module.

How to use it is like this.

use_root_logger.py

import logging

# https://docs.python.org/ja/3/library/logging.html
# https://docs.python.org/ja/3/howto/logging.html
logging.warning('Watch out!')  # will print a message to the console
logging.info('I told you so')  # will not print anything

Next, about the Logger instance. There is only one Logger instance on the same process that can be obtained by getLogger (name = None). In other words, it's a Singleton. Each Logger instance is managed by logging.Manager, and logging.Manager itself is [instantiated](https: /) so that it becomes a class field of the logging.Logger class when the logging module is loaded. /github.com/python/cpython/blob/3.8/Lib/logging/init.py#L1890). logging.Manager looks for an existing Logger instance with the argument name as a key and returns that instance if it exists.

You don't have to think hard, and this is how to use it.

use_get_logger.py

import logging

# https://docs.python.org/ja/3/library/logging.html
# https://docs.python.org/ja/3/howto/logging.html
logger = logging.getLogger('simple_example')
#Omission
logger.warning('warn message')

Logger tree

The word root logger came out. In many logging libraries, Logger is a Singleton and has a tree structure. (At least I know python logging, java java.util.logging, org.apache.logging.log4j. C # NLog was certainly the same.)

The Logger in the logging module is designed to have a tree structure with the root logger as the apex. It may be easier to imagine that it is a directory structure for people in the Internet area and Windows infrastructure engineers like me. There may be many purposes for this design, but I think the biggest advantage is that namespaces can be separated and that the only resource can be clearly shown. Since logging.Manager identifies and manages Logger instances by strings, it is easy to maintain the uniqueness of the resource called Logger instance because the method of making a tree structure like FQDN is dead.

For example, let's say you have created a support service for travelers in Gero Onsen. The reservation system has the subsystem ID "book", the reservation web has "web", the API has "api", OSS is used as the development framework, and the logs are separated because they are operated by different teams. If so, it would be useful to be able to divide the Logger instance by that unit. Like this.

gero_onsen.py

web_book_logger = logging.getLogger('gero.book.web')
... #Set a handler to insert into the DB displayed on the management user screen

api_book_logger = logging.getLogger('gero.book.api')
... #Set handlers to fly to CloudWatch Logs

from flask import Flask
app = Flask('gero')
app.logger.addHandler(...) #Set up a handler to notify the infrastructure team of Slack

Since the logger name can be classified and identified by connecting it with ., the risk of accidentally wearing the name and, as a result, overwriting the operation of Logger can be reduced.

There is also another feature that is convenient for developers. That is, the contents set in the upper Logger are inherited by the child.

In the previous example, if you change the log level of "gero. ** book **", the log levels of "gero. ** book.web **" and "gero. ** book.api **" will also change. , Gero.book ". You can switch from the debug state to the non-deubg state by switching only the upper Logger instance without changing the settings of all Logger instances. This is useful.

• As will be described later, this is more like the child using the parent's Logger or Handler, rather than the settings being propagated from the parent to the child.

Let's move it.

logger_tree_exam_child1.py

import logging
import sys


def init_logger():
    # INIT
    global gero_book_logger
    global gero_question_logger
    global gero_book_web_logger
    # gero.book
    gero_book_logger = logging.getLogger('gero.book')
    gero_book_handler = logging.StreamHandler()
    gero_book_formatter = logging.Formatter(fmt='%(asctime)-15s [%(name)s] %(message)s')
    gero_book_handler.setFormatter(gero_book_formatter)
    gero_book_logger.addHandler(gero_book_handler)

    # gero.question
    gero_question_logger = logging.getLogger('gero_question')
    gero_question_handler = logging.StreamHandler()
    gero_question_formatter = logging.Formatter(fmt='%(asctime)-15s [%(name)s] %(message)s')
    gero_question_handler.setFormatter(gero_question_formatter)
    gero_question_logger.addHandler(gero_question_handler)

    # gero.book.web (gero.Make a child of book)
    gero_book_web_logger = logging.getLogger('gero.book.web')
    # handler,formatter not set


init_logger()

# PRINT
print('test 1-1: "gero.book.Is there a web log?"', file=sys.stderr)
# SET LOG LEVEL (gero.book.Do not set on the web)
gero_book_logger.setLevel(logging.DEBUG)
gero_question_logger.setLevel(logging.INFO)

# gero.book
gero_book_logger.debug('debug now')
gero_book_logger.info('info now')
gero_book_logger.warning('warning now')
gero_book_logger.error('error now')
gero_book_logger.critical('critical now')

# gero.question
gero_question_logger.debug('debug now')
gero_question_logger.info('info now')
gero_question_logger.warning('warning now')
gero_question_logger.error('error now')
gero_question_logger.critical('critical now')

# gero.book.web
gero_book_web_logger.debug('debug now')
gero_book_web_logger.info('info now')
gero_book_web_logger.warning('warning now')
gero_book_web_logger.error('error now')
gero_book_web_logger.critical('critical now')

print('test 1-2: "gero.If you change the error level of book logger, gero.book.Will the level of the web change?"', file=sys.stderr)
gero_book_logger.setLevel(logging.ERROR)

# gero.book.web
gero_book_web_logger.debug('debug now')
gero_book_web_logger.info('info now')
gero_book_web_logger.warning('warning now')
gero_book_web_logger.error('error now')
gero_book_web_logger.critical('critical now')

The execution result is as follows.

test 1-1: "gero.book.Is there a web log?"
2020-09-05 13:51:02,874 [gero.book] debug now
2020-09-05 13:51:02,875 [gero.book] info now
2020-09-05 13:51:02,875 [gero.book] warning now
2020-09-05 13:51:02,875 [gero.book] error now
2020-09-05 13:51:02,875 [gero.book] critical now
2020-09-05 13:51:02,875 [gero_question] info now
2020-09-05 13:51:02,875 [gero_question] warning now
2020-09-05 13:51:02,875 [gero_question] error now
2020-09-05 13:51:02,875 [gero_question] critical now
2020-09-05 13:51:02,875 [gero.book.web] debug now
2020-09-05 13:51:02,875 [gero.book.web] info now
2020-09-05 13:51:02,875 [gero.book.web] warning now
2020-09-05 13:51:02,875 [gero.book.web] error now
2020-09-05 13:51:02,876 [gero.book.web] critical now
test 1-2: "gero.If you change the error level of book logger, gero.book.Will the level of the web change?"
2020-09-05 13:51:02,876 [gero.book.web] error now
2020-09-05 13:51:02,876 [gero.book.web] critical now

Process finished with exit code 0

By changing the log level of the parent Logger instance, you can see that the log output level of the child changes. So what if you set your own log level for the child Logger instance, or if you set your own Handler for the child Loggger instance, and you change the log level for the parent Logger instance?

logger_tree_exam_child1.py

import logging
import sys

"""If you set your own log level for child Logger instances
"""


def init_logger():
    # INIT
    global gero_book_logger
    global gero_book_web_logger
    # gero.book
    gero_book_logger = logging.getLogger('gero.book')
    gero_book_handler = logging.StreamHandler()
    gero_book_formatter = logging.Formatter(fmt='%(asctime)-15s [%(name)s] %(message)s')
    gero_book_handler.setFormatter(gero_book_formatter)
    gero_book_logger.addHandler(gero_book_handler)

    # gero.book.web (gero.Make a child of book)
    gero_book_web_logger = logging.getLogger('gero.book.web')
    # handler,formatter not set


init_logger()

# PRINT
print('test 2-1: "gero.book.After setting the log level to the web separately, gero.Change book log level"', file=sys.stderr)
# SET LOG LEVEL
gero_book_logger.setLevel(logging.DEBUG)
gero_book_web_logger.setLevel(logging.DEBUG)

print('Change before', file=sys.stderr)
# gero.book
gero_book_logger.debug('Should come out')
gero_book_logger.info('Should come out')
gero_book_logger.warning('Should come out')
gero_book_logger.error('Should come out')
gero_book_logger.critical('Should come out')

# gero.book.web
gero_book_web_logger.debug('Should come out')
gero_book_web_logger.info('Should come out')
gero_book_web_logger.warning('Should come out')
gero_book_web_logger.error('Should come out')
gero_book_web_logger.critical('Should come out')

print('After change', file=sys.stderr)
gero_book_logger.setLevel(logging.WARNING)

# gero.book
gero_book_logger.debug('Does not appear')
gero_book_logger.info('Does not appear')
gero_book_logger.warning('Should come out')
gero_book_logger.error('Should come out')
gero_book_logger.critical('Should come out')

# gero.book.web
gero_book_web_logger.debug('Will you come out? Does not appear?')
gero_book_web_logger.info('Will you come out? Does not appear?')
gero_book_web_logger.warning('Should come out')
gero_book_web_logger.error('Should come out')
gero_book_web_logger.critical('Should come out')

The execution result is as follows. It seems that the log level set for the instance of the child gero.book.web is working.

test 2-1: "gero.book.After setting the log level to the web separately, gero.Change book log level"
Change before
2020-09-06 03:11:27,524 [gero.book]Should come out
2020-09-06 03:11:27,525 [gero.book]Should come out
2020-09-06 03:11:27,525 [gero.book]Should come out
2020-09-06 03:11:27,525 [gero.book]Should come out
2020-09-06 03:11:27,525 [gero.book]Should come out
2020-09-06 03:11:27,525 [gero.book.web]Should come out
2020-09-06 03:11:27,525 [gero.book.web]Should come out
2020-09-06 03:11:27,525 [gero.book.web]Should come out
2020-09-06 03:11:27,525 [gero.book.web]Should come out
2020-09-06 03:11:27,525 [gero.book.web]Should come out
After change
2020-09-06 03:11:27,525 [gero.book]Should come out
2020-09-06 03:11:27,525 [gero.book]Should come out
2020-09-06 03:11:27,525 [gero.book]Should come out
2020-09-06 03:11:27,525 [gero.book.web]Will you come out? Does not appear?
2020-09-06 03:11:27,526 [gero.book.web]Will you come out? Does not appear?
2020-09-06 03:11:27,526 [gero.book.web]Should come out
2020-09-06 03:11:27,526 [gero.book.web]Should come out
2020-09-06 03:11:27,526 [gero.book.web]Should come out

Process finished with exit code 0

Now let's add a Handler to gero.book.web. This time, we don't set the log level for gero.book.web.

logger_tree_exam_child3.py

import logging
import sys

"""If you set your own Handler for a child Loggger instance
"""


def init_logger():
    # INIT
    global gero_book_logger
    global gero_book_web_logger
    # gero.book
    gero_book_logger = logging.getLogger('gero.book')
    gero_book_handler = logging.StreamHandler()
    gero_book_formatter = logging.Formatter(fmt='%(asctime)-15s [%(name)s] %(message)s')
    gero_book_handler.setFormatter(gero_book_formatter)
    gero_book_logger.addHandler(gero_book_handler)

    # gero.book.web (gero.Make a child of book)
    gero_book_web_logger = logging.getLogger('gero.book.web')


init_logger()

# PRINT
print('test 3-1: "gero.book.After setting the log level to the web separately, gero.Change book log level"', file=sys.stderr)
# SET LOG LEVEL
gero_book_logger.setLevel(logging.DEBUG)

print('Change before', file=sys.stderr)
# gero.book
gero_book_logger.debug('Should come out')
gero_book_logger.info('Should come out')
gero_book_logger.warning('Should come out')
gero_book_logger.error('Should come out')
gero_book_logger.critical('Should come out')

# gero.book.web
gero_book_web_logger.debug('Should come out')
gero_book_web_logger.info('Should come out')
gero_book_web_logger.warning('Should come out')
gero_book_web_logger.error('Should come out')
gero_book_web_logger.critical('Should come out')

print('After change', file=sys.stderr)
print('- gero.book.Handler added to web side', file=sys.stderr)
gero_book_web_handler = logging.StreamHandler()
gero_book_web_formatter = logging.Formatter(fmt='%(asctime)-15s [%(name)s] ### this is web ### %(message)s')
gero_book_web_handler.setFormatter(gero_book_web_formatter)
gero_book_web_logger.addHandler(gero_book_web_handler)
print('- gero.Change log level of book to WARNING', file=sys.stderr)
gero_book_logger.setLevel(logging.WARNING)

# gero.book
gero_book_logger.debug('Does not appear')
gero_book_logger.info('Does not appear')
gero_book_logger.warning('Should come out')
gero_book_logger.error('Should come out')
gero_book_logger.critical('Should come out')

# gero.book.web
gero_book_web_logger.debug('Will you come out? Does not appear?')
gero_book_web_logger.info('Will you come out? Does not appear?')
gero_book_web_logger.warning('Should come out')
gero_book_web_logger.error('Should come out')
gero_book_web_logger.critical('Should come out')

print(gero_book_web_logger.handlers)

The execution result is as follows. There are two logs for gero.book.web. Since the added Handler is really "added", the behavior is that both the parent Logger's Handler and the original Handler are issued. Also, for the log of the original Handler, it works according to the parent's LogLevel.

test 3-1: "gero.book.After setting the log level to the web separately, gero.Change book log level"
Change before
2020-09-06 03:21:11,709 [gero.book]Should come out
2020-09-06 03:21:11,709 [gero.book]Should come out
2020-09-06 03:21:11,710 [gero.book]Should come out
2020-09-06 03:21:11,710 [gero.book]Should come out
2020-09-06 03:21:11,710 [gero.book]Should come out
2020-09-06 03:21:11,710 [gero.book.web]Should come out
2020-09-06 03:21:11,710 [gero.book.web]Should come out
2020-09-06 03:21:11,710 [gero.book.web]Should come out
2020-09-06 03:21:11,710 [gero.book.web]Should come out
2020-09-06 03:21:11,710 [gero.book.web]Should come out
After change
- gero.book.Handler added to web side
- gero.Change log level of book to WARNING
2020-09-06 03:21:11,710 [gero.book]Should come out
2020-09-06 03:21:11,710 [gero.book]Should come out
2020-09-06 03:21:11,710 [gero.book]Should come out
2020-09-06 03:21:11,711 [gero.book.web] ### this is web ###Should come out
2020-09-06 03:21:11,711 [gero.book.web]Should come out
2020-09-06 03:21:11,711 [gero.book.web] ### this is web ###Should come out
2020-09-06 03:21:11,711 [gero.book.web]Should come out
2020-09-06 03:21:11,711 [gero.book.web] ### this is web ###Should come out
2020-09-06 03:21:11,711 [gero.book.web]Should come out
[<StreamHandler <stderr> (NOTSET)>]

Process finished with exit code 0

In the sample code above, I wrote a little print (gero_book_web_logger.handlers) at the end. The result of this execution is [<StreamHandler <stderr> (NOTSET)>]. There is only one. This means that the lower level does not have the Handler set at the higher level. The parent-child relationship between Logger instances is more like the behavior that a child Logger instance knows who its parent Logger instance is and also calls its logging method (class inheritance). Sometimes, it's similar to the behavior when calling a method on the superclass side among the methods overridden in the child class). This implementation is based on the following implementation of the callHandlers () method.

logging/__init__.py

#Abbreviation
    def callHandlers(self, record):
        #Abbreviation
        c = self
        found = 0
        while c:
            for hdlr in c.handlers:
                found = found + 1
                if record.levelno >= hdlr.level:
                    hdlr.handle(record)
            if not c.propagate:
                c = None    #break out
            else:
                c = c.parent
        #Abbreviation

A review of Logger instances

So, the name specified bygetLogger (name = None)is not just a name, it's like the absolute path of Logger, and it's hierarchical. Furthermore, it can be seen that the settings made at the higher level are inherited by the child, and that the settings made by the child are given priority.

From these actions, I can imagine that it will be easier to use if you use it in the following way.

1. For logging such as keeping in the log for no purpose, give a handler to the higher Logger instance.
2. Except for situations where you want the child Logger instance to spit out another level of log for a specific purpose, it is easier to change it by controlling it with the parent log level without setting the log level (assuming dev → prd etc. If). --The specific purpose is, for example, when you want to create a trace-only log for dictated Exceptions. --If you decide to use a trace-only log, you'll probably spit a stack trace into the log, but it's unpleasant (I think) to spit this into the log with logger.warning (), for example. --In such a case, for example, there is a plan to design as follows. --Print debug system (including stack trace) is output with DEBUG. --Logger for trace-only logs sets LogLevel to DEBUG.
3. If you set the handler according to the purpose of each Logger instance to spit out logs, it will be easier to use the logs (for example, you can spit out only the access log of the service to a dedicated file to make it easier to aggregate, or create a dedicated Exception log).
4. The above process only needs to be done once in the initialization process when the application starts. The instance already set by logging.get_logger ("path.to.logger ") will be fetched.

Afterword

This article first mentions how to use the logging function (ie root logger) of the logging module, which is also mentioned in the official Python documentation, to keep things organized. However, I personally don't recommend using the root logger. It's easy to do something like "When I try to spit out the logs of a program I wrote, I get a lot of logs from other libraries I'm importing and die on Disk Full."

On the other hand, logging and logging libraries are so deep that it is not easy to write them neatly, so I decided to study from scratch and leave them in the article.

Links

Below, miscellaneous licks.

--logging --- Logging function for Python

• https://docs.python.org/ja/3/library/logging.html
• Logging HOWTO
  • https://docs.python.org/ja/3/howto/logging.html
• python/cpython - Github
  • https://github.com/python/cpython/tree/3.8/Lib/logging