背景
最近分析数据偶然发现nginx log中有一批用户所有的HTTP POST log上报请求均返回400,没有任何200成功记录,由于只占整体请求的不到0.5%,所以之前也一直没有触发监控报警,而且很奇怪的是只对于log上报的POST接口会存在这种特定用户全部400的情况,而对于其他接口无论POST还是GET均没有此类问题。
进一步分析log发现其实对某些地区的用户请求,这个比例甚至超过了10%,于是花时间跟进了一下,最终发现源于部分机型客户端发出的HTTP请求格式不规范导致,这里记录一下分析过程、原因以及最终解决方案。
问题分析
常见nginx 400原因
搜寻网上资料,发现一般可能有以下几个原因会导致nginx响应400:
- request_uri 过长超过nginx配置大小
- cookie或者header过大超过nginx配置大小
- 空HOST头
- content_length和body长度不一致
这些错误其实都是发生在nginx这一层,即nginx处理时认为客户端请求格式错误,于是直接返回400,不会向upstream server转发请求,因而upstream server对这些错误请求其实完全是无感知的。
而这次根据nginx log分析,可以看到nginx其实有向upstream server转发请求–upstream_addr已经是upstream server 有效地址,所以400实际应当是upstream server返回的,而不是nginx直接返回,这说明至少nginx这一层认为请求格式是没问题的。
实际nginx 400 log分析
截取部分线上部分用户的错误日志,其大体样式如下
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
>
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
>
发现凡是带空格的请求upstream server均会直接返回400,这里可以推断query 参数未urlencode是400问题的直接原因了,但是为什么未转码会导致400呢?怎么从HTTP原理上解释这个现象?为了找到答案,需要回顾了一下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…
golang net/http解析HTTP代码分析
负责日志上报的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
可以看到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 Big {
788 return 0, 0, false
789 }
790 minor, err = strconv.Atoi(vers[dot+1:])
791 if err != nil || minor Big {
792 return 0, 0, false
793 }
794 return major, minor, true
795 }
解决方案
首先要做的是先和客户端对齐问题,客户端确认部分机型上其调用unity的网络库方法未能对其query参数正常urlencode,新版本将在unity网络库之上增加额外代码保证所有参数必须urlencode,使其符合HTTP规范。
而后进一步考虑可否先临时兼容处理线上已有的异常请求,防止新版本覆盖修复前这部分异常用户log上报数据的持续丢失,针对兼容考虑了以下几个方案
尝试三方HTTP golang库 gin && echo
由于日志服务由独立的golang server负责,其代码逻辑很简单:只是对log 的POST请求的body进行解压缩、解析、写入kafka,并无其他额外逻辑,改动成本较低,因此先考虑了替换net/http为其他三方库看是否能解决问题。
先后尝试了流行的gin和echo库发现都报400,忍不住又探究了其源码,结果发现这两个库内部其实都调用了net/http 的ListenAndServer 和 Serve方法,其前面的解析逻辑就是net/http对应代码负责的,因而自然也会报400。
nginx lua/perl脚本更改query参数
想到的另一个可能方法是在nginx层使用lua/perl脚本对传入的未urlencode的request_uri参数进行urlencode后再发给upstream server,但是发现线上nginx编译时并未集成lua、perl的模块。要采用此种方法则只能:
- 要么重新编译整个nginx替换原nginx
- 或者采用动态加载的方式单独编译perl、lua模块后使用nginx动态加载
考虑到本人作为RD而非专业nginx OP人员,和对线上影响的风险不轻易尝试。
nginx 将log/report路由至可兼容空格未转码HTTP请求的server
开头提到过对于待空格的异常请求,只有log上报POST接口会返回400,其他接口都返回正常,这其实是因为在nginx转发时对正常的业务接口和log接口进行了拆分,log/report接口会单独转发到独立的golang logsvc服务,而正常业务请求均会转发给python的主api服务。
回顾当初之所以会拆分一个单独的golang server负责app log上报的解析和写kafka,而不再和其他接口逻辑一样都由主api服务负责,主要是两个原因:
- Pythono写的api主服务相对效率较低,对于频繁、大量的log上报可能耗费过多资源,速度也较慢
- 避免log上报类请求影响其他正常的业务请求响应速度,将业务逻辑与日志上报两者解耦
当前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