> For the complete documentation index, see [llms.txt](https://meetbill.gitbook.io/butterfly-project-doc/llms.txt). Markdown versions of documentation pages are available by appending `.md` to page URLs; this page is available as [Markdown](https://meetbill.gitbook.io/butterfly-project-doc/project-framework/how/butterfly-log.md). # 框架之日志管理 ## 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 "" -------------------------- 正常无参数请求 ``` 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 "" ------- 正常有参数请求 ``` 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 "" ------ 接口存在，但参数错误 ``` 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 "" -- 接口不存在 ``` 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 "" ------- 正常有参数请求 ``` 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: 源代码所在的文件名。 ``` > 代码 ```python 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 ```python #!/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:%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]: :test_inspect.py, line:29 func: v2() :test_inspect.py, line:32 func: v1() :test_inspect.py, line:35 func: main() ``` > inspect.stack() 信息 ``` [ (, 'test_inspect.py', 12, 'get_stack', [' stack = inspect.stack()\n'], 0), (, 'test_inspect.py', 25, 'v2', [' w = get_stack()\n'], 0), (, 'test_inspect.py', 29, 'v1', [' v2()\n'], 0), (, 'test_inspect.py', 32, 'main', [' v1()\n'], 0), (, 'test_inspect.py', 35, '', [' 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:%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\d*)/(?P\d*)" (?P\d*) 是将后面匹配的 \d* 数据，取一个组名，这个组名必须是唯一的，不重复的，没有特殊符号，函数可以获得这个组名下的数据 ``` [re 基础知识](https://github.com/meetbill/MyPythonLib/tree/master/Example/python_base/re) #### 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[0-9]+)us\)', # cost_time(110614us) r'recv_client_time\((?P[0-9]+)\.(?P[0-9]+)s\)', # recv_client_time(1582432235.162875s) r'send_server_time\((?P[0-9]+)\.(?P[0-9]+)s\)', # send_server_time(1582432235.163468s) r'recv_server_time\((?P[0-9]+)\.(?P[0-9]+)s\)', # recv_server_time(1582432235.164527s) r'send_client_time\((?P[0-9]+)\.(?P[0-9]+)s\)', # send_client_time(1582432235.273489s) r'(?P.*)', ] 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.*)\]', r'logid\[(?P.*)\]', r'task_id\[(?P.*)\]', r'task_batch_id\[(?P.*)\]', r'unit_id\[(?P.*)\]', r'entity\[(?P.*)\]', r'processor\[(?P.*)\]', r'user_orderid\[(?P.*)\]', r'deployset\[(?P.*)\]', r'count\[(?P.*)\]', r'reserve\[(?P.*)\]', r'user_id\[(?P.*)\]', r'bcc_orderid\[(?P.*)\]', r'exe_step\[(?P.*)\]', r'error\[(?P.*)\]', r'message\[(?P.*)\]', 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\S+)', # date eg.:2019-08-12 r'(?P