干了十来年开发和运维我最怕看到的不是线上告警而是告警拉起来之后打开日志文件翻半天找不到一条能说明问题的记录。要么是INFO满天飞把关键错误淹没要么是异常堆栈被截断只剩个NullPointerException要么是时间戳全部对不上连事发顺序都还原不出来。日志这东西写代码的时候没人当回事出事的时候它就是唯一的现场。“打印高质量日志的10条军规”听起来像标题党实际上每一条都是用线上事故换来的教训。这篇文章我不讲虚的十条规矩一条条拆开说清楚背后的原因、具体怎么落地、踩过哪些坑适合写后端服务的开发、维护老系统的同学也包括被日志折腾过的运维朋友。1. 为什么要把日志当成“军规”来执行1.1 日志烂的代价不是一句“补一下”能解决的很多人觉得日志就是System.out.println的升级版想打就打不打也行。真到了线上出问题的时候这句话会被现实狠狠打脸。我见过凌晨三点被拉起来处理支付超时结果查日志发现关键服务连一条入参都没记录也见过日志文件里全是DEBUG刷屏真正的ERROR被淹没在上万行垃圾里排查问题像在垃圾堆里找针。日志质量差的代价是连锁反应的。第一层是排查效率极低本来十分钟能定位的问题因为没有关键信息得靠猜、靠复现、靠加日志重新发布一等就是半小时起步第二层是误判日志不完整的时候你会把A服务的问题归因到B服务身上改了一通配置发现毫无用处第三层是舆论层面的信任消耗研发说“日志显示没问题”运维说“日志根本没记录到”业务方说“你们到底能不能修”一来二去团队内部的信任就被磨没了。高质量日志解决的就是这三层问题。它让你在事故发生时能快速还原现场、找到根因、验证修复也让你平时能通过监控和告警提前发现问题。它不是给机器看的也不是给自己当时看的而是给“未来的自己”和“一起值班的同事”看的。这也是为什么日志规范值得用“军规”这两个字来对待它不是建议是必须。1.2 高质量日志应该长什么样先给一个直观的印象。一条高质量日志你扫一眼就能回答四个问题什么时间发生的、在哪个服务哪个类哪个方法里发生的、当时发生了什么业务动作、结果怎么样。它应该是结构化的、完整的、可检索的而不是一段散文。举两个例子对比一下。这是我在项目里见过最多的写法2024-03-15 14:23:01.213 INFO OrderService - order create success这条日志乍一看没问题但实际上等于什么都没说。哪个订单创建成功了订单号是多少用户是谁耗时多久库存扣了没有全部没有。如果这是个定时任务批量创建订单一分钟打几千条这条日志毫无区分度。对比一下高质量版本2024-03-15 14:23:01.213 INFO [http-nio-8080-exec-3] [traceId8a3f9b2c1d4e] [userId10086] OrderService.createOrder - orderId20240315142301001, itemIdSKU123, quantity2, amount99.80, cost12ms时间、线程、traceId、用户、类名方法名、业务关键参数、耗时全部齐了。出问题时你可以用orderId或者userId直接搜到这一条再通过traceId把整条链路串起来。这才是“高质量”三个字的含义。后面这十条军规本质上都在往这个方向靠。2. 军规一至五让日志“有话可说”2.1 军规一统一日志门面杜绝日志框架互殴这一条是地基地基没打好后面九条全是空中楼阁。Java项目里最常见的日志框架有Log4j2、Logback、java.util.logging早期还有Log4j 1.x。如果项目里不同模块用了不同框架classpath上一旦出现多份日志实现就会出现一个很经典的“日志地狱”你配的logback.xml不生效因为某个二方库强行绑定了log4j或者运行时报警说SLF4J的绑定出现多个日志输出到底走哪条通道全看类加载顺序玄学得很。解决办法是统一使用SLF4J作为门面底层绑定一个实现。SLF4J的好处是它的API是稳定的你代码里只依赖slf4j-api具体用logback还是log4j2由部署时决定。换实现的时候不需要改业务代码改个依赖换个配置文件就行。具体落地时要注意三点。第一排除传递依赖里的其他日志实现尤其是老项目里log4j 1.x的残留Maven的exclusion要写干净第二确保classpath只有一个绑定启动时看到类似“Class path contains multiple SLF4J bindings”的警告必须处理不要觉得不影响就跳过第三使用占位符{}而不是字符串拼接比如log.info(userId: {}, userId)这不仅仅是性能问题更重要的是只有占位符写法才能配合后面的参数化日志和延迟计算。日志框架统一之后整个团队才拥有共同的语言基础后续所有规范才有讨论的前提。2.2 军规二日志级别是严肃契约别把INFO当垃圾桶日志级别不是随便选的它是你和未来排查问题的人之间的一份契约。我见过太多团队把INFO当成默认输出口业务逻辑每一步都打INFO结果ERROR真正出现时没人注意到。也见过反过来整个项目只有ERROR和INFO两级DEBUG从来没有用过排查问题时没法打开细致追踪。级别选择的判断标准其实很清晰。TRACE和DEBUG用于开发调试输出的是详细的中间状态、算法步骤、临时变量这些信息量巨大正常生产环境不应该输出。INFO记录的是业务的关键节点用户下单成功、订单状态变更、外部接口调用完成这些信息要能回答“系统当时在做什么”。WARN表示“有问题但不需要立即处理”比如重试了一次成功、缓存击穿走了DB、接口响应偏慢但还在阈值内。ERROR表示“功能确实出错了需要人工介入”必须包含完整的异常堆栈和当时的关键上下文。我自己常用的一个辅助判断方法是如果这条日志打出来线上所有INFO加起来一天不超过几百MB说明INFO用得还算克制如果INFO日志一小时就刷几个GB那肯定是级别使用失控了。特别是生产环境INFO级别应该只记录业务里程碑事件那种“进入方法xxx”“调用xxx开始”之类的日志降级到DEBUG去。另外要提一个我踩过的坑日志级别的配置不要写死在代码里必须通过配置文件控制。因为同样的代码在测试环境可能DEBUG在生产环境是WARN及以上你不可能让开发改代码去切换级别。后面军规八也会展开讲。2.3 军规三每条日志都要包含完整的上下文要素我排查问题的时候最崩溃的就是日志里只有信息没有上下文。比如数据库查询报错了日志打了一句“query failed”但是查的是什么表参数是什么数据源是哪个全都没有。这种日志打不如不打它只能让你知道出错了却无法让你知道为什么出错。一条合格的日志至少要包含四类上下文。第一类是时间与环境要素。时间戳默认要带毫秒和时区多节点部署时如果服务器时间不一致后面排查会非常痛苦。第二类是定位要素也就是类名、方法名、线程名logback的pattern里配置好就行目的是让搜索的人快速跳到代码位置。第三类是业务要素订单号、用户ID、商品ID、请求路径、关键参数这些取决于具体的业务但核心原则是一个原则凡是能用于检索的ID都必须放进日志。第四类是调用链要素也就是traceId和spanId这个军规九单独展开。这里还有一条容易被忽略的日志里的关键参数要做脱敏。用户手机号、身份证、银行卡、密码相关字段不能明文打出来换句话说是“能脱敏就脱敏”。手机号打前三位后四位身份证打前六后四这既是合规要求也是保护用户和公司自己。我曾经接手过一个项目登录日志里居然把明文密码打出来了当时冷汗都下来了这个锅一旦出事就是重大事故。日志内容这块我个人的一个习惯是写每一条业务日志的时候脑子里模拟一下“如果我是三个月后值班的人我看到这条日志能不能不用看代码就知道发生了什么”。如果答案是不能说明日志内容还不够。2.4 军规四结构化输出让机器替你读日志很多老一辈开发喜欢看那种排版漂亮的文本日志对齐、缩进、彩色人眼扫着很舒服。但二十个节点、一天上亿条日志的时候人眼是看不过来的必须交给机器。机器读取的效率和日志结构强相关一段自由文本和一段JSON机器解析成本天差地别。结构化的意思就是让日志带上明确的字段名和值最通用的做法是输出JSON格式。举个例子{time:2024-03-15T14:23:01.21308:00,level:INFO,logger:com.example.OrderService,thread:http-nio-8080-exec-3,traceId:8a3f9b2c1d4e,userId:10086,msg:order created,orderId:20240315142301001,costMs:12}这样一条日志可以直接被Logstash、Filebeat采集倒入Elasticsearch后字段自动映射Kibana里可以用orderId.keyword精确搜索、用costMs做范围过滤、用level做聚合统计。换成文本格式你还要写一堆grok正则去解析解析规则稍微匹配不上整条日志就废了。结构化的另一个好处是字段可以无限扩展。今天是orderId明天可以加channelId、promotionId、skuId反正都是键值对不需要改日志框架。Logback里可以配置PatternLayout输出JSON更推荐的做法是用logstash-logback-encoder这个encoder它帮你把MDC里的字段、异常堆栈、自定义字段都序列化成JSON。这里有一个注意点日志内容里如果包含换行符或者引号JSON格式可能会被撑坏尤其是异常堆栈里的多行文本。用logstash-logback-encoder处理时会自动转义问题不大。但如果你手拼JSON字符串打日志那大概率会在某个晚上格式化出一个非法JSON采集端直接丢弃。我的建议是永远不要手拼JSON通过配置和工具生成。2.5 军规五异常日志必须带着堆栈一起打这条单独拎出来说是因为它太重要又太容易被做错。最常见的错误写法有两种。第一种是只打异常messagetry { doSomething(); } catch (Exception e) { log.error(doSomething failed: e.getMessage()); }看起来好像把错误信息打出来了但e.getMessage()往往只是一个非常笼统的描述比如“null”或者“Connection refused”根本没有告诉你哪个环节出了问题。第二种是打堆栈但姿势不对log.error(failed, e.getStackTrace());getStackTrace()返回的是StackTraceElement[]数组直接拼到字符串里输出的是数组的toString打印出来是[Ljava.lang.StackTraceElement;3f99bd52这种地址串没有任何价值。正确的写法只有一种把异常对象作为最后一个参数传进去让日志框架自己处理堆栈。try { doSomething(); } catch (Exception e) { log.error(doSomething failed, param{}, param, e); }这样输出的是完整的异常类名、message、以及整个堆栈轨迹。多行堆栈在JSONencoder下会正确转义在文本格式下会自然换行两种场景都没问题。还有一个进阶要求日志的上下文信息要放在堆栈前面别让堆栈独占一行。因为堆栈打出来之后后面的字段很容易被忽略检索的时候也只能看到堆栈看不到当时的业务参数。正确的顺序是先打业务上下文再带异常对象。比如log.error(createOrder failed, userId{}, orderId{}, userId, orderId, e)这样堆栈是附在最后的前面字段完整。说到这儿就不得不提一个重要原则catch到异常后要么打日志要么抛出去不要打了一条日志之后又抛了一个新异常结果同一个错误打了三遍排查的人被重复堆栈搞到精神崩溃。3. 军规六至十让日志“经得起检验”3.1 军规六同步改异步日志不能拖垮业务QPS日志虽然重要但如果打日志把业务拖慢了那也得不偿失。同步日志最大的问题是输出过程中存在IO等待尤其是机械磁盘或者网络文件系统上写一条日志可能阻塞几十毫秒。在高QPS场景下这是不可接受的。我测过一个项目把同步日志切到异步日志后同样的压测流量下接口P99耗时直接从180ms降到了95ms几乎翻倍。解决方案是使用异步Appender。Logback的AsyncAppender和Log4j2的AsyncLogger是两种主流方案。Log4j2的AsyncLogger性能更极致只要配置了disruptor依赖可以在业务线程里直接组装日志事件交给后台线程batch刷盘对业务线程的阻塞极小。Logback的AsyncAppender本质上是一个有界队列加一个后台线程队列满了之后有丢弃策略配置上要留意queueSize和discardingThreshold。异步日志有一个必须避免的坑丢日志。很多团队为了性能把队列大小调得太小或者设置了discardingThreshold导致流量高峰期掉日志。真到了出事的时候恰恰是高峰期结果日志被丢弃了等于废了。我的建议是队列至少要开到8192以上discardingThreshold调成0也就是永不丢弃代价是极端情况下业务线程要等一下队列腾位置但日志完整性优先。另一个容易被忽视的点是AsyncAppender里不能配置多个Appender如果你既想写文件又想输出到Console正确做法是配置两个Appender然后AsyncAppender包住它们。还有一个常见误解是异步只对文件输出有意义Console输出如果管道被阻塞照样会拖慢生产环境Console建议关闭或者重定向到/dev/null。3.2 军规七日志轮转与保留策略提前定好日志如果不做轮转三个月就能把一个磁盘分区写满然后整个服务直接宕掉。这里说的日志轮转rotation和时间策略retention必须在系统上线第一天就定好而不是等到磁盘满了再处理。最常见的策略是按天轮转加按大小兜底。Logback里用TimeBasedRollingPolicy按天生成一个文件比如app.log.2024-03-15。同时设置maxHistory比如保留30天超过的自动删除。为了防止某天流量异常导致单文件过大再叠加SizeAndTimeBasedRollingPolicy设置单文件最大200MB超过就分卷。配置示例长这样appender nameFILE classch.qos.logback.core.rolling.RollingFileAppender file/data/logs/app.log/file rollingPolicy classch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy fileNamePattern/data/logs/app.%d{yyyy-MM-dd}.%i.log/fileNamePattern maxFileSize200MB/maxFileSize maxHistory30/maxHistory totalSizeCap20GB/totalSizeCap /rollingPolicy encoder pattern%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n/pattern /encoder /appendertotalSizeCap这个参数容易被忽略它的作用是控制所有历史日志的总大小上限防止maxHistory虽然只有30天但某天文件特别大导致磁盘还是爆了。两个参数结合才是完整的保留策略。还要提醒一句pattern里的%d要和文件名里的日期格式一致否则logback会报错。日志目录最好单独挂一个分区和系统盘、数据盘分开这样即使日志量异常增长也不会拖垮整个机器。热词里的“linux 清空日志文件”就是这种情况的补救但不要指望事后清空事前策略更重要。3.3 军规八环境差异化配置开发环境与生产严格分开同一个logback.xml在不同环境必须有不同的行为。开发环境要能输出到Console级别开到DEBUG方便调试日志文件不轮转都行。生产环境只输出ERROR和WARNConsole关掉文件做轮转和异步另外还要考虑把敏感字段过滤开启。实现方式是用Spring Boot的profile机制或者logback自身的springProfile配置。例如logback-spring.xml里可以写springProfile namedev root levelDEBUG appender-ref refCONSOLE/ /root /springProfile springProfile nameprod root levelWARN appender-ref refASYNC_FILE/ /root /springProfile这样同一套配置在不同环境自动切换不需要改代码。注意这里文件要命名为logback-spring.xml而不是logback.xml否则springProfile标签不会被识别。提到环境差异化还有一个很多人忽略的问题日志格式里的环境标识。同一套代码部署了多个环境排查问题时你拿到的日志内容是一样的但可能分不清来自哪个环境。建议在pattern里加上环境变量占位符比如在logback里读Spring的变量输出到每行日志pattern%d{yyyy-MM-dd HH:mm:ss.SSS} [${APP_ENV}] [%thread] %-5level %logger{36} - %msg%n/pattern这样一眼就能看出日志来源。特别是在多环境共用一套Kibana索引的时候没有环境标识跨环境检索会非常痛苦。3.4 军规九链路追踪贯穿traceId一查到底现代后端服务基本都是拆分架构一个用户请求要经过网关、鉴权服务、订单服务、库存服务、支付回调好几个节点。如果每个服务都各自打日志排查问题时你要在四五个日志文件里来回跳靠时间戳硬凑调用顺序。这个效率太低了正确的姿势是给每个请求分配一个全局唯一的traceId让它贯穿整个调用链。实现上分两层。第一层是生成和传递traceId。在网关或入口处生成一个UUID放到HTTP请求头里比如X-Request-Id下游服务调用时把上游的traceId接着往下传。内部服务间通过HTTP调用的要用拦截器比如Spring的HandlerInterceptor配合RestTemplate的ClientHttpRequestInterceptor自动把traceId从请求头取出塞进MDC调用下游时再从MDC取出来放回请求头。第二层是在日志输出里体现traceId。MDC是SLF4J提供的线程本地变量代码里可以这样MDC.put(traceId, traceId); try { // 业务逻辑 } finally { MDC.remove(traceId); }然后在logback的pattern里加上pattern%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{traceId}] [%thread] %-5level %logger{36} - %msg%n/pattern这样每条日志后面都会自动带上traceId搜索的时候只需要copy第一个traceId就能把整条调用链的所有日志串起来。这里有一个要注意的坑MDC是线程绑定的一旦你的代码用了线程池异步执行任务子线程里默认是拿不到父线程的MDC值的。如果日志里突然发现traceId丢了先怀疑是不是跨线程了。解决方式是用ThreadPoolTaskExecutor包装或者提交任务时在子线程里重新设置MDC。Spring Cloud Sleuth和Micrometer Tracing这些组件已经把这些封装好了新项目建议直接用老项目改造可以自己封装一个线程池工具类。3.5 军规十打通采集与检索日志真正的归宿是可观测平台如果日志只是躺在服务器的磁盘上那它充其量是个离线存档监控告警和问题定位的效率都上不来。高质量日志的最终形态是进入统一的日志平台能检索、能聚合、能告警。典型架构是Filebeat或者Fluentd采集服务器上的日志文件经过Logstash做解析和清洗写入Elasticsearch再由Kibana做可视化检索。轻量一点的方案直接用Filebeat的Elasticsearch output省掉Logstash缺点是解析能力弱一些。但是前面军规四强调的结构化JSON日志在这里就能体现出巨大优势——Filebeat采集JSON日志后字段原样进入ES不需要复杂的grok解析直接可用。采集方案打通后有三件事值得做。第一是常用的检索视图比如按服务、按环境、按时间范围过滤一个后端同学接到工单后的标准动作应该是打开Kibana输traceId回车看到整条链路。第二是告警规则比如某个服务ERROR级别日志在五分钟内超过阈值自动触发告警这是从“人找问题”变成“问题找人”的关键一步。第三是日志与指标关联日志中的响应耗时可以和APM的指标做联动从日志里发现某个接口突然变慢再到链路追踪里看看是不是下游服务超时。打通这一步之后前面九条军规才算真正开始发挥价值。否则你打了再好的日志排查的人还是得ssh到服务器上去tail -f效率和在垃圾堆里翻找没有本质区别。4. 实战排查日志现场还原的四个高频坑4.1 日志神秘消失先查异步队列和buffer如果你配置了异步日志某天突然发现高峰期日志有缺口或者某些时间段一条记录都没有大概率是异步队列配置出了问题。Logback的AsyncAppender默认在队列剩余容量低于20%时会直接丢弃TRACE、DEBUG、INFO级别的日志保留WARN和ERROR美其名曰“防止业务线程被阻塞”实际上就是把日志丢了。验证方法很简单看丢日志的时候有没有输出“Discarding”相关的警告到系统输出或者看队列的丢弃计数。另外还有一个可能是buffer太小如果用的是Log4j2的AsyncLogger它内部使用LMAX Disruptor的RingBuffer默认大小是4K即4096条日志事件高吞吐场景下很容易填满后写入的日志会被阻塞或覆盖。调大RingBuffer到65536一般能解决问题。排查时先确认是否是异步框架吞了日志而不是业务代码压根没走到。方法是在日志平台里按traceId搜如果前半段有、后半段突然断了优先怀疑是线程切换导致MDC丢失或者是日志事件被丢弃而不是业务逻辑中断。我碰过好几次开发以为是代码崩了结果是异步队列满了把日志吞了白白浪费了两小时查代码。4.2 时间不同步排查事故时的“背锅侠”多节点部署时如果服务器时间不一致日志的时间戳完全不可信。排查问题时你会发现节点A的日志显示14:01:02节点B显示14:01:15同一个请求经过两个节点时间错位十三秒看起来像是B节点处理了13秒实际上可能是A节点的时间快了13秒。这个问题必须在基础设施层面解决。生产环境强制所有机器配置NTP时间同步并且监控系统要能检测到时钟偏移。日志框架这边时间戳不要用本地时间尽量输出带时区信息的ISO 8601格式比如2024-03-15T14:23:01.21308:00这样即使两个机器时间有偏偏移量也能从时间戳里看出来。另外一个跟时间相关的高频坑是时区配置。容器化部署时基础镜像默认是UTC时区但业务代码里期望的是东八区。如果日志和数据库时间显示差了8小时别怀疑数据库先看容器的TZ环境变量有没有设置。Dockerfile里设置ENV TZAsia/Shanghai或者运行容器时-e TZAsia/Shanghai基础镜像如果有tzdata包就能解决。4.3 日志文件撑爆磁盘清理也有正确姿势日志把磁盘写满导致服务崩溃这是运维最常见的故障之一。轮转策略没配置好或者某个错误分支疯狂打日志都可能触发。热词里“linux 清空日志文件”的需求就是这么来的但清理本身也需要讲姿势。最粗暴的错误做法是直接rm掉正在被进程写入的日志文件。你以为删了就释放空间了实际上Linux里文件被进程持有句柄时删除目录项并不会真正释放磁盘空间空间要等进程关闭文件句柄才释放。结果就是你rm完了df一看可用空间还是0因为那个进程还在往已删除的inode上写数据。正确做法有两种。第一种是清空文件而不是删除文件用cat /dev/null app.log或者truncate -s 0 app.log文件句柄不变目录项还在空间立即释放。第二种是让日志框架自己处理配合logrotate工具或者应用自身的轮转策略删旧文件。事后清理只能止损治本还是要把轮转和保留策略做好。另外要关注的是“错误分支疯狂打日志”的场景。代码里如果有个循环里打印ERROR而错误原因一直没被修复日志量会指数级增长。我见过一个项目因为某个第三方接口key过期每秒钟打几百条ERROR一晚上写了60GB日志。这种情况除了修复根因还建议加上限流打印机制比如同一个异常每分钟最多打一次避免日志风暴放大故障。4.4 机器读不懂你的txt检索命令也得讲究日志平台还没完全覆盖老系统的时候ssh上去手动搜日志还是日常操作。这里有几个能大幅提升效率的命令习惯。最常用的组合是grep加上下文。只看匹配行往往不够前后几行能还原现场grep -n -A 5 -B 5 orderId20240315142301001 app.log-A是after-B是before分别显示匹配行后5行和前5行。搜的时候能少打不少字比如grep --coloralways可以高亮关键字肉眼扫起来省力得多。按时间段切片再搜比直接搜整个大文件快很多。先用sed截取某段时间或者某个范围的日志再在结果里精确搜索sed -n /2024-03-15 14:20:00/,/2024-03-15 14:30:00/p app.log slice.log grep ERROR slice.log还有一个实战技巧日志文件特别大的时候不要用vim打开整个文件会卡到你怀疑人生。用less F进行实时跟踪less F app.log这和tail -f效果类似但允许你在跟踪模式下按Ctrl-C停下来搜索再按F继续跟踪排查正在发生的问题特别方便。热词里提到Windows安全日志、ADB logcat抓取日志、任务计划日志查看等等这些是不同的日志域但核心方法论是一样的先定位时间范围再锁定关键字最后结合上下文还原事件链。工具可以不同思路必须统一。5. 最后两句私货写了这么多其实我觉得打印日志这件事本质上是一种“对自己未来负责”的工作习惯。你在代码里多写一个参数多打一行结构化输出当时可能觉得无所谓但真到了深夜被拉起来处理故障的时候你会感谢自己当时的“强迫症”。如果你现在维护的是一个老系统日志还处于“能用就行”的阶段我的建议是从十条例里挑两三条最痛的下手统一的日志框架、完整的上下文、异常堆栈正确地打出来。不用追求一步到位但每改一条下一次排查问题的效率就会明显提升一块。日志质量是慢慢养出来的而不是某一次重构“改”出来的。