那天线上又双叒叕出问题,我正准备点外卖,运维在群里一句话: “东哥,日志看不懂,你写的 Python 那个服务,又炸了没?”
我心里一咯噔,因为我知道,那玩意儿的日志,是我一怒之下“临时加的 print + logging.debug 大法”,能不乱才有鬼。 你们应该有同款经历:线上 grep 半天,看到一堆:
2025-02-10 10:10:10,123 - root - INFO - start
2025-02-10 10:10:10,124 - root - INFO - here
2025-02-10 10:10:10,125 - root - INFO - here2
然后凌晨两点问灵魂三连: “start 是啥 start?” “here 到底在哪儿?” “是谁在用 root 打一辈子日志的?”
就这种原始人级别的日志,我自己都不想看,更别说排查问题了。 你看,之前 SpringBoot 默认日志不滚动把磁盘打爆那次,我也是被教育得明明白白。
后来真的是被某次线上事故搞到破防,我才老老实实搞了个“小利器”,专门管 Python 日志,搞完之后,调试这事儿,真的香了不少。
大概场景是这样:一个小微服务,要连好几个外部系统,什么下单、扣库存、发券,乱七八糟。那次问题是用户订单“偶尔”消失,你们懂得,偶发 Bug 就是调试地狱。
以前我的写法,羞愧拿出来给你们看下:
def create_order(user_id, items):
print("create_order start", user_id)
# ... 一堆业务逻辑
print("create_order ok")
return order_id
然后多进程一上,print 混在一起,简直弹幕现场。 而且没有 trace_id,没有请求耗时,没有环境信息,排查就跟在黑屋子里摸黑找猫一样。
我当时在工位上叹了口气: “算了,别装了,整点像样的日志框架吧。”
问题来了,Python 自带那个 logging,你们第一次用是不是也是一脸懵?basicConfig、Formatter、Handler、Logger、propagate…… 感觉就像刚学会骑电瓶车,旁边停了一台波音 747,让你自己研究怎么起飞。
我一开始也硬刚,项目里到处都是:
logger = logging.getLogger()
logger.setLevel(logging.INFO)
handler = logging.StreamHandler()
fmt = logging.Formatter('%(asctime)s %(levelname)s %(message)s')
handler.setFormatter(fmt)
logger.addHandler(handler)
结果每个模块 copy 一份,偶尔还叠加 handler, 日志直接变成双份输出,运维看日志的时候差点以为服务在 stutter(口吃)。
那一刻我就明白了,问题不是 logging 复杂,而是——我每次都在“现场搭积木”。 你想啊,Postgres 那些复杂配置你也不可能每个项目重写一遍,都是封装摸板统一搞。
所以我干脆写了一个自己的“小利器”:只干三件事—— 统一初始化、统一格式、统一上下文。
我先整了个最简单版的封装,名字就叫:logkit(随手起的,别吐槽)
# logkit.py
import logging
import sys
def init_logger(service_name: str, level: str = "INFO") -> logging.Logger:
logger = logging.getLogger(service_name)
if logger.handlers:
# 已经初始化过了,直接用,避免重复加 handler
return logger
logger.setLevel(level.upper())
fmt = (
"%(asctime)s | %(levelname)s | %(name)s | "
"trace_id=%(trace_id)s | %(message)s"
)
formatter = logging.Formatter(fmt)
handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(formatter)
logger.addHandler(handler)
logger.propagate = False
# 给没带 trace_id 的日志一个默认值,防止 KeyError
logger = logging.LoggerAdapter(logger, extra={"trace_id": "-"})
return logger
这个东西刚写好我自己先用了一圈,最大的感受是—— “哦,原来日志居然可以长得有点像人话。”
关键点几个:
每个服务用自己的 service_name,以后一看日志就知道是谁闯的祸。固定加上 trace_id这个字段,没传就默认-,不会炸。LoggerAdapter这个小玩意儿,专门帮你塞上下文,巨好用但大家老忘记它存在。
有了这个 init 之后,业务代码就清爽多了。 比如下单接口,我是这么写的:
# order_service.py
from logkit import init_logger
logger = init_logger("order-service")
def create_order(user_id, items, trace_id: str | None = None):
log = logger
if trace_id:
# 带上本次请求的 trace_id
log = logging.LoggerAdapter(logger, extra={"trace_id": trace_id})
log.info("create_order start, user_id=%s, items=%s", user_id, items)
try:
# ... 业务逻辑略
order_id = "ORD123456"
log.info("create_order success, order_id=%s", order_id)
return order_id
except Exception as e:
log.error("create_order failed: %s", e, exc_info=True)
raise
你看,这样一来:
线上一搜 trace_id=xxxx,整条链路的日志一条不落, 不会像之前那样到处只有“start”“here2”这种鬼词。报错的时候带 exc_info=True,栈信息一整条打出来,和 TCP 抓包那次一样,一眼就能看到哪儿断了。
关键是,这段封装你写一次,后面所有项目 copy 一下就完事儿。
后来我嫌命令行日志还不够,就又加了一点“小心机”, 搞了个按天滚动+保留 N 天的配置,免得哪天日志把磁盘写满,被运维在工位后面呼吸。
我没用啥复杂的 YAML 配置,直接在 Python 里写:
# logkit.py 里再加一个文件日志版本
from logging.handlers import TimedRotatingFileHandler
import os
def init_logger_with_file(service_name: str,
level: str = "INFO",
log_dir: str = "./logs") -> logging.Logger:
os.makedirs(log_dir, exist_ok=True)
logger = logging.getLogger(service_name)
if logger.handlers:
return logger
logger.setLevel(level.upper())
fmt = (
"%(asctime)s | %(levelname)s | %(name)s | "
"trace_id=%(trace_id)s | %(message)s"
)
formatter = logging.Formatter(fmt)
# 控制台
console = logging.StreamHandler(sys.stdout)
console.setFormatter(formatter)
logger.addHandler(console)
# 文件,按天滚动,保留 7 天
file_handler = TimedRotatingFileHandler(
filename=os.path.join(log_dir, f"{service_name}.log"),
when="midnight",
backupCount=7,
encoding="utf-8",
)
file_handler.setFormatter(formatter)
logger.addHandler(file_handler)
logger.propagate = False
logger = logging.LoggerAdapter(logger, extra={"trace_id": "-"})
return logger
这个真的是救命,用法跟前面一模一样,只是换了个函数。 那次线上排查 MQ 丢消息的时候,我就是靠滚动日志把前几天的消费记录翻出来,一条条对比,才发现是消费端自动提交 offset 搞的鬼。
再后来,有同事吐槽,说看日志的时候总想知道“这一串日志,到底花了多久”。 我一开始还想整个 APM 上去,想想又太重了,就写了个最土但巨好用的小装饰器:
import time
from functools import wraps
def log_duration(logger, msg: str):
def wrapper(fn):
@wraps(fn)
def inner(*args, **kwargs):
start = time.time()
try:
return fn(*args, **kwargs)
finally:
cost = int((time.time() - start) * 1000)
logger.info("%s, cost=%dms", msg, cost)
return inner
return wrapper
用的时候就这样:
log = init_logger("payment-service")
@log_duration(log, "pay_order")
def pay_order(order_id):
# ... 调支付渠道那些慢腾腾的操作
pass
线上一看日志:
2025-02-10 10:10:10,500 | INFO | payment-service | trace_id=abc | pay_order, cost=832ms
负责人看到之后第一句话: “哦,原来慢在这里啊,怪不得 Feign 那边超时。”
所以你看,Python 日志这玩意儿,确实一开始有点劝退,概念多,配置碎。 但你只要咬牙抽个半天,把那几件烦人的事儿——
初始化 格式统一 trace_id / cost 这些通用字段 文件滚动、保留时间
通通封装进一个小模块里,后面写新服务基本就是三行:
logger = init_logger_with_file("xxx-service")
logger.info("service started")
再也不用现场搭积木,也不用半夜在服务器上疯狂 grep "here2" 了。
哦对,还有个小经验: 别在业务代码里到处 logging.basicConfig(...), 那玩意儿就跟在项目里乱 @Transactional 一样,迟早有一天你会不知道是谁改了全局行为。
乖乖写个 logkit.py,扔到所有项目里去用, 等哪天线上又出事,你打开日志能一眼看出:
“哪个服务、哪个请求、哪一步、花了多久、哪儿报错。”
那时候你就会发现—— 日志这东西,其实比现场抓包、看 TCP 分段那些快乐多了,起码不容易看吐…
行了,先这样,我去把刚才外卖续上,写着写着都凉了。