Grpc-go: RPC returns error "code = Unknown desc = context deadline exceeded"

[gyuho]

What version of gRPC are you using?

v1.6.0

What version of Go are you using (go version)?

Go 1.9.2

What operating system (Linux, Windows, …) and version?

Linux 4.10.0-38-generic 16.04.1-Ubuntu x86_64 x86_64 x86_64 GNU/Linux

What did you do?

We have a test https://github.com/coreos/etcd/issues/8809 that sends RPC with short context timeout, expecting context.DeadlineExceeded errors. Kind of hard to reproduce (happens once every >3,000 runs).

What did you expect to see?

Expect context.DeadlineExceeded error.

What did you see instead?

Got rpc error: code = Unknown desc = context deadline exceeded of type grpc/*status.statusError. Our question is whether this error from RPC is expected? Should it be converted to context.DeadlineExceeded from gRPC side?

I looked through the code and (sort of) found where it returns rpc error: code = Unknown desc = context deadline exceeded.

First, invoke call has 3 parts.

1. https://github.com/grpc/grpc-go/blob/84671c5e11bfb5b7c237ff1799a660ff11a518d2/call.go#L228-L229
2. https://github.com/grpc/grpc-go/blob/84671c5e11bfb5b7c237ff1799a660ff11a518d2/call.go#L246-L247
3. https://github.com/grpc/grpc-go/blob/84671c5e11bfb5b7c237ff1799a660ff11a518d2/call.go#L265-L266
4. https://github.com/grpc/grpc-go/blob/84671c5e11bfb5b7c237ff1799a660ff11a518d2/call.go#L282-L283

Our RPC call in this invoke did not receive any errors from those 4 calls above.

Then to the last return statement here:

https://github.com/grpc/grpc-go/blob/84671c5e11bfb5b7c237ff1799a660ff11a518d2/call.go#L307

stream.Status().Err() was returning rpc error: code = Unknown desc = context deadline exceeded.

So, I looked through where that *transport.Stream/*status.Status gets updated to return rpc error: code = Unknown desc = context deadline exceeded.

(still inside that grpc/call.go/invoke call)

Until sendRequest is done, the stream's status is still nil:

https://github.com/grpc/grpc-go/blob/84671c5e11bfb5b7c237ff1799a660ff11a518d2/call.go#L265-L266

But right after recvResponse, the stream status is now

https://github.com/grpc/grpc-go/blob/84671c5e11bfb5b7c237ff1799a660ff11a518d2/call.go#L282-L283

fmt.Sprintf("%+v", stream.status.s) == "code:2 message:\"context deadline exceeded\" "

(code:2 is Unknown)

Then who writes that status to the stream? It was

https://github.com/grpc/grpc-go/blob/84671c5e11bfb5b7c237ff1799a660ff11a518d2/transport/transport.go#L404-L410

Then who passes code:2 message:\"context deadline exceeded\" to finish? It was (t *http2Client) operateHeaders:
https://github.com/grpc/grpc-go/blob/84671c5e11bfb5b7c237ff1799a660ff11a518d2/transport/http2_client.go#L1157

At the beginning of that operateHeaders call, my logs here say:

https://github.com/grpc/grpc-go/blob/84671c5e11bfb5b7c237ff1799a660ff11a518d2/transport/http2_client.go#L1115-L1117

if state.httpStatus != nil {
    fmt.Printf("%+v / %d / code %v / text %q\n",
        state.status().s,
        *(state.httpStatus),
        httpStatusConvTab[*(state.httpStatus)],
        http.StatusText(*(state.httpStatus)))
}
"code:2 message:\"context deadline exceeded\" " / 200 / code OK / text "OK"

This is my current progress. I couldn't figure out where that Unknown context deadline exceeded state comes from...

Thanks in advance!
/cc @xiang90

[dfawley]

Got rpc error: code = Unknown desc = context deadline exceeded of type grpc/*status.statusError.
Our question is whether this error from RPC is expected? Should it be converted to
context.DeadlineExceeded from gRPC side?

RPCs should _always_ return an error implemented by the status package. However, the code should be codes.DeadlineExceeded in this case, not Unknown. We'll look into this more. Thanks for filing the bug.

[gyuho]

Turns out our server was returning status.Error(codes.Unknown, context.DeadlineExceeded).
We fixed our server to return original context error and let gRPC server handle the error conversion.

Thanks!