最近分析数据偶然发现nginx log中有一批用户所有的HTTP POST log上报请求均返回400,没有任何200成功记录,由于只占整体请求的不到0.5%,所以之前也一直没有触发监控报警,而且很奇怪的是只对于log上报的POST接口会存在这种特定用户全部400的情况,而对于其他接口无论POST还是GET均没有此类问题。
进一步分析log发现其实对某些地区的用户请求,这个比例甚至超过了10%,于是花时间跟进了一下,最终发现源于部分机型客户端发出的HTTP请求格式不规范导致,这里记录一下分析过程、原因以及最终解决方案。
搜寻网上资料,发现一般可能有以下几个原因会导致nginx响应400:
这些错误其实都是发生在nginx这一层,即nginx处理时认为客户端请求格式错误,于是直接返回400,不会向upstream server转发请求,因而upstream server对这些错误请求其实完全是无感知的。
而这次根据nginx log分析,可以看到nginx其实有向upstream server转发请求--upstream_addr已经是upstream server 有效地址,所以400实际应当是upstream server返回的,而不是nginx直接返回,这说明至少nginx这一层认为请求格式是没问题的。
截取部分线上部分用户的错误日志,其大体样式如下
127.0.0.1:63646 - 24/Apr/2022:00:50:07 +0900 127.0.0.1:1080 0.000 0.000 POST /log/report?appd=abc.demo.android&appname=abcdemo&v=1.0&langes=zh-CN&phonetype=android&device_type=android&osn=Android OS 10 / API-29 (QKQ1.190825.002/V12.0.6.0.QFKCNXM)&channel=Google Play&build=Android OS 10 / API-29 (QKQ1.190825.002/V12.0.6.0.QFKCNXM)&resolution=1080x2340&ts=1650636192534 HTTP/1.1 400 50 - curl/7.52.1 - 0.000 0.000 127.0.0.1 1563 2021
日志分析可以发现大部分400请求都有一个问题:其query参数并未经过urlencode,比如可以很明显看到其参数channel=Google Play 中的空格并未转码成%20,直觉上推断这应该和400的原因有直接关系。
为了验证未转码query参数是否是导致400的直接原因,简单通过curl构造几个测试http请求:
# 无空格 curl -v 'http://127.0.0.1/log/report?appd=abc.demo.android&appname=abcdemo&v=1.0&langes=zh-CN&phonetype=android&channel=Google%20Play' -d @test.json * Trying 127.0.0.1... * TCP_NODELAY set * Connected to 127.0.0.1 (127.0.0.1) port 80 (#0) > POST /log/report?appd=abc.demo.android&appname=abcdemo&v=1.0&langes=zh-CN&phonetype=android&channel=Google%20Play HTTP/1.1 > Host: 127.0.0.1 > User-Agent: curl/7.52.1 > Accept: */* > Content-Length: 1563 > Content-Type: application/x-www-form-urlencoded > Expect: 100-continue > < HTTP/1.1 100 Continue * We are completely uploaded and fine < HTTP/1.1 200 OK < Server: nginx/1.16.1 < Date: Sat, 23 Apr 2022 15:54:53 GMT < Content-Type: application/json < Content-Length: 22 < Connection: keep-alive < * Curl_http_done: called premature == 0 * Connection #0 to host 127.0.0.1 left intact # 有空格 curl -v 'http://127.0.0.1/log/report?appd=abc.demo.android&appname=abcdemo&v=1.0&langes=zh-CN&phonetype=android&channel=Google Play' -d @test.json * Trying 127.0.0.1... * TCP_NODELAY set * Connected to 127.0.0.1 (127.0.0.1) port 80 (#0) > POST /log/report?appd=abc.demo.android&appname=abcdemo&v=1.0&langes=zh-CN&phonetype=android&channel=Google Play HTTP/1.1 > Host: 127.0.0.1 > User-Agent: curl/7.52.1 > Accept: */* > Content-Length: 1563 > Content-Type: application/x-www-form-urlencoded > Expect: 100-continue > < HTTP/1.1 100 Continue * We are completely uploaded and fine < HTTP/1.1 400 Bad Request < Server: nginx/1.16.1 < Date: Sat, 23 Apr 2022 15:55:14 GMT < Content-Type: text/plain; charset=utf-8 < Transfer-Encoding: chunked < Connection: keep-alive < * Curl_http_done: called premature == 0 * Connection #0 to host 127.0.0.1 left intact
发现凡是带空格的请求upstream server均会直接返回400,这里可以推断query 参数未urlencode是400问题的直接原因了,但是为什么未转码会导致400呢?怎么从HTTP原理上解释这个现象?为了找到答案,需要回顾了一下HTTP协议标准。
HTTP的请求消息格式如下:
如上图所示,作为一种文本协议,对HTTP请求消息中不同部分的区别、拆分完全是基于空格 、回车符\r、换行符\n这些字符标记进行的,对于第一行的三个部分请求方法、URL和协议版本的拆分即是根据空格进行split。
分析查到的400 HTTP请求,可以发现由于query参数未urlencode,导致其中会出现空格,这时严格来说这个请求已经不符合HTTP规范了,因为此时第一行再根据空格可以split出超过3部分,无法与method、URL、version再一一对应,从语义上来说此时直接返回400是合理处理逻辑。
实际处理中,面对这种情况,有的组件能兼容处理--把split的首部和尾部分别作为method与version,而中间剩余部分统一作为URL,比如nginx即兼容了这种不规范格式,但是很多组件并不能兼容处理这种情况--毕竟这并不符合HTTP规范,比如charles抓包此种请求会出错、golang 的net/http库、Django的http模块收到这类请求都会报400...
负责日志上报的upstream server是golang实现的logsvc,其使用标准卡库net/http处理HTTP请求,进一步探究一下该标准库是怎么解析HTTP请求的,以确认错误原因。
根据golang源码,可以发现其HTTP请求解析的路径为 http.ListenAndServe => http.Serve => serve => readRequest.... 其解析HTTP请求头的逻辑即位于readRequest函数中。
readRequest部分代码如下:
// file: net/http/request.go ... 1009 func readRequest(b *bufio.Reader, deleteHostHeader bool) (req *Request, err error) { 1010 tp := newTextprotoReader(b) 1011 req = new(Request) 1012 1013 // First line: GET /index.html HTTP/1.0 1014 var s string 1015 if s, err = tp.ReadLine(); err != nil { 1016 return nil, err 1017 } 1018 defer func() { 1019 putTextprotoReader(tp) 1020 if err == io.EOF { 1021 err = io.ErrUnexpectedEOF 1022 } 1023 }() 1024 1025 var ok bool 1026 req.Method, req.RequestURI, req.Proto, ok = parseRequestLine(s) 1027 if !ok { 1028 return nil, &badStringError{"malformed HTTP request", s} 1029 } 1030 if !validMethod(req.Method) { 1031 return nil, &badStringError{"invalid method", req.Method} 1032 } 1033 rawurl := req.RequestURI 1034 if req.ProtoMajor, req.ProtoMinor, ok = ParseHTTPVersion(req.Proto); !ok { 1035 return nil, &badStringError{"malformed HTTP version", req.Proto} 1036 } ...
可以看到readRequest中先通过parseRequestLine解析出首行的method, URL与Proto三个字段,然后通过ParseHTTPVersion解析version是否正确,不正确则报错{"malformed HTTP version", 最终会导致响应400。
parseRequestLine代码如下:
... 966 // parseRequestLine parses "GET /foo HTTP/1.1" into its three parts. 967 func parseRequestLine(line string) (method, requestURI, proto string, ok bool) { 968 s1 := strings.Index(line, " ") 969 s2 := strings.Index(line[s1+1:], " ") 970 if s1 < 0 || s2 < 0 { 971 return 972 } 973 s2 += s1 + 1 974 return line[:s1], line[s1+1 : s2], line[s2+1:], true 975 }
可以看到parseRequestLine的解析代码是通过查找第0个、第1个空格index,然后直接基于slice语法将其切成了method、requestURI、proto三部分,如果requestURI中包含额外空格,会导致proto取值实际变为第一个空格之后的所有字符,比如"POST abc/?x=o space d HTTP/1.1"会被解析为:method=POST, requestURI=abc/?x=0, proto=" space d HTTP/1.1",这会导致下一步ParseHTTPVersion解析出错。
ParseHTTPVersion代码如下,可以发现之前parseRequestLine解析得到的version字段如果不合法,则会返回错误:
... 769 // ParseHTTPVersion parses an HTTP version string. 770 // "HTTP/1.0" returns (1, 0, true). 771 func ParseHTTPVersion(vers string) (major, minor int, ok bool) { 772 const Big = 1000000 // arbitrary upper bound 773 switch vers { 774 case "HTTP/1.1": 775 return 1, 1, true 776 case "HTTP/1.0": 777 return 1, 0, true 778 } 779 if !strings.HasPrefix(vers, "HTTP/") { 780 return 0, 0, false 781 } 782 dot := strings.Index(vers, ".") 783 if dot < 0 { 784 return 0, 0, false 785 } 786 major, err := strconv.Atoi(vers[5:dot]) 787 if err != nil || major < 0 || major > Big { 788 return 0, 0, false 789 } 790 minor, err = strconv.Atoi(vers[dot+1:]) 791 if err != nil || minor < 0 || minor > Big { 792 return 0, 0, false 793 } 794 return major, minor, true 795 }
首先要做的是先和客户端对齐问题,客户端确认部分机型上其调用unity的网络库方法未能对其query参数正常urlencode,新版本将在unity网络库之上增加额外代码保证所有参数必须urlencode,使其符合HTTP规范。
而后进一步考虑可否先临时兼容处理线上已有的异常请求,防止新版本覆盖修复前这部分异常用户log上报数据的持续丢失,针对兼容考虑了以下几个方案
由于日志服务由独立的golang server负责,其代码逻辑很简单:只是对log 的POST请求的body进行解压缩、解析、写入kafka,并无其他额外逻辑,改动成本较低,因此先考虑了替换net/http为其他三方库看是否能解决问题。
先后尝试了流行的gin和echo库发现都报400,忍不住又探究了其源码,结果发现这两个库内部其实都调用了net/http 的ListenAndServer 和 Serve方法,其前面的解析逻辑就是net/http对应代码负责的,因而自然也会报400。
想到的另一个可能方法是在nginx层使用lua/perl脚本对传入的未urlencode的request_uri参数进行urlencode后再发给upstream server,但是发现线上nginx编译时并未集成lua、perl的模块。要采用此种方法则只能:
考虑到本人作为RD而非专业nginx OP人员,和对线上影响的风险不轻易尝试。
开头提到过对于待空格的异常请求,只有log上报POST接口会返回400,其他接口都返回正常,这其实是因为在nginx转发时对正常的业务接口和log接口进行了拆分,log/report接口会单独转发到独立的golang logsvc服务,而正常业务请求均会转发给python的主api服务。
回顾当初之所以会拆分一个单独的golang server负责app log上报的解析和写kafka,而不再和其他接口逻辑一样都由主api服务负责,主要是两个原因:
当前logsvc无法处理的此种情况,使用uwsgi协议与nginx交互的api主服务却可以正常解析,因而在nginx添加如下临时配置:
location /log/report { include proxy_params; if ( $args !~ "^(.*) (.*)$" ) { proxy_pass http://test_log_stream; break; } include uwsgi_params; uwsgi_pass test_api_stream; }
即通过正则匹配query参数(args)中若不存在空格直接交由logsvc处理,存在空格则交由使用uwsgi协议的api主服务处理,由于此类异常请求仅占整体请求的不到0.5%,之前考虑的拆分架构依然work,只是对于少量的异常请求先通过api主服务进行兼容处理。
转载请注明出处,原文地址: https://www.cnblogs.com/AcAc-t/p/nginx_400_problem_for_not_encode_http_request.html
https://www.cnblogs.com/ranyonsue/p/5984001.html
https://www.920430.com/archives/4291504507.html
https://blog.csdn.net/iamlihongwei/article/details/103611655
https://dbaplus.cn/news-21-1129-1.html
https://blog.51cto.com/leejia/1434564
https://blog.csdn.net/kaosini/article/details/8433044