在开发过程中,如果程序运行出现了问题,我们是可以使用我们自己的 Debug 工具来检测到到底是哪一步出现了问题,如果出现了问题的话,是很容易排查的。但程序开发完成之后,我们会将它部署到生产环境中去,这时候代码相当于是在一个黑盒环境下运行的,我们只能看到其运行的效果,是不能直接看到代码运行过程中每一步的状态的。在这个环境下,运行过程中难免会在某个地方出现问题,甚至这个问题可能是我们开发过程中未曾遇到的问题,碰到这种情况应该怎么办?
如果我们现在只能得知当前问题的现象,而没有其他任何信息的话,如果我们想要解决掉这个问题的话,那么只能根据问题的现象来试图复现一下,然后再一步步去调试,这恐怕是很难的,很大的概率上我们是无法精准地复现这个问题的,而且 Debug 的过程也会耗费巨多的时间,这样一旦生产环境上出现了问题,修复就会变得非常棘手。但这如果我们当时有做日志记录的话,不论是正常运行还是出现报错,都有相关的时间记录,状态记录,错误记录等,那么这样我们就可以方便地追踪到在当时的运行过程中出现了怎样的状况,从而可以快速排查问题。
因此,日志记录是非常有必要的,任何一款软件如果没有标准的日志记录,都不能算作一个合格的软件。作为开发者,我们需要重视并做好日志记录过程。
那么在 Python 中,怎样才能算作一个比较标准的日志记录过程呢?或许很多人会使用 print 语句输出一些运行信息,然后再在控制台观察,运行的时候再将输出重定向到文件输出流保存到文件中,这样其实是非常不规范的,在 Python 中有一个标准的 logging 模块,我们可以使用它来进行标注的日志记录,利用它我们可以更方便地进行日志记录,同时还可以做更方便的级别区分以及一些额外日志信息的记录,如时间、运行模块信息等
接下来我们先了解一下日志记录流程的整体框架:
如图所示,整个日志记录的框架可以分为这么几个部分:
以上就是整个 logging 模块的基本架构和对象功能,了解了之后我们详细来了解一下 logging 模块的用法。
1 import logging 2 3 logging.basicConfig(level=logging.INFO, 4 format="%(asctime)s - %(name)s - %(levelname)s - %(message)s") 5 logger = logging.getLogger(__name__) 6 7 logger.info("This is a log info") 8 logger.debug(‘Debugging‘) 9 logger.warning(‘Warning exists‘) 10 logger.info("Finish")
首先引入了 logging 模块,然后进行了一下基本的配置,这里通过 basicConfig 配置了 level 信息和 format 信息,这里 level 配置为 INFO 信息,即只输出 INFO 级别的信息,另外这里指定了 format 格式的字符串,包括 asctime、name、levelname、message 四个内容,分别代表运行时间、模块名称、日志级别、日志内容,这样输出内容便是这四者组合而成的内容了,这就是 logging 的全局配置。
接下来声明了一个 Logger 对象,它就是日志输出的主类,调用对象的 info() 方法就可以输出 INFO 级别的日志信息,调用 debug() 方法就可以输出 DEBUG 级别的日志信息,非常方便。在初始化的时候我们传入了模块的名称,这里直接使用 __name__ 来代替了,就是模块的名称,如果直接运行这个脚本的话就是 __main__,如果是 import 的模块的话就是被引入模块的名称,这个变量在不同的模块中的名字是不同的,所以一般使用 __name__ 来表示就好了,再接下来输出了四条日志信息,其中有两条 INFO、一条 WARNING、一条 DEBUG 信息,我们看下输出结果:
我们发现 DEBUG 的信息是没有输出的,这是因为我们在全局配置的时候设置了输出为 INFO 级别,所以 DEBUG 级别的信息就被过滤掉了。
将输出的日志级别设置为 DEBUG,就可以看到 DEBUG 级别的日志输出了:
basicConfig 的参数
实例:
1 mport logging 2 3 logging.basicConfig(level=logging.DEBUG, 4 filename=‘output.log‘, 5 datefmt=‘%Y/%m/%d %H:%M:%S‘, 6 format=‘%(asctime)s - %(name)s - %(levelname)s - %(lineno)d - %(module)s - %(message)s‘) 7 logger = logging.getLogger(__name__) 8 9 logger.info(‘This is a log info‘) 10 logger.debug(‘Debugging‘) 11 logger.warning(‘Warning exists‘) 12 logger.info(‘Finish‘)
这里我们指定了输出文件的名称为 output.log,另外指定了日期的输出格式,其中年月日的格式变成了 %Y/%m/%d,另外输出的 format 格式增加了 lineno、module 这两个信息,运行之后便会生成一个 output.log 的文件,内容如下:
2019/08/03 10:18:43 - __main__ - INFO - 9 - test - This is a log info 2019/08/03 10:18:43 - __main__ - DEBUG - 10 - test - Debugging 2019/08/03 10:18:43 - __main__ - WARNING - 11 - test - Warning exists 2019/08/03 10:18:43 - __main__ - INFO - 12 - test - Finish
可以看到日志便会输出到文件中,同时输出了行号、模块名称等信息。
首先我们来了解一下输出日志的等级信息,logging 模块共提供了如下等级,每个等级其实都对应了一个数值,列表如下:
我们设置了输出 level,系统便只会输出 level 数值大于或等于该 level 的的日志结果,例如我们设置了输出日志 level 为 INFO,那么输出级别大于等于 INFO 的日志,如 WARNING、ERROR 等,DEBUG 和 NOSET 级别的不会输出。
1 import logging 2 3 logger = logging.getLogger(__name__) 4 logger.setLevel(level=logging.WARN) 5 6 # Log 7 logger.debug(‘Debugging‘) 8 logger.critical(‘Critical Something‘) 9 logger.error(‘Error Occurred‘) 10 logger.warning(‘Warning exists‘) 11 logger.info(‘Finished‘)
输出结果:
可以看到只有 CRITICAL、ERROR、WARNING 信息输出了,DEBUG、INFO 信息没有输出。
1 import logging 2 3 # logger对象 4 logger = logging.getLogger(__name__) 5 logger.setLevel(level=logging.INFO) 6 7 # handler对象 8 handler = logging.FileHandler(‘./output.log‘) 9 formatter = logging.Formatter(‘%(asctime)s - %(name)s - %(levelname)s - %(message)s‘) 10 handler.setFormatter(formatter) 11 12 logger.addHandler(handler) 13 14 logger.info("This is a log info") 15 logger.debug(‘Debugging‘) 16 logger.warning("Warning exists") 17 logger.info(‘Finished‘)
这里我们没有再使用 basicConfig 全局配置,而是先声明了一个 Logger 对象,然后指定了其对应的 Handler 为 FileHandler 对象,然后 Handler 对象还单独指定了 Formatter 对象单独配置输出格式,最后给 Logger 对象添加对应的 Handler 即可,最后可以发现日志就会被输出到 output.log 中,内容如下:
1 2019-08-03 11:09:38,664 - __main__ - INFO - This is a log info 2 2019-08-03 11:09:38,664 - __main__ - WARNING - Warning exists 3 2019-08-03 11:09:38,664 - __main__ - INFO - Finished
logging 模块提供的 Handler :
下面我们使用三个 Handler 来实现日志同时输出到控制台、文件、HTTP 服务器:
1 import logging 2 from logging.handlers import HTTPHandler 3 import sys 4 5 logger = logging.getLogger(__name__) 6 logger.setLevel(level=logging.DEBUG) 7 8 # StremHandler 9 stream_handler = logging.StreamHandler(sys.stdout) 10 stream_handler.setLevel(level=logging.DEBUG) 11 logger.addHandler(stream_handler) 12 # FileHandler 13 file_handler = logging.FileHandler(‘./out.log‘) 14 file_handler.setLevel(level=logging.INFO) 15 formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s") 16 file_handler.setFormatter(formatter) 17 logger.addHandler(file_handler) 18 19 # HTTPHandler 20 http_handler = HTTPHandler(host="localhost:80001", url=‘log‘, method="POST") 21 logger.addHandler(http_handler) 22 23 # Log 24 logger.info("This is a log info") 25 logger.debug(‘Debugging‘) 26 logger.warning("Warning exists") 27 logger.info(‘Finished‘)
运行之前我们需要先启动 HTTP Server,并运行在 8001 端口,其中 log 接口是用来接收日志的接口。
运行之后控制台输出会输出如下内容:
1 This is a log info 2 Debugging 3 Warning exists 4 Finish
output.log 文件会写入如下内容:
1 2019-08-03 11:25:28,152 - __main__ - INFO - This is a log info 2 2019-08-03 11:25:32,695 - __main__ - WARNING - Warning exists 3 2019-08-03 11:25:34,976 - __main__ - INFO - Finished
HTTP Server 会收到控制台输出的信息。
这样一来,我们就通过设置多个 Handler 来控制了日志的多目标输出。
另外值得注意的是,在这里 StreamHandler 对象我们没有设置 Formatter,因此控制台只输出了日志的内容,而没有包含时间、模块等信息,而 FileHandler 我们通过 setFormatter() 方法设置了一个 Formatter 对象,因此输出的内容便是格式化后的日志信息。
另外每个 Handler 还可以设置 level 信息,最终输出结果的 level 信息会取 Logger 对象的 level 和 Handler 对象的 level 的交集。
在进行日志格式化输出的时候,我们可以不借助于 basicConfig 来全局配置格式化输出内容,可以借助于 Formatter 来完成,下面我们再来单独看下 Formatter 的用法:
1 import logging 2 3 logger = logging.getLogger() 4 logger.setLevel(level=logging.WARN) 5 6 formatter = logging.Formatter(fmt = "%(asctime)s - %(name)s - %(levelname)s - %(message)s", 7 datefmt=‘%Y/%m/%d %H:%M:%S‘) 8 handler = logging.StreamHandler() 9 handler.setFormatter(formatter) 10 logger.addHandler(handler) 11 # Log 12 logger.debug(‘Debugging‘) 13 logger.critical(‘Critical Something‘) 14 logger.error(‘Error Occurred‘) 15 logger.warning(‘Warning exists‘) 16 logger.info(‘Finished‘)
在这里我们指定了一个 Formatter,并传入了 fmt 和 datefmt 参数,这样就指定了日志结果的输出格式和时间格式,然后 handler 通过 setFormatter() 方法设置此 Formatter 对象即可,输出结果如下:
如果遇到错误,我们更希望报错时出现的详细 Traceback 信息,便于调试,利用 logging 模块我们可以非常方便地实现这个记录:
1 import logging 2 3 logger = logging.getLogger(__name__) 4 logger.setLevel(level=logging.DEBUG) 5 6 # Formatter 7 formatter = logging.Formatter(‘%(asctime)s - %(name)s - %(levelname)s - %(message)s‘) 8 9 # FileHandler 10 file_handler = logging.FileHandler(‘./result.log‘) 11 file_handler.setFormatter(formatter) 12 logger.addHandler(file_handler) 13 14 # StreamHandler 15 stream_handler = logging.StreamHandler() 16 stream_handler.setFormatter(formatter) 17 logger.addHandler(stream_handler) 18 19 # Log 20 logger.info(‘Start‘) 21 logger.warning(‘Something maybe fail‘) 22 try: 23 result = 10 / 0 24 except Exception: 25 logger.error(‘Failed to get result‘, exc_info=True) 26 27 logger.info(‘Finished‘)
这里我们在 error() 方法中添加了一个参数,将 exc_info 设置为了 True,这样我们就可以输出执行过程中的信息了,即完整的 Traceback 信息。
运行结果如下:
可以看到这样我们就非常方便地记录下来了报错的信息,一旦出现了错误,我们也能非常方便地排查。
在写项目的时候,我们肯定会将许多配置放置在许多模块下面,这时如果我们每个文件都来配置 logging 配置那就太繁琐了,logging 模块提供了父子模块共享配置的机制,会根据 Logger 的名称来自动加载父模块的配置。
1 import logging 2 import core 3 4 logger = logging.getLogger(‘main‘) 5 logger.setLevel(level=logging.DEBUG) 6 7 # Handler 8 handler = logging.FileHandler(‘result.log‘) 9 handler.setLevel(logging.INFO) 10 formatter = logging.Formatter(‘%(asctime)s - %(name)s - %(levelname)s - %(message)s‘) 11 handler.setFormatter(formatter) 12 logger.addHandler(handler) 13 14 logger.info(‘Main Info‘) 15 logger.debug(‘Main Debug‘) 16 logger.error(‘Main Error‘) 17 core.run()
这里我们配置了日志的输出格式和文件路径,同时定义了 Logger 的名称为 main,然后引入了另外一个模块 core,最后调用了 core 的 run() 方法。
接下来我们定义 core.py,内容如下:
1 import logging 2 3 logger = logging.getLogger(‘main.core‘) 4 5 def run(): 6 logger.info(‘Core Info‘) 7 logger.debug(‘Core Debug‘) 8 logger.error(‘Core Error‘)
这里我们定义了 Logger 的名称为 main.core,注意这里开头是 main,即刚才我们在 main.py 里面的 Logger 的名称,这样 core.py 里面的 Logger 就会复用 main.py 里面的 Logger 配置,而不用再去配置一次了。
运行如下:
1 2018-06-03 16:55:56,259 - main - INFO - Main Info 2 2018-06-03 16:55:56,259 - main - ERROR - Main Error 3 2018-06-03 16:55:56,259 - main.core - INFO - Core Info 4 2018-06-03 16:55:56,259 - main.core - ERROR - Core Error
可以看到父子模块都使用了同样的输出配置。
如此一来,我们只要在入口文件里面定义好 logging 模块的输出配置,子模块只需要在定义 Logger 对象时名称使用父模块的名称开头即可共享配置,非常方便。
在开发过程中,将配置在代码里面写死并不是一个好的习惯,更好的做法是将配置写在配置文件里面,我们可以将配置写入到配置文件,然后运行时读取配置文件里面的配置,这样是更方便管理和维护的,下面我们以一个实例来说明一下,首先我们定义一个 yaml 配置文件:
1 version: 1 2 formatters: 3 brief: 4 format: "%(asctime)s - %(message)s" 5 simple: 6 format: "%(asctime)s - %(name)s - %(levelname)s - %(message)s" 7 handlers: 8 console: 9 class : logging.StreamHandler 10 formatter: brief 11 level : INFO 12 stream : ext://sys.stdout 13 file: 14 class : logging.FileHandler 15 formatter: simple 16 level: DEBUG 17 filename: debug.log 18 error: 19 class: logging.handlers.RotatingFileHandler 20 level: ERROR 21 formatter: simple 22 filename: error.log 23 maxBytes: 10485760 24 backupCount: 20 25 encoding: utf8 26 loggers: 27 main.core: 28 level: DEBUG 29 handlers: [console, file, error] 30 root: 31 level: DEBUG 32 handlers: [console]
这里我们定义了 formatters、handlers、loggers、root 等模块,实际上对应的就是各个 Formatter、Handler、Logger 的配置,参数和它们的构造方法都是相同的。
接下来我们定义一个主入口文件,main.py,内容如下:
1 def setup_logging(default_path=‘config.yaml‘, default_level=logging.INFO): 2 path = default_path 3 if os.path.exists(path): 4 with open(path, ‘r‘, encoding=‘utf-8‘) as f: 5 config = yaml.load(f) 6 logging.config.dictConfig(config) 7 else: 8 logging.basicConfig(level=default_level) 9 10 11 def log(): 12 logging.debug(‘Start‘) 13 logging.info(‘Exec‘) 14 logging.info(‘Finished‘) 15 16 17 if __name__ == ‘__main__‘: 18 yaml_path = ‘config.yaml‘ 19 setup_logging(yaml_path) 20 log() 21 core.run()
这里我们定义了一个 setup_logging() 方法,里面读取了 yaml 文件的配置,然后通过 dictConfig() 方法将配置项传给了 logging 模块进行全局初始化。
另外这个模块还引入了另外一个模块 core,所以我们定义 core.py 如下:
1 import logging 2 3 logger = logging.getLogger(‘main.core‘) 4 5 def run(): 6 logger.info(‘Core Info‘) 7 logger.debug(‘Core Debug‘) 8 logger.error(‘Core Error‘)
这个文件的内容和上文是没有什么变化的。
观察配置文件,主入口文件 main.py 实际上对应的是 root 一项配置,它指定了 handlers 是 console,即只输出到控制台。另外在 loggers 一项配置里面,我们定义了 main.core 模块,handlers 是 console、file、error 三项,即输出到控制台、输出到普通文件和回滚文件。
这样运行之后,我们便可以看到所有的运行结果输出到了控制台:
1 2018-06-03 17:07:12,727 - Exec 2 2018-06-03 17:07:12,727 - Finished 3 2018-06-03 17:07:12,727 - Core Info 4 2018-06-03 17:07:12,727 - Core Info 5 2018-06-03 17:07:12,728 - Core Error 6 2018-06-03 17:07:12,728 - Core Error
在 debug.log 文件中则包含了 core.py 的运行结果:
1 2018-06-03 17:07:12,727 - main.core - INFO - Core Info 2 2018-06-03 17:07:12,727 - main.core - DEBUG - Core Debug 3 2018-06-03 17:07:12,728 - main.core - ERROR - Core Error
可以看到,通过配置文件,我们可以非常灵活地定义 Handler、Formatter、Logger 等配置,同时也显得非常直观,也非常容易维护,在实际项目中,推荐使用此种方式进行配置。
以上便是 logging 模块的基本使用方法,有了它,我们可以方便地进行日志管理和维护,会给我们的工作带来极大的方
在日志输出的时候经常我们会用到字符串拼接的形式,很多情况下我们可能会使用字符串的 format() 来构造一个字符串,但这其实并不是一个好的方法,因为还有更好的方法,下面我们对比两个例子:
1 import logging 2 3 logging.basicConfig(level=logging.DEBUG, format=‘%(asctime)s - %(name)s - %(levelname)s - %(message)s‘) 4 5 # bad 6 logging.debug(‘Hello {0}, {1}!‘.format(‘World‘, ‘Congratulations‘)) 7 # good 8 logging.debug(‘Hello %s, %s!‘, ‘World‘, ‘Congratulations‘)
这里有两种打印 Log 的方法,第一种使用了字符串的 format() 的方法进行构造,传给 logging 的只用到了第一个参数,实际上 logging 模块提供了字符串格式化的方法,我们只需要在第一个参数写上要打印输出的模板,占位符用 %s、%d 等表示即可,然后在后续参数添加对应的值就可以了,推荐使用这种方法。
1 2019-08-03 11:55:35,758 - root - DEBUG - Hello World, Congratulations! 2 2019-08-03 11:55:35,758 - root - DEBUG - Hello World, Congratulations!
另外在进行异常处理的时候,通常我们会直接将异常进行字符串格式化,但其实可以直接指定一个参数将 traceback 打印出来,示例如下:
1 import logging 2 3 logging.basicConfig(level=logging.DEBUG, format=‘%(asctime)s - %(name)s - %(levelname)s - %(message)s‘) 4 5 try: 6 result = 5 / 0 7 except Exception as e: 8 # bad 9 logging.error(‘Error: %s‘, e) 10 # good 11 logging.error(‘Error‘, exc_info=True) 12 # good 13 logging.exception(‘Error‘)
如果我们直接使用字符串格式化的方法将错误输出的话,是不会包含 Traceback 信息的,但如果我们加上 exc_info 参数或者直接使用 exception() 方法打印的话,那就会输出 Traceback 信息了。
运行结果如下:
1 2019-08-03 11:57:18,134 - root - ERROR - Error: division by zero 2 2019-08-03 11:57:18,164 - root - ERROR - Error 3 Traceback (most recent call last): 4 File "C:\Users\huangm\Desktop\3666.py", line 6, in <module> 5 result = 5 / 0 6 ZeroDivisionError: division by zero 7 2019-08-03 11:57:18,164 - root - ERROR - Error 8 Traceback (most recent call last): 9 File "C:\Users\huangm\Desktop\3666.py", line 6, in <module> 10 result = 5 / 0 11 ZeroDivisionError: division by zero 12 [Finished in 0.1s]
参考文章:
http://www.cnblogs.com/dahu-daqing/p/7040764.html
https://docs.python.org/3/library/logging.html
https://blog.csdn.net/zyz511919766/article/details/25136485/
原文:https://www.cnblogs.com/huangm1314/p/11293908.html