Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

x/net/http2: handle the case of more content received than was declared by server in content-length headers #32728

Open
kokizzu opened this issue Jun 21, 2019 · 3 comments

Comments

Projects
None yet
3 participants
@kokizzu
Copy link

commented Jun 21, 2019

What version of Go are you using (go version)?

$ go version
1.12

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output
$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/asd/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/asd/MEGA/go"
GOPROXY=""
GORACE=""
GOROOT="/usr/lib/go"
GOTMPDIR=""
GOTOOLDIR="/usr/lib/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build964683646=/tmp/go-build -gno-record-gcc-switches"

What did you do?

running this code:
https://gist.github.com/anysz/e32dfd5bd501da3836ee4960f2620f68

What did you expect to see?

data decoded correctly like in http/1.0 version

What did you see instead?

panic: net/http: server replied with more than declared Content-Length; truncated

workaround:
GODEBUG=http2client=0 go run works fine

@odeke-em

This comment has been minimized.

Copy link
Member

commented Jun 22, 2019

Thank you for reporting this bug @kokizzu!

So here is an isolation for your reproduction for anyone to easily debug it https://play.golang.org/p/_0dQKCF-CMm or inlined below

package main

import (
	"bytes"
	"crypto/md5"
	"io"
	"log"
	"net/http"
	"net/http/httputil"
	"os"
)

func main() {
	log.SetFlags(0)
	body := bytes.NewReader([]byte{106, 204, 139, 83, 126, 106, 65, 96, 38, 202, 93, 211, 200, 152, 32, 20, 244, 204, 205, 230, 148, 131, 53, 220, 206, 144, 100, 11, 173, 82, 161, 230, 225, 166, 91, 215, 34, 78, 211, 88, 149, 111, 42, 6, 176, 239, 98, 100, 77, 158, 167, 94, 114, 197, 173, 160, 21, 2, 152, 212, 186, 134, 35, 166, 20, 95, 128, 59, 230, 149, 82, 59, 234, 80, 0, 241, 165, 53, 90, 231, 34, 163, 145, 90, 175, 184, 201, 133, 21, 138, 158, 73, 244, 181, 48, 49, 20, 237, 54, 122, 159, 94, 5, 62, 239, 221, 100, 234, 110, 106, 250, 188, 80, 209, 119, 255, 68, 227, 207, 17, 84, 13, 210, 1, 37, 67, 2, 13, 65, 1, 44, 155, 218, 247, 157, 190, 168, 111, 89, 182, 40, 105, 189, 90, 193, 67, 251, 218})
	req, err := http.NewRequest("POST", "https://gfs.line.naver.jp/enc", body)
	if err != nil {
		log.Fatalf("Failed to compose request: %v", err)
	}
	req.Header = map[string][]string{
		"content-type":       {"application/x-thrift"},
		"accept":             {"application/x-thrift; charset=latin1"},
		"User-Agent":         {"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.86 Safari/537.36"},
		"x-line-application": {"ANDROIDLITE\t8.2.4\tAndroid\tOS\t6.0"},
		"x-le":               {"18"},
		"x-lst":              {"1000"},
		"x-lal":              {"en"},
		"x-lcs":              {"0005fF9u99g+fCJaX0CiyHrj+/nhwDV2k72si+qxjA9ZNcR/zlgE4W1i1DQL3/zhNBC4UDFlwGz5K+TN9iB0L3AhBJ8+FA9OrY9P/4CHtkrqvJmubO37mXmlXnNCyYk2vbb864it3sxbcl5B1HahIh9SkfHgZUvKek6hcobn/c3+GG033xuYvjBt/DzgfrkPcj4Gu3SFxKSGppTobvtkT/YZocTz+U9Hm0DalRsQr1DadjreZgUdSBlAv2DLd59SqEbsx8fIXIvkHZ8s/84ujTEIeA6t9mv2YA0GFobqejP0PSlNvlW5rN+EN/XVdfbF9YKyNxJIzjjFkPpy/F/1D3T13A=="},
		"x-lhm":              {"POST"},
	}
	reqDump, _ := httputil.DumpRequest(req, false)
	log.Printf("Request dump:\n%s\n\n", reqDump)

	res, err := http.DefaultClient.Do(req)
	if err != nil {
		log.Fatalf("Failed to make request: %v\n", err)
	}
        resDump, _ := httputil.DumpResponse(res, false)
	log.Printf("Response dump:\n%s\n\n", resDump)
	h := md5.New()
	tr := io.TeeReader(res.Body, h)
	n, err := io.Copy(os.Stdout, tr)
	_ = res.Body.Close()
	log.Printf("\n\nMd5Checksum: %x", h.Sum(nil))

	log.Printf("\n\033[32mBytes read: %d err: %v\033[00m\n", n, err)
}

