某客户ERP华为云502错误案例

1、客户反馈系统出现502错误

图1

上面的截图，我们大致可以看到浏览器显示的502错误，但是我们还有获知更多的信息。通过沟通我们可以确定：此功能为新上线功能，上线后一直是访问502，但是开发又找不到相关问题，需要我们帮忙定位问题。

2、排查故障原因

我们根据DNS解析找到对应的ELB实例，发现ELB实例没有开启日志记录，我们先根据转发规则查到了后端服务，我们把后端服务的日志打开后进行搜索，发现相对应的时间段并没有日志记录的 502错误。由于日志量比较大，这里就不做展示了。那现在就很有意思了，浏览器上面显示的是：502错误，但是在服务端的日志里面并没有。这是非常奇怪的现象，我们还是建议开启ELB的相关日志，通过ELB的日志再次进行排查。由于日志非常的多，这里有一个测试的小技巧：因为我们测试的系统很多都是有token和cookie进行登录验证的，所以我们可以通过浏览器登录之后，通过F12打开开发控制台，在网络这一栏右键我们要测试的URL，然后选择cURL，这样我们就可以把token和cookie全部复制出来，直接使用CURL进行直接测试，这样更高效，而且可以通过修改http_user_agent的值，让我们的请求可以快速的通过日志库查询到，具体的步骤就是：

a. 拷贝登录后的浏览器中的cURL值，如图所示：

图2

b. 修改拷贝出来的CURL命令中的http_user_agent值，如下所示：

$ curl -k 'https://erpuat.mailang.com/std/xxxxxx/xxxxxxx?mode=3&autoTitle=true&_mp=blank&oid=xxxxxx&_hid=xxxxxx&title=%E5%90%88%E5%90%8C%E5%8F%98%E6%9B%B4%E7%94%B3%E6%8A%A5%E9%98%B6%E6%AE%B5&_t=xxxxxx&_tFields=BUGUID%2CPROJGUID&BUGUID=xxxxxx' \
  -H 'Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7' \
  -H 'Accept-Language: zh-CN,zh;q=0.9' \
  -H 'Cache-Control: max-age=0' \
  -H 'Connection: keep-alive' \
  -H 'Cookie: ASP.NET_SessionId=xxxxxxxxxxxxxxxxxxx; table_limit_4230bc6e-69e6-46a9-a39e-b929a06a84e8=20; keeplastname=xxxxxxx; _userHash=xxxxxxxx; __tracker_user_id__=xxxxxxxxxxxxxxxxxxxxxxx; __fast_sid__=xxxxxxxxxxxxxxxxx; userToken=xxxxxxxxxxxxxxxxxxxx; ck_login_out=xxxxxxxxxxxxxxxxxxxxx; table_limit_3d782708-71df-44de-0e66-08dacf924e4f=20' \
  -H 'Referer: https://erpuat.mailang.com/PubPlatform/Login/prelogin?returnUrl=xxxxxxxxxxxxxxxxxxxxxx' \
  -H 'Sec-Fetch-Dest: document' \
  -H 'Sec-Fetch-Mode: navigate' \
  -H 'Sec-Fetch-Site: same-origin' \
  -H 'Sec-Fetch-User: ?1' \
  -H 'Upgrade-Insecure-Requests: 1' \
  -H 'User-Agent: mailang' \
  -H 'sec-ch-ua: "Chromium";v="110", "Not A(Brand";v="24", "Google Chrome";v="110"' \
  -H 'sec-ch-ua-mobile: ?0' \
  -H 'sec-ch-ua-platform: "Windows"' \
  -H 'x-fiddler-profiler: db,ar,http' \
  --compressed

其中User-Agent的值就是我们要修改的http_user_agent的值，我们这里配置为mailang，如果这里没有配置的话，我们也可以直接通过-A mailang进行配置。由于执行的过程中，curl报证书问题，我们添加了-k参数进行忽略。

我们通过在日志控制台搜索，发现如下日志：

