Grpc-web: proxy: stream terminated by RST_STREAM

[jonahbron]

I'm trying to get a basic example of grpc-web working in my application. Using the HelloWorld service example from the grpc-node library, and the example code from grpc-web/example, I've put together what I think should work. The proxy connects to my server...

time="2018-02-27T18:22:42Z" level=info msg="dialing to target with scheme: \"\"" system=system
time="2018-02-27T18:22:42Z" level=info msg="listening for http_tls on: [::]:8443"
time="2018-02-27T18:22:42Z" level=info msg="ccResolverWrapper: sending new addresses to cc: [{stern-server:9000 0  <nil>}]" system=system
time="2018-02-27T18:22:42Z" level=info msg="ClientConn switching balancer to \"pick_first\"" system=system
time="2018-02-27T18:22:42Z" level=info msg="listening for http on: [::]:8080"
time="2018-02-27T18:22:42Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc42016e370, CONNECTING" system=system
time="2018-02-27T18:22:42Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc42016e370, READY" system=system

When I use the client to make the call, it creates a request like this (copied as cURL from Chrome network log):

curl 'https://localhost:8443/helloworld.Greeter/SayHello' -H 'origin: https://localhost:4200' -H 'accept-encoding: gzip, deflate, br' -H 'accept-language: en-US,en;q=0.9' -H 'user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.167 Safari/537.36' -H 'content-type: application/grpc-web+proto' -H 'accept: */*' -H 'x-grpc-web: 1' -H 'referer: https://localhost:4200/operations' -H 'authority: localhost:8443' --data-binary $'\x00\x00\x00\x00\x04\n\x02yo' --compressed --insecure

But this is the error message it gives back:

stream terminated by RST_STREAM with error code: INTERNAL_ERROR

That same error shows up in the log output from the proxy itself.

I know my server should work because I created a grpc-node client and it was able to connect just fine.

What could this error indicate? Where should I start looking? I've run out of ideas at this point.

[jonahbron]

Just to experiment, I tried trimming the request down the the absolute minimum, but got the same result. Full output:

