On context deadline exceeded, response headers aren't set

[miparnisari]

🐛 Bug Report

When a request exceeds runtime.DefaultContextTimeout, a context deadline exceeded error is returned to the client. However, any prior headers that were set via grpc.SetHeader aren't returned to the client.

To Reproduce

1. git clone https://github.com/miparnisari/jaegerGoTest && cd jaegerGoTest && git checkout c0189835bf9d8af8b81636916ef2608dbdf871f3
2. docker-compose up --build
3. curl http://localhost:8080/01HVHZX1S19BBD8J8CVW535KB0 -v

Expected behavior

Custom header Grpc-Metadata-Store-Id-Header: 01HVHZX1S19BBD8J8CVW535KB0 is visible in the response

Actual Behavior

[23/04/24 9:26:47] ~/GitHub/jaegerGoTest (master) $ curl http://localhost:8080/01HVHZX1S19BBD8J8CVW535KB0 -v
*   Trying [::1]:8080...
* Connected to localhost (::1) port 8080
> GET /01HVHZX1S19BBD8J8CVW535KB0 HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/8.4.0
> Accept: */*
> 
< HTTP/1.1 504 Gateway Timeout
< Content-Type: application/json
< Date: Wed, 24 Apr 2024 04:29:15 GMT
< Content-Length: 61
< 
* Connection #0 to host localhost left intact
{"code":4,"message":"context deadline exceeded","details":[]}%
[23/04/24 9:29:15] ~/GitHub/jaegerGoTest (master) $ 

Your Environment

• MacOS Sonoma 14.4.1
• github.com/grpc-ecosystem/grpc-gateway/v2 v2.19.1
• github.com/grpc/grpc-go v1.63.2

[johanbrandhorst]

Hi, thanks for your issue! I'm a little confused about exactly what the bug is here. From what I can gather, this is the chain of events:

1. curl sends HTTP request to server
2. gRPC-Gateway handles the request
3. The request reaches the gRPC server
4. The store ID interceptor runs on the gRPC server, storing an ID in the ctx via grpc.SetHeader (not actually sure this works, since the use of the grpc-ecosystem interceptor pattern is making things hard to follow).
5. The gRPC server handler runs, which sleeps for 1 second, causing the gRPC client to time out the request.

Is this correct? Because as far as I'm concerned there is no way for the server to do anything while the handler is sleeping, and the gRPC client is timing out without waiting for a response. What do you think the gateway is doing wrong here? Nothing has been written on the wire for it to translate, and even if it was, I'm not sure it should.

Perhaps you could start by explaining what you were trying to do, and we can see if there's some other way to do it? I would recommend simplifying your test repo to just the essentials too (I assume the OTel observability stuff isn't necessary to exhibit the issue).

Thanks!

[miparnisari]

Hey @johanbrandhorst, thanks for the fast response 🙇‍♀️ I've trimmed the repo now 😄

I'm a little confused about exactly what the bug is here

It's likely that it's not a bug, more of a misunderstanding on my part on how to achieve my goal.

Perhaps you could start by explaining what you were trying to do

Yes, sorry, I wasn't clear. My goal is two-fold.

1. set a maximum amount of time that server handlers are allowed to run. (I thought runtime.DefaultContextTimeout = 50 ms achieved this)
2. send response headers back to clients in the case of errors (which includes the deadline being hit).

The store ID interceptor runs on the gRPC server, storing an ID in the ctx via grpc.SetHeader (not actually sure this works, since the use of the grpc-ecosystem interceptor pattern is making things hard to follow).

What part of the interceptor pattern is hard to follow? I thought this was the standard way of implementing middlewares? I can't think of an easier way of setting headers 🤔

In any case, my issue is that if you remove the time.Sleep in the handler (i.e. produce a success response) the response header is correctly received by the client. But if i artificially produce a deadline exceeded error, then the client doesn't get this header.

The gRPC server handler runs, which sleeps for 1 second, causing the gRPC client to time out the request.... Because as far as I'm concerned there is no way for the server to do anything while the handler is sleeping, and the gRPC client is timing out without waiting for a response

This is where i'm seeing cracks on my understanding. I thought that by doing

runtime.DefaultContextTimeout = 50 * time.Millisecond

i was setting a deadline on the server handler, not on the client. Is there a way of setting a deadline on the server?

[johanbrandhorst]

Thanks for your explanation. I should have been clearer about what I mean by "client" and "server". In this case, the grpc-gateway is both a server and client. The timeout you configured is on the client side of the grpc-gateway <-> grpc server connection. The client part of the gateway will not wait for the grpc server to respond before terminating the connection. So when you call grpc.SetHeader on the grpc side, it probably has no way of doing that since it's in the middle of a sleep. Again, I'm not sure what PostMsgReceive actually does on the interceptor side. I would recommend implementing the interceptors as functions directly instead of using go-grpc-middleware (I say this as a maintainer of go-grpc-middleware). There's no need to involve the complicated interface pattern used there for this simple test.

In any case, if the timeout was on the grpc server side, you might be able to stop processing and send headers, but you wouldn't be able to use a sleep since it pauses the goroutine completely, you'd have to use a select, like so:

select {
case <-time.After(time.Second): // replaces the sleep
case <-ctx.Done():
   // call SetHeader here, maybe?
}

I also think, generally, it's going to be hard to intercept timeouts and set headers in the grpc infrastructure. Perhaps you could write a HTTP middleware around the grpc-gateway which can detect certain status codes and set headers appropriately instead?