search

golang / go

The Go programming language
https://go.dev
BSD 3-Clause "New" or "Revised" License
122.86k stars 17.52k forks source link

x/net/http2/h2c: h2c server hangs on empty r.Body read and fails on writes + hangs for POSTs #52882

Closed ldemailly closed 2 years ago

ldemailly commented 2 years ago

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

$ go version
go version go1.18.2 darwin/arm64

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="arm64"
GOVERSION="go1.18.2"
GOHOSTARCH="arm64"
GOHOSTOS="darwin"

What did you do?

h2c server - with code to read request body:

https://go.dev/play/p/yaKhF5u4ut6

package main

import (
    "crypto/tls"
    "fmt"
    "io"
    "log"
    "net"
    "net/http"
    "net/url"

    "golang.org/x/net/http2"
    "golang.org/x/net/http2/h2c"
)

func server() {
    h2s := &http2.Server{}

    handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        fmt.Printf("Got %v %v request from %v\n", r.Method, r.Proto, r.RemoteAddr)
        body, err := io.ReadAll(r.Body)
        if err != nil {
            log.Fatalf("server body read err: %v\n", err)
        }
        fmt.Printf("read %d from body\n", len(body))
        w.WriteHeader(http.StatusAccepted)
        fmt.Fprintf(w, "Hello, %v; HTTP Version: %v\n\nbody:\n%s\n", r.URL.Path, r.Proto, string(body))
    })

    server := &http.Server{
        Addr:    ":8001",
        Handler: h2c.NewHandler(handler, h2s),
    }
    fmt.Printf("H2c Server starting on %s\n", server.Addr)
    err := server.ListenAndServe()
    if err != nil {
        panic(err)
    }
}

func main() {
    server()
}

What did you expect to see?

$ curl -d bar --http2 localhost:8001/foo
Hello, /foo; HTTP Version: HTTP/2.0

body:
bar

to succeed - it hangs

note that --http2-prior-knowledge or --http1.1 works fine

What did you see instead?

hang on curl side, server side:

H2c Server starting on :8001
Got POST HTTP/1.1 request from 127.0.0.1:57205
read 3 from body
2022/05/12 17:15:13 http: response.WriteHeader on hijacked connection from main.server.func1 (h2-bug.go:51)
2022/05/12 17:29:16 http: response.Write on hijacked connection from fmt.Fprintf (print.go:205)

If not doing a POST (ie without a body) the ReadAll hangs (that I could workaround by checking the method, even though it probably shouldn't hang)

ldemailly commented 2 years ago

Forgot to mention that this is with

curl 7.83.0 (aarch64-apple-darwin21.3.0) libcurl/7.83.0 (SecureTransport) OpenSSL/1.1.1o zlib/1.2.11 brotli/1.0.9 zstd/1.5.2 libidn2/2.3.2 libssh2/1.10.0 nghttp2/1.47.0 librtmp/2.3 OpenLDAP/2.6.2
Release-Date: 2022-04-27
Protocols: dict file ftp ftps gopher gophers http https imap imaps ldap ldaps mqtt pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp 
Features: alt-svc AsynchDNS brotli GSS-API HSTS HTTP2 HTTPS-proxy IDN IPv6 Kerberos Largefile libz MultiSSL NTLM NTLM_WB SPNEGO SSL TLS-SRP UnixSockets zstd

and just rechecked, same with go1.18.2

just the error is only on 2nd write:

H2c Server starting on :8001
Got POST HTTP/1.1 request from 127.0.0.1:57528
read 3 from body
2022/05/12 17:29:16 http: response.Write on hijacked connection from fmt.Fprintf (print.go:205)
ldemailly commented 2 years ago

Code is also available on https://github.com/fortio/h2-bug

heschi commented 2 years ago

cc @neild

ldemailly commented 2 years ago

Thanks! Note that the same happens when trying to use ReverseProxy as well (which is how I went down this path:)

curl/7.83.0/bin/curl -v --http2 -d foo "localhost:8001/echo?delay=1s"

Server GODEBUG=http2debug=2 go run .

2022/05/14 14:21:57 http2: Framer 0x1400014e1c0: wrote SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=33554432, ENABLE_PUSH=0
2022/05/14 14:21:57 http2: Framer 0x1400014e1c0: wrote HEADERS flags=END_HEADERS stream=1 len=74
web req: /echo?delay=1s
2022/05/14 14:21:58 http: response.WriteHeader on hijacked connection from net/http/httputil.(*ReverseProxy).ServeHTTP (reverseproxy.go:337)
2022/05/14 14:21:58 http: response.Write on hijacked connection from net/http/httputil.(*ReverseProxy).copyBuffer (reverseproxy.go:467)
    httpURL, _ := url.Parse("http://localhost:8080/")
    httpProxy := httputil.NewSingleHostReverseProxy(httpURL)
    mux := http.NewServeMux()

    mux.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
        fmt.Printf("web req: %v\n", r.URL)
        httpProxy.ServeHTTP(w, r)
    })
    h2s := &http2.Server{}
    srv := &http.Server{
        Addr:    ":8001",
        Handler: h2c.NewHandler(mux, h2s),
    }
    //http2.ConfigureServer(srv, nil)
    log.Fatal(srv.ListenAndServe())

