search

golang / go

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

net/http/httputil: ReverseProxy doesn't proxy grpc without help due to 'te' header handling #21096

Closed groob closed 6 years ago

groob commented 7 years ago

Please answer these questions before submitting your issue. Thanks!

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

Go 1.8.3 (but can reproduce with 1.9beta2.

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

darwin and linux

What did you do?

Tried to use the http2 transport to talk to a remote http2 server. https://play.golang.org/p/W_HbQGJZK9

The server on the other end is the grpc helloworld example. When running against the grpc-go implementation, the code works. When running agains ruby or python(both backed by C code) I get the INTERNAL_ERROR response described above. Logging on the server side itself is silent.

Note, the HTTP POST is only to more easily reproduce the issue. What I'm trying to do instead is use httputil.ReverseProxy to proxy grpc traffic: https://play.golang.org/p/micZul79Ow This succeeds if the upstream server is in Go

C server examples: https://github.com/grpc/grpc/tree/master/examples (connecting to these fails) grpc-go examples: https://github.com/grpc/grpc-go/tree/master/examples (connecting to this server succeeds)

What did you expect to see?

An HTTP response.

What did you see instead?

GODEBUG=http2debug=2 go run main.go                                                                                                                                                                    
2017/07/19 23:34:05 http2: Transport creating client conn 0xc42013c000 to [::1]:8082
2017/07/19 23:34:05 http2: Framer 0xc42014e000: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2017/07/19 23:34:05 http2: Framer 0xc42014e000: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2017/07/19 23:34:05 http2: Transport encoding header ":authority" = "localhost:8082"
2017/07/19 23:34:05 http2: Transport encoding header ":method" = "POST"
2017/07/19 23:34:05 http2: Transport encoding header ":path" = "/"
2017/07/19 23:34:05 http2: Transport encoding header ":scheme" = "https"
2017/07/19 23:34:05 http2: Transport encoding header "content-type" = "application/grpc"
2017/07/19 23:34:05 http2: Transport encoding header "content-length" = "5"
2017/07/19 23:34:05 http2: Transport encoding header "accept-encoding" = "gzip"
2017/07/19 23:34:05 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2017/07/19 23:34:05 http2: Framer 0xc42014e000: wrote HEADERS flags=END_HEADERS stream=1 len=51
2017/07/19 23:34:05 http2: Framer 0xc42014e000: wrote DATA stream=1 len=5 data="hello"
2017/07/19 23:34:05 http2: Framer 0xc42014e000: read SETTINGS len=24, settings: INITIAL_WINDOW_SIZE=65535, MAX_FRAME_SIZE=65538, MAX_HEADER_LIST_SIZE=16384, UNKNOWN_SETTING_65027=1
2017/07/19 23:34:05 http2: Framer 0xc42014e000: wrote DATA flags=END_STREAM stream=1 len=0 data=""
2017/07/19 23:34:05 http2: Transport received SETTINGS len=24, settings: INITIAL_WINDOW_SIZE=65535, MAX_FRAME_SIZE=65538, MAX_HEADER_LIST_SIZE=16384, UNKNOWN_SETTING_65027=1
2017/07/19 23:34:05 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 16384]
2017/07/19 23:34:05 Unhandled Setting: [UNKNOWN_SETTING_65027 = 1]
2017/07/19 23:34:05 http2: Framer 0xc42014e000: wrote SETTINGS flags=ACK len=0
2017/07/19 23:34:05 http2: Framer 0xc42014e000: read SETTINGS flags=ACK len=0
2017/07/19 23:34:05 http2: Transport received SETTINGS flags=ACK len=0
2017/07/19 23:34:05 http2: Framer 0xc42014e000: read RST_STREAM stream=1 len=4 ErrCode=INTERNAL_ERROR
2017/07/19 23:34:05 http2: Transport received RST_STREAM stream=1 len=4 ErrCode=INTERNAL_ERROR
2017/07/19 23:34:05 http2: Framer 0xc42014e000: read HEADERS flags=END_STREAM|END_HEADERS stream=1 len=83
2017/07/19 23:34:05 http2: decoded hpack field header field ":status" = "200"
2017/07/19 23:34:05 http2: decoded hpack field header field "content-type" = "application/grpc"
2017/07/19 23:34:05 RoundTrip failure: stream error: stream ID 1; INTERNAL_ERROR
2017/07/19 23:34:05 http2: decoded hpack field header field "grpc-status" = "1"
2017/07/19 23:34:05 http2: decoded hpack field header field "grpc-message" = "Cancelled"
2017/07/19 23:34:05 http2: Transport received HEADERS flags=END_STREAM|END_HEADERS stream=1 len=83
2017/07/19 23:34:05 Post https://localhost:8082: stream error: stream ID 1; INTERNAL_ERROR
bradfitz commented 7 years ago

