昔我往矣

Python日志:从原理到实践

2020年11月28日

日志
日志是调试程序、记录代码执行过程和排查线上线下问题的重要手段,Python中内置了logging模块,可以很方便的根据需要输出日志。本文将详细的讲解和演示Pythonlogging模块的几个重要组件,并提供一些日志输出的经验和方法。

环境版本

Python 3.7.5
Ubuntu 18.04

logging的重要组件

Logger:用户程序调用Logger组件输出日志。
Handler:具体决定日志输出的日志处理器,日志处理器决定日志输出的格式、目标文件等。比如输出到日志文件或者标准输出。
Formatter:日志的格式,有许多变量可以使用,比如时间,级别,Logger的名字等。
Filter:过滤器,决定要输出哪些日志,本文中不会直接使用到。

Logger 组件

Logger组件采用树形结构组织,除顶层Logger(root)外,其他Logger都有自己的parent。Logger组件有namelevelparentpropagateHandlers等主要属性。Logger的重要属性如下:

  • name:组件的名字,可以使用__name__变量自动生成,也可以手动指定。形成层级关系,比如app.model这个Loggerparent通常是app
  • level:输出的最低日志级别。logging定义了6个日志级别,分别对应不同的数值,关系如下,Logger只会记录等于或高于设置级别的日志。