curl side logs (failing upgrade:):

/opt/homebrew/Cellar/curl/7.83.0/bin/curl --trace - --trace-time -m 2 --http2 -d foo "localhost:8001/echo?delay=1s"   
14:34:15.830214 == Info:   Trying 127.0.0.1:8001...
14:34:15.830736 == Info: Connected to localhost (127.0.0.1) port 8001 (#0)
14:34:15.830800 => Send header, 253 bytes (0xfd)
0000: 50 4f 53 54 20 2f 65 63 68 6f 3f 64 65 6c 61 79 POST /echo?delay
0010: 3d 31 73 20 48 54 54 50 2f 31 2e 31 0d 0a 48 6f =1s HTTP/1.1..Ho
0020: 73 74 3a 20 6c 6f 63 61 6c 68 6f 73 74 3a 38 30 st: localhost:80
0030: 30 31 0d 0a 55 73 65 72 2d 41 67 65 6e 74 3a 20 01..User-Agent: 
0040: 63 75 72 6c 2f 37 2e 38 33 2e 30 0d 0a 41 63 63 curl/7.83.0..Acc
0050: 65 70 74 3a 20 2a 2f 2a 0d 0a 43 6f 6e 6e 65 63 ept: */*..Connec
0060: 74 69 6f 6e 3a 20 55 70 67 72 61 64 65 2c 20 48 tion: Upgrade, H
0070: 54 54 50 32 2d 53 65 74 74 69 6e 67 73 0d 0a 55 TTP2-Settings..U
0080: 70 67 72 61 64 65 3a 20 68 32 63 0d 0a 48 54 54 pgrade: h2c..HTT
0090: 50 32 2d 53 65 74 74 69 6e 67 73 3a 20 41 41 4d P2-Settings: AAM
00a0: 41 41 41 42 6b 41 41 51 43 41 41 41 41 41 41 49 AAABkAAQCAAAAAAI
00b0: 41 41 41 41 41 0d 0a 43 6f 6e 74 65 6e 74 2d 4c AAAAA..Content-L
00c0: 65 6e 67 74 68 3a 20 33 0d 0a 43 6f 6e 74 65 6e ength: 3..Conten
00d0: 74 2d 54 79 70 65 3a 20 61 70 70 6c 69 63 61 74 t-Type: applicat
00e0: 69 6f 6e 2f 78 2d 77 77 77 2d 66 6f 72 6d 2d 75 ion/x-www-form-u
00f0: 72 6c 65 6e 63 6f 64 65 64 0d 0a 0d 0a          rlencoded....
14:34:15.830909 => Send data, 3 bytes (0x3)
0000: 66 6f 6f                                        foo
14:34:15.831048 == Info: Mark bundle as not supporting multiuse
14:34:15.831057 <= Recv header, 34 bytes (0x22)
0000: 48 54 54 50 2f 31 2e 31 20 31 30 31 20 53 77 69 HTTP/1.1 101 Swi
0010: 74 63 68 69 6e 67 20 50 72 6f 74 6f 63 6f 6c 73 tching Protocols
0020: 0d 0a                                           ..
14:34:15.831078 <= Recv header, 21 bytes (0x15)
0000: 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 55 70 67 72 Connection: Upgr
0010: 61 64 65 0d 0a                                  ade..
14:34:15.831093 <= Recv header, 14 bytes (0xe)
0000: 55 70 67 72 61 64 65 3a 20 68 32 63 0d 0a       Upgrade: h2c..
14:34:15.831103 == Info: Received 101
14:34:15.831118 == Info: Using HTTP2, server supports multiplexing
14:34:15.831131 == Info: Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
14:34:17.831253 == Info: Operation timed out after 2003 milliseconds with 0 bytes received
14:34:17.831512 == Info: Connection #0 to host localhost left intact
curl: (28) Operation timed out after 2003 milliseconds with 0 bytes received

prior knowledge (working):

dl@Laurents-Air fortio % /opt/homebrew/Cellar/curl/7.83.0/bin/curl --trace - --trace-time -m 2 --http2-prior-knowledge -d foo "localhost:8001/echo?delay=1s"
14:35:43.087749 == Info:   Trying 127.0.0.1:8001...
14:35:43.088298 == Info: Connected to localhost (127.0.0.1) port 8001 (#0)
14:35:43.088327 == Info: Using HTTP2, server supports multiplexing
14:35:43.088338 == Info: Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
14:35:43.088396 == Info: h2h3 [:method: POST]
14:35:43.088402 == Info: h2h3 [:path: /echo?delay=1s]
14:35:43.088407 == Info: h2h3 [:scheme: http]
14:35:43.088412 == Info: h2h3 [:authority: localhost:8001]
14:35:43.088417 == Info: h2h3 [user-agent: curl/7.83.0]
14:35:43.088421 == Info: h2h3 [accept: */*]
14:35:43.088426 == Info: h2h3 [content-length: 3]
14:35:43.088430 == Info: h2h3 [content-type: application/x-www-form-urlencoded]
14:35:43.088442 == Info: Using Stream ID: 1 (easy handle 0x14c013a00)
14:35:43.088469 => Send header, 158 bytes (0x9e)
0000: 50 4f 53 54 20 2f 65 63 68 6f 3f 64 65 6c 61 79 POST /echo?delay
0010: 3d 31 73 20 48 54 54 50 2f 32 0d 0a 48 6f 73 74 =1s HTTP/2..Host
0020: 3a 20 6c 6f 63 61 6c 68 6f 73 74 3a 38 30 30 31 : localhost:8001
0030: 0d 0a 75 73 65 72 2d 61 67 65 6e 74 3a 20 63 75 ..user-agent: cu
0040: 72 6c 2f 37 2e 38 33 2e 30 0d 0a 61 63 63 65 70 rl/7.83.0..accep
0050: 74 3a 20 2a 2f 2a 0d 0a 63 6f 6e 74 65 6e 74 2d t: */*..content-
0060: 6c 65 6e 67 74 68 3a 20 33 0d 0a 63 6f 6e 74 65 length: 3..conte
0070: 6e 74 2d 74 79 70 65 3a 20 61 70 70 6c 69 63 61 nt-type: applica
0080: 74 69 6f 6e 2f 78 2d 77 77 77 2d 66 6f 72 6d 2d tion/x-www-form-
0090: 75 72 6c 65 6e 63 6f 64 65 64 0d 0a 0d 0a       urlencoded....
14:35:43.088555 => Send data, 3 bytes (0x3)
0000: 66 6f 6f                                        foo
14:35:43.088564 == Info: We are completely uploaded and fine
14:35:43.088786 == Info: Connection state changed (MAX_CONCURRENT_STREAMS == 250)!
14:35:44.092396 <= Recv header, 13 bytes (0xd)
0000: 48 54 54 50 2f 32 20 32 30 30 20 0d 0a          HTTP/2 200 ..
14:35:44.092445 <= Recv header, 49 bytes (0x31)
0000: 63 6f 6e 74 65 6e 74 2d 74 79 70 65 3a 20 61 70 content-type: ap
0010: 70 6c 69 63 61 74 69 6f 6e 2f 78 2d 77 77 77 2d plication/x-www-
0020: 66 6f 72 6d 2d 75 72 6c 65 6e 63 6f 64 65 64 0d form-urlencoded.
0030: 0a                                              .
14:35:44.092484 <= Recv header, 37 bytes (0x25)
0000: 64 61 74 65 3a 20 53 61 74 2c 20 31 34 20 4d 61 date: Sat, 14 Ma
0010: 79 20 32 30 32 32 20 32 31 3a 33 35 3a 34 34 20 y 2022 21:35:44 
0020: 47 4d 54 0d 0a                                  GMT..
14:35:44.092515 <= Recv header, 19 bytes (0x13)
0000: 63 6f 6e 74 65 6e 74 2d 6c 65 6e 67 74 68 3a 20 content-length: 
0010: 33 0d 0a                                        3..
14:35:44.092537 <= Recv header, 2 bytes (0x2)
0000: 0d 0a                                           ..
14:35:44.092557 <= Recv data, 3 bytes (0x3)
0000: 66 6f 6f                                        foo
foo14:35:44.092602 == Info: Connection #0 to host localhost left intact

working server side:

2022/05/14 14:35:43 h2c: attempting h2c with prior knowledge.
2022/05/14 14:35:43 http2: server connection from 127.0.0.1:50901 on 0x14000282460
2022/05/14 14:35:43 http2: Framer 0x14000282620: wrote SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
2022/05/14 14:35:43 http2: server: client 127.0.0.1:50901 said hello
2022/05/14 14:35:43 http2: Framer 0x14000282620: wrote WINDOW_UPDATE len=4 (conn) incr=983041
2022/05/14 14:35:43 http2: Framer 0x14000282620: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=33554432, ENABLE_PUSH=0
2022/05/14 14:35:43 http2: server read frame SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=33554432, ENABLE_PUSH=0
2022/05/14 14:35:43 http2: server processing setting [MAX_CONCURRENT_STREAMS = 100]
2022/05/14 14:35:43 http2: server processing setting [INITIAL_WINDOW_SIZE = 33554432]
2022/05/14 14:35:43 http2: server processing setting [ENABLE_PUSH = 0]
2022/05/14 14:35:43 http2: Framer 0x14000282620: wrote SETTINGS flags=ACK len=0
2022/05/14 14:35:43 http2: Framer 0x14000282620: read WINDOW_UPDATE len=4 (conn) incr=33488897
2022/05/14 14:35:43 http2: server read frame WINDOW_UPDATE len=4 (conn) incr=33488897
2022/05/14 14:35:43 http2: Framer 0x14000282620: read HEADERS flags=END_HEADERS stream=1 len=72
2022/05/14 14:35:43 http2: decoded hpack field header field ":method" = "POST"
2022/05/14 14:35:43 http2: decoded hpack field header field ":path" = "/echo?delay=1s"
2022/05/14 14:35:43 http2: decoded hpack field header field ":scheme" = "http"
2022/05/14 14:35:43 http2: decoded hpack field header field ":authority" = "localhost:8001"
2022/05/14 14:35:43 http2: decoded hpack field header field "user-agent" = "curl/7.83.0"
2022/05/14 14:35:43 http2: decoded hpack field header field "accept" = "*/*"
2022/05/14 14:35:43 http2: decoded hpack field header field "content-length" = "3"
2022/05/14 14:35:43 http2: decoded hpack field header field "content-type" = "application/x-www-form-urlencoded"
2022/05/14 14:35:43 http2: server read frame HEADERS flags=END_HEADERS stream=1 len=72
2022/05/14 14:35:43 http2: Framer 0x14000282620: read DATA flags=END_STREAM stream=1 len=3 data="foo"
2022/05/14 14:35:43 http2: server read frame DATA flags=END_STREAM stream=1 len=3 data="foo"
2022/05/14 14:35:43 http2: Framer 0x14000282620: read SETTINGS flags=ACK len=0
2022/05/14 14:35:43 http2: server read frame SETTINGS flags=ACK len=0
web2 req: /echo?delay=1s
2022/05/14 14:35:43 http2: Framer 0x14000282620: wrote WINDOW_UPDATE len=4 (conn) incr=3
2022/05/14 14:35:44 http2: server encoding header ":status" = "200"
2022/05/14 14:35:44 http2: server encoding header "content-type" = "application/x-www-form-urlencoded"
2022/05/14 14:35:44 http2: server encoding header "date" = "Sat, 14 May 2022 21:35:44 GMT"
2022/05/14 14:35:44 http2: server encoding header "content-length" = "3"
2022/05/14 14:35:44 http2: Framer 0x14000282620: wrote HEADERS flags=END_HEADERS stream=1 len=54
2022/05/14 14:35:44 http2: Framer 0x14000282620: wrote DATA flags=END_STREAM stream=1 len=3 data="foo"
ZekeLu commented 2 years ago

