日志这东西在项目里往往是被最后想起的那块拼图。平时不觉得它重要代码里print一坨坨地打等项目上了生产环境某天深夜接口超时、数据对不上才反应过来自己对系统内部到底发生了什么几乎一无所知。Python自带的logging模块从一开始就内置了一套完整的日志框架但默认配置相当简陋导致很多人的用法要么是print平替要么就是日志刷屏根本没法看。这篇文章我结合自己这些年写Python服务、接口脚本和数据处理任务的实操经历把日志记录的那些最佳实践从头捋一遍——从logging模块的核心设计逻辑到一套可以直接抄进项目的配置模板再到多进程日志、轮转切割、结构化日志这些进阶话题。不管你是刚入门的新手还是已经在写工程化项目的开发者看完这篇文章应该都能把日志这件事一次弄明白。1. 为什么日志不能拿print凑合先理解logging的设计逻辑1.1 print和logging的本质差异很多初学者刚接触Python时习惯用print来打点——在关键位置输出变量、标记走到哪个分支。这在写100行的小脚本时完全没问题但项目一旦超过几个模块print的局限性就会完全暴露出来。print本质上是写给人看的它把内容输出到标准输出流你盯着终端看仅此而已。而日志是写给系统看的它的目标可能是控制台也可能是文件、消息队列、远程日志平台甚至同时发往多个地方。更关键的是print没有任何级别概念。同一个脚本里调试信息、业务警告、错误堆栈全都用同样的方式输出线上环境根本没法区分哪些日志是必须关注的哪些只是写代码时自己看的。另一个容易被忽略的问题是性能。在循环里大量调用print每一次都会执行字符串格式化并写入标准输出对高频场景来说这是一个实实在在的开销。而logging模块默认是延迟求值日志级别不满足时根本不会执行格式化操作这在大规模数据处理任务里能省下很可观的CPU时间。我之前接过一个遗留项目整个业务模块全是print要排查一个线上问题需要加print重新跑一遍流程跑完还要把输出重定向到文件靠肉眼在几千行输出里找线索效率低到离谱。后来我花了半天时间把print全部替换成logging从那以后再排查问题直接看每天的日志文件几分钟就能定位到问题入口。1.2 logging的四件套Logger、Handler、Formatter、Filterlogging模块的设计其实很接近工业级的日志框架它把日志处理拆成了几个独立组件各司其职Logger日志记录器应用程序直接调用的入口。你调用logger.info、logger.debug实际就是告诉Logger这里发生了一件事。Handler处理器决定日志去向。StreamHandler输出到控制台FileHandler写入文件SocketHandler发到网络。Formatter格式化器决定日志长什么样。时间、级别、模块名、行号、消息内容排列组合全靠它。Filter过滤器决定哪些日志能通过。可以按级别、按模块、按自定义规则过滤。理解这几个组件后你会发现logging模块真正厉害的地方在于解耦。Logger不关心日志最终去了哪里Handler不关心日志内容是什么格式所有组件之间只通过名为LogRecord的数据结构交互。这意味着你可以在不修改任何业务代码的情况下随时调整日志的输出方式和格式。打个比方Logger就像家里厨房水槽上的水龙头Handler是连接水龙头的水管Formatter是水管上装的水表而Filter是管道里的过滤器。你想要热水还是冷水想把水引到阳台还是厨房不需要换水龙头只需要调整管道配置就行。1.3 Logger的层级结构和命名规则logging模块里有一个很容易被忽略但非常重要的机制Logger是按层级组织的。当你调用logging.getLogger(myapp.api.user)时得到的是一个名字为myapp.api.user的Logger它同时是myapp.api的子Logger而myapp.api又是myapp的子Logger最顶层是根Loggerroot。子Logger默认会把日志向上传递给父Logger这个机制叫propagate传播。很多初学者的日志重复输出问题就是这么来的自己在模块里创建了一个Logger并添加了Handler结果日志被打印一次又传到根Logger那里被打印一次。基于这个机制日志命名的黄金法则就是在模块里使用logging.getLogger(name)。__name__在模块被导入时会自动变成包的路径.模块名比如myapp.api.user_service这样日志天然按照项目结构分层组织。你可以在根Logger上设置全局级别再针对某个特定模块单独调整级别这种灵活性只有层级结构才能提供。刚开始接触这套概念时可能会觉得繁琐但这就是logging模块的设计精髓——用组合代替配置堆砌理解之后你会发现它比那些花哨的第三方库更可靠、更可控。2. 一套能直接抄进项目的日志配置模板2.1 配置之前先想清楚三件事不少人在配置日志时是蒙着头配的哪个参数都设置了但心里没数。实际动手写配置之前建议先想清楚三件事第一日志写到哪里。开发阶段输出到控制台就够了生产环境通常需要同时输出到控制台和文件。如果公司有日志采集平台还需要通过HTTP、Kafka等渠道上报。第二哪些级别需要记录。开发环境希望看到Debug信息生产环境则通常Info起步Error和Critical一定要留。这决定了Logger和Handler的级别设置。第三日志长什么样。几行日志对比2024-01-15 14:23:45,123 - INFO - user_service - user 123 login显然比一句光秃秃的user 123 login更容易定位问题。想清楚这三件事配置就变成了填空。2.2 从basicConfig到完整配置一个生产级示例Python官方文档最常出现的日志配置方式是logging.basicConfig()它确实简单但有几个明显的坑。首先basicConfig在第一次调用后就不会再生效了这个一次性的魔法治愈往往让你后续的配置静默失效。其次它只能在根Logger上设置Handler想给不同模块配不同级别时完全无能为力。下面这套配置是我实际在多个项目里跑过的模板兼顾了开发调试和生产使用的需求import logging import logging.config from logging.handlers import TimedRotatingFileHandler LOGGING_CONFIG { version: 1, disable_existing_loggers: False, formatters: { standard: { format: %(asctime)s | %(levelname)-8s | %(name)s | %(filename)s:%(lineno)d | %(message)s, datefmt: %Y-%m-%d %H:%M:%S } }, handlers: { console: { class: logging.StreamHandler, level: INFO, formatter: standard }, file: { class: logging.handlers.TimedRotatingFileHandler, filename: logs/app.log, when: midnight, backupCount: 7, encoding: utf-8, level: DEBUG, formatter: standard } }, root: { level: DEBUG, handlers: [console, file] } } logging.config.dictConfig(LOGGING_CONFIG)这个配置里每个参数都有明确意图version: 1dictConfig的配置格式版本固定写1。disable_existing_loggers: False默认情况下dictConfig会禁用配置前已存在的所有Logger。如果项目里某些模块在导入时就创建了Logger这个参数不设成False日志会莫名消失。formatters定义输出格式。%(asctime)s是时间%(levelname)-8s是级别名左对齐占8位%(name)s是Logger名称%(filename)s和%(lineno)d是产生日志的文件名和行号%(message)s是具体消息。handlersconsole输出到标准输出file按天轮转写入logs/app.log保留7天。控制台INFO级别文件DEBUG级别这样开发时看控制台不会刷屏但文件里保留了完整Debug信息用来排查深层次问题。root设置了根Logger的Handler和级别。业务代码里logging.getLogger(__name__)创建的Logger最终都会传到根Logger。basicConfig不是说完全不能用但它更适合简单脚本面对生产环境的需求确实力不从心。我在新项目里只用dictConfig运维维护起来也很直观。2.3 级别选择的经验法则Python日志级别从低到高依次是DEBUG、INFO、WARNING、ERROR、CRITICAL。很多人的困惑是判断一条日志该用哪个级别标准到底是什么我自己用的判断标准很简单这条日志出现时需不需要人立刻关注。级别适用场景典型例子DEBUG调试阶段才需要看的详细信息函数入参出参、循环中间变量、外部接口原始响应INFO关键业务节点正常运行也产生用户登录成功、订单创建完成、任务开始/结束WARNING异常但不会影响当前流程重试请求、缓存失效、旧接口警告ERROR当前请求/任务失败但整体服务还活着调用第三方接口失败、数据库查询抛错CRITICAL整个应用即将无法运行磁盘写满、启动时配置加载失败有个常见的错误是把所有异常都打成ERROR。比如调一个第三方接口失败代码里做了重试第一次失败用INFO或WARNING记录重试依然失败才应该打ERROR。这样线上告警才不会天天被无效告警淹没。同样ERROR日志应该包含足够的信息错误的请求标识、对方的响应码、当前上下文参数至少让人一眼看出哪个请求、哪个环节出错了。2.4 格式化串里到底该放什么字段格式化串决定了日志的可读性和可排查性建议至少包含时间、级别、Logger名、文件名和行号、消息正文这五个字段。我的标准格式是%(asctime)s | %(levelname)-8s | %(name)s | %(filename)s:%(lineno)d | %(message)s对应的输出长这样2024-01-15 14:23:45 | INFO | myapp.api.user_service | user_service.py:42 | user 123 login success这里有几个字段的取舍值得说说。%(filename)s:%(lineno)d能帮你快速定位日志出处但要注意它会增加日志体积。如果日志量非常大可以去掉%(filename)s只保留%(name)s代价是定位问题稍微慢一点。多进程部署时强烈建议把进程ID加进去格式是%(process)d在多进程服务里排查日志你才能分清哪条日志属于哪个worker进程。时间字段也有讲究。默认的asctime格式是2024-01-15 14:23:45,123带毫秒。如果不需要毫秒级精度配置datefmt%Y-%m-%d %H:%M:%S能稍微缩短日志长度。还有个很多人不知道的细节%(asctime)s按本地时间输出如果你部署的机器时区和本地不一致排查问题会非常痛苦建议在Handler层面考虑占用UTC时间还是显式设置时区。3. 进阶实战轮转切割、异常记录与结构化日志3.1 TimedRotatingFileHandler实现按天切分日志文件如果不做轮转一个月下来可能膨胀到几个GB不仅占磁盘排查问题时打开超大日志文件也是灾难。标准库提供了两种轮转方案RotatingFileHandler按文件大小切分TimedRotatingFileHandler按时间间隔切分。我大多数时候选择按时间切分配置方式就是上一节模板里的from logging.handlers import TimedRotatingFileHandler handler TimedRotatingFileHandler( logs/app.log, whenmidnight, backupCount7, encodingutf-8 )参数说明when切分时间点。midnight表示每天零点切分S秒、M分钟、H小时、D天、W0-W6星期几都支持。backupCount保留的日志文件数量超过就自动删除最旧的。设7就保留7天的日志。encoding必须显式指定否则在Windows中文系统下容易乱码。utcTrue可选项按UTC时间切分而不是本地时间多机部署时建议启用。轮转后的文件命名是app.log.2024-01-15这种格式。有个小坑需要注意TimedRotatingFileHandler在午夜切分时如果上一次日志写入时间离零点很近偶尔会出现一天有两份文件的情况这可能让依赖文件名的统计脚本出错。我的应对方式是切分不用midnight而是用固定时间点加interval参数比如每小时轮转一次配合backupCount24文件命名更规律。3.2 异常和堆栈信息用logger.exception代替traceback.printPython的logging模块里有个被低估的方法logger.exception(msg, *args)。它只能在except块内调用作用等同于logger.error(msg, exc_infoTrue)会在日志中附带完整的异常堆栈信息。很多人习惯在except块里写except Exception as e: print(fsomething went wrong: {e})这种写法的最大问题是只记录了异常的字符串表示没有堆栈。异常是在哪个文件的哪一行抛出的、调用链是什么全都丢了排查问题等于盲人摸象。正确写法try: user get_user_from_api(user_id) except ApiError as e: logger.exception(fetch user failed, user_id%s, user_id) raise注意两点第一logger.exception自带堆栈不需要再手动拼接traceback。第二我在日志消息里固定带了user_id这个上下文这比单纯打个failed有价值得多。线上排查时知道哪个ID的请求失败就直接在日志里搜索这个ID一条请求的完整调用链就出来了。如果不在except块里但想记录当前堆栈可以用logger.error(..., exc_infoTrue)效果一样。还有个小技巧在日志消息中把关键的入参出参都带上比如logger.info(order created, order_id%s, amount%s, user_id%s, order.id, order.amount, order.user_id)排查问题时照着ID去搜索日志即可。3.3 结构化日志让日志可以被机器读懂传统文本日志人眼看得懂但机器不好处理。如果你的项目接入了ELK、Splunk这类日志平台或者需要定时脚本从日志里统计业务指标建议把日志输出成JSON格式这就是常说的结构化日志。实现方式非常简单自定义一个Formatterimport json import logging class JsonFormatter(logging.Formatter): def format(self, record): log_data { time: self.formatTime(record), level: record.levelname, logger: record.name, message: record.getMessage(), module: record.module, line: record.lineno, } if record.exc_info: log_data[exc_info] self.formatException(record.exc_info) return json.dumps(log_data, ensure_asciiFalse)在配置里把formatters的standard换成JsonFormatter即可。输出就变成了{time: 2024-01-15 14:23:45, level: INFO, logger: myapp.api.user_service, message: user 123 login success, module: user_service, line: 42}这样做的好处是日志平台可以直接解析每个字段按级别聚合、按模块过滤、按时间范围检索都很方便。如果你用logging.config.dictConfig配置JsonFormatter需要包装一下才能被实例化可以写个工厂函数或在配置里用()。结构化日志也不是没有代价。JSON格式显然比纯文本更占磁盘空间而且人眼看日志时没有纯文本直观。我的建议是小型脚本用纯文本已经接入日志平台的项目用JSON格式控制台用纯文本、文件用JSON是一种很实用的折中方案——既有可读性也保留了机器可解析的结构化数据。4. 多进程与性能日志最容易踩的两个坑4.1 多进程写同一个日志文件的问题Python的logging模块官方明确是线程安全的但不是进程安全的。多线程写同一个Handler不会出问题因为内部有锁但多进程场景下多个进程同时往同一个文件里写日志会交错、互相覆盖轮转切割时甚至会把正在使用的日志文件切坏。我用过三种解决方案按优先级排列方案一标准库的QueueHandler QueueListener推荐。import logging from logging.handlers import QueueHandler, QueueListener import queue log_queue queue.Queue(-1) handler logging.StreamHandler() # 主进程/主线程中启动listener listener QueueListener(log_queue, handler) listener.start() # 实际业务进程里使用QueueHandler queue_handler QueueHandler(log_queue) root logging.getLogger() root.handlers [] root.addHandler(queue_handler)原理很简单业务进程只负责把日志放进队列真正的文件写入由QueueListener所在的进程统一完成。这样从根源上回避了多进程并发写文件的问题而且因为队列是异步的业务线程写日志几乎不会阻塞。方案二使用第三方库ConcurrentLogHandler。它基于操作系统文件锁实现多进程安全写文件配置方式跟FileHandler类似from concurrent_log_handler import ConcurrentRotatingFileHandler handler ConcurrentRotatingFileHandler( logs/app.log, maxBytes10 * 1024 * 1024, backupCount5, encodingutf-8 )这个方案适合不想引入队列架构、只是希望多进程别把文件写乱的场景但它在Windows下的表现不如Linux稳定需要实测验证。方案三每个进程写自己的日志文件。名字上带进程ID比如app-2718.log。排查问题时按进程分别看缺点是无法从整体时间线串起一次请求的完整流程。4.2 延迟格式化别再用f-string拼接日志消息这是个非常常见而且容易忽视的性能问题。看下面两种写法# 写法一f-string不推荐 logger.debug(fuser {user_id} login, role{role}) # 写法二logging的延迟格式化推荐 logger.debug(user %s login, role%s, user_id, role)两种写法的区别在于写法一在调用logger.debug之前就已经执行了字符串格式化生成最终字符串后才传进去写法二是先把模板和参数传给logging由logging内部判断当前Logger的级别是否达到DEBUG如果没达到直接丢弃参数格式化操作压根不会执行。在日志级别设置为INFO的生产环境里每条DEBUG日志如果用f-string等于白白做了一次字符串拼接然后扔进垃圾堆。在循环里这开销会被放大成明显的CPU消耗。我之前有一个数据清洗任务日志量很大改成延迟格式化写法后任务耗时下降了将近20%主要是因为省掉了大量没用的字符串操作。还有个附带的好处logger.debug(user %s login, role%s, user_id, role)这种写法里的参数在日志采集平台里可以被当作结构化字段提取比把内容拼在字符串里方便得多。4.3 高频日志降噪采样和摘要日志也不是越多越好。访问日志、心跳日志这类高频日志如果每条都打一天就能刷出几百MB磁盘和日志平台都吃不消。我的做法是采样只需要一个几行的Filterimport random import logging class SampleFilter(logging.Filter): def __init__(self, sample_rate0.1): super().__init__() self.sample_rate sample_rate def filter(self, record): return random.random() self.sample_rate # 使用只让10%的日志通过 handler.addFilter(SampleFilter(0.1))如果采样日志还是不够可以改成摘要日志每隔一段时间只输出一条聚合信息比如每10秒统计一次请求量、平均耗时、错误数。这比无脑采样更有信息量。5. 常见问题排查与实战心得5.1 日志重复输出的元凶propagate和根Logger为什么我明明只调用了一次logger.info控制台却打印了两遍这是我在各种技术社群里看到的高频问题。原因几乎都是propagate在作祟。当你创建一个子Logger并给它添加Handler时这条日志会先被自己的Handler处理一次然后因为propagateTrue日志记录还会被传递给父Logger父Logger的Handler再处理一次。如果你的父Logger通常就是根Logger也配置了Handler日志自然就重复了。修复办法有两种选一个就行# 方式一关闭子Logger的传播 logger logging.getLogger(myapp) logger.propagate False # 方式二不使用basicConfig在根Logger上统一配置Handler logging.basicConfig(levellogging.INFO) logger logging.getLogger(myapp)我的建议是优先采用所有Handler都挂在根Logger上的架构子Logger只负责设置级别不添加Handler。这样所有模块的日志格式统一、输出目标统一也更符合dictConfig的配置思路。5.2 中文乱码配置文件写入时的编码问题第二个高频问题是日志文件里中文变成了一堆乱码。原因在于Python的logging.FileHandler默认使用系统编码Windows中文系统默认是GBK而你期望输出UTF-8。解决方式很简单显式指定编码。handler logging.FileHandler(app.log, encodingutf-8)在dictConfig配置里对应就是handlers: { file: { class: logging.FileHandler, filename: logs/app.log, encoding: utf-8 } }还有一个很多人都没注意到的细节日志消息本身分两部分一部分是你写的消息内容另一部分是Formatter格式化的时间、级别等固定文本。如果消息是从第三方库传过来的而这个库内部用的编码不是UTF-8可能会导致UnicodeEncodeError。稳妥的做法是在Formatter配置里不要自己拼接容易出错的字段以及尽量保证全项目字符串都是UTF-8这个在上线前就统一检查一遍避免排查问题时被编码问题干扰。5.3 配置时序为什么日志在模块导入时不生效这个坑我踩过好几次项目里有一个config.py在模块导入阶段就打印日志结果日志信息神秘消失了。排查半天才发现是配置时序问题——主程序还没有执行logging.config.dictConfig模块就已经完成导入并创建了Logger。很多人不知道logging模块在第一次使用时如果没有显式配置会自动调用一次basicConfig但默认级别是WARNING而且只输出到stderr。所以你在模块导入阶段打INFO日志很可能会直接消失。解决方式是在项目入口的第一时间完成日志配置再导入任何业务模块import logging.config LOGGING_CONFIG {...} logging.config.dictConfig(LOGGING_CONFIG) # 之后再导入业务模块 from myapp.api.user_service import UserService如果业务模块必须先在配置前导入也可以在模块里延迟初始化Logger或者使用logging.getLogger(__name__)后只调用方法不打日志等配置完成后再输出。5.4 日志内容规范与几个实操小技巧做了一段时间日志治理后我总结了几条打日志时的潜规则写在这里供参考日志消息要固定格式不要每次不一样。比如logger.warning(failed to connect, target%s, retry%d, target, retry)这个格式一旦定下来全项目保持一致日志平台聚合和告警规则才能生效。如果每个开发都自由发挥日志内容就成了无规律的散文什么统计分析都没法做。不要在日志里放敏感信息。密码、token、身份证号、银行卡号这些一律不能进日志。哪怕只是测试环境也会有人通过日志平台搜索数据一旦泄露就是安全事故。如果确实需要记录接口入参用掩码处理比如tokensk-***abc****。给关键操作加关联ID。一条用户请求往往会触发多个模块的日志如果没有关联ID没法把一条请求的日志串起来。在Web框架的中间件里生成一个request_id通过LoggerAdapter这样的机制传进日志字段排查体验会有质的提升。养成审计日志的习惯。修改配置、删除数据、管理员操作这类高风险操作除了业务日志外单独记录一份审计日志只增不改这对问题的回溯和合规要求都有帮助。DEBUG日志不影响线上排查但要能随时开启。很多DEBUG日志打到文件里会很占用空间我的做法是文件Handler默认INFO级别需要排查时通过环境变量临时把某个模块的级别调成DEBUG比如export LOG_LEVEL_DEBUGmyapp.api.user_service然后在配置里做一次条件判断将指定模块的Logger级别设置为DEBUG排查完撤掉环境变量即可。写在最后日志配置一次做对值得花这半小时我个人这些年写Python最深的体会是日志配置值得在项目启动的第一天就花半小时做好而不是等线上出了故障再熬夜翻print。以前我接手过一个老项目代码里全是print想查一个函数入参出参只能加print重新跑一遍那个滋味真不好受。后来我把日志配置抽成一个独立的log_config.py模块每个项目直接import新项目落地日志体系基本上十分钟就搞定了。这篇文章里的配置模板和注意事项都是我真实运行过的方案你直接抄到项目里再根据实际场景做取舍就行。如果你们团队有多进程服务一定要提前把队列方案纳入进来别等到日志文件被切坏才回头改。日志这件事平时看着不起眼出问题的时候它就是你在系统里唯一的眼睛把眼睛擦亮了排查问题才能不费劲。