关于我如何用一个bug让自己加班到凌晨三点这件事

这事儿得从昨天下午说起。周五下午四点半我已经在收拾东西准备跑路了。测试那边丢过来一个issue说生产环境有个接口偶尔超时让我看一眼。偶尔超时这种词儿在程序员字典里基本等于大概率是你的问题但我懒得查日志。我打开skywalking看了下调用链没毛病啊响应时间平均120ms挺正常的。又翻了翻nginx日志也没有明显慢请求。我就回了一句这边看正常再观察一下。然后测试就炸了。他贴了张截图请求时间15:47:23响应时间3.2秒。我一看这个时间点心里咯噔一下——那个时间我刚发完一个版本重启了服务。你以为的bug其实是feature接下来就是一个小时的血泪排查。先怀疑是缓存失效导致回源DB查了redis命中率99.8%正常。再怀疑是日志打印太多把IO堵了看了下logback的异步队列积压为0正常。怀疑是GC问题看了眼GC日志频率正常单次耗时也都在50ms以内。然后我注意到一个细节这个超时请求里带了一个特殊的headerx-request-id的格式是abc-123-def这种但正常我们内部生成的格式是UUID.randomUUID().toString()全是横杠分段的那种。我就顺着这个header往上查发现这个请求经过了一个网关服务而网关里有个拦截器会对这个header做一次MD5计算然后塞到MDC里用于链路追踪。MD5计算本身不慢但这个拦截器的实现是这样的String requestId request.getHeader(x-request-id); if (StringUtils.isNotBlank(requestId)) { // 为了兼容旧版本对非标准格式的requestId做一次摘要 if (!requestId.matches(^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$)) { requestId DigestUtils.md5DigestAsHex(requestId.getBytes()); } }这个正则每次请求进来都要执行一次。大部分请求的requestId都是标准UUID匹配很快。但那个特殊请求的requestId是不带横杠的短格式正则引擎在做回溯匹配的时候复杂度直接起飞了。再加上那个时间点服务刚重启JIT还没热身解释执行模式下这个正则匹配的耗时从纳秒级飙升到了秒级。问题找到了改法很简单把正则匹配改成尝试按UUID格式解析抛异常就说明不是标准格式再做MD5。try { UUID.fromString(requestId); } catch (IllegalArgumentException e) { requestId DigestUtils.md5DigestAsHex(requestId.getBytes()); }三行代码改完测试环境验证通过预发布验证通过准备发生产。有时候顺风顺水反而让人害怕发生产的流程走了半个多小时——code review、merge、构建镜像、滚动更新。整个过程异常顺利顺到我心里有点发毛。果然上线后五分钟监控突然弹出一堆告警错误率飙到15%全是NullPointerException。我当时整个人是懵的。改的就是一个拦截器里的小逻辑怎么干出NPE了赶紧回滚。回滚后服务恢复然后我开始看错误日志。堆栈指向的代码行是String traceId MDC.get(traceId); Span span tracer.buildSpan(traceId).start();traceId是null所以buildSpan的时候抛了NPE。那traceId为什么是null呢因为设置traceId的逻辑就在我改的那个拦截器里在requestId的基础上又加了一层处理。我改完之后对于非标准格式的requestId走MD5分支这个没问题。但问题是我改代码的时候把一个前置的判断条件顺手优化掉了。原来的代码是if (StringUtils.isNotBlank(requestId)) { // 设置traceId MDC.put(traceId, generateTraceId(requestId)); }我重构的时候觉得isNotBlank这个判断跟后面正则匹配的逻辑有重叠就给合并了变成了javaif (requestId ! null requestId.matches(...)) { // 只对标准格式处理 }这样非标准格式的requestId就直接跳过了整个逻辑连MDC都没设置。更隐蔽的是之前那个拦截器的逻辑里即使requestId是空也会用UUID.randomUUID()生成一个兜底的traceId。我重构的时候把这个兜底逻辑挪到了一个我认为更合适的位置但那个位置在某些异常路径下根本执行不到。所以结果就是部分请求的traceId没设置下游服务拿不到traceId就崩了。凌晨两点的感悟问题最终在凌晨两点修复了。改回去三行加了三行注释发版观察了二十分钟一切正常。回家路上我在想一个问题我为什么会在周五下午去动一个看起来可以优化但已经在线上跑了两年的代码答案其实挺简单的——我看到那段正则匹配的时候就难受职业病犯了。总觉得这种写法不优雅性能有隐患应该重构一下。但事实上那个接口的QPS也就200多那个正则匹配即使是最差情况对整个系统的影响也微乎其微。我花了一个小时定位了一个非关键问题然后用一个不那么稳妥的方案修复了它最后引入了一个更严重的bug。你说这事儿怪谁怪测试没覆盖全怪CR没看出来说到底还是怪我自己没守住线上代码能不动就不动这条底线尤其是周五下午四点半这个死亡时间点。写这段文字的时候已经是周六了。我给自己立了个规矩以后周五下午三点之后除了紧急故障任何代码变更都不做。优化代码这种事儿留给周三上午脑子最清醒的时候干。别学我。