Skip to content

Fix/mint client side timeout - #571

Open
freevova wants to merge 2 commits into
elixir-grpc:masterfrom
freevova:fix/mint-client-side-timeout
Open

Fix/mint client side timeout#571
freevova wants to merge 2 commits into
elixir-grpc:masterfrom
freevova:fix/mint-client-side-timeout

Conversation

@freevova

Copy link
Copy Markdown
Contributor

The Mint adapter accepts and parses :timeout, but never applies it. do_receive_data/3 waits on the stream response process with GenServer.call(pid, :get_response, :infinity), so the option only ever leaves the client as the grpc-timeout header — a deadline the server enforces. When no response can arrive at all, the caller blocks forever despite having asked for a deadline.

We hit this in production. The connection process crashed partway through notifying pending requests on a closed connection, so the callers queued behind it were never told the connection was gone; their background jobs stayed blocked for ~19 hours until the pod was restarted. #559 fixes that particular crash (thank you — 1.0.3 resolved it for us), but the :infinity receive means any other path that leaves a caller unnotified ends the same way.

What this changes

The requested timeout is passed down to build_stream/3, and an elapsed deadline becomes a DEADLINE_EXCEEDED GRPC.RPCError. Two related corrections came out of that:

  • :deadline now takes precedence over :timeout, as recv/2 documents ("when the request is timeout, will override timeout"). recv/2 always fills in the 10s default under :timeout via Keyword.put_new/3, so an explicit deadline could otherwise never take effect.
  • Both options are resolved by GRPC.TimeUtils.to_relative/2, which returns a float — and a negative one for a deadline already in the past — so the value is rounded and clamped before it reaches a receive timeout, which requires a non-negative integer.

Giving up also cleans up after itself: the request is reset, so the server stops working on it, and the process buffering the response is stopped. That process is linked to the caller rather than to the connection, so nothing else would shut it down — least of all when the connection process is the very thing that went away. Both steps are best effort and bounded: they run after the deadline already elapsed, against processes that may themselves be gone or wedged, so a failure to tidy up must neither replace the error the caller is about to get nor keep it waiting much longer. ConnectionProcess.cancel/3 gained an optional timeout for that; its default is unchanged.

Scope

Only unary receives are bounded.

Server and bidirectional streams are consumed lazily by the caller, where a gap between messages is expected rather than a failure.

Client streams are left as they are: recv/2 fills in the unary 10s default for every request type, while GRPC.Stub documents streaming calls as unbounded, so honouring :timeout there would silently cut off uploads that legitimately take longer to be answered.

Behaviour changes

  • A unary call that never receives a response now fails after the 10s that GRPC.Stub.call/5 already documents, instead of blocking indefinitely.
  • If DATA arrived but trailers never did, the call now returns DEADLINE_EXCEEDED rather than the partial message. A unary response is not complete without grpc-status, so I believe this is correct, but it is a deliberate choice rather than an accident.

Both are recorded in the changelog. There was no unreleased heading to file them under, so I added one — move the entry wherever you prefer.

Tests

  • the deadline fires and halts the stream, and does not fire when the response arrives in time
  • the float milliseconds a :deadline resolves into are accepted, and a deadline already in the past is treated as an immediate one
  • an explicit :deadline wins over a long :timeout
  • the stream response process is stopped after the caller gives up
  • an end-to-end deadline: call through GRPC.Stub against a live server, which is what actually exercises the parse_req_opts pipeline the two fixes above live in

The whole suite passes locally (375 passed, 2 skipped), and reverting the library change makes every new test fail.

One adjacent thing, not fixed here

While adding the reset I noticed that handle_call({:cancel_request, ref}, ...) pops the ref and calls Mint.HTTP2.cancel_request/2, but does not call drop_queued_request_chunks/2 the way cancel_dead_stream/4 does. Leftover {ref, body, from} entries then survive in request_stream_queue, and the next handle_continue(:process_request_stream_queue, ...) calls get_window_size/2 for a ref Mint no longer knows, which raises ArgumentError. That was reachable before only through an explicit GRPC.Stub.cancel/1; automatic reset on a deadline makes it easier to hit.

I have only reproduced the leftover state by injecting it rather than by starving a real send window end to end, so I am flagging it rather than fixing it here.

The Mint adapter accepts and parses `:timeout` but never applies it: unary
receives wait on the stream response process with `:infinity`, so the option
only ever reaches the server as the `grpc-timeout` header. When no response can
arrive — the connection going down without notifying the pending request, for
instance — the caller blocks forever even though it asked for a deadline.

Pass the requested timeout down to `build_stream/3` and translate an elapsed
deadline into `DEADLINE_EXCEEDED`. Along the way:

  * `:deadline` now takes precedence over `:timeout`, as documented. `recv/2`
    always fills in the 10s default under `:timeout`, so an explicit deadline
    could otherwise never take effect.
  * Both options are resolved by `GRPC.TimeUtils.to_relative/2`, which returns a
    float — and a negative one for a deadline already in the past — so the value
    is rounded and clamped before it reaches a receive timeout.
  * Giving up resets the request, so the server stops working on it, and stops
    the process buffering the response, which is linked to the caller rather
    than to the connection and would otherwise outlive the call. Both steps are
    bounded and best effort: they run after the deadline elapsed, against
    processes that may themselves be gone or wedged.

Only unary receives are bounded. Server and bidirectional streams are consumed
lazily by the caller, where a gap between messages is expected rather than a
failure. A client stream awaits its response through a separate `recv/2` call,
which `GRPC.Stub` documents as unbounded even though it fills in the same 10s
default — worth settling separately from this fix.

Note this changes the default behaviour of a unary call that never receives a
response: it now fails after the 10s documented in `GRPC.Stub.call/5` instead of
blocking indefinitely.
The enforced deadline alters a documented default, which is the kind of
change this changelog records under `### Behavior Changes`. There was no
unreleased heading to file it under, so add one rather than assume the
next version number.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant