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.
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?
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.
The introduction has become longer.
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')
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.
Setting | Taken over from the top * |
---|---|
Log level of Logger instance | ✔ |
Handler | ✔ |
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.
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
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.
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
.logging.get_logger ("path.to.logger ")
will be fetched.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
Recommended Posts