Fix peekLogRouter() born-exhausted cursor when begin == oldEnd#13238
Conversation
There was a problem hiding this comment.
Pull request overview
This PR defensively fixes an edge case in LogSystem::peekLogRouter() where begin == oldEnd could previously fall through and construct a SetPeekCursor over an empty range (begin == end), producing a cursor that is immediately exhausted and can cause LogRouter replay to stall/hang.
Changes:
- Treat
begin == oldEndthe same asbegin > oldEndwhen iterating old epochs, skipping that old epoch instead of constructing aSetPeekCursorwith an empty range. - Add an explanatory comment and update the associated trace event emitted when skipping an old epoch whose range is already fully behind
begin.
Result of foundationdb-pr-clang-ide on Linux RHEL 9
|
Result of foundationdb-pr-macos-m1 on macOS Ventura 13.x
|
Result of foundationdb-pr-macos on macOS Ventura 13.x
|
Result of foundationdb-pr-clang-arm on Linux CentOS 7
|
Result of foundationdb-pr-cluster-tests on Linux RHEL 9
|
Result of foundationdb-pr-clang on Linux RHEL 9
|
Result of foundationdb-pr on Linux RHEL 9
|
|
@tclinkenbeard-oai can you also comment on this? I saw that you explicitly changed this the other way in your PR commit: 5a63d11. So curious what issue you saw there. |
|
Thank you for the review @sbodagala . Yeah, @tclinkenbeard-oai , interested in your opinion on this one. Thank you. |
|
RandomSeed="1663748750" SourceVersion="df7ce9300dd36343d59a4e66c6a1f9622cffdddb" Time="1779156188" BuggifyEnabled="0" DeterminismCheck="0" FaultInjectionEnabled="1" TestFile="tests/slow/CommitBug.toml" Test times out. Test doesn't get to start. Not seemingly related to TLog and peeking... |
Result of foundationdb-pr-clang-ide on Linux RHEL 9
|
Result of foundationdb-pr-macos-m1 on macOS Ventura 13.x
|
Result of foundationdb-pr-clang-arm on Linux CentOS 7
|
Result of foundationdb-pr on Linux RHEL 9
|
Result of foundationdb-pr-clang on Linux RHEL 9
|
Result of foundationdb-pr-cluster-tests on Linux RHEL 9
|
Result of foundationdb-pr-macos on macOS Ventura 13.x
|
When begin == oldEnd, the code falls through and creates a SetPeekCursor with begin == end. This cursor is born exhausted -- getMore() returns immediately with no data and no advancement, which can cause LogRouters to hang. The >= check catches this case and skips the old epoch (same path as begin > oldEnd), preventing the born-exhausted cursor from being created. This is a defensive correctness fix -- a cursor with begin == end is always wrong. The case is rare and was not directly observed in traced failures, but closing this edge case is warranted. Validated with 100k simulation runs across AutomaticIdempotency, InventoryTestSomeWrites, and MaxGrvQueueDelay with no obvious regressions.
|
Rebased. |
|
This good by you @tclinkenbeard-oai ? Thanks. |
|
Yeah, this change LGTM, thank you |
Result of foundationdb-pr-clang-ide on Linux RHEL 9
|
Result of foundationdb-pr-macos-m1 on macOS Ventura 13.x
|
Result of foundationdb-pr-clang-arm on Linux CentOS 7
|
Result of foundationdb-pr-clang on Linux RHEL 9
|
Result of foundationdb-pr on Linux RHEL 9
|
Result of foundationdb-pr-cluster-tests on Linux RHEL 9
|
Result of foundationdb-pr-macos on macOS Ventura 13.x
|
When begin == oldEnd, the code falls through and creates a SetPeekCursor with begin == end. This cursor is born exhausted -- getMore() returns immediately with no data and no advancement, which can cause LogRouters to hang.
The >= check catches this case and skips the old epoch (same path as begin > oldEnd), preventing the born-exhausted cursor from being created.
This is a defensive correctness fix -- a cursor with begin == end is always wrong. The case is rare and was not directly observed in traced failures, but closing this edge case is warranted.
Here is a 100k run
20260518-223352-stack_one_liner-58efc5e594c8620e compressed=True data_size=37007600 duration=3861738 ended=100000 fail=4 fail_fast=10 max_runs=100000 pass=99996 priority=100 remaining=0 runtime=0:52:28 sanity=False started=100000 stopped=20260518-232620 submitted=20260518-223352 timeout=5400 username=stack_one_linerTwo failures are:
RandomSeed="1027964057" SourceVersion="df7ce9300dd36343d59a4e66c6a1f9622cffdddb" Time="1779145186" BuggifyEnabled="0" DeterminismCheck="0" FaultInjectionEnabled="1" TestFile="tests/fast/Sideband.toml"
and
RandomSeed="762784548" SourceVersion="df7ce9300dd36343d59a4e66c6a1f9622cffdddb" Time="1779145515" BuggifyEnabled="0" DeterminismCheck="0" FaultInjectionEnabled="1" TestFile="tests/fast/Sideband.toml"
These are from an existing 'live-TLog' hang I've been following (multi-region, timed out at 5401s, 0 TracedTooManyLines). I just ran 500k against main and 4 of these Sideband failures showed up there.
This issue comes of the work over in #13228 where I had trouble proving an improvement. This one-liner extracts from that work an obvious (to-me) improvement.