I bet it doesn't like the :path of / you're sending.

But that would have nothing to do with Go's HTTP/2 support.

groob commented 7 years ago

Here is the debug output of the proxy version:

func proxyForGRPC(backendURL string) (*httputil.ReverseProxy, error) {
    u, err := url.Parse(backendURL)
    if err != nil {
        return nil, err
    }
    u.Scheme = "https" // enforce https scheme on urls for htt2
    dial := func(network, addr string, cfg *tls.Config) (net.Conn, error) {
        return net.Dial(network, addr)
    }
    transport := &http2.Transport{

        DialTLS: dial,
    }
    p := httputil.NewSingleHostReverseProxy(u)
    p.Transport = transport
    return p, nil
}

proxying to the ruby grpc greeter server. 

2017/07/20 01:19:17 http2: server connection from [::1]:63477 on 0xc4200835f0
2017/07/20 01:19:17 http2: Framer 0xc4201da2a0: wrote SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
2017/07/20 01:19:17 http2: server: client [::1]:63477 said hello
2017/07/20 01:19:17 http2: Framer 0xc4201da2a0: wrote WINDOW_UPDATE len=4 (conn) incr=983041
2017/07/20 01:19:17 http2: Framer 0xc4201da2a0: read SETTINGS len=0
2017/07/20 01:19:17 http2: server read frame SETTINGS len=0
2017/07/20 01:19:17 http2: Framer 0xc4201da2a0: wrote SETTINGS flags=ACK len=0
2017/07/20 01:19:17 http2: Framer 0xc4201da2a0: read HEADERS flags=END_HEADERS stream=1 len=73
2017/07/20 01:19:17 http2: decoded hpack field header field ":method" = "POST"
2017/07/20 01:19:17 http2: decoded hpack field header field ":scheme" = "https"
2017/07/20 01:19:17 http2: decoded hpack field header field ":path" = "/helloworld.Greeter/SayHello"
2017/07/20 01:19:17 http2: decoded hpack field header field ":authority" = "localhost:8083"
2017/07/20 01:19:17 http2: decoded hpack field header field "content-type" = "application/grpc"
2017/07/20 01:19:17 http2: decoded hpack field header field "user-agent" = "grpc-go/1.5.0"
2017/07/20 01:19:17 http2: decoded hpack field header field "te" = "trailers"
2017/07/20 01:19:17 http2: server read frame HEADERS flags=END_HEADERS stream=1 len=73
2017/07/20 01:19:17 http2: Framer 0xc4201da2a0: read DATA flags=END_STREAM stream=1 len=12 data="\x00\x00\x00\x00\a\n\x05world"
2017/07/20 01:19:17 http2: server read frame DATA flags=END_STREAM stream=1 len=12 data="\x00\x00\x00\x00\a\n\x05world"
2017/07/20 01:19:17 http2: Framer 0xc4201da2a0: read SETTINGS flags=ACK len=0
2017/07/20 01:19:17 http2: server read frame SETTINGS flags=ACK len=0
2017/07/20 01:19:17 http2: Transport creating client conn 0xc42008a9c0 to [::1]:8082
2017/07/20 01:19:17 http2: Framer 0xc4201da540: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2017/07/20 01:19:17 http2: Framer 0xc4201da540: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2017/07/20 01:19:17 http2: Transport encoding header ":authority" = "localhost:8083"
2017/07/20 01:19:17 http2: Transport encoding header ":method" = "POST"
2017/07/20 01:19:17 http2: Transport encoding header ":path" = "/helloworld.Greeter/SayHello"
2017/07/20 01:19:17 http2: Transport encoding header ":scheme" = "https"
2017/07/20 01:19:17 http2: Transport encoding header "x-forwarded-for" = "::1"
2017/07/20 01:19:17 http2: Transport encoding header "content-type" = "application/grpc"
2017/07/20 01:19:17 http2: Transport encoding header "user-agent" = "grpc-go/1.5.0"
2017/07/20 01:19:17 http2: Transport encoding header "accept-encoding" = "gzip"
2017/07/20 01:19:17 http2: Framer 0xc4201da540: wrote HEADERS flags=END_HEADERS stream=1 len=84
2017/07/20 01:19:17 http2: Framer 0xc4201da540: wrote DATA stream=1 len=12 data="\x00\x00\x00\x00\a\n\x05world"
2017/07/20 01:19:17 http2: Framer 0xc4201da540: read SETTINGS len=24, settings: INITIAL_WINDOW_SIZE=65535, MAX_FRAME_SIZE=65545, MAX_HEADER_LIST_SIZE=16384, UNKNOWN_SETTING_65027=1
2017/07/20 01:19:17 http2: Framer 0xc4201da2a0: wrote WINDOW_UPDATE len=4 (conn) incr=12
2017/07/20 01:19:17 http2: Transport received SETTINGS len=24, settings: INITIAL_WINDOW_SIZE=65535, MAX_FRAME_SIZE=65545, MAX_HEADER_LIST_SIZE=16384, UNKNOWN_SETTING_65027=1
2017/07/20 01:19:17 http2: Framer 0xc4201da540: wrote DATA flags=END_STREAM stream=1 len=0 data=""
2017/07/20 01:19:17 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 16384]
2017/07/20 01:19:17 Unhandled Setting: [UNKNOWN_SETTING_65027 = 1]
2017/07/20 01:19:17 http2: Framer 0xc4201da540: wrote SETTINGS flags=ACK len=0
2017/07/20 01:19:17 http2: Framer 0xc4201da540: read SETTINGS flags=ACK len=0
2017/07/20 01:19:17 http2: Transport received SETTINGS flags=ACK len=0
2017/07/20 01:19:17 http2: Framer 0xc4201da540: read RST_STREAM stream=1 len=4 ErrCode=INTERNAL_ERROR
2017/07/20 01:19:17 http2: Transport received RST_STREAM stream=1 len=4 ErrCode=INTERNAL_ERROR
2017/07/20 01:19:17 http2: Framer 0xc4201da540: read HEADERS flags=END_STREAM|END_HEADERS stream=1 len=83
2017/07/20 01:19:17 http2: decoded hpack field header field ":status" = "200"
2017/07/20 01:19:17 http2: decoded hpack field header field "content-type" = "application/grpc"
2017/07/20 01:19:17 http2: decoded hpack field header field "grpc-status" = "1"
2017/07/20 01:19:17 http2: decoded hpack field header field "grpc-message" = "Cancelled"
2017/07/20 01:19:17 http2: Transport received HEADERS flags=END_STREAM|END_HEADERS stream=1 len=83
2017/07/20 01:19:17 http2: Framer 0xc4201da540: read RST_STREAM stream=1 len=4 ErrCode=NO_ERROR
2017/07/20 01:19:17 http2: Transport received RST_STREAM stream=1 len=4 ErrCode=NO_ERROR
2017/07/20 01:19:17 RoundTrip failure: stream error: stream ID 1; INTERNAL_ERROR
2017/07/20 01:19:17 http: proxy error: stream error: stream ID 1; INTERNAL_ERROR
2017/07/20 01:19:17 http2: server encoding header ":status" = "502"
2017/07/20 01:19:17 http2: server encoding header "content-type" = "text/plain; charset=utf-8"
2017/07/20 01:19:17 http2: server encoding header "content-length" = "0"
2017/07/20 01:19:17 http2: server encoding header "date" = "Thu, 20 Jul 2017 05:19:17 GMT"
2017/07/20 01:19:17 http2: Framer 0xc4201da2a0: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=51
2017/07/20 01:19:17 http2: Framer 0xc4201da2a0: read RST_STREAM stream=1 len=4 ErrCode=CANCEL
2017/07/20 01:19:17 http2: server read frame RST_STREAM stream=1 len=4 ErrCode=CANCEL
groob commented 7 years ago

