谭智轩, 2018 年加入去哪儿网技术团队, 目前在大前端 / 小程序, 参与了新版 touch 重构, 微信支付宝等小程序开发, 以及 JAVA 后端迁移 Node 接口等项目. 个人对前端性能优化及框架设计思想有浓厚兴趣.
背景介绍
随着部门的 web 接口不断增多, Java 后端逐步向 Node 迁移. 在大住宿事业部, 这个 Web 接口有一个好听的名字: 热狗. 不, 不对, 它叫 HOTDOG. 即从这个状态:
变为了这个状态:
我们需要做的, 就是搭建 Node 服务, 作为客户端和 WEB_HOTDOG 的通讯桥梁. 考虑到负载均衡, 一般会采用类似 Nginx 的软件作为反向代理. 同时源服务器一般会有多台, 所以经常看到这样的配置:
- upstream node_server {
- server 111.111.111.10:6666;
- server 111.111.111.11:6666;
- server 111.111.111.12:6666;
- server 111.111.111.13:6666;
- }
- server {
- ...
- location /interface/to/location {
- proxy_pass http://node_server;
- }
- }
即对 /interface/to/location 的请求会被转发到 upstream node_server 上, 当然详细的配置还有很多.
故障重现
配置好 NG, 部署好工程, 万事俱备, 只差验收了. 然而, 当访问新增的 Node 接口时, 总是时不时的返回 502!
还有一个现象: 当一个接口 502 后, 其它接口基本上也跟着 502(首屏会发 3 个请求). 但是直接 Node 服务器的 IP+PORT 访问, 一切都是那么的完美! 既然有问题了, 开始查问题!
Fix Problem
接下来将以多个步骤, 讲解 Fix 的过程.
Step.1 OPS 查 NG 日志
首先 OPS 贴了一份 NG 日志:
支 OPS 支持人员说: Google 了下, 意思大概是说这部分访问进来走的是 NG 上处于半连接的 tcp 连接, 导致服务没处理就关闭连接了. 所以我们看到是 502. 我们可以先尝试增加连接的超时时间.
Step.1_result
增加了超时连接后, 依然出现 502, 继续.
Step.2 Node.JS 服务端查日志
作为大前端, 查 Node 日志肯定是我们基本功. 守护程序使用的是 pm2. 但是我们却意外地发现, 并没有看到任何 502 的请求进来! 并且查看到当时的系统负载很低, 不会因为负载大而断链. 也就说是, NG 返回给前端的 502 请求, 并没有进入到 Node 服务器中! 这时候我们认为是 NG 转发有问题! 联系 OPS 继续看 NG.
Step.2_result
失败, 继续找 OPS 定位问题.
Step.3 OPS 修改到 upstream 为长连接
OPS 说, 考虑到多种因素, 一般连接到 upstream 都采用的是短链接, 对于频繁访问的接口, 可以尝试使用长连接. 经过我们大前端的确认, Node 服务器支持 HTTP1.1 的长连接, 开始实验.
Step.3_result
更为长连接后, 502 情况依然存在, 失败.
Step.4 查看 Node 服务的超时处理
OPS 认为 Node 服务在处理请求时, 会有默认的超时处理. 经过我们的确认, Node.JS 的 http 服务器默认超时时间是 2min(我们并未手动更改超时时间), 而出现 502 的情况是在请求发出后 1 秒内返回的. Node 服务器代码内, 我们并未手动返回 502 状态(如果能手动返回 502, 那么说明请求已经到了 Node 服务中间件, 不可能出现没有请求日志的情况).
Step.4_result
Node 服务器并没手动返回 502 状态码, 准确地说应该是没走到业务逻辑中就已经挂了.
Step.5 网络层面 --- 抓包
现在的问题是, OPS 认为是 Node 服务器有问题, 我们认为是 NG 服务器有问题(确实各有各的道理), 所以得找出是不是自身的问题. OPS 决定采用抓包的方式, 看请求转发过程中请求, 响应情况. 下图是 OPS 提供的 NG 服务器抓包图:
由上图可以看出, NG 发出请求到 upstream 的服务端口 (这里将简称 D 端口) 后(就是当前 hover 的条目),D 端口监听的程序 (Node 服务器) 没有给出相应, 而是先回了个 Ack, 然后直接发起 Fin, 结束连接. NG 也回复 Fin, 确定结束连接. 对于 NG 来说, upstream 没有返回任何东西, 连响应头也没有, 就给前端返回 502 了. 找到了问题, 下面就看这种情况产生的原因及处理方案了.
Step.6 两端各自的尝试
前端方案 --Node
查日志过程中发现了大量的乱码, 如下图:
发现前端并未对非英文字符或其他特殊字符做 encode. 在 encode 之后, 抓包后未发现乱码, 同时也并未再产生 502 的情况.(此时我已经觉得是 Node 的问题了). 我的猜想是: 含有特殊字符 (或者叫非法字符) 的 url 请求, 当到达 Node 的 http 服务时, 在最底层 net 层就挂了, 以至于传不到业务层(表现上就是肉眼不可见的请求日志). 为了验证猜想, 我查了一下 Node-http 文档: http.Server 有一个 clientError 事件回调(只看到这么一个跟 Error 有关的 server 级回调). 于是我写了一个基本的 http 服务, 并发送了一个如下的请求:
- const http = require('http');
- const server = http.createServer(function (req, res) {
- res.end('你好 \ n');
- });
- server.on('clientError', (err, socket) => {
- console.log('clientError 事件回调');
- console.log(err);
- socket.end('HTTP/1.1 400 Bad Request\r\n\r\n');
- });
- server.listen(8888);
- curl 'localhost:8888/api/hotel/detailrecommend?hotelName=7)R(fI7) ┳ ┓┏ ┯ ┓┌ ┬ ┐╔ ╦ ╗╓ ╥ ╖╒ ╤'
这里只是模拟乱码的出现, 不一定非是这些字符. 然后 Node 服务打出的日志:
确实是 server 层面的出错了. 我们看看这个 rawPacket 是什么:
- GET /API/hotel/detailrecommend?hotelName=7)R(fI7) ┳ ┓┏ ┯ ┓┌ ┬ ┐╔ ╦ ╗╓ ╥ ╖╒ ╤ HTTP/1.1
- Host: localhost:8888
- User-Agent: curl/7.47.0
- Accept: */*
这就是出错的请求头. 找到了问题所在, 我们可以处理这个问题了: 对 server 添加 clientError 事件, 打点记录错误请求信息, 并将该 socket 以状态码 400 返回(给 NG 服务器), 不处理这个事件的话, socket 会 hang 住, 然后由 tcp 层面自动关闭(这纯属我瞎逼逼的). 问了一下 Java 的同学, 说 Java 中是会处理非法字符的, 但 Node 确实是没有处理, 还是说留了个 clientError 让我们自己处理?
OPS 方案 --NG
至于为什么 Node 服务器未响应, 导致用户请求的其它请求也 502 了? OPS 同学给了如下解释: Nginx 被动检查导致, 过多的错误会让 NG 认为 server 下线了, 于是在一个 fail_timeout 周期内的请求都被 NG 直接返回 502 码, 不管该请求是不是非法请求. OPS 同学继续补充: 让 touch 域名的配置尽快迁移到 OpenResty.OpenResty 没有这个问题, 它针对每个请求都是独立的, 只依赖 healthcheck 状态, 而不会依赖上一次请求的成功与否.
总结
这一次的故障, 让我和多个部门的同学一起定位问题. 从前端到 NG, 从 NG 到 Node, 从业务层面到网络底层, 都有了更深的理解. 错误不可怕, 可怕的是找不到哪里错了. 顺便记一下 NG+Node 模式下的坑点: (1)Node 处理中要对所有异常进行处理, 不管是业务层的, 还是底层的. 如果一开始就监听了 clientError 事件, 那么解决这个问题就更加显而易见. (2)NG 处理请求失败要结合具体场景, 而不是所有 upstream 都是一个通用的模板. 同时也 get 到了新技能: 服务器抓包中使用, tcpdump 命令进行抓包, 常用的:
tcpdump -vv -nn host <ng server ip> -w ng-request.pcap
即可捕获所有 NG 打过来的请求, 并保存在 ng-request.pcap 文件中, 拉到本地用 wiresharp 瞅一眼, 就知道 tcp 层面上的网络交互情况.
来源: https://juejin.im/entry/5c25cf1f6fb9a04a044117a3