解决一个偶现的503 bug,花了俺不少时间

概述

---

在3月2日晚上，大概8点左右，本想打道回府，回家休息，突然被人在bug群@了一下，说是管理后台，访问不了，界面上出现了:

503 service temporarily unavailable

我赶紧尝试访问了一下，确实如此，但不是每次都不行，而是偶发503的错误提示。当时我是没有立刻动手去定位问题，而是先拉了一个临时处理群，这样做的原因是：

• 先将线上出故障了这件事情同步出去，要让相关的人知道，像运维、测试、你的上级、产品等；
• 一定是先止损，优先【线下去处理故障】，而不是【直接在线上处理故障】；

群拉完后，我简单同步现象后，就开始分析了，首先想的第一点就是：

是不是因为做了线上变更导致的，比如有发版之类的。

从这个点切入去想的原因是源于自己处理线上故障的经验，大部分都是发版导致的，能回滚的优先回滚，第一时间降低影响。因此我打开了发版日历（技术团队是有维护一个发版日历的，记录了每次发版或者变更的内容），发现3月2号当天，在线上做了如下两件事情：

• 部分服务接入了阿里云WAF，这个是因为安全原因，需要接入；
• 管理后台对应的前后端服务，确实也发版了；

火速电话公司的安全专家，先临时关闭WAF，但关闭后没有用，访问管理后台还是一直出现503提示，没办法了，得立刻回滚当天上线的内容，正当运维要操作回滚的时候，我反而制止了它。因为：

管理后台突然又能访问了。

😂，跟产品和业务方确认了一下，他们也反馈系统恢复了。好吧，这个也算一个好消息，毕竟可以给技术团队多一些时间去定位问题。

系统临时性恢复后，我这边也就没那么大的压力和紧迫感了，静下心来开始着手仔细分析，找出根因。

---

分析过程

---

是否有突增的流量过来

使用阿里云的SLS日志平台，写了个简单的脚本，执行后发现，流量一直很平滑。虽然是管理后台的服务，但是还是要先看看流量的，因为有可能有一些定时任务或者重量级业务操作，导致疯狂的调用管理后台服务。

是否是发版导致的?

由于发版的内容还不少，很难一下子分析出是哪些代码导致的，只能利用阿里的日志平台以及监控平台，从故障发生的时间范围里，寻找一些蛛丝马迹。

首先是查看故障时间内，对应的后端服务有无返回状态码非200的，可以使用阿里的SLS日志平台，写个简单命令查询一下即可：

xxxx_app_id:yyyy not statusCode: 200

上面的一些查询字段，是可以在SLS上自己定义的。最终发现返回的状态码都是200的，这个就有点奇怪，但还是继续看一下有无异常日志。

xxxx_app_id:yyyy and logLevel: ERROR 

发现也没有，初步判断，不是后端代码上线导致的，便转而开始用阿里云的监控平台观察后端服务pod节点的运行情况，但也没有什么收获，pod既无重启的情况，内存、CPU usage也都正常，也没有什么慢的请求。

当时就有点摸不着北了，由于那会也比较晚了，后台管理系统也暂时没有出现问题了，我就先回家了。而隔天又有其他重要紧急的事情要处理，我就忘记去跟这个事情了，一直到3月6号早上，又开始出现503问题了，持续时间是两分钟，然后就又自己恢复了。

这次我就把手头上的事情先全部放下，全力跟进这个问题。经过3月2号晚上的分析，感觉跟后端服务没有关系，那会不会是前端的node服务有问题呢? 当然平时如果线上出故障，我很少认为会是前端问题，都是先从后端服务定位起。

但这次没办法，死马当活马医，于是便到阿里云上去看一下前端pod节点的运行情况，发现有重启的情况，我感觉发现新大陆了，马上去确定pod重启时间，但是很遗憾，我没权限看，就临时去看一下这个pod的内存波动情况，一般来说，pod有重启的话，内存会短暂释放，果然，在故障期间，前端的pod的内存占用有下降的趋势，然后故障后的几秒，内存占用又恢复了日常水平。

于是便火急火燎的跑去找了一下运维：

把前端的xxx pod有重启的情况，我怀疑管理后台503问题，是这个原因导致的，你能不能把这个pod重启前的日志发我一下。

当时运维回复说，重启前的日志找不到了哦。当然，这句话我是不信的。就让运维去查一下或者找阿里云的售后，看看怎么拿到pod重启前的日志。果然，可以使用kubectl命令，找到日志：

kubectl describe pod xxxx-pro-vyyyyyyyy | grep 'State: ’ -A 5

日志里有几个信息：

• 一个是pod重启前的代码报错日志；
• 一个是pod具体的重启时间；
• 一个是Exit Code，这个code等于1，说明pod重启，是服务自身的报错导致的。

报错日志如下：

TypeError [ERR_HTTP_INVALID_HEADER_VALUE]: Invalid value “undefined” for header “Content-Length”

到此，基本就清楚了，请求先经过阿里WAF和阿里nginx-ingress后，由nginx-ingress转发给前端的service，进而进入到pod，但是由于pod同一时间都在重启，暂时无法提供服务，service这一层就不知道pod的状态，nginx-ingress自然也就无法知道service的状态，于是便返回了503。等重启完毕后，就又正常提供服务，之所以偶发的出问题，原因就在这里。

于是便找了前端的开发leader去定位原因，最后他回复说，要改一个底层文件，兼容一下Content-Length为空的情况，改完后，简单在在测试环境和预发布环境测试一下，过一下核心主流程，没问题后，就上线了。

从3月9日上线到现在，暂时没有发现503问题了。

那灵魂一问来了，这个底层文件，从2021年来一直都没有改动过，也没出过啥事，为啥最近才开始出问题呢?
答案是：

比较难查，不知道是哪些请求会没有Content-Length，但肯定是发版导致的。