And this is what happens when the remote is a grpc-go server:


2017/07/20 01:18:26 http2: server connection from [::1]:63450 on 0xc420085520
2017/07/20 01:18:26 http2: Framer 0xc4201dc2a0: wrote SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
2017/07/20 01:18:26 http2: server: client [::1]:63450 said hello
2017/07/20 01:18:26 http2: Framer 0xc4201dc2a0: wrote WINDOW_UPDATE len=4 (conn) incr=983041
2017/07/20 01:18:26 http2: Framer 0xc4201dc2a0: read SETTINGS len=0
2017/07/20 01:18:26 http2: server read frame SETTINGS len=0
2017/07/20 01:18:26 http2: Framer 0xc4201dc2a0: wrote SETTINGS flags=ACK len=0
2017/07/20 01:18:26 http2: Framer 0xc4201dc2a0: read HEADERS flags=END_HEADERS stream=1 len=73
2017/07/20 01:18:26 http2: decoded hpack field header field ":method" = "POST"
2017/07/20 01:18:26 http2: decoded hpack field header field ":scheme" = "https"
2017/07/20 01:18:26 http2: decoded hpack field header field ":path" = "/helloworld.Greeter/SayHello"
2017/07/20 01:18:26 http2: decoded hpack field header field ":authority" = "localhost:8083"
2017/07/20 01:18:26 http2: decoded hpack field header field "content-type" = "application/grpc"
2017/07/20 01:18:26 http2: decoded hpack field header field "user-agent" = "grpc-go/1.5.0"
2017/07/20 01:18:26 http2: decoded hpack field header field "te" = "trailers"
2017/07/20 01:18:26 http2: server read frame HEADERS flags=END_HEADERS stream=1 len=73
2017/07/20 01:18:26 http2: Framer 0xc4201dc2a0: read DATA flags=END_STREAM stream=1 len=12 data="\x00\x00\x00\x00\a\n\x05world"
2017/07/20 01:18:26 http2: server read frame DATA flags=END_STREAM stream=1 len=12 data="\x00\x00\x00\x00\a\n\x05world"
2017/07/20 01:18:26 http2: Framer 0xc4201dc2a0: read SETTINGS flags=ACK len=0
2017/07/20 01:18:26 http2: server read frame SETTINGS flags=ACK len=0
2017/07/20 01:18:26 http2: Transport creating client conn 0xc42008a9c0 to [::1]:8082
2017/07/20 01:18:26 http2: Framer 0xc4201dc540: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2017/07/20 01:18:26 http2: Framer 0xc4201dc540: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2017/07/20 01:18:26 http2: Transport encoding header ":authority" = "localhost:8083"
2017/07/20 01:18:26 http2: Framer 0xc4201dc540: read SETTINGS len=0
2017/07/20 01:18:26 http2: Transport encoding header ":method" = "POST"
2017/07/20 01:18:26 http2: Transport encoding header ":path" = "/helloworld.Greeter/SayHello"
2017/07/20 01:18:26 http2: Transport encoding header ":scheme" = "https"
2017/07/20 01:18:26 http2: Transport encoding header "user-agent" = "grpc-go/1.5.0"
2017/07/20 01:18:26 http2: Transport encoding header "x-forwarded-for" = "::1"
2017/07/20 01:18:26 http2: Transport received SETTINGS len=0
2017/07/20 01:18:26 http2: Transport encoding header "content-type" = "application/grpc"
2017/07/20 01:18:26 http2: Transport encoding header "accept-encoding" = "gzip"
2017/07/20 01:18:26 http2: Framer 0xc4201dc540: wrote HEADERS flags=END_HEADERS stream=1 len=84
2017/07/20 01:18:26 http2: Framer 0xc4201dc540: wrote SETTINGS flags=ACK len=0
2017/07/20 01:18:26 http2: Framer 0xc4201dc540: read SETTINGS flags=ACK len=0
2017/07/20 01:18:26 http2: Transport received SETTINGS flags=ACK len=0
2017/07/20 01:18:26 http2: Framer 0xc4201dc540: wrote DATA stream=1 len=12 data="\x00\x00\x00\x00\a\n\x05world"
2017/07/20 01:18:26 http2: Framer 0xc4201dc2a0: wrote WINDOW_UPDATE len=4 (conn) incr=12
2017/07/20 01:18:26 http2: Framer 0xc4201dc540: wrote DATA flags=END_STREAM stream=1 len=0 data=""
2017/07/20 01:18:26 http2: Framer 0xc4201dc540: read WINDOW_UPDATE len=4 (conn) incr=12
2017/07/20 01:18:26 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=12
2017/07/20 01:18:26 http2: Framer 0xc4201dc540: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2017/07/20 01:18:26 http2: Transport received PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2017/07/20 01:18:26 http2: Framer 0xc4201dc540: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2017/07/20 01:18:26 http2: Framer 0xc4201dc540: read HEADERS flags=END_HEADERS stream=1 len=14
2017/07/20 01:18:26 http2: decoded hpack field header field ":status" = "200"
2017/07/20 01:18:26 http2: decoded hpack field header field "content-type" = "application/grpc"
2017/07/20 01:18:26 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=14
2017/07/20 01:18:26 http2: Framer 0xc4201dc540: read DATA stream=1 len=18 data="\x00\x00\x00\x00\r\n\vHello world"
2017/07/20 01:18:26 http2: Transport received DATA stream=1 len=18 data="\x00\x00\x00\x00\r\n\vHello world"
2017/07/20 01:18:26 http2: Framer 0xc4201dc540: read HEADERS flags=END_STREAM|END_HEADERS stream=1 len=24
2017/07/20 01:18:26 http2: decoded hpack field header field "grpc-status" = "0"
2017/07/20 01:18:26 http2: decoded hpack field header field "grpc-message" = ""
2017/07/20 01:18:26 http2: Transport received HEADERS flags=END_STREAM|END_HEADERS stream=1 len=24
2017/07/20 01:18:26 http2: server encoding header ":status" = "200"
2017/07/20 01:18:26 http2: server encoding header "content-type" = "application/grpc"
2017/07/20 01:18:26 http2: server encoding header "content-length" = "18"
2017/07/20 01:18:26 http2: server encoding header "date" = "Thu, 20 Jul 2017 05:18:26 GMT"
2017/07/20 01:18:26 http2: Framer 0xc4201dc2a0: wrote HEADERS flags=END_HEADERS stream=1 len=42
2017/07/20 01:18:26 http2: Framer 0xc4201dc2a0: wrote DATA stream=1 len=18 data="\x00\x00\x00\x00\r\n\vHello world"
2017/07/20 01:18:26 http2: server encoding header "grpc-message" = ""
2017/07/20 01:18:26 http2: server encoding header "grpc-status" = "0"
2017/07/20 01:18:26 http2: Framer 0xc4201dc2a0: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=24
2017/07/20 01:18:26 http2: Framer 0xc4201dc2a0: read WINDOW_UPDATE len=4 (conn) incr=18
2017/07/20 01:18:26 http2: server read frame WINDOW_UPDATE len=4 (conn) incr=18
2017/07/20 01:18:26 http2: Framer 0xc4201dc2a0: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2017/07/20 01:18:26 http2: server read frame PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2017/07/20 01:18:26 http2: Framer 0xc4201dc2a0: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"```
groob commented 7 years ago