I think the server is not correctly configured. Here is the revised version that works: https://go.dev/play/p/hO_OnkMS-wz

I will highlight the changes at the end of this comment.

According to the doc of https://pkg.go.dev/golang.org/x/net/http2#ConfigureServer,

ConfigureServer must be called before s begins serving.

And here is the now deleted http2 server demo that could be helpful: https://github.com/golang/net/blob/69e39bad7dc2bbb411fa35755c46020969029fa7/http2/h2demo/h2demo.go

 package main

 import (
-   "crypto/tls"
    "fmt"
    "io"
    "log"
-   "net"
    "net/http"
-   "net/url"

    "golang.org/x/net/http2"
-   "golang.org/x/net/http2/h2c"
 )

 func server() {
    h2s := &http2.Server{}

    handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        fmt.Printf("Got %v %v request from %v\n", r.Method, r.Proto, r.RemoteAddr)
        body, err := io.ReadAll(r.Body)
        if err != nil {
            log.Fatalf("server body read err: %v\n", err)
        }
        fmt.Printf("read %d from body\n", len(body))
        w.WriteHeader(http.StatusAccepted)
        fmt.Fprintf(w, "Hello, %v; HTTP Version: %v\n\nbody:\n%s\n", r.URL.Path, r.Proto, string(body))
    })