{"access_log_topic_id":"b955495c-e522-4f95-bb7a-499ff1e2cb89","body_bytes_sent":"138","bytes_sent":"286",
"category":"elb","certificate_id":"-","collectTime":"1678171697072","content":"1678171687.669 
b955495c-e522-4f95-bb7a-499ff1e2cb89 [2023-03-07T14:48:07+08:00] elb_01 xxxxxx:52758 502 
\"GET https://erpuat.mailang.com/std/xxxxxx/ HTTP/1.1\" 2347 286 138 0.694 \"502\" \"0.001\" \"-\" 
\"0.694\" \"100.107.239.79:80\" \"mailang\" \"https://erpuat.mailang.com/std/\" \"-\","eip_address":"xxxxxx",
"eip_port":"443","host":"erpuat.mailang.com","hostIP":"10.148.32.22","hostName":"xxxxxx","http_referer":
" 
"GET","request_time":"0.694","router_request_uri":"std/xxxxxx/","scheme":"https","server_protocol":"HTTP/1.1",
"sni_domain_name":"erpuat.mailang.com","status":"502","upstream_addr":"100.107.239.79:80",
"upstream_addr_priv":"xxxxxx:80","upstream_connect_time":"0.001","upstream_response_time":"0.694",
"upstream_status":"502"}

我们通过日志看到：upstream_status 502，这里显示的是后端服务返回的502。但是如果是后端服务返回的502，为什么我们在服务端没有找到对应的502的相关日志呢？遇到这种疑难杂症，最终还是祭出网络抓包来进行定位会比较好。接下来我们在服务端进行了抓包。

3、网络抓包定位问题根源

a、定位网络包

我们先通过wireshark打开抓取的网络包，然后通过http.user_agent == mailang把我们请求的网络包过滤出来，如图所示：

图3

b、通过此网络包进行tcp steam跟踪

我们根据tcp会话把交互的所有网络包都跟踪出来，具体操作如图所示：

图4

c、分析这个tcp流

TCP包如图所示：

图5

我们可以看到 11539包为我们发起的GET请求，11763为服务端返回的网络包，从11763包可以明确看到：服务端返回了200 OK，并不是ELB日志上面所记录的502。并且我们发现在服务端返回了200 OK的11763号包之后，ELB竟然返回的是 RST包，RST一般为重置TCP连接的数据包，正常情况下是不会使用此包的，现在多用于负载均衡器对后端服务的心跳检测，检测成功或失败后，用于快速释放TCP连接，为服务端节省资源，还有一种情况就是安全方面会使用。针对以上的网络包，我们找到了华为云的工程师，但是华为云的工程师拒不承认，认为要以ELB的日志为准。为了拿到更多的证据，我们再次进行网络抓包，这次我们在后端服务器和请求客户端同时进行网络抓包。

4、再次进行双向抓包

由于客户端到ELB的网络流量为https加密的，又因为我们无法进行正常的浏览器登录（因为客户没有给账号，我们是通过远程客户的电脑通过浏览器拷贝出来的Curl命令来进行测试的），所以我们无法使用wireshark进行解密https的抓包。还好目前业界里面又开源了一个新的工具：eCapture，此工具是借助eBPF进行网络加密抓包的。eBPF  我们在去年就跟大家讲过了，建议大家都要进行学习跟进。由于eCapture 依赖比较新的Linux内核和BTF，所以我这里使用的是Debian 11进行的网络抓取。

