http/2 transport failing for gRPC

[Zetanova]

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.

Info on the gRPC protocol

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

[mholt]

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]

Go itself had this issue with the trailing header: https://github.com/golang/go/issues/21096

[francislavoie]

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]

@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]

@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]

@Zetanova Caddy already uses that patch: https://github.com/caddyserver/caddy/blob/8b2dbc52ec6bc0359b4b8c47a3f9835e9460649e/modules/caddyhttp/reverseproxy/reverseproxy.go#L389-L405

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]

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

[mholt]

@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]

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

[mholt]

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]

@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]

@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]

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

[Zetanova]

@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]

@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]

@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]

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

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]

Hold the phone.

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

[mholt]

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

As a bonus, this should slightly improve performance.

[Zetanova]

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

[mholt]

@Zetanova Excellent! Is there anything else remaining then?

[Zetanova]

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

[mholt]

Great - thank you for your help!