In HTTP/1.1 mode GODEBUG=http2client=0

$ GODEBUG=http2client=0 go run main.go 
Request dump:
POST /enc HTTP/1.1
Host: gfs.line.naver.jp
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.86 Safari/537.36
accept: application/x-thrift; charset=latin1
content-type: application/x-thrift
x-lal: en
x-lcs: 0005fF9u99g+fCJaX0CiyHrj+/nhwDV2k72si+qxjA9ZNcR/zlgE4W1i1DQL3/zhNBC4UDFlwGz5K+TN9iB0L3AhBJ8+FA9OrY9P/4CHtkrqvJmubO37mXmlXnNCyYk2vbb864it3sxbcl5B1HahIh9SkfHgZUvKek6hcobn/c3+GG033xuYvjBt/DzgfrkPcj4Gu3SFxKSGppTobvtkT/YZocTz+U9Hm0DalRsQr1DadjreZgUdSBlAv2DLd59SqEbsx8fIXIvkHZ8s/84ujTEIeA6t9mv2YA0GFobqejP0PSlNvlW5rN+EN/XVdfbF9YKyNxJIzjjFkPpy/F/1D3T13A==
x-le: 18
x-lhm: POST
x-line-application: ANDROIDLITE	8.2.4	Android	OS	6.0
x-lst: 1000



Response dump:
HTTP/1.1 200 OK
Content-Length: 100
Content-Type: application/x-thrift;charset=UTF-8
Server: legy
X-Lcr: 290
X-Le: 18
X-Line-Http: P,LP,HC
X-Ls: 2wqUHWVL1DfLlp+0cu+76A



