今天一个接口502,不理解一个逻辑很简单的接口怎么会失败。因为我们的的架构是ofe+nginx+php,熟悉这个架构的人都知道,502错误码通常是php-fpm对应的fastcgi进程处理不过来请求导致的。
502状态码也叫网关错误,通常是因为并发请求高超过php-fpm处理能力,导致nginx没有从upstream收到正确的返回结果。
nginx
从上面的图中可以看到,upstream_time超过了5s,而正常的请求只需要10ms左右。乍一看像是超时,因为nginx.conf里面配置的fastcgi_connect_timeout是5s。
upstream上的nginx日志同样是502,和ofe上基本一样。
从nginx error.log可以看出似乎是php fastcgi没有按时返回结果。
php
问题大概率是出在php层或者业务代码。查看php7-fpm-error.log日志发现问题时间点fastcgi出现过重启。
一度怀疑是php出问题了。
php-fpm允许的最大子进程数是128,也就是同时有128个fastcgi可以处理并发请求,如果超过了这个数就会出现雪崩,导致502网关错误。但是查看机器负载和当时的请求数,还没有那么多。
接着分析pool.d/php7-www.conf中配置的request_terminate_timeout是5s,代表如果如果业务没有再5s内返回,fastcgi就会终止进程。正好和上面的日志吻合。
我们重新分析一下php7-fpm-error.log就豁然开朗了。
15:31:20是收到请求并且执行了2s后,打出了executing too slow的trace日志。这是因为php7-www.conf中配置的request_slowlog_timeout=2s,表示2s如果请求还没结束就打日志。
接下来在15:31:24的时候请求达到5s,就触发了request_terminate_timeout限制,child26113被终止,重新启动了10022子进程。
因为child26113是被主进程终止的,所以业务日志并没有体现,所以导致了我一度以为没有调到我的业务代码。
慢请求
经过上面的分析可以看出是因为代码执行超时导致502。此时还有另一个日志可以排上用场。那就是php7.php7-www.slow.log,记录了慢请求的一些细节。
找到对应的时间点,分析发现是因为用curl调用其他服务超时。查询下游的服务并没有找到对应的日志,进一步推测可能是网络问题。
网络问题
初步分析如果是下游服务执行慢导致超时,那么至少下游会有日志。下游服务没有日志说明是curl请求丢失或者网络连接失败,也有可能是dns解析问题。
进一步查看配置发现,调用下游服务用的是外网域名,所以失败的可能性会更高。根据推断把外网域名换成内网域名后问题就没有再出现了。
总结
平时业务开发中最常见的就是502和504错误,每次遇到这两种错误都觉得可能是因为并发过大导致php,mysql,redis中的某一个超时或者抖动。
由于目前微服务架构比较普及,所以服务间的调用也会带来问题追查的复杂度,并且服务调用稳定性问题也越来越普遍。但是每个问题细心追查起来都可能是因为一个参数或者配置用的不合理,或者格式一行代码引起的。一旦通过一次事故排查解决了问题,那么对架构的理解就会更上一层。
欢迎关注微信公众号『野狐』