$ curl 'https://localhost:8443/helloworld.Greeter/SayHello' -H 'content-type: application/grpc-web+proto' -H 'x-grpc-web: 1' -H 'authority: localhost:8443' --data-binary $'\x00\x00\x00\x00\x04\n\x02yo' --insecure -v
*   Trying ::1...
* TCP_NODELAY set
* Connected to localhost (::1) port 8443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/cert.pem
  CApath: none
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Client hello (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS change cipher, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN, server accepted to use h2
* Server certificate:
*  subject: CN=localhost
*  start date: Feb 27 17:56:43 2018 GMT
*  expire date: Dec 17 17:56:43 2020 GMT
*  issuer: CN=localhost
*  SSL certificate verify result: self signed certificate (18), continuing anyway.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x7fc5dd000400)
> POST /helloworld.Greeter/SayHello HTTP/2
> Host: localhost:8443
> User-Agent: curl/7.54.0
> Accept: */*
> content-type: application/grpc-web+proto
> x-grpc-web: 1
> authority: localhost:8443
> Content-Length: 0
> 
* Connection state changed (MAX_CONCURRENT_STREAMS updated)!
< HTTP/2 200 
< access-control-expose-headers: Grpc-Message, Vary, Content-Type, Grpc-Status
< content-type: application/grpc+proto
< grpc-message: stream terminated by RST_STREAM with error code: INTERNAL_ERROR
< grpc-status: 13
< vary: Origin
< date: Tue, 27 Feb 2018 19:22:30 GMT
< 
* Connection #0 to host localhost left intact

[jonahbron]

I figured out how to get verbose logging out of GRPC. This is the log from the server and the proxy together.
log.txt

[borismus]

I'm seeing the same problem. How did you enable verbose logging?

[jonahbron]

@borismus Set these environmental variables for your server:

GRPC_TRACE=all
GRPC_VERBOSITY=DEBUG

[borismus]

I'm seeing these errors in my server's output in response to my request.

E0227 16:50:35.574250360  250830 call.cc:942]                Invalid entry in accept encoding metadata: ' deflate'. Ignoring.
E0227 16:50:35.574276369  250830 call.cc:942]                Invalid entry in accept encoding metadata: ' br'. Ignoring.

Thanks @jonahbron, will keep digging. DEBUG output is overwhelming.

[jonahbron]

@borismus Yes, I get that error too, but I don't think it's the root cause. If you use a stripped down cURL request like I pasted above (specifically omitting the accept-encoding), those invalid entry errors go away, but you still get the same final error.

[borismus]

Yeah, I think those are benign warnings. I didn't see any actual errors in my gRPC service backend though (see here: https://github.com/improbable-eng/grpc-web/issues/146). Did you?

[jonahbron]

@borismus Not really. The only thing that looks like an error is a line that contains the string: Error received from peer. I don't see that in your file, but I see you only set the verbosity level to "INFO". Try setting it to DEBUG and searching for something like this:

D0227 20:00:30.713151575       1 call.cc:753]                  1: {"created":"@1519761630.713126987","description":"Error received from peer","file":"../deps/grpc/src/core/lib/surface/call.cc","file_line":1148,"grpc_message":"Stream removed","grpc_status":2}

If you get that same error too, we should probably mark our respective tickets as duplicates of each-other.

[jonahbron]

For what it's worth, I did another test with no fields on the request object and that didn't improve anything. I was hoping the bug was specifically related to body encoding or something. No dice.

[jonahbron]

@borismus HOWEVER, when I add debugging output to the server implementation (console.log something), that never shows up. For that reason, I don't think the handler is ever invoked. It really seems like there's a problem with the way that the proxy is formatting the call.

[borismus]

I think it is a dupe. I'm seeing the same error in DEBUG mode...

[jonahbron]

@borismus That's good. Hopefully one of the devs will see this soon and know what's going on. 😀

[jonahbron]

@borismus I found out that there's actually an issue putting null bytes into bash strings (\x00). If you're just using the browser then you're fine, but if you're trying to use cURL, make sure you alter the curl command you copied from Chrome like so:

printf '\x00\x00\x00\x00\x04\n\x02yo' | curl 'https://localhost:8443/helloworld.Greeter/SayHello' -H 'content-type: application/grpc-web+proto' -H 'x-grpc-web: 1' -H 'authority: localhost:8443' --data-binary @- --insecure -v

Compare to my curl command above, it pulls out the value passed to data-binary and pipes it in from printf.

Note that this does not change the outcome, I still get the same INTERNAL_ERROR response.

To highlight that this seems to be a bug with grpcwebproxy, I was able to get a command working through the nginx gateway created on the grpc/grpc-web repository.

https://github.com/grpc/grpc-web/issues/152

^ That's a private repository for now apparently, so you have to request access if you don't already have it.

[jonahbron]

It looks like this is a bug that was introduced some time between now and October 27th last year. I say that because I was able to get a working proxy running from this Docker image, last built with the current master code on October 27th.

https://store.docker.com/community/images/jfyne/docker-grpcwebproxy/builds
https://github.com/jfyne/docker-grpcwebproxy/commits/master

I'm able to make calls to this build of the proxy server. Here are the commits made to the proxy:

https://github.com/improbable-eng/grpc-web/commits/master/go/grpcwebproxy

Without much knowledge of the code, these two commits look like they're most likely to have caused a regression:

https://github.com/improbable-eng/grpc-web/commit/5539469b5d7040156fd9c270bf14d77f08e220b1#diff-74efd2d8a9d5e4c02bef1573c46685b4
https://github.com/improbable-eng/grpc-web/commit/595734003c5631cfc448bdf919d0980271130da8#diff-74efd2d8a9d5e4c02bef1573c46685b4

Can one of the devs take a look at those?

[Matan]

Same issue here! I was able to get the docker image working which was built 4 months ago.

[jmrobles]

Workaround, not use a context created with metadata

func buildGrpcProxyServer(logger *logrus.Entry) *grpc.Server {
    // gRPC-wide changes.
    grpc.EnableTracing = true
    grpc_logrus.ReplaceGrpcLogger(logger)

    // gRPC proxy logic.
    backendConn := dialBackendOrFail()
    director := func(ctx context.Context, fullMethodName string) (context.Context, *grpc.ClientConn, error) {
        //md, _ := metadata.FromIncomingContext(ctx)
        outCtx, _ := context.WithCancel(ctx)
        //outCtx = metadata.NewOutgoingContext(outCtx, md.Copy())
        return outCtx, backendConn, nil
    }
    // Server with logging and monitoring enabled.
    return grpc.NewServer(
        grpc.CustomCodec(proxy.Codec()), // needed for proxy to function.
        grpc.UnknownServiceHandler(proxy.TransparentHandler(director)),
        grpc_middleware.WithUnaryServerChain(
            grpc_logrus.UnaryServerInterceptor(logger),
            grpc_prometheus.UnaryServerInterceptor,
        ),
        grpc_middleware.WithStreamServerChain(
            grpc_logrus.StreamServerInterceptor(logger),
            grpc_prometheus.StreamServerInterceptor,
        ),
    )
}

But dunno, if it's a compat issue with grpcio-tools (in my case) at Django backend.

[hpidcock]

Appears to be an issue with forwarding the user-agent metadata/header.
Removing it fixes it.

`outCtx, _ := context.WithCancel(ctx)

mdCopy := md.Copy()

delete(mdCopy, "user-agent")

outCtx = metadata.NewOutgoingContext(outCtx, mdCopy)`

[Matan]

Is this project still alive? The official gRPC team are building a grpc-web version. See https://stackoverflow.com/a/41243005/578277

My worry is that the master branch has been broken (just referring to the go-proxy) for quite a while with no one stepping up to fix it. I'd like to fix it, but my go knowledge is far from good enough to tackle it.

[johanbrandhorst]

The project is still alive, and FYI the official gRPC team has been working on gRPC-Web for 2 years now without putting out anything, so I wouldn't hold my breath for that. They're moving at a glacial pace as far as I can tell, perhaps dragging their feet and waiting for the Streams API to land in browsers.

[Matan]

That's good to hear. :) Any indication to when this issue would be resolved?

[johanbrandhorst]

I'm not part of the team that maintain this, but I think a first step towards fixing this would be diagnosing what's going wrong, there seems to be some information on what triggers the bug, but more diagnostic would be helpful. Also, the project does accept PRs, so feel free to just submit one removing the user agent string.

[Matan]

Ah ok, believe there is more capable people on this thread. I wouldn't feel comfortable submitting a PR as I'm not fully clued-up.

[MrWinstead]

Gentlemen, I've applied the patch suggested by @hpidcock and things are functional again. See PR 148.

[jonahbron]

You're my hero @MrWinstead . Commented on your PR.

[jonny-improbable]

Fixed by #148, thanks to @MrWinstead for the patch.

[lnshi]

@jmrobles @hpidcock @jonahbron sorry to @ you guys at closed issue.

Can someone help to explain me what is the magic/difference here? I mean

outCtx := metadata.NewOutgoingContext(ctx, md.Copy())
outCtx, cancel := context.WithCancel(outCtx)

vs

outCtx, _ := context.WithCancel(ctx)
mdCopy := md.Copy()
outCtx = metadata.NewOutgoingContext(outCtx, mdCopy)

It looks like really a dirty black magic if the first way cause any problem....

[johanbrandhorst]

There should be no difference between the two options you've just posted, and I'm not sure the previous posts imply that there would be? The question seems to be about certain headers causing trouble. Could you clarify your concerns please?

[lnshi]

@johanbrandhorst ah, sorry, i didn't read it properly.