Here's something. I figured out how to enable http tracing on the ruby server: GRPC_TRACE=http

D0720 01:34:57.102142000 140736940794816 ev_posix.c:121]               Using polling engine: poll
D0720 01:34:57.102229000 140736940794816 dns_resolver.c:316]           Using native dns resolver
I0720 01:34:57.102439000 140736940794816 server.c:984]                 Completion queue which is not of type GRPC_CQ_NEXT is being registered as a server-completion-queue
D0720 01:34:57.104157000 123145437982720 rb_channel.c:696]             GRPC_RUBY: run_poll_channels_loop - create connection polling thread
D0720 01:34:57.104181000 123145437982720 rb_channel.c:620]             GRPC_RUBY: run_poll_channels_loop_no_gil - begin
D0720 01:35:04.216769000 140736940794816 chttp2_transport.c:811]       W:0x7ff795800c00 SERVER state IDLE -> WRITING [push_setting]
D0720 01:35:04.216805000 140736940794816 chttp2_transport.c:811]       W:0x7ff795800c00 SERVER state WRITING -> WRITING+MORE [push_setting]
D0720 01:35:04.216903000 140736940794816 chttp2_transport.c:811]       W:0x7ff795800c00 SERVER state WRITING+MORE -> WRITING [begin writing]
D0720 01:35:04.216932000 140736940794816 chttp2_transport.c:811]       W:0x7ff795800c00 SERVER state WRITING -> IDLE [finish writing]
D0720 01:35:04.216975000 140736940794816 frame_settings.c:228]         CHTTP2:SVR:ipv6:[::1]:63784: got setting ENABLE_PUSH = 0
D0720 01:35:04.216982000 140736940794816 frame_settings.c:222]         adding 4128769 for initial_window change
D0720 01:35:04.216987000 140736940794816 frame_settings.c:228]         CHTTP2:SVR:ipv6:[::1]:63784: got setting INITIAL_WINDOW_SIZE = 4194304
D0720 01:35:04.216991000 140736940794816 frame_settings.c:228]         CHTTP2:SVR:ipv6:[::1]:63784: got setting MAX_HEADER_LIST_SIZE = 10485760
D0720 01:35:04.217011000 140736940794816 chttp2_transport.c:1497]      perform_stream_op[s=0x7ff79682c4c8]: [UNCOVERED] RECV_INITIAL_METADATA
I0720 01:35:04.217296000 140736940794816 parsing.c:499]                HTTP:1:HDR:SVR: :authority: 6c 6f 63 61 6c 68 6f 73 74 3a 38 30 38 33 'localhost:8083'
I0720 01:35:04.217309000 140736940794816 parsing.c:499]                HTTP:1:HDR:SVR: :method: 50 4f 53 54 'POST'
I0720 01:35:04.217322000 140736940794816 parsing.c:499]                HTTP:1:HDR:SVR: :path: 2f 68 65 6c 6c 6f 77 6f 72 6c 64 2e 47 72 65 65 74 65 72 2f 53 61 79 48 65 6c 6c 6f '/helloworld.Greeter/SayHello'
I0720 01:35:04.217327000 140736940794816 parsing.c:499]                HTTP:1:HDR:SVR: :scheme: 68 74 74 70 73 'https'
I0720 01:35:04.217333000 140736940794816 parsing.c:499]                HTTP:1:HDR:SVR: content-type: 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc'
I0720 01:35:04.217339000 140736940794816 parsing.c:499]                HTTP:1:HDR:SVR: user-agent: 67 72 70 63 2d 67 6f 2f 31 2e 35 2e 30 'grpc-go/1.5.0'
I0720 01:35:04.217346000 140736940794816 parsing.c:499]                HTTP:1:HDR:SVR: x-forwarded-for: 3a 3a 31 '::1'
I0720 01:35:04.217351000 140736940794816 parsing.c:499]                HTTP:1:HDR:SVR: accept-encoding: 67 7a 69 70 'gzip'
D0720 01:35:04.217360000 140736940794816 chttp2_transport.c:811]       W:0x7ff795800c00 SERVER state IDLE -> WRITING [send_ping]
D0720 01:35:04.217369000 140736940794816 chttp2_transport.c:1254]      perform_stream_op_locked: [UNCOVERED] RECV_INITIAL_METADATA; on_complete = 0x7ff79682cbe8
D0720 01:35:04.217421000 140736940794816 chttp2_transport.c:1497]      perform_stream_op[s=0x7ff79682c4c8]: [UNCOVERED] CANCEL:{"created":"@1500528904.217380000","description":"Missing :authority or :path","file":"src/core/lib/surface/server.c","file_line":754,"referenced_errors":[{"created":"@1500528904.217376000","description":"Failed processing incoming headers","file":"src/core/ext/filters/http/server/http_server_filter.c","file_line":102,"referenced_errors":[{"created":"@1500528904.217375000","description":"Missing header","file":"src/core/ext/filters/http/server/http_server_filter.c","file_line":157,"key":"te"}]}]}
D0720 01:35:04.217430000 140736940794816 chttp2_transport.c:1109]      complete_closure_step: 0x7ff79682cbe8 refs=0 flags=0x0000 desc=op->on_complete err="No Error"
D0720 01:35:04.217437000 140736940794816 chttp2_transport.c:1497]      perform_stream_op[s=0x7ff79682c4c8]: [UNCOVERED] CANCEL:"Cancelled"
D0720 01:35:04.217444000 140736940794816 chttp2_transport.c:1254]      perform_stream_op_locked: [UNCOVERED] CANCEL:{"created":"@1500528904.217380000","description":"Missing :authority or :path","file":"src/core/lib/surface/server.c","file_line":754,"referenced_errors":[{"created":"@1500528904.217376000","description":"Failed processing incoming headers","file":"src/core/ext/filters/http/server/http_server_filter.c","file_line":102,"referenced_errors":[{"created":"@1500528904.217375000","description":"Missing header","file":"src/core/ext/filters/http/server/http_server_filter.c","file_line":157,"key":"te"}]}]}; on_complete = 0x7ff794f31a50
D0720 01:35:04.217459000 140736940794816 chttp2_transport.c:811]       W:0x7ff795800c00 SERVER state WRITING -> WRITING+MORE [rst_stream]
D0720 01:35:04.217467000 140736940794816 chttp2_transport.c:1109]      complete_closure_step: 0x7ff794f31a50 refs=0 flags=0x0000 desc=op->on_complete err="No Error"
D0720 01:35:04.217473000 140736940794816 chttp2_transport.c:1254]      perform_stream_op_locked: [UNCOVERED] CANCEL:"Cancelled"; on_complete = 0x7ff794f5c340
D0720 01:35:04.217525000 140736940794816 chttp2_transport.c:1109]      complete_closure_step: 0x7ff794f5c340 refs=0 flags=0x0000 desc=op->on_complete err="No Error"
D0720 01:35:04.217541000 140736940794816 chttp2_transport.c:811]       W:0x7ff795800c00 SERVER state WRITING+MORE -> WRITING [begin writing]
D0720 01:35:04.217568000 140736940794816 chttp2_transport.c:811]       W:0x7ff795800c00 SERVER state WRITING -> IDLE [finish writing]
bradfitz commented 7 years ago

