fix(core): stop silently shortening gRPC deadlines on the wire - #574
Conversation
|
Hi @cgreeno I merged the aforementioned PR, and if you want to continue from here, I'll be waiting. |
|
Rebased onto master now that #571 has landed. Adds one commit required by that change. The problem#571 asserts CI for this PR does not show the failure. The Without this commit, the test fails the next time Type assertion
The assertion is now milliseconds when is_number(milliseconds) -> max(0, round(milliseconds))
Call site
I did not change the implementation. The test records which of the two is required. VerificationThree suites, green against hex |
fcdaecd to
0fd0dd4
Compare
Two defects in grpc_core, both silent, both making the deadline a caller asks for differ from the one that travels. 1. encode_timeout/1 truncated any duration >= 1000 ms to whole seconds. @ms_ceiling was 1000, so only sub-second values used the millisecond unit and everything above went through div(timeout, 1000). 2500 ms went out as "2S" and was read back as 2000 ms; 3847 ms lost 847 ms. The wire format defines TimeoutValue as "a positive integer as ASCII string of at most 8 digits", with Millisecond among the valid units, so any duration below 100_000_000 ms is representable exactly and needs no coarser unit. The ceiling is raised to that limit and the second/minute/hour ladder rescaled to stay inside 8 digits. grpc-go does the opposite of the current behaviour on both axes. Its EncodeDuration starts at nanoseconds and steps coarser only when the value will not fit, maximising precision, and its div() rounds *up* -- so a deadline is never silently shortened. Its maxTimeoutValue is 100000000 - 1, the same 8-digit limit this now uses. Round-number timeouts encoded exactly (1000 -> "1S" -> 1000 ms), which is why this went unnoticed: a configured constant is usually a round number. A *propagated* deadline is not -- it is whatever is left of the caller's budget, so the loss lands on every value and compounds at every hop. 2. TimeUtils.to_relative/2 returned a float, so the :deadline option was inert. The result was built as `DateTime.to_unix(dt, :second) * 1000 + elem(dt.microsecond, 0) * 0.001`; the trailing term made every return value a float and added binary rounding error, so 5.005 ms came back as 5.0048828125. append_timeout/2 matches on is_integer/1 and falls through to a catch-all, so `deadline:` produced no grpc-timeout header at all. The gun adapter's start_timeout/1 has the same is_integer//:infinity clause pair with no catch-all, so a float also failed locally -- as a FunctionClauseError that await/2 converts into a misleading terminated-stream error, and only when the response had not already arrived. Fast calls silently lost the deadline; slow ones failed pointing at the wrong cause. DateTime.diff/3 over microseconds, truncated with div/2, replaces the hand-rolled arithmetic. Relationship to elixir-grpc#571 -------------------- elixir-grpc#571 (Fix/mint client side timeout) independently ran into (2) and works around it at the call site in mint.ex: milliseconds when is_number(milliseconds) -> max(0, round(milliseconds)) With this commit that round/1 becomes redundant. The max(0, _) should stay: a deadline already in the past still resolves to a negative number of milliseconds (verified: -5003 for a deadline 5s ago), and a receive timeout needs a non-negative integer. Nothing here overlaps elixir-grpc#571's own subject -- that the mint adapter never applied the timeout at all -- and this touches no file it touches. elixir-grpc#571 also corrects `:deadline` being unable to override the `:timeout` that recv/2 fills in by default. That fix is left to it rather than duplicated here. Verification ------------ The existing encode_timeout tests asserted encoded strings and never a round-trip, which is exactly how the truncation survived: encode_timeout(1000) == "1S" holds both before and after data is lost. Added round-trip fidelity assertions, an 8-digit wire-limit check, and grpc-timeout header coverage. Every new assertion was confirmed to fail against the unfixed code. Separately property-checked 448 values from 1 ms to 1.8e13 ms: no encoding exceeds 8 digits, no decoded value is greater than its input, and the loss is always below the granularity of the unit chosen. utils_test.exs moves from grpc/test to grpc_core/test. It covers a grpc_core module, but the grpc package resolves grpc_core from hex, so a test there cannot exercise a local change to it -- and its assertions, written against a 1000 ms ceiling, would have broken the next time grpc bumped grpc_core. http2_test.exs stays in grpc because it needs GRPC.Channel and GRPC.Server.Stream from sibling packages; the new header coverage lives in grpc_core against a bare map. All three suites pass with --warnings-as-errors: grpc_core 116, grpc_server 211, grpc 342.
…re change elixir-grpc#571 landed `assert is_float(timeout)` on the value GRPC.TimeUtils.to_relative/2 returns. The parent commit makes that an integer, so the assertion becomes wrong -- but not visibly: the grpc package resolves grpc_core from hex, so its suite tests the published 1.0.4 and stays green either way. Verified by path-linking grpc_core, where it fails with `code: assert is_float(timeout)`. It would have broken whoever next bumped grpc's grpc_core requirement rather than failing here. Swapping it to is_integer just inverts the problem -- green after the release, red before it. No concrete type is correct on both sides, and this package straddles that release by construction. So it asserts is_number/1, which mirrors the guard the call site actually depends on: milliseconds when is_number(milliseconds) -> max(0, round(milliseconds)) That is the real contract, and it holds whichever grpc_core is resolved. The test's subject is unchanged and still passes: a `:deadline` resolved through to_relative/2 is accepted and fires DEADLINE_EXCEEDED. Also notes which half of the call site is load-bearing -- round/1 becomes a no-op once to_relative/2 returns an integer, while max(0, _) is still required, because a deadline in the past resolves to a negative number of milliseconds and a receive timeout must be non-negative.
0fd0dd4 to
e7e51b6
Compare
Every comment removed here restated the name of the test it sat above. The 8-digit wire limit comment duplicated the test named for that limit, and the float comment duplicated an assertion on is_integer. The one case where the comment carried information the code did not is now in the test name: to_relative/2 returns an integer because append_timeout/2 drops a float rather than sending it. The reasoning behind the change belongs in the pull request, not beside the assertions.
|
@sleipnir cleaned up comments my bad |
|
Thank you @cgreeno |
Two defects in
grpc_corethat make the deadline a caller asks for differ from the one that travels. Both are silent.1.
encode_timeout/1truncates any duration ≥ 1000 ms to whole seconds@ms_ceilingwas1000, so only sub-second values used the millisecond unit and everything above went throughdiv(timeout, 1000):"1S""2S""3S""5S"The wire format defines
TimeoutValueas "a positive integer as ASCII string of at most 8 digits", withMillisecondamong the valid units, so any duration below100_000_000ms is representable exactly and needs no coarser unit. This raises the ceiling to that limit and rescales the second/minute/hour ladder to stay inside 8 digits.For comparison, grpc-go's
EncodeDurationdoes the opposite of the current behaviour on both axes: it starts at nanoseconds and steps coarser only when the value will not fit, maximising precision, and itsdiv()rounds up so a deadline is never silently shortened. ItsmaxTimeoutValueis100000000 - 1— the same 8-digit limit used here.Round-number timeouts encode exactly (
1000 -> "1S" -> 1000 ms), which is why this has gone unnoticed: a configured constant is usually a round number. A propagated deadline is not — it is whatever is left of the caller's budget — so the loss lands on every value and compounds at every hop.2.
TimeUtils.to_relative/2returns a float, so:deadlineis inertThe result was built as:
The trailing term makes every return value a float, and adds binary rounding error on top —
5.005ms comes back as5.0048828125.append_timeout/2matches onis_integer/1and falls through to a catch-all, so passingdeadline:toGRPC.Stubsends nogrpc-timeoutheader at all. The gun adapter'sstart_timeout/1has the sameis_integer/:infinityclause pair with no catch-all, so a float also fails locally — as aFunctionClauseErrorthatawait/2converts into a misleading terminated-stream error, and only when the response had not already arrived. Fast calls silently lose the deadline; slow ones fail pointing at the wrong cause.DateTime.diff/3over microseconds, truncated withdiv/2, replaces the hand-rolled arithmetic.Relationship to #571
#571 independently ran into (2) and works around it at the call site in
mint.ex:With this change that
round/1becomes redundant. Themax(0, _)should stay — a deadline already in the past still resolves to a negative number of milliseconds (I measured-5003for a deadline 5 s ago), and a receive timeout needs a non-negative integer.Nothing here overlaps #571's own subject — that the mint adapter never applied the timeout at all — and this touches none of the files it touches. #571 also fixes
:deadlinebeing unable to override the:timeoutthatrecv/2fills in by default; that is left to it rather than duplicated here. Happy to rebase in whichever order suits you.Verification
The existing
encode_timeouttests asserted encoded strings and never a round-trip, which is precisely how the truncation survived —encode_timeout(1000) == "1S"holds both before and after data is lost. Added round-trip fidelity assertions, an 8-digit wire-limit check, andgrpc-timeoutheader coverage. Every new assertion was confirmed to fail against the unfixed code.Separately property-checked 448 values from 1 ms to 1.8×10¹³ ms: no encoding exceeds 8 digits, no decoded value is greater than its input, and the loss is always below the granularity of the unit chosen.
utils_test.exsmoves fromgrpc/testtogrpc_core/test. It covers agrpc_coremodule, but thegrpcpackage resolvesgrpc_corefrom hex, so a test living there cannot exercise a local change to it — and its assertions, written against a 1000 ms ceiling, would have broken the next timegrpcbumpedgrpc_core.http2_test.exsstays ingrpcbecause it needsGRPC.ChannelandGRPC.Server.Streamfrom sibling packages; the new header coverage lives ingrpc_coreagainst a bare map.All three suites pass with
--warnings-as-errors:grpc_core116,grpc_server211,grpc342.One open question
to_relative/2here truncates down, on the reasoning that a conversion should never extend a deadline. grpc-go rounds up for the mirror reason — never shorten below what was asked. It is a ±1 ms difference; happy to flip it to match grpc-go if you would rather be consistent with the reference implementation.