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.

Sign up for GitHub

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

Jump to bottom

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

Closed
groob opened this issue Jul 20, 2017 · 15 comments
Closed

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

groob opened this issue Jul 20, 2017 · 15 comments
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Milestone
Go1.11

Comments

@groob
Copy link
Contributor

groob commented Jul 20, 2017

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
Copy link
Contributor

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
Copy link
Contributor Author

groob commented Jul 20, 2017 •
edited
Loading

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
Copy link
Contributor Author

groob commented Jul 20, 2017

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"```

@bradfitz bradfitz changed the title x/net/http2 transport results in stream error INTERNAL_ERROR x/net/http2: transport results in stream error INTERNAL_ERROR when proxying to C grpc server Jul 20, 2017
@groob
Copy link
Contributor Author

groob commented Jul 20, 2017

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
Copy link
Contributor

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
Copy link
Contributor Author

groob commented Jul 20, 2017

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

go/src/net/http/httputil/reverseproxy.go

Line 135 in 3498012

"Te", // canonicalized version of "TE"

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

@groob
Copy link
Contributor Author

groob commented Jul 20, 2017 •
edited
Loading

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
Copy link
Contributor Author

groob commented Jul 21, 2017

@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
Copy link
Contributor

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 bradfitz changed the title x/net/http2: transport results in stream error INTERNAL_ERROR when proxying to C grpc server net/http/httputil: ReverseProxy doesn't proxy grpc without help due to 'te' header handling Jul 21, 2017
@bradfitz bradfitz added the NeedsDecision Feedback is required from experts, contributors, and/or the community before a change can be made. label Jul 21, 2017
@bradfitz bradfitz added this to the Go1.10 milestone Jul 21, 2017
@bradfitz
Copy link
Contributor

bradfitz commented Dec 4, 2017

Pushing to Go 1.11.

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

@bradfitz bradfitz modified the milestones: Go1.10, Go1.11 Dec 4, 2017
@bradfitz bradfitz assigned bradfitz and unassigned tombergan May 29, 2018
@bradfitz bradfitz added the NeedsFix The path to resolution is known, but the work has not been done. label May 29, 2018
@gopherbot
Copy link
Contributor

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

@gopherbot gopherbot removed the NeedsDecision Feedback is required from experts, contributors, and/or the community before a change can be made. label May 29, 2018
This was referenced Jun 15, 2018
Closed
Closed
@Cas-pian
Copy link

@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
Copy link
Contributor

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

@Cas-pian
Copy link

@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
Copy link

idefixcert commented Jan 16, 2019 •
edited
Loading

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?

@buger buger mentioned this issue Feb 11, 2019
Closed
buger added a commit to TykTechnologies/tyk that referenced this issue Feb 11, 2019
@buger
Fix gRPC proxying
00113fd 
Pass "Te" trailer. See golang/go#21096
@buger buger mentioned this issue Feb 11, 2019
Closed
furkansenharputlu pushed a commit to furkansenharputlu/tyk that referenced this issue Feb 15, 2019
@buger @furkansenharputlu
Fix gRPC proxying
56f3a87 
Pass "Te" trailer. See golang/go#21096
@furkansenharputlu furkansenharputlu mentioned this issue Feb 15, 2019
Merged
buger pushed a commit to TykTechnologies/tyk that referenced this issue Feb 15, 2019
@furkansenharputlu @buger
Fix gRPC and add test (#2119)
c589132 
Pass "Te" trailer. See golang/go#21096

This PR adds gRPC test.

Fixes #2105
@golang golang locked and limited conversation to collaborators Jan 16, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Milestone
Go1.11
Development

No branches or pull requests
6 participants
@bradfitz @groob @idefixcert @Cas-pian @gopherbot @tombergan