At PyCon 2018, Mario Corchero talked about the process of making logging easier and easier during development.

The lecture will cover: Why logging is Important What is the logging process? How to Log? How to Configure Logging

The core of the presentation is to introduce the logging module and its configuration.

The importance of logging the outdoor dividing line of football sports

In the development process, if there is a problem in the program operation, we can use our own Debug tool to detect the problem in the end, if there is a problem, it is easy to troubleshoot. But after the program is developed, we will deploy it to the production environment. At this time, the code is like running in a black box environment, we can only see the effect of its operation, not directly see the status of each step in the process of running the code. In this environment, it is inevitable that there will be a problem somewhere during the operation, or even a problem that we have not encountered during the development process. What should we do in this case? If we only know that now the phenomenon of the current problems, without any other information, if we want to get rid of this problem, so only phenomenon in an attempt to reconstruct it according to the problems, and then to debug step by step, I’m afraid that it is difficult, we are unable to accurately on the probability of large emersion this problem, The Debug process can also take an enormous amount of time, making it very difficult to fix any problems that occur in production. But if we did log at that time, whether it is normal operation or error, there are relevant time records, status records, error records, etc., so that we can easily track what happened in the operation process at that time, so that we can quickly troubleshoot problems. Therefore, logging is very necessary, any software without standard logging, is not a qualified software. As developers, we need to take logging seriously and do it well.

The flow frame of outdoor dividing line log recording of football game

So what counts as a fairly standard logging process in Python? A lot of people might use print statements to print some run information, then watch it on the console, then redirect the output to a file at run time and save the output stream to a file. This is actually quite non-standard. There is a standard logging module in Python that we can use for annotated logging. Using it we can log more easily, but also can do more convenient level differentiation and some additional log information, such as time, running module information, etc. Let’s look at the overall framework of the logging process.

As shown in the figure, the whole logging framework can be divided into several parts: Logger: Namely, Logger Main Class, which is the object created when we Log. We can call its method to pass in Log template and information to generate one Log Record, called Log Record. Log Record: the generation of Log records. Handler: this class is used to process the Log Record. It can output the Log Record to the specified location and storage format. For example, we can specify the FTP protocol to Record the Log to a remote server, and the Handler will do these things for us. The Formatter: In fact, the generated Log Record is also an object, so if we want to save them as a Log text we need to have a formatting process, so this process is done by Formatter, returns the Log string, and then passes it back to the Handler for processing. The Filter: Also save the time log we may not need all save, we may have to do is save we want to be part of, so save is needed before the Filter, leaving us to log, if only to save a certain level of logs, or save only contains a keyword logs, etc., then the filtering process to the Filter. Parent Handler: There can be hierarchical relationships between handlers so that different handlers share code with the same functionality. This is the basic architecture and object function of the logging module. After understanding this, we will look at the usage of the logging module in detail.

Football game outdoor dividing line log records related usage

In general, the logging module has several advantages compared with print: it can set the log level in the logging module and record the corresponding log by setting different output levels in different versions (such as development environment and production environment), which is very flexible. The output of print is printed to the standard output stream, whereas the logging module is more flexible and can be set to any location, such as writing to a file or remote server. The logging module has flexible configuration and formatting functions, such as configuring the output of the current module information, running time, etc., which is more convenient and easy to use than the string formatting of print. To get a feel for the basic usage of the Logging module, use an example: importLogging

logging.basicConfig(level=logging.INFO,format=’%(asctime)s – %(name)s – %(levelname)s – %(message)s’) logger = logging.getLogger(name)

logger.info(‘This is a log info’) logger.debug(‘Debugging’) logger.warning(‘Warning exists’) logger.info(‘Finish’) Here, we first introduce the logging module, and then perform basic configuration. Here, we configure level information and format information through basicConfig. Here, level is configured as INFO information, that is, only INFO level information is output. In addition, the format string includes asctime, name, LevelName, and message, representing the runtime, module name, log level, and log content respectively. The output content is a combination of these four elements. This is the global configuration of logging. Next, we declare a Logger object, which is the main class for logging output. Calling the object’s info() method can output info level logs, and calling the debug() method can output DEBUG level logs, which is very convenient. When initializing, we pass in the name of the module. Instead, we use __name__, which is the name of the module, __main__ if we run the script directly, or the name of the imported module if it is an import module. The name of this variable varies from module to module. The output of the following four log messages, including two INFO messages, one WARNING message, and one DEBUG message, is as follows:

