虽然前面自己写过一个 Python Logging 的各种玩法（折腾 Python logging 的一些记录），结果没两个月，自己就在之前特意叮嘱过的地方翻了车
事情是这样的，我们的项目使用 Flask 作为业务框架，用 Celery 作为异步任务框架，按上篇里提到的，我们加了个 Filter 来加入 request_id 用于跟踪同一个 Web 请求或同一个 Task。所以，我们的 logging.conf 一开始是这样的，在 logfile 这个 Handler 里加入 request_id 并打印到日志文件，我们用阿里云的 logtail 把所有部署实例的日志文件都收集到一起，这一层 app Logger 往上抛是让终端都打印所有的日志，并且用 sentry 这个 Handler 在最上面收集各种异常报错
logging_conf = {
"version": 1,
"disable_existing_loggers": True,
"filters": {
"addRequestId": {
"()": "app.utils.logging.request_filter.ContextFilter"
}
},
"formatters": {
"standard": {
"format": "[%(asctime)s][%(levelname)s][%(pathname)s:%(lineno)s][%(funcName)s]: %(message)s"
},
"withRequestId": {
"format": "[%(asctime)s][%(levelname)s][%(relpath)s:%(lineno)s][%(funcName)s][%(request_id)s]: %(message)s"
}
},
"handlers": {
"console": {
"level": "DEBUG",
"class": "logging.StreamHandler",
"formatter": "standard"
},
"logfile": {
"level": "DEBUG",
"class": "logging.handlers.WatchedFileHandler",
"filters": ["addRequestId"],
"formatter": "withRequestId",
"filename": "log/app.log"
},
"sentry": {
"level": "ERROR",
"class": "raven.handlers.logging.SentryHandler",
"dsn": "DSN_URI",
"string_max_length": 512000
}
},
"loggers": {
"app": {
"level": "DEBUG",
"handlers": ["logfile"],
"propagate": True
}
},
"root": {
"level": "DEBUG",
"handlers": ["console", "sentry"]
}
}
后来，为了把 Celery 调度信息等也通过 logtail 收集到阿里云，我们就把 logtail 的源从日志文件改成了 stdout/stderr 输出，不同时收集日志文件是因为同样的日志在 logfile 和 console 里会出现两次，没有必要。但是只改 stdout/stderr 又会导致收集到的信息没有我们辛苦加进去的 relpath 和 request_id，一个很直接的思路就是，在 app 这层 Logger 上加一个 consoleWithId 的 StreamHandler，并且 formatter 用 withRequestId 不就好了，然后限制 app Logger 的 propagate 为 False 禁止上抛，问题应该完美解决？等会，这里有好几个问题
第一个问题是，如果 app Logger 不往上抛，那万一异常了，sentry Handler 也收集不到错误？头疼医头脚疼医脚，那就给 app Logger 也挂上 sentry Handler 不就解决问题
第二个问题是，handlers 的处理顺序是不是严格按我们配置的顺序来？如果不是的话，consoleWithId 进入的时候，可能 addRequestId 这个 Filter 还没执行，出现了输出时拿不到 relpath 和 request_id 那不就挂了？这个简单，把 Filter 移到 Logger 这一层不就解决了。至此，配置如下（只摘录改动部分）
# ...
"handlers": {
# ...
"logfile": {
"level": "DEBUG",
"class": "logging.handlers.WatchedFileHandler",
"formatter": "withRequestId",
"filename": "log/app.log"
},
"consoleWithId": {
"level": "DEBUG",
"class": "logging.StreamHandler",
"formatter": "withRequestId"
},
# ...
},
"loggers": {
"app": {
"level": "DEBUG",
"filters": ["addRequestId"],
"handlers": ["logfile", "consoleWithId", "sentry"],
"propagate": False
}
},
# ...
翻车就翻在「这个简单」上，按这个思路配置后，跑起来还是在 consoleWithId 的 Handler 上输出报错，而且报的就是 relpath 和 request_id 字段不存在。怀疑自己的配置有问题，跑到代码里打日志的地方用 logging.getLogger(__name__) 看拿到的到底是哪个 Logger，以及上面挂了哪些 Handler，还有 Logger 和 Handler 的 Filters 都配的啥，发现除了 app 根上，如果是 app.foo 这样的路径，拿到的都是一个叫 celery.utils.log.ProcessAwareLogger 的 Logger，而且没有任何 Handler 和 Filter 挂在上面，所以，Celery 你这个坏人，到底对我的代码做了什么？
跑去翻 celery.utils.log.ProcessAwareLogger 这个东西的源码都没看出个所以然，似乎只是为了保证 Flask 的 signal handler 机制正常，排查思路也断掉，再跑去看看我们那个 app.utils.logging.request_filter 的处理，有没有哪里不对的，在这个自定义的 filter 里裸用 print 打印，发现这个 filter 压根没被调用到？嗯？没被调用到？
回去看自己的上一篇，果然里面自己就提到过这里有坑（主流程解释的第 5 步）
如果开启了日志往上传递，则判断当前 Logger 是否有父 Logger，如果有的话，直接将当前 LogRecord 传给父 Logger 从 4 开始处理（跳过 1/2/3，注意此处级别控制 1 会不生效，绑定在父 Logger 上的 Filter 也不执行）
WTF！果然坑都是自己不掉一遍，别人说千万遍也不会记得的，哪怕说的这个人是自己。那好咯，把 addRequestId 这个 Filter 还是从 app Logger 上移到 Handler 层面上好了，每个需要的 Handler 都给挂上，多点性能开销就多点吧
不过这样配的感觉还是怪怪的，比如有些错误会被 sentry 收集两次，因为在 app 里一直往上抛会被 app Logger 里的 sentry 收集，如果这个错误还继续往上抛到了框架层面，框架的错误还会被 rootLogger 的 sentry 又收集一次。而且，既然 app 的里面和外面都有终端和 sentry，为啥不在最外面一次处理好，中间拦着不往上抛没有任何意义。调整了下，直接把 standard 这个 Formatter 和 console 这个 Handler 给去掉，在 rootLogger 上挂 consoleWithId 和 sentry 就好，最后完整的配置如下
logging_conf = {
"version": 1,
"disable_existing_loggers": True,
"filters": {
"addRequestId": {
"()": "app.utils.logging.request_filter.ContextFilter"
}
},
"formatters": {
"request": {
"format": "[%(asctime)s][%(levelname)s][%(relpath)s:%(lineno)s][%(funcName)s][%(request_id)s]: %(message)s"
}
},
"handlers": {
"logfile": {
"level": "DEBUG",
"class": "logging.handlers.WatchedFileHandler",
"filters": ["addRequestId"],
"formatter": "request",
"filename": "log/app.log"
},
"consoleWithId": {
"level": "DEBUG",
"class": "logging.StreamHandler",
"filters": ["addRequestId"],
"formatter": "request"
},
"sentry": {
"level": "ERROR",
"class": "raven.handlers.logging.SentryHandler",
"dsn": "DSN_URI",
"string_max_length": 512000
}
},
"loggers": {
"app": {
"level": "DEBUG",
"handlers": ["logfile"],
}
},
"root": {
"level": "DEBUG",
"handlers": ["consoleWithId", "sentry"]
}
}
因为 Logger 的 propagate 默认就是 True，所以相对于第一版在 app 这个 Logger 上去掉了这条配置也没关系
最后，因为 addRequestId 这个 Filter 还是会被调两次，想优化下性能，就在 Filter 做完后加一个标记，下次再进来如果看到有这个标记就直接跳过，以及，对于非项目内的日志就不要用项目内的相对路径而用绝对路径替代。代码如下
# coding: utf8
import logging
import os.path
from celery import current_task
from flask import g, has_app_context, has_request_context
_proj_root_path = os.path.abspath(os.path.join(__file__, './../../../../'))
_proj_root_length = len(_proj_root_path)
class ContextFilter(logging.Filter):
def filter(self, record):
# ignore duplicate filter
if hasattr(record, 'filter_by_yewen'):
return True
# request_id for flask web or celery task
request_id = 'Standalone'
if has_app_context():
if has_request_context():
request_id = g.get('request_id', 'UnknownRequest')
elif current_task:
request_id = current_task.request.id or 'UnknownTask'
record.request_id = request_id
# handle log_decorator pass
record.funcName = getattr(record, 'orig_funcName', record.funcName)
record.pathname = getattr(record, 'orig_pathname', record.pathname)
record.lineno = getattr(record, 'orig_lineno', record.lineno)
# relative path
if record.pathname.startswith(_proj_root_path):
record.relpath = record.pathname[_proj_root_length:]
else:
record.relpath = record.pathname
record.filter_by_yewen = True
return True
