前言
最近公司项目做安全漏洞审查，把一批服务的fastjson,tomcat,log4j版本做升级，那天上线了50+个服务，所有服务上线之后，现网有客服反馈录音笔下单异常。查询了现网日志，发现适配服务有异常信息，报错信息如下
Caused by: feign.FeignException: status 400 reading TestServiceClient#calculateDuration(String); content:
<!doctype html><html lang="en"><head><title>HTTP Status 400 – Bad Request</title><style type="text/css">body {font-family:Tahoma,Arial,sans-serif;} h1, h2, h3, b {color:white;background-color:#525D76;} h1 {font-size:22px;} h2 {font-size:16px;} h3 {font-size:14px;} p {font-size:12px;} a {color:black;} .line {height:1px;background-color:#525D76;border:none;}</style></head><body><h1>HTTP Status 400 – Bad Request</h1></body></html>
at feign.FeignException.errorStatus(FeignException.java:62)
at feign.codec.ErrorDecoder$Default.decode(ErrorDecoder.java:91)熟悉Http协议的应该都知道，400响应状态是客户端请求不合法导致服务端无法解析请求。下面再看看当时的排查过程。
排查过程
上面说到适配服务的异常日志，我们知道是客户端的请求问题，由于适配服务此次上线内容不涉及具体业务需求，所以通知运维把现网的客户端适配服务做了紧急回滚，适配服务所有节点都回滚完成之后，发现老版本的适配服务还是报错。说明问题不是上层适配服务导致的，所以我们开始排查订单业务。问题是在kibana上根据traceId来进行链路排查，只能看到适配服务的报错信息，下面的订单服务的请求信息看不到。当时现网越来越多用户反馈了，没得办法，只能把订单服务也回滚了，订单服务回滚完成之后现网的报错日志没了.....
后来在集成环境部署了现网的版本，然后在本地IDEA中远程调试，在录音笔上下单，结果连音频都上传不上去，后来排查了集成环境音频上传服务的版本是第二天要上线的版本，也是做了一些漏洞修复的问题，所以把集成环境音频上传服务版本回滚到现网一致。再去复现现网的版本，在订单服务日志中，果然发现了蛛丝马迹
Error parsing HTTP request header
Note: further occurrences of HTTP request parsing errors will be logged at DEBUG level.
java.lang.IllegalArgumentException: The HTTP header line [x-device-info:{"content":""0x00.","createTime":1562298084000,"deviceId":"12132123213213","deviceType":"ashkdahdksahkd","key":"232hahkdkadhksadhkad"}] does not conform to RFC 7230. The request has been rejected.
at org.apache.coyote.http11.Http11InputBuffer.skipLine(Http11InputBuffer.java:1074)
at org.apache.coyote.http11.Http11InputBuffer.parseHeader(Http11InputBuffer.java:977)
at org.apache.coyote.http11.Http11InputBuffer.parseHeaders(Http11InputBuffer.java:606)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:514)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:932)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1695)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)原来适配服务的请求，在到底订单服务的时候，被订单服务的tomcat服务reject了，所以请求根本就没有尽到订单服务里面，所以也就解释了在kibana上根据traceId查询链路日志，没有订单服务的请求信息。看到上面的异常信息，我们跟到tomcat的源码中来看看具体是啥问题，导致tomcat拒绝了这个请求。报错的位置如下
看到这里，我们再去看看rejectThisHeader是在什么时候设置为true的
注意看这个注释// Malformed content-length headers must always be rejected，不合法的content-length请求头会被拒绝。看到这里，准备去看看请求的content-length哪里不合法，结果神奇的发现，请求头里居然没有content-length属性。这个请求是post请求，但是没有body数据，如果没有请求体数据，则请求头中不会包含Content-Length属性。 Content-Length属性主要用于指示请求体数据的长度，如果没有请求体数据，则该属性会被省略。所以故障的最终原因算是找到了。那之前为啥没问题呢，后来看了服务的提交记录，发现同事这次漏洞修复不仅升级jackson，还升级了tomcat版本。
总结
通过这件事，总结如下
- 遇到现网问题不要慌，冷静思考问题本质，不要仅关注业务日志，业务日志排查没有头绪，tomcat和Nginx的access.log也是很有用的，还有网关日志，根据这些日志排查请求具体在什么位置中断了。
- 这次上线的一批服务都是做一些安全漏洞修复，没有业务需求，所以测试在功能验证中可能有遗漏，导致了这次现网故障，所以还是得谨慎点。