golang低版本http2偶现400

祈雨的笔记

2020-08-01

other

描述

项目组在对某个Golang应用进行压测时，在请求TPS较高的时间段，偶现发起HTTP请求外部系统错误，被请求的外部系统为Nginx代理的另一个Golang应用。

查看Nginx日志时发现，Golang客户端请求报错时，Nginx日志显示该报错请求被返回400状态码，如下所示：

将Nginx日志中压测期间所有返回400状态码的日志过滤出来，可见该错误稳定每几秒复现一两次，如下所示：

问题定位

起初认为是外部系统应用因为压测压力过大导致拒绝访问错误而返回的400状态码，但是经排查发现被调用的外部系统并没有明显的错误日志，且HTTP Server队列也并没有达到上限。

然后排查是否是Linux系统端口不足或者TCP的半连接和全连接队列溢出导致拒绝连接，但实际上查看监控发现由于Nginx代理到外部系统应用之间使用的HTTP长连接，在压测期间外部系统应用所在服务器的TCP连接数量并没的太大的起伏，且通过ss -lnt命令也发现该服务器的TCP全连接队列远远没有到溢出门槛。

在摸不到头脑的情况下，才注意到Nginx返回400错误码时，日志显示该请求并未转发到后台，也就是说偶现的请求错误是请求被Nginx拒绝后返回了400错误码。

查看Nginx的error日志，没有发现任何有用的信息，于是下调error日志的输出级别。Nginx的error日志的错误日志级别有debug、info、notice、warn、error、crit、alert、emerg。公司当前使用的错误输出级别为error，于是暂时修改成notice后监控错误日志，依然没有输出任何有用的信息。

再进一步调整错误输出级别为info，终于在每次出现400错误时，对应的error日志同时会输出如下日志。

1	client prematurely closed stream: only 0 out of 224 bytes of request body received, client: 106.x.x.x, server: xxx.com, request: "POST /api/v1/gateway HTTP/2.0", host: "xxx.com"

非常眼生的错误，字面意思似乎是长度应当224字节的请求，实际body为空。去找Google搜了一波，还真找到了一波一样的错误和场景：https://github.com/golang/go/issues/25009。

该错误实际上是被压测的Golang应用使用的官方库的bug导致，在客户端使用HTTP/2时多线程高并发发起请求，会偶现请求body丢失，被Nginx检查Content-Length长度不符而响应400 Bad Request。

复现

import (
	"bytes"
	"net/http"
	"sync"
	"fmt"
	"time"
)

func main() {
	link := "https://host/path"
	content := []byte(`{"body": 1}`)

	client := &http.Client{
		Timeout: time.Second * 60
	}

	var wg sync.WaitGroup
	for i := 0; i < 100; i++ {
		wg.Add(1)
		go func() {
			defer wg.Done()
			for ; ; {
				req, _ := http.NewRequest("POST", link, bytes.NewReader(content))
				req.Header.Add("Content-Type", "application/json")

				res, err := client.Do(req)
				if err != nil {
					fmt.Println(err)
					continue
				}
				fmt.Println(res)
			}
		}()
	}
	wg.Wait()
}

2020-07-30T11:33:52+08:00 220.x.x.x POST /path HTTP/2.0 x.com 200 0.072 1584 1492 127.0.0.1:8888 200 0.066 "Go-http-client/2.0"
2020-07-30T11:33:52+08:00 220.x.x.x POST /path HTTP/2.0 x.com 400 0.000 241 173 - - - "Go-http-client/2.0"
2020-07-30T11:33:52+08:00 220.x.x.x POST /path HTTP/2.0 x.com 400 0.000 241 173 - - - "Go-http-client/2.0"
2020-07-30T11:33:52+08:00 220.x.x.x POST /path HTTP/2.0 x.com 200 0.072 1584 1492 127.0.0.1:8888 200 0.066 "Go-http-client/2.0"
2020-07-30T11:33:52+08:00 220.x.x.x POST /path HTTP/2.0 x.com 200 0.079 1584 1492 127.0.0.1:8888 200 0.079 "Go-http-client/2.0"
2020-07-30T11:33:52+08:00 220.x.x.x POST /path HTTP/2.0 x.com 200 0.023 1584 1492 127.0.0.1:8888 200 0.023 "Go-http-client/2.0"
2020-07-30T11:33:52+08:00 220.x.x.x POST /path HTTP/2.0 x.com 200 0.029 1584 1492 127.0.0.1:8888 200 0.029 "Go-http-client/2.0"

解决

1. 禁用HTTP/2

import (
	"bytes"
	"net/http"
	"sync"
	"fmt"
	"time"
	"crypto/tls"
)

func main() {
	link := "https://host/path"
	content := []byte(`{"body": 1}`)

	client := &http.Client{
		Timeout: time.Second * 60,
		Transport: &http.Transport{
			TLSNextProto: make(map[string]func(authority string, c *tls.Conn) http.RoundTripper),
		},
	}

	var wg sync.WaitGroup
	for i := 0; i < 100; i++ {
		wg.Add(1)
		go func() {
			defer wg.Done()
			for ; ; {
				req, _ := http.NewRequest("POST", link, bytes.NewReader(content))
				req.Header.Add("Content-Type", "application/json")

				res, err := client.Do(req)
				if err != nil {
					fmt.Println(err)
					continue
				}
				fmt.Println(res)
			}
		}()
	}
	wg.Wait()
}

2. 升级Golang版本到1.14

该bug于go1.14修复https://golang.org/cl/242117。