框架之日志管理
1 Butterfly 日志
1.1 Butterfly 日志概览
程序标准输出
__stdout框架日志
logs/acc.log: access 日志
logs/err.log: error 日志
logs/init.log: 启动信息日志
自定义日志
logs/common.log
logs/common.log.wf
logs/common_bf.log
logs/common_bf.log.wf
1.2 访问日志
logs/acc.log
1.2.1 不同请求时的访问日志
curl "http://127.0.0.1:8585/demo_api/ping" -------------------------- 正常无参数请求
2021-02-09 10:18:02 97082 /meetbill/butterfly/xlib/httpgateway.py:259 127.0.0.1 75DA11E45E4644EF GET /demo_api/ping cost:0.000455 stat:OK user:- talk: params:x=1 error_msg: res:curl "http://127.0.0.1:8585/demo_api/hello?str_info=meetbill" ------- 正常有参数请求
2021-02-09 10:19:51 97082 /meetbill/butterfly/xlib/httpgateway.py:259 127.0.0.1 549D3CA17B4182EE GET /demo_api/hello cost:0.001822 stat:OK user:- talk: params:str_info=meetbill error_msg: res:curl "http://127.0.0.1:8585/demo_api/hello?str_infox=meetbill" ------ 接口存在，但参数错误
2021-02-09 10:21:08 97082 /meetbill/butterfly/xlib/httpgateway.py:259 127.0.0.1 4E44BDEBD770F599 GET /demo_api/hello cost:0.000263 stat:ERR_BAD_PARAMS user:- talk: params:str_infox=meetbill error_msg:Param check failed res:curl -v "http://127.0.0.1:8585/demo_api/hellox?str_info=meetbill" -- 接口不存在
2021-02-09 10:22:10 97082 /meetbill/butterfly/xlib/httpgateway.py:259 127.0.0.1 8A348A0C7D9699D2 GET /demo_api/hellox cost:0.002694 stat:400 user:- talk: params: error_msg:API Not Found res:1.2.2 字段解析
curl "http://127.0.0.1:8585/demo_api/hello?str_info=meetbill" ------- 正常有参数请求
2021-02-08 21:35:30 91640 /meetbill/butterfly/xlib/httpgateway.py:259 127.0.0.1 1FA15BDE4B6CD7A0 GET /demo_api/hello cost:0.000162 stat:OK user:- talk:ceshi1=0.098;ceshi2=0.002 params:str_info=hello error_msg: res:ceshi2=5.4;ceshi1=5.3以正常有参数请求日志为例
DATE: 2021-02-08
TIME: 21:35:30
PID : 91640
CODE_INFO: /meetbill/butterfly/xlib/httpgateway.py:259
IP: 127.0.0.1
REQID: 1FA15BDE4B6CD7A0 (请求 ID)
METHOD: GET
PATH: /demo_api/hello
COST: cost:0.000162 (整体耗时，单位是秒)
STAT: stat:OK (执行结果状态, 若自定义 HTTP 方式时，则此处会是 HTTP 状态码)
USER: user:- (用户名)
TALK: talk:ceshi1=0.098;ceshi2=0.002 (代码片段耗时，比如一个 SQL 语句，请求 Redis 的耗时等)
PARAMS: params:str_info=hello (请求参数)
ERROR_MSG: error_msg:(错误信息)
RES: res:ceshi2=5.4;ceshi1=5.3 (需要记录的结果数据信息)
1.2.3 时间说明
厂内 GDP 的时间
+--------+------+---------+-------+-------------------+------+--------+-------+
| | | | | | | | |
| ...... | pack | connect | write | server processing | read | unpack | ..... |
| | | | | | | | |
+--------+----------------+-------+-------------------+---------------+-------+
| | | |
| | <----------------- talk -----------------> | |
| |
| |
| <--------------------------------- cost ----------------------------------> |
| |
talk[7.561] 本次交互耗时， 单位ms
connect[3.673] 链接耗时， 单位ms
write[0.241] 写耗时, 单位ms
read[0.100] 读耗时, 单位ms
pack[0] 打包的耗时, 单位ms
unpack[0.179] 解包的耗时,单位ms
1.3 自定义日志 logging
logging 中的几个概念：
Logger ：日志记录器，是应用程序中可以直接使用的接口。
Handler ：日志处理器，用以表明将日志保存到什么地方以及保存多久。
Formatter：格式化，用以配置日志的输出格式。上述三者的关系是：一个 Logger 使用多个 Handler，一个 Handler 使用一个 Formatter。
+----------------------------------------+
| Logger |
+----------------------------------------+
| | |
V V V
+----------+ +----------+ +----------+
| Handler1 | | Handler2 | | Handler3 |
+----------+ +----------+ +----------+
| | |
V V V
+----------+ +----------+ +----------+
|Formatter1| |Formatter2| |Formatter3|
+----------+ +----------+ +----------+配置
def init_log(log_path, level=logging.INFO, when="D", backup=7,
format="%(levelname)s: %(asctime)s: %(filename)s:%(lineno)d * %(thread)d %(message)s",
datefmt="%m-%d %H:%M:%S"):
formatter = logging.Formatter(format, datefmt)
logger = logging.getLogger()
handler = logging.handlers.TimedRotatingFileHandler(log_path, when=when, backupCount=backup)
handler.setLevel(level)
handler.setFormatter(formatter)
logger.addHandler(handler)
handler = logging.handlers.TimedRotatingFileHandler(log_path + ".wf", when=when, backupCount=backup)
handler.setLevel(logging.WARNING)
handler.setFormatter(formatter)
logger.addHandler(handler)1.3.1 logging 模块常用 format 格式说明
%(name)s : Logger 的名字 # 也就是其中的 .getLogger 里的路径，或者我们用他的文件名看我们填什么
%(levelno)s : 数字形式的日志级别 # 日志里面的打印的对象的级别
%(levelname)s : 文本形式的日志级别 # 级别的名称
%(pathname)s : 调用日志输出函数的模块的完整路径名，可能没有
%(filename)s : 调用日志输出函数的模块的文件名
%(module)s : 调用日志输出函数的模块名
%(funcName)s : 调用日志输出函数的函数名
%(lineno)d : 调用日志输出函数的语句所在的代码行
%(created)f : 当前时间，用 UNIX 标准的表示时间的浮 点数表示
%(relativeCreated)d : 输出日志信息时的，自 Logger 创建以 来的毫秒数
%(asctime)s : 字符串形式的当前时间。默认格式是 “2003-07-08 16:49:45,896”。逗号后面的是毫秒
%(thread)d : 线程 ID。可能没有
%(threadName)s : 线程名。可能没有
%(process)d : 进程 ID。可能没有
%(message)s : 用户输出的消息common 日志 format
format="%(levelname)s: %(asctime)s: %(filename)s:%(lineno)d * %(thread)d %(message)s",1.3.2 logging 记录日志时默认添加 reqid 信息
除了传递给日志记录函数的参数外，有时候我们还想在日志输出中包含一些额外的上下文信息。
比如，在一个网络应用中，可能希望在日志中记录客户端的特定信息，如：请求 id
这里我们来介绍以下几种实现方式，详细查看传送门：
通过向日志记录函数传递一个 extra 参数引入上下文信息
使用 LoggerAdapters 引入上下文信息
使用 Filters 引入上下文信息
实现
本框架使用 Filters 实现对要打印的日志默认添加 reqid 信息
主线程中设置：logging 的 filters 模块添加 reqid 信息，reqid 从 butterfly_local 中获取
butterfly_local = threading.local()
class RequestLogFilter(logging.Filter):
"""
日志过滤器，将当前请求线程的 reqid 信息保存到日志的 record 上下文
Filter 提供的是比 log level 更精确的过滤控制，只有当 Filter.filter 函数返回 True 的时候，这条日志才会被输出。
https://docs.python.org/zh-cn/3/howto/logging-cookbook.html#using-loggeradapters-to-impart-contextual-information
"""
def filter(self, record):
record.reqid = getattr(butterfly_local, 'reqid', "XXXXXXXXXXXXXXXX")
return True线程中更新 butterfly_local 的属性
import xlib.logger
...
xlib.logger.butterfly_local.reqid = reqid
...todo
以上方式在使用 logging 记录日志时不需要额外传参，但每次写日志都会查询全局作用域，所以会消耗一些时间, 后续可以再优化下
变量作用域
Python 中，程序的变量并不是在哪个位置都可以访问的，访问权限决定于这个变量是在哪里赋值的。
变量的作用域决定了在哪一部分程序可以访问哪个特定的变量名称。Python 的作用域一共有 4 种，分别是：
L （Local） 局部作用域
E （Enclosing） 闭包函数外的函数中
G （Global） 全局作用域
B （Built-in） 内建作用域
以 L –> E –> G –>B 的规则查找，即：在局部找不到，便会去局部外的局部找（例如闭包），再找不到就会去全局找，再者去内建中找作用域例子
a = int(3.14) # int 函数在内建作用域中
NAME='John' # NAME 在全局作用域中
def fun():
name='July' # 闭包函数外的函数域
def fun2():
name='Jack' # 局部作用域
print(name)
fun()2 Butterfly 日志相关实现
2.1 获取当前运行函数文件名和代码行号
对象的属性
dir（对象） 获取实例的属性名，以列表形式返回
函数 (function) 的属性一般为 func_*
方法 (method) 的属性一般为 im_* (instance_method)
生成器 (generator) 的属性一般为 gi_*
代码块 (code) 的属性一般为 co_*
栈帧 (frame) 的属性一般为 f_*, 函数调用时才会产生
追踪 (traceback) 的属性为 tb_*, 异常时才会构建生成栈帧 (frame)
栈帧表示程序运行时函数调用栈中的某一帧。函数没有属性可以获取它，因为它在函数调用时才会产生，而生成器则是由函数调用返回的，所以有属性指向栈帧。想要获得某个函数相关的栈帧，则必须在调用这个函数且这个函数尚未返回时获取。你可以使用 sys 模块的_getframe() 函数、或 inspect 模块的 currentframe() 函数获取当前栈帧。这里列出来的属性全部是只读的。
f_back: 调用栈的前一帧。
f_code: 栈帧对应的 code 对象。
f_locals: 用在当前栈帧时与内建函数 locals() 相同，但你可以先获取其他帧然后使用这个属性获取那个帧的 locals()。
f_globals: 用在当前栈帧时与内建函数 globals() 相同，但你可以先获取其他帧……。
f_lineno: 代码在哪一行代码块 (code)
代码块可以由类源代码、函数源代码或是一个简单的语句代码编译得到。这里我们只考虑它指代一个函数时的情况；
co_argcount: 普通参数的总数，不包括*参数和**参数。
co_names: 所有的参数名（包括*参数和**参数）和局部变量名的元组。
co_varnames: 所有的局部变量名的元组。
co_filename: 源代码所在的文件名。代码
def get_cur_info()
func = inspect.currentframe().f_back
filename = os.path.basename(func.f_code.co_filename)
lineno = func.f_lineno
cur_info = "{filename}:{lineno}".format(filename=filename, lineno=lineno)2.2 使用 inspect.stack() 获取调用栈
2.2.1 demo
#!/usr/bin/python
# coding=utf8
import inspect
def get_stack():
"""
return call stack info
# stack[0] 是调用 stack() 处的 frame_record, 丢弃（即本函数中的 stack = inspect.stack())
# stack[1] 是调用 get_stack() 处的 frame_record, 丢弃
"""
stack = inspect.stack()
msg="[call stack]:"
for i in range(2, len(stack) ):
filename = stack[i][1]
lineno = stack[i][2]
code = stack[i][4][0]
# code[0:-1] 是为了去掉后面的 "\n"
msg=msg +"\n" + '\t\t<frame %d>:%s, line:%d func:%s' % (i - 1, filename, lineno, code[0:-1] )
return msg
def v2():
w = get_stack()
print w
def v1():
v2()
def main():
v1()
if __name__ == "__main__":
main()输出
[call stack]:
<frame 1>:test_inspect.py, line:29 func: v2()
<frame 2>:test_inspect.py, line:32 func: v1()
<frame 3>:test_inspect.py, line:35 func: main()inspect.stack() 信息
[
(<frame object at 0x7fbe78f1ab20>, 'test_inspect.py', 12, 'get_stack', [' stack = inspect.stack()\n'], 0),
(<frame object at 0x10a6bc200>, 'test_inspect.py', 25, 'v2', [' w = get_stack()\n'], 0),
(<frame object at 0x10a617548>, 'test_inspect.py', 29, 'v1', [' v2()\n'], 0),
(<frame object at 0x10a6173a0>, 'test_inspect.py', 32, 'main', [' v1()\n'], 0),
(<frame object at 0x10a4d4c20>, 'test_inspect.py', 35, '<module>', [' main()\n'], 0)
]2.2.2 封装为库
import inspect
def get_stack():
"""
return call stack info
# stack[0] 是调用 stack() 处的 frame_record, 丢弃（即本函数中的 stack = inspect.stack())
# stack[1] 是调用 get_stack() 处的 frame_record, 丢弃
"""
stack = inspect.stack()
msg="[call stack]:"
for i in range(2, len(stack) ):
filename = stack[i][1]
lineno = stack[i][2]
code = stack[i][4][0]
# code[0:-1] 是为了去掉后面的 "\n"
msg=msg +"\n" + '\t\t<frame %d>:%s, line:%d func:%s' % (i - 1, filename, lineno, code[0:-1] )
return msg即在需要打印日志的时候，可以通过调用 get_stack() 获取调用栈信息
3 报表
报表统计需要分析日志的字段并进行统计
3.1 使用 re 进行日志中的字段预处理
3.1.1 re 匹配日志
re 分组
r"/index/(?P<num>\d*)/(?P<nid>\d*)"
(?P<num>\d*) 是将后面匹配的 \d* 数据，取一个组名，这个组名必须是唯一的，不重复的，没有特殊符号，函数可以获得这个组名下的数据3.1.2 twemproxy 解析日志 demo
# [2020-02-23 12:30:35.273] nc_response.c:646 SLOW_LOG_1 : cost_time(110614us) recv_client_time(1582432235.162875s) send_server_time(1582432235.163468s) recv_server_time(1582432235.164527s) send_client_time(1582432235.273489s)
# 此处的时间格式和常态表示方法不同
# 此处的 1582432235.162875s 小数点前是秒数，小数点后是微妙数，当 1582432235.875s 时表示 875 微秒，而不是毫秒
parts = [
r'.*SLOW_LOG_1\s+:', # [2020-02-23 12:30:35.273] nc_response.c:646 SLOW_LOG_1 :
r'cost_time\((?P<cost_time>[0-9]+)us\)', # cost_time(110614us)
r'recv_client_time\((?P<recv_client_time_s>[0-9]+)\.(?P<recv_client_time_us>[0-9]+)s\)', # recv_client_time(1582432235.162875s)
r'send_server_time\((?P<send_server_time_s>[0-9]+)\.(?P<send_server_time_us>[0-9]+)s\)', # send_server_time(1582432235.163468s)
r'recv_server_time\((?P<recv_server_time_s>[0-9]+)\.(?P<recv_server_time_us>[0-9]+)s\)', # recv_server_time(1582432235.164527s)
r'send_client_time\((?P<send_client_time_s>[0-9]+)\.(?P<send_client_time_us>[0-9]+)s\)', # send_client_time(1582432235.273489s)
r'(?P<EXTRA>.*)',
]
pattern = re.compile(r'\s+'.join(parts)+r'\s*')
m = pattern.match(line)
if m:
print m.groupdict()3.1.2 GDP 解析日志 demo
GDP 日志是以 key1[value1] key2[value2] 方式输出，可以通过如下方式获取到每个 field 的值
parts_auto = [
r'.*apply_bcc_resource.go:[0-9]+',
r'worker_id\[(?P<worker_id>.*)\]',
r'logid\[(?P<logid>.*)\]',
r'task_id\[(?P<task_id>.*)\]',
r'task_batch_id\[(?P<task_batch_id>.*)\]',
r'unit_id\[(?P<unit_id>.*)\]',
r'entity\[(?P<entity>.*)\]',
r'processor\[(?P<processor>.*)\]',
r'user_orderid\[(?P<user_orderid>.*)\]',
r'deployset\[(?P<deployset>.*)\]',
r'count\[(?P<count>.*)\]',
r'reserve\[(?P<reserve>.*)\]',
r'user_id\[(?P<user_id>.*)\]',
r'bcc_orderid\[(?P<bcc_orderid>.*)\]',
r'exe_step\[(?P<exe_step>.*)\]',
r'error\[(?P<error>.*)\]',
r'message\[(?P<message>.*)\]',
r'.*',
]
pattern_auto = re.compile(r'\s+'.join(parts_auto)+r'\s*')3.2 将日志转换为 dict
import re
def line2dict(line):
#Snippet, thanks to http://www.seehuhn.de/blog/52
parts = [
r'(?P<DATE>\S+)', # date eg.:2019-08-12
r'(?P<TIME>\S+)', # time eg.:09:22:47
r'(?P<PID>\S+)', # pid eg.:41442
r'(?P<CODE_INFO>\S+)', # code_info eg.:httpgateway.py:185
r'(?P<HOST>\S+)', # host eg.:127.0.0.1
r'(?P<REQID>\S+)', # reqid eg.:CACE332C8F5E39F8
r'(?P<METHOD>\S+)', # method eg.:GET
r'(?P<PATH>\S+)', # path eg.:/x/ping
r'cost:(?P<COST>\S+)', # cost time eg.:0.002147
r'stat:(?P<STAT>\S+)', # status eg.:200(careful, can be 'OK'/'ERR')
r'user:(?P<USER>\S+)', # username eg.:meetbill (or -)
r'talk:(?P<TALK>\S*)', # talk eg.:ceshi1=404.443;ceshi2=101.594
r'params:(?P<PARAMS>\S*)', # params eg.:str_info=hello
r'error_msg:(?P<ERROR_MSG>.*)', # error_msg eg.:API Processing Exception
r'res:(?P<RES>.*)', # result eg.:ceshi2=5.4;ceshi1=5.3
]
pattern = re.compile(r'\s+'.join(parts)+r'\s*\Z')
m = pattern.match(line)
res = m.groupdict()
return res
with open("./acc.log") as f:
for line in f.readlines():
print line2dict(line)eg.
源日志：
2021-02-09 10:18:02 97082 /meetbill/butterfly/xlib/httpgateway.py:259 127.0.0.1 75DA11E45E4644EF GET /demo_api/ping cost:0.000455 stat:OK user:- talk: params:x=1 error_msg: res:
2021-02-09 10:19:51 97082 /meetbill/butterfly/xlib/httpgateway.py:259 127.0.0.1 549D3CA17B4182EE GET /demo_api/hello cost:0.001822 stat:OK user:- talk: params:str_info=meetbill error_msg: res:
2021-02-09 10:21:08 97082 /meetbill/butterfly/xlib/httpgateway.py:259 127.0.0.1 4E44BDEBD770F599 GET /demo_api/hello cost:0.000263 stat:ERR_BAD_PARAMS user:- talk: params:str_infox=meetbill error_msg:Param check failed res:
2021-02-09 10:22:10 97082 /meetbill/butterfly/xlib/httpgateway.py:259 127.0.0.1 8A348A0C7D9699D2 GET /demo_api/hellox cost:0.002694 stat:400 user:- talk: params: error_msg:API Not Found res:
转换后：
{'STAT': 'OK', 'RES': '', 'TIME': '10:18:02', 'PID': '97082', 'HOST': '127.0.0.1', 'METHOD': 'GET', 'REQID': '75DA11E45E4644EF', 'COST': '0.000455', 'PARAMS': 'x=1', 'USER': '-', 'CODE_INFO': '/meetbill/butterfly/xlib/httpgateway.py:259', 'DATE': '2021-02-09', 'PATH': '/demo_api/ping', 'ERROR_MSG': '', 'TALK': ''}
{'STAT': 'OK', 'RES': '', 'TIME': '10:19:51', 'PID': '97082', 'HOST': '127.0.0.1', 'METHOD': 'GET', 'REQID': '549D3CA17B4182EE', 'COST': '0.001822', 'PARAMS': 'str_info=meetbill', 'USER': '-', 'CODE_INFO': '/meetbill/butterfly/xlib/httpgateway.py:259', 'DATE': '2021-02-09', 'PATH': '/demo_api/hello', 'ERROR_MSG': '', 'TALK': ''}
{'STAT': 'ERR_BAD_PARAMS', 'RES': '', 'TIME': '10:21:08', 'PID': '97082', 'HOST': '127.0.0.1', 'METHOD': 'GET', 'REQID': '4E44BDEBD770F599', 'COST': '0.000263', 'PARAMS': 'str_infox=meetbill', 'USER': '-', 'CODE_INFO': '/meetbill/butterfly/xlib/httpgateway.py:259', 'DATE': '2021-02-09', 'PATH': '/demo_api/hello', 'ERROR_MSG': 'Param check failed', 'TALK': ''}
{'STAT': '400', 'RES': '', 'TIME': '10:22:10', 'PID': '97082', 'HOST': '127.0.0.1', 'METHOD': 'GET', 'REQID': '8A348A0C7D9699D2', 'COST': '0.002694', 'PARAMS': '', 'USER': '-', 'CODE_INFO': '/meetbill/butterfly/xlib/httpgateway.py:259', 'DATE': '2021-02-09', 'PATH': '/demo_api/hellox', 'ERROR_MSG': 'API Not Found', 'TALK': ''}3.3 输出例子
访问方式
http://{IP}:{PORT}/demo_template/log4 tips
4.1 如何匹配 acc.log 对应的列数据
acc.log 的各列间使用 TAB 间隔
假设要获取 400 状态码的日志，需要加
—P来匹配 TAB
cat acc.log | grep -P "\tstat:400\t"4.2 如果查看大日志文件
比如一行日志就有 200MB
方法1: 只查看某些列数据
awk '{for(i=1;i<15;i++) printf("%s ",$i); printf("\n")}' common_bf.log
方法2: 将日志进行切割(按字节大小分割)
split -b 10m large_file.log new_file_prefix5 在线调整日志级别
在线调整日志级别
获取缓存命中率等信息
5.1 logging 日志级别调整
DEBUG(10) < INFO(20) < WARNING(30) < ERROR(40) < CRITICAL(50)
目前调整时只能调整为启动时的级别及对应级别以上的级别
当前 Butterfly 启动时的级别是 INFO 级别@funcattr.api
def loglevel_get(req):
"""
获取 logging logger 日志级别
DEBUG(10) < INFO(20) < WARNING(30) < ERROR(40) < CRITICAL(50)
Args:
req : Request
Returns:
json_status, Content, headers
"""
isinstance(req, Request)
data = {}
root_level = root_logger.level
butterfly_level = butterfly_logger.level
data["root"] = root_level
data["butterfly"] = butterfly_level
return retstat.OK, {"data": data}, [(__info, __version)]
@funcattr.api
def loglevel_set(req, name, level):
"""
调整 logging logger 日志级别
DEBUG(10) < INFO(20) < WARNING(30) < ERROR(40) < CRITICAL(50)
Args:
req : Request
name : logger name
level : 日志级别，应该为数字，并在 [10, 20, 30, 40, 50] 中
Returns:
json_status, Content, headers
"ERR_LEVEL_NOT_NUM": level 不是数字
"ERR_LEVEL_INVALID": level 不在 [10, 20, 30, 40, 50] 中
"ERR_NAME_INVALID" : name 不为 root 或 butterfly
"""
isinstance(req, Request)
try:
level_num = int(level)
except BaseException:
return ERR_LEVEL_NOT_NUM, {}, [(__info, __version)]
if level_num not in [10, 20, 30, 40, 50]:
return ERR_LEVEL_INVALID, {}, [(__info, __version)]
if name == "root":
root_logger.setLevel(level_num)
return retstat.OK, {}, [(__info, __version)]
elif name == "butterfly":
butterfly_logger.setLevel(level_num)
return retstat.OK, {}, [(__info, __version)]
else:
return ERR_NAME_INVALID, {}, [(__info, __version)]参考传送门
Last updated
