✍🏻Logging如何优雅记日志

✍🏻Logging如何优雅记日志

如何为后端web接口生成清晰明了、便于查错追踪的日志

  • 日志相关概念

  • Python的logging模块介绍

  • 使用logging记录日志

  • 配置logging的几种方式

  • 错误日志发送邮件方法

  • 常见问题

一、日志相关概念

日志是一种可以追踪某些软件运行时所发生事件的方法。软件开发人员可以向他们的代码中调用日志记录相关的方法来表明发生了某些事情。一个事件可以用一个可包含可选变量数据的消息来描述。此外，事件也有重要性的概念，这个重要性也可以被称为严重性级别（level）。

1.日志的作用

通过log的分析，可以方便用户了解系统或软件、应用的运行情况；如果你的应用log足够丰富，也可以分析以往用户的操作行为、类型喜好、地域分布或其他更多信息；如果一个应用的log同时也分了多个级别，那么可以很轻易地分析得到该应用的健康状况，及时发现问题并快速定位、解决问题，补救损失。
简单来讲就是，我们通过记录和分析日志可以了解一个系统或软件程序运行情况是否正常，也可以在应用程序出现故障时快速定位问题。比如，做运维的同学，在接收到报警或各种问题反馈后，进行问题排查时通常都会先去看各种日志，大部分问题都可以在日志中找到答案。再比如，做开发的同学，可以通过IDE控制台上输出的各种日志进行程序调试。对于运维老司机或者有经验的开发人员，可以快速的通过日志定位到问题的根源。可见，日志的重要性不可小觑。日志的作用可以简单总结为以下3点：

  • 程序调试

  • 了解软件程序运行情况，是否正常

  • 软件程序运行故障分析与问题定位

如果应用的日志信息足够详细和丰富，还可以用来做用户行为分析，如：分析用户的操作行为、类型洗好、地域分布以及其它更多的信息，由此可以实现改进业务、提高商业利益。

2.日志的等级

我们先来思考下下面的两个问题：

  • 作为开发人员，在开发一个应用程序时需要什么日志信息？在应用程序正式上线后需要什么日志信息？

  • 作为应用运维人员，在部署开发环境时需要什么日志信息？在部署生产环境时需要什么日志信息？

在软件开发阶段或部署开发环境时，为了尽可能详细的查看应用程序的运行状态来保证上线后的稳定性，我们可能需要把该应用程序所有的运行日志全部记录下来进行分析，这是非常耗费机器性能的。当应用程序正式发布或在生产环境部署应用程序时，我们通常只需要记录应用程序的异常信息、错误信息等，这样既可以减小服务器的I/O压力，也可以避免我们在排查故障时被淹没在日志的海洋里。那么，怎样才能在不改动应用程序代码的情况下实现在不同的环境记录不同详细程度的日志呢？这就是日志等级的作用了，我们通过配置文件指定我们需要的日志等级就可以了。

不同的应用程序所定义的日志等级可能会有所差别，分的详细点的会包含以下几个等级：

日志等级（level） 描述
DEBUG 最详细的日志信息，典型应用场景是 问题诊断
INFO 信息详细程度仅次于DEBUG，通常只记录关键节点信息，用于确认一切都是按照我们预期的那样进行工作
WARNING 当某些不期望的事情发生时记录的信息（如，磁盘可用空间较低），但是此时应用程序还是正常运行的
ERROR 由于一个更严重的问题导致某些功能不能正常运行时记录的信息
CRITICAL 当发生严重错误，导致应用程序不能继续运行时记录的信息

开发应用程序或部署开发环境时，可以使用DEBUG或INFO级别的日志获取尽可能详细的日志信息来进行开发或部署调试；应用上线或部署生产环境时，应该使用WARNING或ERROR或CRITICAL级别的日志来降低机器的I/O压力和提高获取错误日志信息的效率。日志级别的指定通常都是在应用程序的配置文件中进行指定的。

3.日志字段信息与日志格式

本节开始问题提到过，一条日志信息对应的是一个事件的发生，而一个事件通常需要包括以下几个内容：

  • 事件发生时间

  • 事件发生位置

  • 事件的严重程度—日志级别

  • 事件内容

上面这些都是一条日志记录中可能包含的字段信息，当然还可以包括一些其他信息，如进程ID、进程名称、线程ID、线程名称等。日志格式就是用来定义一条日志记录中包含那些字段的，且日志格式通常都是可以自定义的。

4.日志功能的实现

几乎所有开发语言都会内置日志相关功能，或者会有比较优秀的第三方库来提供日志操作功能，比如：log4j，log4php等。它们功能强大、使用简单。Python自身也提供了一个用于记录日志的标准库模块—logging。

二、logging模块

logging模块定义的模块级别的常用函数