The 13:42:43 2018-06-03, 526 – the main – INFO – Thisisaloginfo 13:42:43 2018-06-03, 526 – the main – WARNING – Warningexists 2018-06-03 13:42:443, 526-main-info-finish you can see that there are three logs in the output. Each log corresponds to the specified formatting content. In addition, we find that the DEBUG message is not output. This is because we set the output to INFO level during global configuration, so DEBUG level messages are filtered out. If we set the output log level to DEBUG, we can see the DEBUG level log output: BasicConfig (level= logging.debug,format=’%(asctime)s – %(name)s – %(LevelName)s – %(message)s’) 2018-06-03 13:49:22, 770-main-info – This is a log INFO 2018-06-03 13:49:22, 770-main-debug-debugging 2018-06-03 13:49:22, 770-main-info-finish WARNING exists Compared with print, we can print time, module name, and different levels of log information to distinguish and filter, isn’t it more flexible? Of course, this is only a small part of the logging module, so let’s look at the parameters of basicConfig. The file name of the log output. If you specify this information, it will actually enable FileHandler instead of StreamHandler, so that the log information will be output to the file. Filemode: Specifies the log file write mode. There are two formats: W and A, respectively. Format: specify the log information output format, as shown in the examples above parameters, detailed parameters can refer to: docs.python.org/3/library/l… %(levelno)s: indicates the value of the print log level. %(levelName)s: indicates the name of the log level. %(pathName)s: Prints the path of the currently executing program, which is sys.argv[0]. %(filename)s: prints the name of the running program. %(funcName)s: current function for printing logs. %(lineno)d: indicates the forward number of the log to be printed. %(asctime)s: indicates the time when a log is printed. %(thread)d: displays the ID of the thread. %(threadName)s: prints the threadName. %(process)d: prints the process ID. %(processName)s: Prints the thread name. %(module)s: prints the module name. %(message)s: Displays log information. Datefmt: Output format for the specified time. Style: If the format argument is specified, this parameter specifies the formatting placeholder style, such as %, {, $, and so on. Level: specifies the log output category. The program will output information greater than or equal to this level. Stream: StreamHandler is used by default when filename is not specified, in which case the stream can specify the file stream to initialize. Handlers: You can specify the handlers to be used for logging, which must be iterative. Here’s another example to get a feel for it: importLogging

logging.basicConfig(level=logging.DEBUG, filename=’output.log’, datefmt=’%Y/%m/%d %H:%M:%S’, format=’%(asctime)s – %(name)s – %(levelname)s – %(lineno)d – %(module)s – %(message)s’) logger = logging.getLogger(name)

logger.info(‘This is a log info’) logger.debug(‘Debugging’) logger.warning(‘Warning exists’) logger.info(‘Finish’) Here we specify the name of the output file as output.log, and specify the output format of the date, in which the format of year, month and day is changed to %Y/%m/% D. In addition, lineno and Module are added to the output format. After running, an output.log file is generated, with the following contents: 2018/06/0314:43:26 -main-INFO-9-demo3-Thisisaloginfo 2018/06/0314:43:26 -main-DEBUG-10-demo3-Debugging 2018/06/0314:43:26 – main-warning-11-DEMO3-warningExists 2018/06/0314:43:26 – main-info-12-demo3-finish The line number and module name are also displayed. We used basicConfig to do some global configuration, we can also use Formatter, Handler for more flexible processing, let’s see. The logging module provides the following levels of logging output. Each Level corresponds to a specific value, as listed below: CRITICAL 50 FATAL 50 ERROR 40 WARNING 30 WARN 30 INFO 20 DEBUG 10 NOTSET 0 The highest levels are CRITICAL and FATAL, both levels are 50. A WARN is also provided as a short form for WARNING, and both values are 30. If the output level is set, the system outputs only logs whose level is greater than or equal to this level. For example, if the output level is set to INFO, the system outputs logs whose level is greater than or equal to INFO, such as WARNING and ERROR. DEBUG and NOSET messages are not output. importlogging

logger = logging.getLogger(name) logger.setLevel(level=logging.WARN)

Log

logger.debug(‘Debugging’) logger.critical(‘Critical Something’) logger.error(‘Error Occurred’) logger.warning(‘Warning Exists ‘) logger.info(‘Finished’) The output level is set to WARN. Five logs of different levels are generated. CriticalSomething Error Occurred Warning exists You can view that only CRITICAL, Error, and Warning information is output, and DEBUG and INFO information is not output. Handler To see how this Handler is used, look at the following example: importLogging

logger = logging.getLogger(name) logger.setLevel(level=logging.INFO) handler = logging.FileHandler(‘output.log’) formatter = logging.Formatter(‘%(asctime)s – %(name)s – %(levelname)s – %(message)s’) handler.setFormatter(formatter) logger.addHandler(handler)

logger.info(‘This is a log info’) logger.debug(‘Debugging’) logger.warning(‘Warning exists’) logger.info(‘Finish’) Instead of using the basicConfig global configuration, we first refer to a Logger object and then specify its Handler as a FileHandler object. The Handler object also specifies a Formatter object to format the output separately. Add Handler to Logger object and the log will be output to output.log as follows: The 14:53:36 2018-06-03, 467 – the main – INFO – Thisisaloginfo 14:53:36 2018-06-03, 468 – the main – WARNING – Warningexists The logging module provides the following handlers: StreamHandler: StreamHandler: Logging. StreamHandler; Logs are output to streams, which can be sys.stderr, sys.stdout, or files. FileHandler: logging. FileHandler; Logs are output to files. BaseRotatingHandler: logging handlers. BaseRotatingHandler; Basic log rollback mode. RotatingHandler: logging handlers. RotatingHandler; Log rollback mode: supports the maximum number of log files and the rollback of log files. TimeRotatingHandler: logging handlers. TimeRotatingHandler; Log rollback mode: rollback log files in a specified period of time. SocketHandler: logging handlers. SocketHandler; Remote output log to TCP/IP Sockets. DatagramHandler: logging handlers. DatagramHandler; Remote output log to UDP Sockets. SMTPHandler: logging handlers. SMTPHandler; Remotely outputting logs to email addresses. SysLogHandler: logging handlers. SysLogHandler; Logs are output to syslog. NTEventLogHandler: logging handlers. NTEventLogHandler; Remotely outputting logs to Windows NT/2000/XP event logs. MemoryHandler: logging handlers. MemoryHandler; The log is output to the specified buffer in memory. An HTTPHandler: logging handlers. An HTTPHandler; Remote output to HTTP server via “GET” or “POST”.

Handlers import HTTPHandler import sys we use three handlers to export logs to the console, file, and HTTP server simultaneously: importLogging from logging.handlers import HTTPHandler import sys

logger = logging.getLogger(name) logger.setLevel(level=logging.DEBUG)

StreamHandler

stream_handler = logging.StreamHandler(sys.stdout) stream_handler.setLevel(level=logging.DEBUG) logger.addHandler(stream_handler)

FileHandler

file_handler = logging.FileHandler(‘output.log’) file_handler.setLevel(level=logging.INFO) formatter = logging.Formatter(‘%(asctime)s – %(name)s – %(levelname)s – %(message)s’) file_handler.setFormatter(formatter) logger.addHandler(file_handler)

HTTPHandler

http_handler = HTTPHandler(host=’localhost:8001′,url=’log’,method=’POST’) logger.addHandler(http_handler)

Log

logger.info(‘This is a log info’) logger.debug(‘Debugging’) logger.warning(‘Warning exists’) logger.info(‘Finish’) Before running, we need to start HTTP Server and run it on port 8001, where the log interface is used to receive logs. The console output is as follows: This isalog info Debugging Warning exists Finish output.log The console output is as follows: The 15:13:44 2018-06-03, 895 – the main – INFO – Thisisaloginfo 15:13:44 2018-06-03, 947 – the main – WARNING – Warningexists [2018-06-0315:13:44, 949-main-info-finish] The HTTP Server receives a message from the console. In this way, we control the multi-destination output of the log by setting up multiple handlers. It is also worth noting that we have no Formatter for the StreamHandler object, so the console outputs only the log content, not the time, module, etc. With FileHandler we set a Formatter object with the setFormatter() method, so the output is formatted log information. In addition, each Handler can set the level information. The output level information will take the intersection of the Logger object’s level and the Handler object’s level.

Formatter when logging formatting output, we can not use basicConfig to global configuration formatting output, can be finished with the aid of the Formatter, here we come again see the Formatter usage alone: importlogging

logger = logging.getLogger(name) logger.setLevel(level=logging.WARN) formatter = logging.Formatter(fmt=’%(asctime)s – %(name)s – %(levelname)s – %(message)s’,datefmt=’%Y/%m/%d %H:%M:%S’) handler = logging.StreamHandler() handler.setFormatter(formatter) logger.addHandler(handler)

Log

logger.debug(‘Debugging’) logger.critical(‘Critical Something’) logger.error(‘Error Occurred’) logger.warning(‘Warning Exists ‘) logger.info(‘Finished’) here we specify a Formatter and pass in the FMT and datefmt parameters, thus specifying the output format and time format of the log result. The handler then sets the Formatter object using the setFormatter() method, and the output is as follows: 2018/06/0315:47:15 -main-CRITICAL-CriticalSomething 2018/06/0315:47:15 -main-ERROR-ErrorOccurred 2018/06/0315:47:15 – main-warning-warningExists Allows each Handler to configure the output format individually. To capture Traceback error information, we would like to report a detailed Traceback error information for debugging. Using the logging module, we can easily implement this logging. Let’s use an example to get a feel for it: importLogging

logger = logging.getLogger(name) logger.setLevel(level=logging.DEBUG)

Formatter

formatter = logging.Formatter(‘%(asctime)s – %(name)s – %(levelname)s – %(message)s’)

FileHandler

file_handler = logging.FileHandler(‘result.log’) file_handler.setFormatter(formatter) logger.addHandler(file_handler)

StreamHandler

stream_handler = logging.StreamHandler() stream_handler.setFormatter(formatter) logger.addHandler(stream_handler)

Log

logger.info(‘Start’) logger.warning(‘Something maybe fail.’) try: result = 10 / 0 except Exception: Logger. error(‘Faild to get result’,exc_info=True) Logger. info(‘Finished’) Here we add a parameter to the error() method,exc_info set to True, This allows us to output the information during execution, namely the complete Traceback information. The running results are as follows: 2018-06-03 16:00:15, 382-main-info-startPrint log 2018-06-03 16:00:15, 382-main-debug-dosomething 2018-06-03 2018-06-03 16:00:15, 382-main-error-faild togetresult Traceback (most recent calllast): File”/private/var/books/aicodes/loggingtest/demo8.py”,line 23,in result= 10 / 0 ZeroDivisionError: This makes it very easy to record error messages and troubleshoot errors in this way.

Football outdoor division line configuration sharing

The logging module provides a mechanism for the parent module to share the configuration, automatically loading the parent module’s configuration based on the Logger name. For example, we first define a main.py file: importlogging Import core

logger = logging.getLogger(‘main’) logger.setLevel(level=logging.DEBUG)

Handler

handler = logging.FileHandler(‘result.log’) handler.setLevel(logging.INFO) formatter = logging.Formatter(‘%(asctime)s – %(name)s – %(levelname)s – %(message)s’) handler.setFormatter(formatter) logger.addHandler(handler)

Logger.info (‘Main info ‘) logger.debug(‘Main debug ‘) logger.error(‘Main error ‘) core.run() We call Logger main, introduce another module core, and finally call the run() method of core. Next we define core.py as follows: importLogging

logger = logging.getLogger(‘main.core’)

defrun(): Logger.info (‘Core info ‘) logger.debug(‘Core debug ‘) logger.error(‘Core error ‘) Here we define logger as main.core, notice that it starts with main, This is the name of the Logger in main.py, so that the Logger in core.py will reuse the Logger configuration in main.py instead of having to configure it again. A result.log file will be generated after running, with the following contents: 2018-06-0316:55:56, 259-main-info-maininfo 2018-06-0316:55:56, 259-main-error-mainError 2018-06-0316:55:56,259 Core.core-info-coreinfo 2018-06-0316:55:56,259 – main.core-error-coreError You can see that both parent and child modules use the same output configuration. In this way, the logging module’s output configuration is defined in the entry file, and the child module can share the configuration by defining the Logger object with the name of the parent module.

Outdoor dividing line file configuration for football sports

In the process of development, configuration in code written to death is not a good habit, it would be better configuration will be written in a configuration file, and we can configure will be written to the configuration file, and then the inside of the runtime reads the configuration file configuration, it’s more convenient to manage and maintain, we an instance to explain below, Version: 1 formatters: brief: format: “%(asctime)s – %(message)s” simple: format: “%(asctime)s – %(name)s – %(levelname)s – %(message)s” handlers: console: class : logging.StreamHandler formatter: brief level : INFO stream : ext://sys.stdout file: class : logging.FileHandler formatter: simple level: DEBUG filename: debug.log error: class: logging.handlers.RotatingFileHandler level: ERROR formatter: simple filename: error.log maxBytes: 10485760 backupCount: 20 encoding: utf8 loggers: main.core: level: DEBUG handlers: [console,file,error] root: level: DEBUG handlers: Handlers, Loggers, root, etc., which correspond to the configuration of the formatters, handlers, loggers, and loggers. The parameters and their constructors are all the same. Next we define a main entry file, main.py, with the following contents: importLogging importCore importyaml importlogging.config Importos

defsetup_logging(default_path=’config.yaml’,default_level=logging.INFO): path = default_path ifos.path.exists(path): withopen(path,’r’,encoding=’utf-8′)asf: config = yaml.load(f) logging.config.dictConfig(config) else: logging.basicConfig(level=default_level)

deflog(): logging.debug(‘Start’) logging.info(‘Exec’) logging.info(‘Finished’)

if__name__ == ‘main’: Yaml_path = ‘config.yaml’ setup_logging(yaml_path) log() core.run() The dictConfig() method is then passed to the logging module for global initialization. This module also introduces another module, core, so we define core.py as follows: importLogging

logger = logging.getLogger(‘main.core’)

Defrun (): logger.info(‘Core info ‘) logger.debug(‘Core debug ‘) logger.error(‘Core error ‘) This file contains the same contents as above. Looking at the configuration file, the main entry file main.py actually corresponds to the root configuration, which specifies that handlers are console, that is, output to the console only. Handlers are console, file and error, that is, to output to console, to normal files and to rollback files. After running like this, we can see all the results of the run printed to the console: The 2018-06-03 17:07:12, 727 – the Exec 2018-06-03 17:07:12, 727 – Finished 17:07:12 2018-06-03, 727 – CoreInfo 2018-06-0317:07:12, 727-coreInfo 2018-06-0317:07:12, 728-coreError 2018-06-0317:07:12, 728-coreError 2018-06-0317:07:12, 728-coreError 2018-06-0317:07:12, 728-coreError 2018-06-0317:07:12, 728-coreError in debug.log The file contains the result of core.py: 2018-06-0317:07:12, core-info-coreinfo 2018-06-0317:07:12, 727-main As you can see from the configuration file, we can define the Handler, Formatter, Logger and other configurations very flexibly and intuitively. It is easy to maintain and is recommended to be configured in this way in actual projects. These are the basic usage methods of the logging module. With this module, we can easily manage and maintain logs, which will bring great convenience to our work.

Common mistakes in the use of outdoor dividing line log for football

String concatenation is often used for logging. In many cases, we might use string format() to construct a string, but this is not a good method because there are better methods. Here are two examples: importLogging

logging.basicConfig(level=logging.DEBUG,format=’%(asctime)s – %(name)s – %(levelname)s – %(message)s’)

bad

logging.debug(‘Hello {0},{1}! ‘.format(‘World’,’Congratulations’))

good

logging.debug(‘Hello %s,%s! ‘,’World’,’Congratulations’) There are two ways to print logs. The first is constructed using the format() method of the string. The logging module uses only the first parameter. We just need to write the template to print in the first parameter, use placeholders like %s, %d, etc., and then add corresponding values in the subsequent parameters. This method is recommended. Results are as follows: the 2018-06-03 22:27:51, 220 – root – DEBUG – the HelloWorld, Congratulations! The 22:27:51 2018-06-03, 220 – root – DEBUG – the HelloWorld, Congratulations!

In addition, when handling exceptions, we usually format the exception as a string, but in fact, we can directly specify a parameter to print the traceback, as shown in the following example: importlogging logging.basicConfig(level=logging.DEBUG,format=’%(asctime)s – %(name)s – %(levelname)s – %(message)s’)

try: result = 5 / 0 exceptException ase: # bad logging.error(‘Error: %s’,e) # good logging.error(‘ error ‘,exc_info=True) # good logging.exception(‘ error ‘) Traceback information is not included, but if we add the exc_info argument or print it directly using the exception() method, the Traceback information will be printed. 2018-06-03 22:24:31, 927-root-error-error: Division by Zero 2018-06-03 22:24:31,927 – root-error-error Traceback (most recent calllast): File”/private/var/books/aicodes/loggingtest/demo9.py”,line 6,in result= 5 / 0 ZeroDivisionError: Division byZero 2018-06-03 22:24:31, 928-root-error-error Traceback (most recent calllast): File”/private/var/books/aicodes/loggingtest/demo9.py”,line 6,in result= 5 / 0 ZeroDivisionError: division byzero

This is the overview of the Logging module. Well, it’s time to ditch print and start logging.

Refer to the content

• https://docs.python.org/3/library/logging.html
• http://www.cnblogs.com/dahu-daqing/p/7040764.html