Open kokizzu opened 5 years ago
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)
}
$ 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.
$ 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?
$ 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
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.
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
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
)
What version of Go are you using (
go version
)?Does this issue reproduce with the latest release?
Yes
What operating system and processor architecture are you using (
go env
)?go env
OutputWhat 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