?U?ۧ
   !??@(&Wj??{?/??T??j	s??H9?????7?r`???:
                                          6s??3?S?7??*?[#???ꪲp(>g??Sw?E?6'[??Þ?

Md5Checksum: d294b73d4742b3208fb4735739d25771

Bytes read: 100 err: <nil>

100 bytes were declared upfront in the content-length and thus read completely so the result is all good.

In HTTP/2 mode GODEBUG=http2client=1

$ GODEBUG=http2client=1 go run main.go 
Request dump:
POST /enc HTTP/1.1
Host: gfs.line.naver.jp
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.86 Safari/537.36
accept: application/x-thrift; charset=latin1
content-type: application/x-thrift
x-lal: en
x-lcs: 0005fF9u99g+fCJaX0CiyHrj+/nhwDV2k72si+qxjA9ZNcR/zlgE4W1i1DQL3/zhNBC4UDFlwGz5K+TN9iB0L3AhBJ8+FA9OrY9P/4CHtkrqvJmubO37mXmlXnNCyYk2vbb864it3sxbcl5B1HahIh9SkfHgZUvKek6hcobn/c3+GG033xuYvjBt/DzgfrkPcj4Gu3SFxKSGppTobvtkT/YZocTz+U9Hm0DalRsQr1DadjreZgUdSBlAv2DLd59SqEbsx8fIXIvkHZ8s/84ujTEIeA6t9mv2YA0GFobqejP0PSlNvlW5rN+EN/XVdfbF9YKyNxJIzjjFkPpy/F/1D3T13A==
x-le: 18
x-lhm: POST
x-line-application: ANDROIDLITE	8.2.4	Android	OS	6.0
x-lst: 1000



Response dump:
HTTP/2.0 200 OK
Content-Length: 89
Content-Type: application/x-thrift;charset=UTF-8
Server: legy
X-Lcr: 290
X-Le: 18



remaining bytes  89
?U?ۧ
   !??@(&Wj??{?/??T??j	s??H9?????7?r`???:
                                          6s??3?S?7??*?[#???ꪲp(>g??Sw?E?

Md5Checksum: da3411328580730f7b5d535f5b1f81d6

Bytes read: 89 err: net/http: server replied with more than declared Content-Length; truncated

Notice that the server deliberately sent back 89 bytes yet somehow the server wants to send back more?

HTTP/2 mode but with debugging on

$ GODEBUG=http2debug=2 go run main.go 
Request dump:
POST /enc HTTP/1.1
Host: gfs.line.naver.jp
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.86 Safari/537.36
accept: application/x-thrift; charset=latin1
content-type: application/x-thrift
x-lal: en
x-lcs: 0005fF9u99g+fCJaX0CiyHrj+/nhwDV2k72si+qxjA9ZNcR/zlgE4W1i1DQL3/zhNBC4UDFlwGz5K+TN9iB0L3AhBJ8+FA9OrY9P/4CHtkrqvJmubO37mXmlXnNCyYk2vbb864it3sxbcl5B1HahIh9SkfHgZUvKek6hcobn/c3+GG033xuYvjBt/DzgfrkPcj4Gu3SFxKSGppTobvtkT/YZocTz+U9Hm0DalRsQr1DadjreZgUdSBlAv2DLd59SqEbsx8fIXIvkHZ8s/84ujTEIeA6t9mv2YA0GFobqejP0PSlNvlW5rN+EN/XVdfbF9YKyNxJIzjjFkPpy/F/1D3T13A==
x-le: 18
x-lhm: POST
x-line-application: ANDROIDLITE	8.2.4	Android	OS	6.0
x-lst: 1000



http2: Transport failed to get client conn for gfs.line.naver.jp:443: http2: no cached connection was available
http2: Transport creating client conn 0xc000080600 to 203.104.174.12:443
http2: Framer 0xc000174000: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
http2: Framer 0xc000174000: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
http2: Transport encoding header ":authority" = "gfs.line.naver.jp"
http2: Framer 0xc000174000: read SETTINGS len=6, settings: MAX_CONCURRENT_STREAMS=20
http2: Transport received SETTINGS len=6, settings: MAX_CONCURRENT_STREAMS=20
http2: Transport encoding header ":method" = "POST"
http2: Transport encoding header ":path" = "/enc"
http2: Transport encoding header ":scheme" = "https"
http2: Transport encoding header "x-lst" = "1000"
http2: Transport encoding header "x-line-application" = "ANDROIDLITE\t8.2.4\tAndroid\tOS\t6.0"
http2: Transport encoding header "accept" = "application/x-thrift; charset=latin1"
http2: Transport encoding header "user-agent" = "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.86 Safari/537.36"
http2: Transport encoding header "x-le" = "18"
http2: Transport encoding header "x-lal" = "en"
http2: Transport encoding header "x-lcs" = "0005fF9u99g+fCJaX0CiyHrj+/nhwDV2k72si+qxjA9ZNcR/zlgE4W1i1DQL3/zhNBC4UDFlwGz5K+TN9iB0L3AhBJ8+FA9OrY9P/4CHtkrqvJmubO37mXmlXnNCyYk2vbb864it3sxbcl5B1HahIh9SkfHgZUvKek6hcobn/c3+GG033xuYvjBt/DzgfrkPcj4Gu3SFxKSGppTobvtkT/YZocTz+U9Hm0DalRsQr1DadjreZgUdSBlAv2DLd59SqEbsx8fIXIvkHZ8s/84ujTEIeA6t9mv2YA0GFobqejP0PSlNvlW5rN+EN/XVdfbF9YKyNxJIzjjFkPpy/F/1D3T13A=="
http2: Transport encoding header "x-lhm" = "POST"
http2: Transport encoding header "content-type" = "application/x-thrift"
http2: Transport encoding header "content-length" = "148"
http2: Transport encoding header "accept-encoding" = "gzip"
http2: Framer 0xc000174000: wrote HEADERS flags=END_HEADERS stream=1 len=541
http2: Framer 0xc000174000: wrote SETTINGS flags=ACK len=0
http2: Framer 0xc000174000: wrote DATA stream=1 len=148 data="j̋S~jA`&\xca]\xd3Ș \x14\xf4\xcc\xcd攃5\xdcΐd\v\xadR\xa1\xe6\xe1\xa6[\xd7\"N\xd3X\x95o*\x06\xb0\xefbdM\x9e\xa7^rŭ\xa0\x15\x02\x98Ժ\x86#\xa6\x14_\x80;\xe6\x95R;\xeaP\x00\xf1\xa55Z\xe7\"\xa3\x91Z\xaf\xb8Ʌ\x15\x8a\x9eI\xf4\xb501\x14\xed6z\x9f^\x05>\xef\xddd\xeanj\xfa\xbcP\xd1w\xffD\xe3\xcf\x11T\r\xd2\x01%C\x02\rA\x01,\x9b\xda\xf7\x9d\xbe\xa8oY\xb6(i\xbdZ\xc1C\xfb\xda"
http2: Framer 0xc000174000: wrote DATA flags=END_STREAM stream=1 len=0 data=""
http2: Framer 0xc000174000: read SETTINGS flags=ACK len=0
http2: Transport received SETTINGS flags=ACK len=0
http2: Framer 0xc000174000: read HEADERS flags=END_HEADERS stream=1 len=55
http2: decoded hpack field header field ":status" = "200"
http2: decoded hpack field header field "x-le" = "18"
http2: decoded hpack field header field "server" = "legy"
http2: decoded hpack field header field "x-lcr" = "290"
http2: decoded hpack field header field "content-length" = "89"
http2: decoded hpack field header field "content-type" = "application/x-thrift;charset=UTF-8"
http2: Transport received HEADERS flags=END_HEADERS stream=1 len=55
http2: Framer 0xc000174000: read DATA flags=END_STREAM stream=1 len=100 data="\x01\x8aU\u007f\xe5\x85ۧ\v!\xec\xf3@(&W\x15j\x8a\x85{\xf8/\x03\x8e\xf1\xb9\xb5T\xe0\xd2j\ts\xfb\x86H9\xc9\xc1\xb5\x94\x827\xc3r`\xe1\xb6\xdb\xc7\x12:\v6s\x98\xec3\x84S\x14\xc27\xf7\xa8*\xe2\xb9[#\xe0\x9b\xe2ꪲp(>g\xe4\xae\xdeSw\xf8E\xbe6'[\xe9\x8c\xef\xa0Þ\xd3\x00"
http2: Transport received DATA flags=END_STREAM stream=1 len=100 data="\x01\x8aU\u007f\xe5\x85ۧ\v!\xec\xf3@(&W\x15j\x8a\x85{\xf8/\x03\x8e\xf1\xb9\xb5T\xe0\xd2j\ts\xfb\x86H9\xc9\xc1\xb5\x94\x827\xc3r`\xe1\xb6\xdb\xc7\x12:\v6s\x98\xec3\x84S\x14\xc27\xf7\xa8*\xe2\xb9[#\xe0\x9b\xe2ꪲp(>g\xe4\xae\xdeSw\xf8E\xbe6'[\xe9\x8c\xef\xa0Þ\xd3\x00"
Response dump:
HTTP/2.0 200 OK
Content-Length: 89
Content-Type: application/x-thrift;charset=UTF-8
Server: legy
X-Lcr: 290
X-Le: 18



http2: Framer 0xc000174000: wrote RST_STREAM stream=1 len=4 ErrCode=PROTOCOL_ERROR
?U?ۧ
   !??@(&Wj??{?/??T??j	s??H9?????7?r`???:
                                          6s??3?S?7??*?[#???ꪲp(>g??Sw?E?

Md5Checksum: da3411328580730f7b5d535f5b1f81d6

Bytes read: 89 err: net/http: server replied with more than declared Content-Length; truncated

and as you see on the last debug line, it sends back 100 bytes yet declared that it would send over 89 bytes

http2: Transport received DATA flags=END_STREAM stream=1 len=100 

With curl

Running this with curl gives a protocol error and an Unexpected EOF

$ curl -v -i -H "content-type":"application/x-thrift" -H "accept":"application/x-thrift; charset=latin1" -H "User-Agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.86 Safari/537.36" -H "x-line-application":"ANDROIDLITE\t8.2.4\tAndroid\tOS\t6.0" -H "x-le":"18" -H "x-lst":"1000" -H "x-lal":"en" -H "x-lhm":"POST" -H "x-lcs":"0005fF9u99g+fCJaX0CiyHrj+/nhwDV2k72si+qxjA9ZNcR/zlgE4W1i1DQL3/zhNBC4UDFlwGz5K+TN9iB0L3AhBJ8+FA9OrY9P/4CHtkrqvJmubO37mXmlXnNCyYk2vbb864it3sxbcl5B1HahIh9SkfHgZUvKek6hcobn/c3+GG033xuYvjBt/DzgfrkPcj4Gu3SFxKSGppTobvtkT/YZocTz+U9Hm0DalRsQr1DadjreZgUdSBlAv2DLd59SqEbsx8fIXIvkHZ8s/84ujTEIeA6t9mv2YA0GFobqejP0PSlNvlW5rN+EN/XVdfbF9YKyNxJIzjjFkPpy/F/1D3T13A==" -F 'data=@./source_bytes' "https://gfs.line.naver.jp/enc"
*   Trying 203.104.174.19...
* TCP_NODELAY set
* Connected to gfs.line.naver.jp (203.104.174.19) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/cert.pem
  CApath: none
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Client hello (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS change cipher, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=JP; ST=Tokyo; L=Shinjuku-ku; O=LINE Corporation; OU=System Operation Team; CN=*.line.naver.jp
*  start date: Jul 20 00:00:00 2018 GMT
*  expire date: Feb 14 12:00:00 2020 GMT
*  subjectAltName: host "gfs.line.naver.jp" matched cert's "*.line.naver.jp"
*  issuer: C=US; O=DigiCert Inc; OU=www.digicert.com; CN=GeoTrust RSA CA 2018
*  SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x7ffec7800400)
> POST /enc HTTP/2
> Host: gfs.line.naver.jp
> accept:application/x-thrift; charset=latin1
> User-Agent:Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.86 Safari/537.36
> x-line-application:ANDROIDLITE\t8.2.4\tAndroid\tOS\t6.0
> x-le:18
> x-lst:1000
> x-lal:en
> x-lhm:POST
> x-lcs:0005fF9u99g+fCJaX0CiyHrj+/nhwDV2k72si+qxjA9ZNcR/zlgE4W1i1DQL3/zhNBC4UDFlwGz5K+TN9iB0L3AhBJ8+FA9OrY9P/4CHtkrqvJmubO37mXmlXnNCyYk2vbb864it3sxbcl5B1HahIh9SkfHgZUvKek6hcobn/c3+GG033xuYvjBt/DzgfrkPcj4Gu3SFxKSGppTobvtkT/YZocTz+U9Hm0DalRsQr1DadjreZgUdSBlAv2DLd59SqEbsx8fIXIvkHZ8s/84ujTEIeA6t9mv2YA0GFobqejP0PSlNvlW5rN+EN/XVdfbF9YKyNxJIzjjFkPpy/F/1D3T13A==
> Content-Length: 352
> content-type:application/x-thrift; boundary=------------------------cc4c59d9aa654d43
> 
* Connection state changed (MAX_CONCURRENT_STREAMS updated)!
* TLSv1.2 (IN), TLS alert, Client hello (1):
* Unexpected EOF
* Closing connection 0
* TLSv1.2 (OUT), TLS alert, Client hello (1):
curl: (56) Unexpected EOF

That server seems to be misbehaving, declaring a content-length of 89 but sending 100 bytes when using HTTP/2.

I'll also kindly page some http2 experts @rs @tombergan and Brad but he is currently on leave.

@odeke-em odeke-em changed the title x/net/http2: server replied with more than declared Content-Length; truncated x/net/http2: handle the case of more content received than was declared by server in content-length headers Jun 22, 2019

@win-t

This comment has been minimized.

Copy link

commented Jun 23, 2019

IMHO, golang already implement http2 correctly,

from RFC7540 - 8.1.2.6. Malformed Requests and Responses:

A request or response is also malformed if the value of a content-length header field does not equal the sum of the DATA frame payload lengths that form the body

and it already return error net/http: server replied with more than declared Content-Length; truncated

@win-t

This comment has been minimized.

Copy link

commented Jun 23, 2019

one possible solution,
instead of truncate the data, make the next read to res.Body to still read the remainder data, but still, return the same error (net/http: server replied with more than declared Content-Length)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.