函数 说明
logging.debug(msg, args, *kwargs) 创建一条严重级别为DEBUG的日志记录
logging.info(msg, args, *kwargs) 创建一条严重级别为INFO的日志记录
logging.warning(msg, args, *kwargs) 创建一条严重级别为WARNING的日志记录
logging.error(msg, args, *kwargs) 创建一条严重级别为ERROR的日志记录
logging.critical(msg, args, *kwargs) 创建一条严重级别为CRITICAL的日志记录
logging.log(level, args, *kwargs) 创建一条严重级别为level的日志记录
logging.basicConfig(**kwargs) 对root logger进行一次性配置

logging模块的四大组件

在介绍logging模块的日志流处理流程之前，我们先来介绍下logging模块的四大组件：

组件名称 对应类名 功能描述
日志器 Logger 提供了应用程序可一直使用的接口
处理器 Handler 将logger创建的日志记录发送到合适的目的输出
过滤器 Filter 提供了更细粒度的控制工具来决定输出哪条日志记录，丢弃哪条日志记录
格式器 Formatter 决定日志记录的最终输出格式
这些组件之间的关系描述：

简单点说就是：日志器（logger）是入口，真正干活儿的是处理器（handler），处理器（handler）还可以通过过滤器（filter）和格式器（formatter）对要输出的日志内容做过滤和格式化等处理操作。

logging模块定义的格式字符串字段

我们来列举一下logging模块中定义好的可以用于format格式字符串中字段有哪些：

字段/属性名称 使用格式 描述
asctime %(asctime)s 日志事件发生的时间—人类可读时间，如：2003-07-08 16:49:45,896
created %(created)f 日志事件发生的时间—时间戳，就是当时调用time.time()函数返回的值
relativeCreated %(relativeCreated)d 日志事件发生的时间相对于logging模块加载时间的相对毫秒数（目前还不知道干嘛用的）
msecs %(msecs)d 日志事件发生事件的毫秒部分
levelname %(levelname)s 该日志记录的文字形式的日志级别（’DEBUG’, ‘INFO’, ‘WARNING’, ‘ERROR’, ‘CRITICAL’）
levelno %(levelno)s 该日志记录的数字形式的日志级别（10, 20, 30, 40, 50）
name %(name)s 所使用的日志器名称，默认是’root’，因为默认使用的是 rootLogger
message %(message)s 日志记录的文本内容，通过 msg % args计算得到的
pathname %(pathname)s 调用日志记录函数的源码文件的全路径
filename %(filename)s pathname的文件名部分，包含文件后缀
module %(module)s filename的名称部分，不包含后缀
lineno %(lineno)d 调用日志记录函数的源代码所在的行号
funcName %(funcName)s 调用日志记录函数的函数名
process %(process)d 进程ID
processName %(processName)s 进程名称，Python 3.1新增
thread %(thread)d 线程ID
threadName %(thread)s 线程名称

三、使用logging记录日志

1.最简单的日志输出

1
2
3
4
5
6
7
import logging

logging.debug("This is a debug log.")
logging.info("This is a info log.")
logging.warning("This is a warning log.")
logging.error("This is a error log.")
logging.critical("This is a critical log.")

2. 高级的日志输出

1. 需求

现在有以下几个日志记录的需求：

  • 1）要求将所有级别的所有日志都写入磁盘文件中

  • 2）all.log 文件中记录所有的日志信息，日志格式为：日期和时间 - 日志级别 - 日志信息

  • 3）error.log 文件中单独记录error及以上级别的日志信息，日志格式为：日期和时间 - 日志级别 - 文件名[:行号] - 日志信息

  • 4）要求 all.log 在每天凌晨进行日志切割

2. 分析

  • 1）要记录所有级别的日志，因此日志器的有效level需要设置为最低级别—DEBUG;

  • 2）日志需要被发送到两个不同的目的地，因此需要为日志器设置两个handler；另外，两个目的地都是磁盘文件，因此这两个handler都是与 FileHandler 相关的；

  • 3）all.log 要求按照时间进行日志切割，因此他需要用 logging.handlers.TimedRotatingFileHandler; 而 error.log 没有要求日志切割，因此可以使用FileHandler;

  • 4）两个日志文件的格式不同，因此需要对这两个handler分别设置格式器；

3. 代码实现

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
import logging
import logging.handlers
import datetime

# 创建一个日志器logger并设置其日志级别为DEBUG
logger = logging.getLogger('mylogger')
logger.setLevel(logging.DEBUG)

# “midnight”: Roll over at midnight
# interval 是指等待多少个单位when的时间后，Logger会自动重建文件
# backupCount 是保留日志个数。默认的0是不会自动删除掉日志
rf_handler = logging.handlers.TimedRotatingFileHandler('all.log', when='midnight', interval=1, backupCount=7, atTime=datetime.time(0, 0, 0, 0), encoding='UTF-8')
# 创建一个格式器formatter并将其添加到处理器handler
formatter = logging.Formatter("[%(levelname)s] [%(asctime)s] [%(filename)s:%(lineno)d] %(message)s")
rf_handler.setFormatter(formatter)