`
levelNamelevel
CRITICAL50
ERROR40
WARNING30
INFO20
DEBUG10
NOTSET0
  • parent:父级Logger。一般最顶层的parent是root
  • propagate:布尔类型,是否把本Logger的日志发送到父级的Logger
  • Handlers:这是一个列表类型的属性,一个Logger可能有多个Handler
  • disabled:布尔类型,是否禁用本Logger,禁用之后不再输出日志。
    我们可以通过__dict__方式观察Logger的以上属性:
In [1]: import logging         
In [2]: app_logger = logging.Logger("app", logging.INFO) 
In [3]: app_ogger.__dict__
Out[3]: 
{'filters': [],
 'name': 'app',
 'level': 20,
 'parent': None,
 'propagate': True,
 'handlers': [],
 'disabled': False,
 '_cache': {}}

Logger组件有2种主要的创建方式:

  • logging.Logger(),接受2个参数:namelevel。创建出来的Logger没有parent,官方文档提示永远不要采取这种方式直接实例化Logger
  • logging.getLogger(__name__)或logging.getLogger('app.model'),这种方式创建的Logger最顶层parent是root。以logging.getLogger('app.model')为例,如果有app这个Logger,则其parent是app这个Logger,否则,其parent是root。例如:
In [1]: import logging
In [2]: model_logger = logging.getLogger("app.model") # 创建 app.model这个Logger
In [3]: model_logger.parent
Out[3]: <RootLogger root (WARNING)> # 这时候的parent是`root`
In [4]: app_logger = logging.getLogger("app") # 创建app这个Logger           
In [5]: model_logger.parent                                        
Out[5]: <Logger app (WARNING)> # 创建app这个logger之后,这时候的parent是`app`

可以调用setLevel方法修改Loggerlevel属性:

In [1]: import logging
In [2]: app_logger = logging.getLogger("app")
In [3]: logging.getLevelName(app_logger.level)               
Out[3]: 'NOTSET'
In [4]: app_logger.setLevel(logging.DEBUG) # 修改Level
In [5]: logging.getLevelName(app_logger.level)                  
Out[5]: 'DEBUG'

重复使用相同的名字调用 getLogger() 会一直返回相同的 Logger 对象的引用。

Handler组件

Handler组件定义了如何处理日志,我目前常用的三类:StreamHandlerFileHandlerRotatingFileHandler

  • StreamHandler:将日志记录输出发送到数据流例如 sys.stdout, sys.stderr 或任何文件类对象。
  • FileHandler:它可将日志记录输出到磁盘文件中。
  • RotatingFileHandler:支持磁盘日志文件的轮转。可以设置到达多少大小之后切割日志文件;以及保留多少份最新的日志文件。

官方还支持了QueueHandlerHTTPHandlerSysLogHandlerSocketHandler等等不同发送目标的Handler,有需要可以到logging.handlers官方文档中了解。

接下来通过一小段代码演示如何把日志同时输出到stdout和日志文件。

In [1]: import logging
In [2]: app_logger = logging.getLogger(__name__)
In [3]: app_logger.setLevel(logging.DEBUG)
In [4]: app_handler = logging.FileHandler("/tmp/app.log")
In [5]: console_handler = logging.StreamHandler()        
In [6]: app_logger.addHandler(console_handler)   
In [7]: app_logger.addHandler(app_handler) 
In [8]: app_logger.info("a test log to both file and console")   
a test log to both file and console # 这条是StreamHandler输出的日志
In [9]: cat /tmp/app.log     
a test log to both file and console # 这条是输出到文件的日志
In [10]: app_logger.handlers        
Out[10]: [<StreamHandler <stderr> (NOTSET)>, <FileHandler /tmp/app.log (NOTSET)>] # 检查app_logger的属性,确实有2个handler

Formatter组件

Formatter 对象定义日志的输出格式,可以在LogRecord 属性中查看其支持的变量有哪些,下面是我比较常用的日志输出格式:

In [1]: import logging
In [2]: log = logging.getLogger() 
In [3]: console_handler = logging.StreamHandler()
In [4]: formatter = logging.Formatter(
    "[%(asctime)s] {%(pathname)s:%(lineno)d} %(levelname)s - %(message)s")
In [5]: console_handler.setFormatter(formatter)      
In [6]: log.addHandler(console_handler)
In [7]: log.warning("a msg with format")  
[2020-11-28 17:48:16,774] {<ipython-input-7-215da6f2522c>:1} WARNING - a msg with format

注意

通常Loggerpropagate属性都为True,代表本Logger的日志会向上发送给父级Logger,所以,实践中,我们不需要给每个Logger都定义Handler,只需要在特定的父Logger中添加Handler即可。如果发现日志未正确输出,可以试着从propagate找找原因。
下图是python官方的logging模块日志处理流程图。

日志处理流程图

以上就介绍完了logging模块的主要组件和需要用到的知识点,下面进入实战模式,在实际代码中,我们应该如何使用logging

实战logging

脚本中使用logging

每次都挨个定义LoggerHandlerFormatter还是很麻烦的,尤其是当你只需要一个简单脚本的时候。我们可以偷懒采取如下更简单的方式:

import logging


logging.basicConfig(filename="/tmp/demo.log",
                    format="%(asctime)s " + logging.BASIC_FORMAT,
                    level=logging.DEBUG)


logging.debug("debug msg")
logging.info("info msg")
logging.warning("warn msg")
logging.critical("critical msg")

为了简化流程,在一些简单的脚本开发中,我们可以使用如上的logging.basicConfig方法快速的定义日志记录方法。

flask中使用logging

在使用Flask框架的时候,Flask实例自带了app.logger这个Logger。使用自带的Logger固然很方便,但是往往不利于代码解耦合。例如,我们自己创建了一个模块文件,如果模块文件的日志输出使用的是app.logger,这会导致模块文件强依赖app这个对象。当copy模块到其它程序中将变得无法执行。我建议在每个模块中创建自己的Logger,实例如下。新建一个demo项目,目录结构如下:

$ tree demo
demo
├── api
│ └── __init__.py
└── __init__.py

demo/__init__.py文件的内容如下,这个是demo模块。

import logging
from flask import Flask, request, jsonify
from .api import simple_add


app = Flask(__name__)

handler = logging.FileHandler("app.log")
handler.setFormatter(logging.Formatter(logging.BASIC_FORMAT))
app.logger.setLevel(logging.DEBUG) # 设置级别为DEBUG
app.logger.addHandler(handler) 

app.logger.info("app_logger is ready")

@app.route("/api/simple_add")
def simple_add_view():
    app.logger.info(f"{request.remote_addr} send a request")
    a = request.args.get("a") or 0
    b = request.args.get("b") or 0

    return jsonify(
        arg_a=a,
        arg_b=b,
        result=simple_add(a, b)
    )

demo/api/__init__.py的内容如下,这个就是demo.api模块

import logging

log = logging.getLogger(__name__)

def simple_add(a, b):
    log.debug(f"computing a + b, a is {a} and b is {b}")
    try:
        return float(a) + float(b)
    except ValueError as ex:
        log.error("convert value to float type error")
        log.exception(ex) # 在日志中打印异常traceback

运行以上的代码:

$ export FLASK_APP=demo/__init__.py
$ flask run
 * Serving Flask app "demo"
 * Running on http://127.0.0.1:5000/ (Press CTRL+C to quit)

开一个新终端,使用curl命令测试下上面的程序:

$ curl http://127.0.0.1:5000/api/simple_add # 无参数的情况
{
  "arg_a": 0, 
  "arg_b": 0, 
  "result": 0.0
}
$ curl "http://127.0.0.1:5000/api/simple_add?a=1&b=2" # 提供正常的参数
{
  "arg_a": "1", 
  "arg_b": "2", 
  "result": 3.0
}
$ curl "http://127.0.0.1:5000/api/simple_add?a=1&b=a" # 提供错误的参数
{
  "arg_a": "1", 
  "arg_b": "a", 
  "result": null
}

查看日志的输出情况:

INFO:demo:app_logger is ready
INFO:demo:127.0.0.1 send a request
DEBUG:demo.api:computing a + b, a is 0 and b is 0 
INFO:demo:127.0.0.1 send a request
DEBUG:demo.api:computing a + b, a is 1 and b is 2
INFO:demo:127.0.0.1 send a request
DEBUG:demo.api:computing a + b, a is 1 and b is a # demo.api模块输出的日志
ERROR:demo.api:convert value to float type error
ERROR:demo.api:could not convert string to float: 'a' # log.exception(ex)方法输出的traceback信息
Traceback (most recent call last):
  File "/tmp/demo/api/__init__.py", line 8, in simple_add
    return float(a) + float(b)
ValueError: could not convert string to float: 'a'

通过观察日志可以看到2个模块中各自打印了多行日志,Logger的名字分别为demodemo.api,而且log.exception(ex)记录下了异常情况下的traceback信息 。在这个案例中,demodemo.api2个模块进行了解耦,api模块可以复制到其他项目中直接使用。

三方模块的日志记录

在实际的项目中,我们会使用许多外部的开源库,如在flask中就常常会使用flask-apschedulerflask-sqlalchemy这两个模块。如果不做特殊处理,日志最后会逐层向上传到root Logger,其默认的输出是stdout。为了保证日志输出的一致性,我的习惯是把三方的日志也输出到应用日志文件中,比如app.log文件。做法是:首先创建对应模块的Logger,然后把应用的Handler附加到对应模块的Logger上。核心部分代码如下:

import os
import logging
from flask import Flask
from logging.handlers import RotatingFileHandler
from flask_sqlalchemy import SQLAlchemy
from flask_apscheduler import APScheduler

app = Flask(__name__)
db = SQLAlchemy(app)
scheduler = APScheduler()
scheduler.init_app(app)

MAX_LOG_SIZE = 500000000 # 500MB
RESERVE_COUNT = 10 # keep 10 log file

pwd = os.path.split(os.path.realpath(__file__))[0]  
app_log = pwd + '/app.log'
# 统一的日志handler
handler = RotatingFileHandler(app_log, maxBytes=MAX_LOG_SIZE,
                              backupCount=RESERVE_COUNT)
formatter = logging.Formatter(
    "[%(asctime)s] %(name)s {%(pathname)s:%(lineno)d} %(levelname)s - %(message)s")
handler.setFormatter(formatter)
app.logger.addHandler(handler)
app.logger.setLevel(logging.INFO)

# sqlalchemy 的日志输出
sql_log = logging.getLogger("sqlalchemy")
sql_log.setLevel(logging.INFO)
sql_log.addHandler(handler)

# apscheduler 模块的日志输出
aps_log = logging.getLogger("apscheduler")
aps_log.setLevel(logging.INFO)
aps_log.addHandler(handler)

通过上面的办法,可以将三方模块的日志全部统一输出到app.log文件中。

参考资料:

https://docs.python.org/zh-cn/3/library/logging.handlers.html

https://docs.python.org/zh-cn/3/library/logging.html#logrecord-attributes

当前暂无评论 »

添加新评论 »