It's missing the "te" header.

The https://grpc.io/docs/guides/wire.html does say:

TE → “te” “trailers” # Used to detect incompatible proxies

I guess you're an incompatible proxy! :-)

I forget which layer's job it is to strip/add/handle that. But that's what should be investigated here.

/cc @tombergan

groob commented 7 years ago

Yep, commenting out Te in the httputil.ReverseProxy makes the C server behave as expected.

https://github.com/golang/go/blob/3498012e79e7955513c5a39e193a7a4f7a6cf231/src/net/http/httputil/reverseproxy.go#L135

Doesn't sound like the right solution for a proxy to keep that header though. Should I open a issue with grpc/grpc?

groob commented 7 years ago

Found this article from the nginx blog https://nghttp2.org/blog/2015/03/24/proxying-grpc-with-nghttpx/

So in HTTP/1.1, trailer fields are only allowed in chunked transfer encoding. In HTTP/2, chunked transfer encoding is deprecated because it has more elegant framing and thanks to it, trailer fields are always allowed.

gRPC does not work without “TE” header field.

groob commented 7 years ago

@bradfitz is it too late in the 1.9 cycle or would you accept a CL to update this behavior in httputil/reverseproxy.go?

Something like this is what I had in mind:

diff --git a/src/net/http/httputil/reverseproxy.go b/src/net/http/httputil/reverseproxy.go
index 0d514f529b..4473657542 100644
--- a/src/net/http/httputil/reverseproxy.go
+++ b/src/net/http/httputil/reverseproxy.go
@@ -183,6 +183,11 @@ func (p *ReverseProxy) ServeHTTP(rw http.ResponseWriter, req *http.Request) {
    // important is "Connection" because we want a persistent
    // connection, regardless of what the client sent to us.
    for _, h := range hopHeaders {
+       if outreq.ProtoMajor == 2 &&
+           strings.Contains(outreq.Header.Get("Content-Type"), "application/grpc") &&
+           h == "Te" {
+           continue
+       }
        if outreq.Header.Get(h) != "" {
            outreq.Header.Del(h)
        }
bradfitz commented 7 years ago

It's way too late. But your proxy can add those lines.

It's not obvious that we want to add application-specific hacks to reverseproxy.go.

Let's think about it during Go 1.10 development.

bradfitz commented 6 years ago

Pushing to Go 1.11.

@tombergan, do you know what's right here?

gopherbot commented 6 years ago

Change https://golang.org/cl/115135 mentions this issue: net/http/httputil: pass through any "TE: trailers" header to backend

Cas-pian commented 6 years ago

@gopherbot I've tested the go1.11beta2, the "Te" header in the client still missing when request backend server, I'm using traefik. Thanks.

bradfitz commented 6 years ago

@Cas-pian, you probably didn't recompile your application or didn't do so with the right version of Go.

Cas-pian commented 6 years ago

@bradfitz Thanks for your reply. I've recompile my application. And I found the application didn't use your function. I've fixed it. Thanks again!

idefixcert commented 5 years ago

I have the same problem but cant find a solution: I have a ProxyServer written in go

func main() {
    log.SetPrefix("[proxy] ")
    log.SetOutput(os.Stdout)
    if upstream == "" {
        log.Fatal("ERROR: missing argument upstream ")
    }
    url, _ := url.Parse(upstream)
    proxy := &Upstream{target: url, proxy: httputil.NewSingleHostReverseProxy(url)}
    mux := http.NewServeMux()
    mux.HandleFunc("/", proxy.handle)
    log.Fatal(http.ListenAndServeTLS(httpsSocket, httpsCert, httpsKey, mux))
}

type Upstream struct {
    target *url.URL
    proxy  *httputil.ReverseProxy
}

func (p *Upstream) handle(w http.ResponseWriter, r *http.Request) {
    p.proxy.ServeHTTP(w, r)
}

If I make a call from gnmi server to client, I get:

[proxy] 2019/01/16 12:34:57 http: proxy error: net/http: HTTP/1.x transport connection broken: write tcp 127.0.0.1:55595->127.0.0.1:10161: write: broken pipe
[proxy] 2019/01/16 12:35:15 http: proxy error: net/http: HTTP/1.x transport connection broken: malformed HTTP response "\x00\x00\x00\x04\x00\x00\x00\x00\x00"
[proxy] 2019/01/16 12:35:31 http: proxy error: net/http: HTTP/1.x transport connection broken: malformed HTTP response "\x00\x00\x00\x04\x00\x00\x00\x00\x00"

Any hints?