# 创建一个文件处理器handler并设置其日志级别为ERROR
f_handler = logging.FileHandler('error.log')
f_handler.setLevel(logging.ERROR)
# 创建一个格式器formatter并将其添加到处理器handler
formatter2 = logging.Formatter("[%(levelname)s] [%(asctime)s] [%(filename)s:%(lineno)d] %(message)s")
f_handler.setFormatter(formatter2)

# 这个判断是重复写日志问题，仅handlers列表为空才添加
if not logger.handlers:
    # 为日志器logger添加上面创建的处理器handler
    logger.addHandler(rf_handler)
    logger.addHandler(f_handler)

# 日志输出
logger.debug('debug message')
logger.info('info message')
logger.warning('warning message')
logger.error('error message')
logger.critical('critical message')

all.log文件输出

1
2
3
4
5
2017-05-13 16:12:40,612 - DEBUG - debug message
2017-05-13 16:12:40,612 - INFO - info message
2017-05-13 16:12:40,612 - WARNING - warning message
2017-05-13 16:12:40,612 - ERROR - error message
2017-05-13 16:12:40,613 - CRITICAL - critical message

error.log文件输出

1
2
2017-05-13 16:12:40,612 - ERROR - log.py[:81] - error message
2017-05-13 16:12:40,613 - CRITICAL - log.py[:82] - critical message

六、配置logging的几种方式

作为开发者，我们可以通过以下3中方式来配置logging:

  • 1）使用Python代码显式的创建loggers, handlers和formatters并分别调用它们的配置函数；

  • 2）创建一个日志配置文件，然后使用fileConfig()函数来读取该文件的内容；

  • 3）创建一个包含配置信息的dict，然后把它传递个dictConfig()函数；

具体说明请参考另一篇博文 《python之配置日志的几种方式》

七、错误日志发送邮件或者调用HTTP接口

当系统上线之后， 多多少少程序会因为各种各样的问题产生Error级别的日志。 但是我们又不能一直盯着线上日志。

一个简单的办法， 当出现错误日志的时候， 主动通知。 比如发邮件或者调用Http Webhook 接口。

在标准日志库 logging 之中，就有 SMTPHandler 跟 HTTPHandler 可以实现这个功能。 下面以发邮件为例子。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
# 引入类库
from logging.handlers import SMTPHandler
 
# 配置handler&formatter
# 注意 163 邮箱要求 fromaddr 和你发送邮件的邮箱(即你的邮箱账号)要一致
mail_handler = SMTPHandler(
    mailhost=('smtp.163.com', 25),
    fromaddr='xxx@163.com',
    toaddrs='接收报警邮件的地址',
    subject='[madmalls.com] 服务器出错了',
    credentials=('xxx@163.com', '客户端授权密码'))
mail_handler.setLevel(logging.ERROR)
mail_handler.setFormatter(logging.Formatter(
    "[%(asctime)s][%(module)s:%(lineno)d][%(levelname)s][%(thread)d] - %(message)s"
))
 
# app.logger
app.logger.addHandler(mail_handler)

八、遇到的问题

  1. logging库打印日志，存在日志丢失没打印到文件的情况
    原因：按照官方文档的介绍，logging 是线程安全的，也就是说，在一个进程内的多个线程同时往同一个文件写日志是安全的。但是（对，这里有个但是）多个进程往同一个文件写日志不是安全的（也即Python自带的logging库是不支持多进程的！参考1、参考2 ）使用FileHandler多进程写同一个日志文件的时候会产生日志截断, 丢失等问题, 日志写入不能保证原子性证明, 确实多进程写同一个日志文件会有问题。
    解决：使用第三方库 concurrent_log ，作者对logging库重写后进行了测试，证明已解决多线程、多进程的问题

  2. 12月29的调用日志，打到了27号的log文件中了
    应该同上

  3. logging 重复写日志问题
    情况：用Python的logging模块记录日志时，遇到了重复记录日志的问题（每条记录会重复记录两次）
    原因：没有移除handler或重复添加多个相同的handler
    解决：1、在日志记录完之后removeHandler；2、在log方法里做判断，如果这个logger已有handler，则不再添加handler√ 

1
2
3
if not logger.handlers:
	logger.addHandler(x_handler)
	logger.addHandler(y_handler)

参考

Python之日志处理（logging模块）

【踩坑记录】记录一次使用Pythonlogging库多进程打印日志的填坑过程

https://segmentfault.com/a/1190000018087099

https://www.ctolib.com/topics-137034.html

https://madmalls.com/blog/post/smtphandler-send-error-email/

#Logging
✍🏻Logging如何优雅记日志
http://example.com/2019/10/22/2019-10-22-✍🏻Logging如何优雅记日志/
作者
NSX
发布于
2019年10月22日
许可协议