http/2 transport failing for gRPC #3236

Zetanova · 2020-04-07T14:17:30Z

caddy2 is currently not handling the http/2 protocol well.
and this results that gRPC responses are not working.

the issue is that caddy is expecting a regular http1 response,
but a http/2 stream response is not handled at all.

caddy should handle every http/2-request and http/2-responses
as a unique http2-stream and proxy all frames to the same server and/or client
until STREAM_END is received.

I made a simple demo project to reproduce the behavior:
https://github.com/Zetanova/caddy-grpc-demo

Log output:

....
caddy_1           | {"level":"info","ts":1586265748.2906666,"logger":"http.log.access.log0","msg":"handled request","request":{"method":"POST","uri":"/
helloworld.Greeter/SayHello","proto":"HTTP/2.0","remote_addr":"172.24.0.1:47020","host":"localhost:50051","headers":{"Grpc-Timeout":["999985u"],"Conten
t-Type":["application/grpc"],"User-Agent":["grpc-go/1.29.0-dev"],"Te":["trailers"]}},"common_log":"172.24.0.1 - - [07/Apr/2020:13:22:28 +0000] \"POST /
helloworld.Greeter/SayHello HTTP/2.0\" 200 18","latency":0.0046437,"size":18,"status":200,"resp_headers":{"Server":["Caddy"],"Content-Type":["applicati
on/grpc"],"Trailer:Grpc-Status":["0"],"Trailer:Grpc-Message":[""]}}
greeter_client_1  | 2020/04/07 13:22:28 could not greet: rpc error: code = Internal desc = server closed the stream without sending trailers
greeter_client_1  | exit status 1

The text was updated successfully, but these errors were encountered:

mholt · 2020-04-07T14:24:28Z

Thanks for the sample repository. Do you have a repro without Docker though? I don't have Docker installed (I don't use Linux) also we want to simplify things as much as possible when isolating buggy behavior.

Edit: Nevermind. Maybe I can just run the binaries that are described in the Dockerfiles. That should work I guess.

Zetanova · 2020-04-07T14:52:52Z

Go itself had this issue with the trailing header:
golang/go#21096

francislavoie · 2020-04-07T14:56:02Z

I don't have Docker installed (I don't use Linux)

Docker runs just fine on Mac btw. Uses a VM under the hood. IO performance is worse, but it's good enough to do basically everything except performance testing

mholt · 2020-04-07T15:14:58Z

@Zetanova K I got the server and of course Caddy up and running with your config.

How do I reproduce the isssue though?

This works (at least, as I would expect):

$ grpcurl -plaintext localhost:80 my.custom.server.Service/Method

Yields caddy logs:

2020/04/07 15:14:29.843 DEBUG   http.handlers.reverse_proxy     upstream roundtrip      {"upstream": "localhost:50051", "request": {"method": "POST", "uri": "/grpc.reflection.v1alpha.ServerReflection/ServerReflectionInfo", "proto": "HTTP/2.0", "remote_addr": "[::1]:65174", "host": "localhost", "headers": {"X-Forwarded-For": ["::1"], "Content-Type": ["application/grpc"], "User-Agent": ["grpc-go/1.28.0"], "Te": ["trailers"]}}, "headers": {"Content-Type": ["application/grpc"], "Grpc-Status": ["12"], "Grpc-Message": ["unknown service grpc.reflection.v1alpha.ServerReflection"]}, "duration": 0.000200256, "status": 200}
2020/04/07 15:14:29.843 INFO    http.log.access handled request {"request": {"method": "POST", "uri": "/grpc.reflection.v1alpha.ServerReflection/ServerReflectionInfo", "proto": "HTTP/2.0", "remote_addr": "[::1]:65174", "host": "localhost:80", "headers": {"Content-Type": ["application/grpc"], "User-Agent": ["grpc-go/1.28.0"], "Te": ["trailers"]}}, "common_log": "::1 - - [07/Apr/2020:09:14:29 -0600] \"POST /grpc.reflection.v1alpha.ServerReflection/ServerReflectionInfo HTTP/2.0\" 200 0", "latency": 0.000277344, "size": 0, "status": 200, "resp_headers": {"Server": ["Caddy"], "Grpc-Status": ["12"], "Grpc-Message": ["unknown service grpc.reflection.v1alpha.ServerReflection"], "Content-Type": ["application/grpc"]}}
2020/04/07 15:14:29.844 DEBUG   http.handlers.reverse_proxy     upstream roundtrip      {"upstream": "localhost:50051", "request": {"method": "POST", "uri": "/grpc.reflection.v1alpha.ServerReflection/ServerReflectionInfo", "proto": "HTTP/2.0", "remote_addr": "[::1]:65174", "host": "localhost", "headers": {"Content-Type": ["application/grpc"], "User-Agent": ["grpc-go/1.28.0"], "Te": ["trailers"], "X-Forwarded-For": ["::1"]}}, "headers": {"Content-Type": ["application/grpc"], "Grpc-Status": ["12"], "Grpc-Message": ["unknown service grpc.reflection.v1alpha.ServerReflection"]}, "duration": 0.000152639, "status": 200}
2020/04/07 15:14:29.844 INFO    http.log.access handled request {"request": {"method": "POST", "uri": "/grpc.reflection.v1alpha.ServerReflection/ServerReflectionInfo", "proto": "HTTP/2.0", "remote_addr": "[::1]:65174", "host": "localhost:80", "headers": {"Content-Type": ["application/grpc"], "User-Agent": ["grpc-go/1.28.0"], "Te": ["trailers"]}}, "common_log": "::1 - - [07/Apr/2020:09:14:29 -0600] \"POST /grpc.reflection.v1alpha.ServerReflection/ServerReflectionInfo HTTP/2.0\" 200 0", "latency": 0.000207439, "size": 0, "status": 200, "resp_headers": {"Server": ["Caddy"], "Content-Type": ["application/grpc"], "Grpc-Status": ["12"], "Grpc-Message": ["unknown service grpc.reflection.v1alpha.ServerReflection"]}}

Zetanova · 2020-04-07T16:06:47Z

@mholt

test setup is:
[golang grpc client] <> [caddy] <> [golang grpc server]

Its only in h2c mode because the golang helloworld example has no TLS support.

I think its only the Hop-Hop header removal of TE header

This fix should/maybe solves the problem:
https://go-review.googlesource.com/c/go/+/115135/4/src/net/http/httputil/reverseproxy.go

mholt · 2020-04-07T16:08:52Z

@Zetanova Caddy already uses that patch:

caddy/modules/caddyhttp/reverseproxy/reverseproxy.go

Lines 389 to 405 in 8b2dbc5

    
           // Remove hop-by-hop headers to the backend. Especially 
        
           // important is "Connection" because we want a persistent 
        
           // connection, regardless of what the client sent to us. 
        
           for _, h := range hopHeaders { 
        
           	hv := req.Header.Get(h) 
        
           	if hv == "" { 
        
           		continue 
        
           	} 
        
           	if h == "Te" && hv == "trailers" { 
        
           		// Issue golang/go#21096: tell backend applications that 
        
           		// care about trailer support that we support 
        
           		// trailers. (We do, but we don't go out of 
        
           		// our way to advertise that unless the 
        
           		// incoming client request thought it was 
        
           		// worth mentioning) 
        
           		continue 
        
           	}

grpcurl is a Go gRPC client -- how can I reproduce the error using that? i.e. what grpcurl command can I use to reproduce the error you get?

Zetanova · 2020-04-07T16:12:44Z

@mholt it should be grpcurl -plaintext localhost:80 /helloworld.Greeter/SayHello or grpcurl -plaintext localhost:80 helloworld.Greeter/SayHello

mholt · 2020-04-07T16:16:09Z

@Zetanova Thanks; both of those "work" though (no error as you've reported) -- but grpcurl's output is:

Error invoking method "helloworld.Greeter/SayHello": failed to query for service descriptor "helloworld.Greeter": server does not support the reflection API

How can I see the error you're seeing?

Zetanova · 2020-04-07T16:21:35Z

@mholt grpcurl -d '{"name": "world"}' -plaintext localhost:80 helloworld.Greeter/SayHello

mholt · 2020-04-07T16:24:16Z

Hmm, same result...

% grpcurl -d '{"name": "world"}' -plaintext localhost:80 helloworld.Greeter/SayHello
Error invoking method "helloworld.Greeter/SayHello": failed to query for service descriptor "helloworld.Greeter": server does not support the reflection API

Logs:

2020/04/07 16:24:02.335 DEBUG   http.handlers.reverse_proxy     upstream roundtrip      {"upstream": "localhost:50051", "request": {"method": "POST", "uri": "/grpc.reflection.v1alpha.ServerReflection/ServerReflectionInfo", "proto": "HTTP/2.0", "remote_addr": "[::1]:49945", "host": "localhost", "headers": {"Content-Type": ["application/grpc"], "User-Agent": ["grpc-go/1.28.0"], "Te": ["trailers"], "X-Forwarded-For": ["::1"]}}, "headers": {"Grpc-Status": ["12"], "Grpc-Message": ["unknown service grpc.reflection.v1alpha.ServerReflection"], "Content-Type": ["application/grpc"]}, "duration": 0.000186636, "status": 200}
2020/04/07 16:24:02.335 INFO    http.log.access handled request {"request": {"method": "POST", "uri": "/grpc.reflection.v1alpha.ServerReflection/ServerReflectionInfo", "proto": "HTTP/2.0", "remote_addr": "[::1]:49945", "host": "localhost:80", "headers": {"Te": ["trailers"], "Content-Type": ["application/grpc"], "User-Agent": ["grpc-go/1.28.0"]}}, "common_log": "::1 - - [07/Apr/2020:10:24:02 -0600] \"POST /grpc.reflection.v1alpha.ServerReflection/ServerReflectionInfo HTTP/2.0\" 200 0", "latency": 0.000248992, "size": 0, "status": 200, "resp_headers": {"Content-Type": ["application/grpc"], "Grpc-Status": ["12"], "Grpc-Message": ["unknown service grpc.reflection.v1alpha.ServerReflection"], "Server": ["Caddy"]}}
2020/04/07 16:24:02.336 DEBUG   http.handlers.reverse_proxy     upstream roundtrip      {"upstream": "localhost:50051", "request": {"method": "POST", "uri": "/grpc.reflection.v1alpha.ServerReflection/ServerReflectionInfo", "proto": "HTTP/2.0", "remote_addr": "[::1]:49945", "host": "localhost", "headers": {"Content-Type": ["application/grpc"], "User-Agent": ["grpc-go/1.28.0"], "Te": ["trailers"], "X-Forwarded-For": ["::1"]}}, "headers": {"Content-Type": ["application/grpc"], "Grpc-Status": ["12"], "Grpc-Message": ["unknown service grpc.reflection.v1alpha.ServerReflection"]}, "duration": 0.000131974, "status": 200}
2020/04/07 16:24:02.336 INFO    http.log.access handled request {"request": {"method": "POST", "uri": "/grpc.reflection.v1alpha.ServerReflection/ServerReflectionInfo", "proto": "HTTP/2.0", "remote_addr": "[::1]:49945", "host": "localhost:80", "headers": {"Te": ["trailers"], "Content-Type": ["application/grpc"], "User-Agent": ["grpc-go/1.28.0"]}}, "common_log": "::1 - - [07/Apr/2020:10:24:02 -0600] \"POST /grpc.reflection.v1alpha.ServerReflection/ServerReflectionInfo HTTP/2.0\" 200 0", "latency": 0.00018989, "size": 0, "status": 200, "resp_headers": {"Grpc-Message": ["unknown service grpc.reflection.v1alpha.ServerReflection"], "Server": ["Caddy"], "Content-Type": ["application/grpc"], "Grpc-Status": ["12"]}}

Does this error for you?

Zetanova · 2020-04-07T16:55:57Z

@mholt didnt testet it with grpclient

I made now a simple golang proxy:
https://github.com/Zetanova/caddy-grpc-demo/blob/master/golang-proxy/main.go

To proxy gRPC is working with simple proxy.

mholt · 2020-04-07T17:04:58Z

@Zetanova Thanks, but how can the rest of us encounter the same error you are reporting? Can you test it with grpcurl? We aren't able to fix it if we can't reproduce the error.

mholt · 2020-04-10T15:22:25Z

@Zetanova Any update on this? Would love to be able to get the error you're seeing.

Zetanova · 2020-04-20T09:13:35Z

@mholt sry for the delay
The error is persistent/same

your requested command:

$ grpcurl -d '{"name": "world"}' -plaintext host.docker.internal:50051 helloworld.Greeter/SayHello

Error invoking method "helloworld.Greeter/SayHello": failed to query for service descriptor "helloworld.Greeter": server does not support the reflection API

Server-Log:

caddy_1           | {"level":"info","ts":1587373186.2891846,"logger":"http.log.access.log0","msg":"handled request","req
uest":{"method":"POST","uri":"/grpc.reflection.v1alpha.ServerReflection/ServerReflectionInfo","proto":"HTTP/2.0","remote
_addr":"172.24.0.1:32788","host":"host.docker.internal:50051","headers":{"Content-Type":["application/grpc"],"User-Agent
":["grpc-go/1.30.0-dev"],"Te":["trailers"]}},"common_log":"172.24.0.1 - - [20/Apr/2020:08:59:46 +0000] \"POST /grpc.refl
ection.v1alpha.ServerReflection/ServerReflectionInfo HTTP/2.0\" 200 0","latency":0.0026398,"size":0,"status":200,"resp_h
eaders":{"Server":["Caddy"],"Content-Type":["application/grpc"],"Grpc-Status":["12"],"Grpc-Message":["unknown service gr
pc.reflection.v1alpha.ServerReflection"]}}

modified command with proto file:

$ grpcurl -d '{"name": "world"}' -proto "helloworld/helloworld.proto" -plaintext host.docker.internal:50051 helloworld.Greeter/SayHello

ERROR:
  Code: Internal
  Message: server closed the stream without sending trailers

Server-Log:

greeter_server_1  | 2020/04/20 09:10:36 Received: world
caddy_1           | {"level":"info","ts":1587373836.3367207,"logger":"http.log.access.log0","msg":"handled request","req
uest":{"method":"POST","uri":"/helloworld.Greeter/SayHello","proto":"HTTP/2.0","remote_addr":"172.24.0.1:32836","host":"
host.docker.internal:50051","headers":{"Content-Type":["application/grpc"],"User-Agent":["grpc-go/1.30.0-dev"],"Te":["tr
ailers"]}},"common_log":"172.24.0.1 - - [20/Apr/2020:09:10:36 +0000] \"POST /helloworld.Greeter/SayHello HTTP/2.0\" 200
18","latency":0.0037791,"size":18,"status":200,"resp_headers":{"Server":["Caddy"],"Content-Type":["application/grpc"],"T
railer:Grpc-Message":[""],"Trailer:Grpc-Status":["0"]}}
caddy_1           | {"level":"info","ts":1587373836.3367207,"logger":"http.log.access.log0","msg":"handled request","req
uest":{"method":"POST","uri":"/helloworld.Greeter/SayHello","proto":"HTTP/2.0","remote_addr":"172.24.0.1:32836","host":"
host.docker.internal:50051","headers":{"Content-Type":["application/grpc"],"User-Agent":["grpc-go/1.30.0-dev"],"Te":["tr
ailers"]}},"common_log":"172.24.0.1 - - [20/Apr/2020:09:10:36 +0000] \"POST /helloworld.Greeter/SayHello HTTP/2.0\" 200
18","latency":0.0037791,"size":18,"status":200,"resp_headers":{"Server":["Caddy"],"Content-Type":["application/grpc"],"T
railer:Grpc-Message":[""],"Trailer:Grpc-Status":["0"]}}

mholt · 2020-04-21T00:10:13Z

@Zetanova Thanks, I can see the error now. I'll look into it. Do you have any ideas where we might be going wrong?

mholt · 2020-04-21T00:16:39Z

@Zetanova As you can see, the logs show that trailers are being written:

"resp_headers":{"Server":["Caddy"],"Content-Type":["application/grpc"],"Trailer:Grpc-Message":[""],"Trailer:Grpc-Status":["0"]}}

Do you have any insights as to what is expected, if that's not it?

mholt · 2020-04-21T01:50:55Z

@Zetanova I've spent most of the evening trying to figure out what is going on 😓

This minimal program proxies correctly:

package main

import (
	"crypto/tls"
	"log"
	"net"
	"net/http"
	"net/http/httputil"
	"net/url"

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

func main() {
	upURL, err := url.Parse("http://localhost:50051")
	if err != nil {
		log.Fatal(err)
	}

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

	h2s := &http2.Server{}
	handler := h2c.NewHandler(rp, h2s)

	log.Println("Proxying at localhost:7777")
	http.ListenAndServe("localhost:7777", handler)
}

I've been drilling down into the http2 libs and trying to figure out why the server is closing the connection. As far as I can tell, we're doing the exact same thing as the above program.

Any chance you can help debug this?

For anyone following along at home, I'm on the h2c branch of this repo, using this config:

{
	"logging": {
		"logs": {
			"default": {
				"level": "DEBUG"
			}
		}
	},
	"apps": {
		"http": {
			"servers": {
				"srv0": {
					"listen": [
						":80"
					],
					"insecure_h2c": true,
					"routes": [
						{
							"handle": [
								{
									"handler": "reverse_proxy",
									"headers": {
										"request": {
											"set": {
												"Host": [
													"localhost"
												]
											}
										}
									},
									"transport": {
										"protocol": "http",
										"versions": ["h2c"]
									},
									"upstreams": [
										{
											"dial": "localhost:50051"
										}
									]
								}
							]
						}
					],
					"logs": {}
				}
			}
		}
	}
}

And then using the demo server above provided by @Zetanova, and this command:

$ grpcurl -d '{"name": "world"}' -proto "helloworld/helloworld.proto" -plaintext localhost:80 helloworld.Greeter/SayHello

mholt · 2020-04-21T02:09:37Z

Hold the phone.

Disabling access/request logging (removing "logs": {} from the config) makes it work. Can you verify, @Zetanova ?

mholt · 2020-04-21T03:07:16Z

@Zetanova I am pretty sure I have fixed it in 3c55cf9 in the h2c branch. Could you pull that and try it out? 😃

As a bonus, this should slightly improve performance.

Zetanova · 2020-04-21T05:26:41Z

@mholt It is working now with logging and the original golang gRPC sample client/server

mholt · 2020-04-21T05:30:52Z

@Zetanova Excellent! Is there anything else remaining then?

Zetanova · 2020-04-21T05:37:34Z

@mholt The h2, h2c (tcp, uds) + gRPC support looks ok.

mholt · 2020-04-21T05:47:44Z

Great - thank you for your help!

* reverse_proxy: Initial attempt at H2C transport/client support (#3218) I have not tested this yet * Experimentally enabling H2C server support (closes #3227) See also #3218 I have not tested this * reverseproxy: Clean up H2C transport a bit * caddyhttp: Update godoc for h2c server; clarify experimental status * caddyhttp: Fix trailers when recording responses (fixes #3236) * caddyhttp: Tweak h2c config settings and docs

mholt changed the title ~~BUG: http/2 transport failing for gRPC~~ http/2 transport failing for gRPC Apr 7, 2020

mholt added the needs info 📭 Requires more information label Apr 7, 2020

mholt added bug 🐞 Something isn't working help wanted 🆘 Extra attention is needed and removed needs info 📭 Requires more information labels Apr 21, 2020

mholt added this to the 2.x milestone Apr 21, 2020

mholt removed the help wanted 🆘 Extra attention is needed label Apr 21, 2020

mholt added a commit that referenced this issue Apr 21, 2020

caddyhttp: Fix trailers when recording responses (fixes #3236)

3c55cf9

mholt modified the milestones: 2.x, 2.1 Apr 21, 2020

mholt linked a pull request Apr 21, 2020 that will close this issue

httpserver: Add H2C support #3289

Merged

Zetanova closed this as completed Apr 21, 2020

mholt added a commit that referenced this issue Apr 22, 2020

caddyhttp: Fix trailers when recording responses (fixes #3236)

026937f

mholt mentioned this issue May 12, 2020

proxying http2 explicitly #1772

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

http/2 transport failing for gRPC #3236

http/2 transport failing for gRPC #3236

Zetanova commented Apr 7, 2020

mholt commented Apr 7, 2020 •

edited

Loading

Zetanova commented Apr 7, 2020

francislavoie commented Apr 7, 2020 •

edited

Loading

mholt commented Apr 7, 2020

Zetanova commented Apr 7, 2020

mholt commented Apr 7, 2020 •

edited

Loading

Zetanova commented Apr 7, 2020

mholt commented Apr 7, 2020

Zetanova commented Apr 7, 2020

mholt commented Apr 7, 2020

Zetanova commented Apr 7, 2020

mholt commented Apr 7, 2020 •

edited

Loading

mholt commented Apr 10, 2020

Zetanova commented Apr 20, 2020

mholt commented Apr 21, 2020

mholt commented Apr 21, 2020

mholt commented Apr 21, 2020 •

edited

Loading

mholt commented Apr 21, 2020 •

edited

Loading

mholt commented Apr 21, 2020 •

edited

Loading

Zetanova commented Apr 21, 2020

mholt commented Apr 21, 2020

Zetanova commented Apr 21, 2020

mholt commented Apr 21, 2020

http/2 transport failing for gRPC #3236

http/2 transport failing for gRPC #3236

Comments

Zetanova commented Apr 7, 2020

mholt commented Apr 7, 2020 • edited Loading

Zetanova commented Apr 7, 2020

francislavoie commented Apr 7, 2020 • edited Loading

mholt commented Apr 7, 2020

Zetanova commented Apr 7, 2020

mholt commented Apr 7, 2020 • edited Loading

Zetanova commented Apr 7, 2020

mholt commented Apr 7, 2020

Zetanova commented Apr 7, 2020

mholt commented Apr 7, 2020

Zetanova commented Apr 7, 2020

mholt commented Apr 7, 2020 • edited Loading

mholt commented Apr 10, 2020

Zetanova commented Apr 20, 2020

mholt commented Apr 21, 2020

mholt commented Apr 21, 2020

mholt commented Apr 21, 2020 • edited Loading

mholt commented Apr 21, 2020 • edited Loading

mholt commented Apr 21, 2020 • edited Loading

Zetanova commented Apr 21, 2020

mholt commented Apr 21, 2020

Zetanova commented Apr 21, 2020

mholt commented Apr 21, 2020

mholt commented Apr 7, 2020 •

edited

Loading

francislavoie commented Apr 7, 2020 •

edited

Loading

mholt commented Apr 7, 2020 •

edited

Loading

mholt commented Apr 7, 2020 •

edited

Loading

mholt commented Apr 21, 2020 •

edited

Loading

mholt commented Apr 21, 2020 •

edited

Loading

mholt commented Apr 21, 2020 •

edited

Loading