$ ecapture tls -w mailang.pcap --hex
tls_2023/03/08 11:59:56 ECAPTURE :: ecapture Version : linux_x86_64:0.4.12-20230210-43d79aa:5.15.0-1031-azure
tls_2023/03/08 11:59:56 ECAPTURE :: Pid Info : 2770140
tls_2023/03/08 11:59:56 ECAPTURE :: Kernel Info : 5.18.10
tls_2023/03/08 11:59:56 EBPFProbeOPENSSL        module initialization
tls_2023/03/08 11:59:56 EBPFProbeOPENSSL        Module.Run()
tls_2023/03/08 11:59:56 EBPFProbeOPENSSL        TC MODEL
tls_2023/03/08 11:59:56 EBPFProbeOPENSSL        origin version:OpenSSL 1.1.1k, as key:openssl 1.1.1k
tls_2023/03/08 11:59:56 EBPFProbeOPENSSL        HOOK type:2, binrayPath:/lib/x86_64-linux-gnu/libssl.so.1.1
tls_2023/03/08 11:59:56 EBPFProbeOPENSSL        Ifname:eth0, Ifindex:2,  Port:443, Pcapng filepath:/root/gt-remove-header.pcap
tls_2023/03/08 11:59:56 EBPFProbeOPENSSL        Hook masterKey function:SSL_write
tls_2023/03/08 11:59:56 EBPFProbeOPENSSL        target all process. 
tls_2023/03/08 11:59:56 EBPFProbeOPENSSL        target all users. 
tls_2023/03/08 11:59:56 EBPFProbeOPENSSL        BPF bytecode filename:user/bytecode/openssl_1_1_1j_kern.o
tls_2023/03/08 11:59:56 EBPFProbeOPENSSL        module started successfully.
tls_2023/03/08 11:59:56 EBPFProbeGNUTLS module initialization
tls_2023/03/08 11:59:56 EBPFProbeGNUTLS Module.Run()
tls_2023/03/08 11:59:56 EBPFProbeGNUTLS BPF bytecode filename:user/bytecode/gnutls_kern.o
tls_2023/03/08 11:59:56 EBPFProbeGNUTLS HOOK type:2, binrayPath:/lib/x86_64-linux-gnu/libgnutls.so.30
tls_2023/03/08 11:59:56 EBPFProbeGNUTLS target all process. 
tls_2023/03/08 11:59:56 EBPFProbeGNUTLS module started successfully.
tls_2023/03/08 11:59:56 EBPFProbeNSPR   module initialization failed. [skip it]. error:stat /lib/x86_64-linux-gnu/libnspr4.so: no such file or directory
tls_2023/03/08 11:59:56 EBPFProbeGoSSL  module [disabled].
tls_2023/03/08 11:59:56 ECAPTURE ::     start 2 modules

eCapture 会在抓取的过程中，把wireshark 需要的(pre)-Master-Secret log filename 文件自动保存为：ecapture_masterkey.log，我们在wireshark跟踪TLS流的时候，会用到此文件，如果不跟踪TLS流，可以不进行配置，因为eCapture已经解密了，但是跟踪TLS流的时候，还是加密状态。

我们在wireshark上面打开eCapture抓取的网络包，如图所示：

图6

可以看到13号网络包为：我们收到的502返回，其中Hypertext Transfer Protocol这里我们可以明确看到 server为elb，这就说明了502确实是ELB返回的，当然我们通过curl -I 也能看到类似的情况，我们这里是为了展示后续怎么在命令行客户端进行TLS抓包并进行解密。服务端的包跟之前的是一致的，这里就不做展示了。根据客户端和服务端抓取到的网络包，我们再次找到了华为云的工程师，面对铁一般的事实，华为云的工程师最终确定是ELB的问题。

5、最终解决

华为云的工程师通过我们的访问IP查找到了ELB上面的报错日志，报错如下所示：

图7

图片不是很清醒，我们这里把主要报错展示一下：upstream sent too big header while reading response header from upstream.通过这里的报错，我们可以很清楚的看出来是后端服务返回的header头太大了，超过了ELB的限制，导致ELB出现502错误。我们与华为云的工程师沟通后，确认华为云的ELB共享型的http header限制为8K，独享型的http header限制为64K，根据此情况，我们更换了ELB的规格到独享型，最终解决了此问题。

总结：

很多很奇怪的现象存在其必然性，我们在客户端收到了502，但是在服务端并没有找到502错误日志，但是在ELB上面看到了502错误日志显示的是后端服务返回的502错误，这里明显存在一个问题：要么后端没有记录502错误，要么ELB的日志存在问题。事实证明是ELB的日志存在问题。还有吐槽一下华为云的ELB，出现此问题他们的工程师第一个想的竟然是甩锅。而且ELB返回的错误太过于简单了，只是返回502，但是太多问题会导致502，如果ELB一开始就返回 too big header，我们也没必要折腾这么久去定位问题。