+   http.HandleFunc("/", handler)
+
    server := &http.Server{
        Addr:    ":8001",
-       Handler: h2c.NewHandler(handler, h2s),
    }
+   http2.ConfigureServer(server, h2s)
    fmt.Printf("H2c Server starting on %s\n", server.Addr)
    err := server.ListenAndServe()
    if err != nil {
        panic(err)
    }
 }

 func main() {
    server()
 }
seankhliao commented 2 years ago

@ZekeLu this issue is about the h2c (http2 using cleartext) upgrade process. your example drops the important part out

ZekeLu commented 2 years ago

Ah, I totally missed the h2c part. Thank you for pointing that out and sorry for making the noise.

ldemailly commented 2 years ago

yeah as I mentioned in the description (sorry if it's noisy/unclear) --http2-prior-knowledge does work fine

neild commented 2 years ago

The h2c package handles protocol upgrades by reading the initial HTTP/1 request and rewriting it into an HTTP/2 stream of bytes: https://go.googlesource.com/net/+/refs/heads/master/http2/h2c/h2c.go#208

It then takes those converted HTTP/2 bytes, prepends them to the subsequent HTTP/2 stream sent from the client, and presents this to the HTTP/2 server impementation.

The conversion from HTTP/1 to HTTP/2 does not appear to support request bodies at all, so any initial HTTP/1 request with a body is mishandled. Also, I think reading from the request body at all (even when it's not present) may be broken due to the synthetic HTTP/2 request not including an END_STREAM flag.

To make things even more fun, a fundamental problem with this approach is that it doesn't deal with HTTP/2 flow control at all.

I honestly have no idea how to fix this without completely rearchitecting h2c support. If we want to support h2c, we should stop rewriting HTTP/1 requests into HTTP/2 and have a real mechanism for handing off an upgraded request to the HTTP/2 server.

gopherbot commented 2 years ago

Change https://go.dev/cl/407454 mentions this issue: http2/h2c: connection handoff without translation

ldemailly commented 2 years ago

I used the your cl branch and I can confirm this fixes the issue I reported! thanks so much! do you know when it'll be available on the main branch?

while I have you I would love an h2c upgrade client and a way for the ReverseProxy to do h2c prior knowledge (h2c:// urls?) (the reason I need all this is to write a simple proxy that can do h1.1, h2c and grpc proxy https://github.com/fortio/proxy still doesn't work for grpc after this fix - possibly because I don't know how to change the ReverseProxy Director http.Request to tell it to try h2)

ldemailly commented 2 years ago

Answering my own question, I got it working !!

    rp := httputil.ReverseProxy{
        Director: Director,
        Transport: &http2.Transport{
            AllowHTTP: true,
            DialTLS: func(network, addr string, cfg *tls.Config) (net.Conn, error) {
                return net.Dial(network, addr)
            },
        },
    }

Still wondering how to configure as h2c upgrade though so it would work with h1.1 targets with a single transport

ldemailly commented 2 years ago

unfortunately because of https://github.com/golang/go/issues/44840#issuecomment-1133417501 I can't seem to use my fork to make a release (do I miss something obvious in my go.mod?)

Edit: found a workaround, change the import and go.mod in the fork...