Fix dead TLog hang with sender-side peek timeout#13248
Conversation
There was a problem hiding this comment.
Pull request overview
Adds a sender-side retry timeout for non-parallel TLog peek requests to avoid indefinite hangs when requests are silently dropped (e.g., after a TLog reboots at the same address with new endpoint tokens). This improves simulation/cluster quiescence behavior in “dead TLog” scenarios without relying on receiver-side endpoint errors.
Changes:
- Add
SERVER_KNOBS->PEEK_REPLY_TIMEOUT(default 30s, 0 disables) to bound how long a non-parallel peek waits for a reply. - Extend
serverPeekGetMoreImpl()to race peek reply vs interface change vs timeout, and retry on timeout. - Introduce a new trace event on timeout to aid diagnosis.
Reviewed changes
Copilot reviewed 3 out of 3 changed files in this pull request and generated 2 comments.
| File | Description |
|---|---|
| fdbserver/logsystem/LogSystemPeekCursor.cpp | Adds timeout branch to non-parallel peek reply wait loop and retries on timeout. |
| fdbserver/core/ServerKnobs.cpp | Initializes new PEEK_REPLY_TIMEOUT knob (default 30s). |
| fdbserver/core/include/fdbserver/core/Knobs.h | Declares new PEEK_REPLY_TIMEOUT server knob. |
Result of foundationdb-pr-clang-arm on Linux CentOS 7
|
Result of foundationdb-pr-clang-ide on Linux RHEL 9
|
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
|
BEHAVIOR CHANGE: Non-parallel TLog peek requests now have a sender-side timeout (PEEK_REPLY_TIMEOUT knob, default 30s). Previously, a peek would wait indefinitely for a reply or an interface change. Now, if no reply arrives within PEEK_REPLY_TIMEOUT seconds, the peek is re-sent. Set PEEK_REPLY_TIMEOUT to 0 to disable and restore the old wait-forever behavior. Problem: when a TLog is killed with data destruction (KillType=6) and reboots at the same address, FlowTransport silently drops requests to old endpoint tokens. The sender (LogRouter/SS/consistency checker) waits forever because: - The connection is healthy (same address, process is alive) - No ENDPOINT_NOT_FOUND is sent (non-stream unknown endpoints are silently discarded by scanPackets in FlowTransport.cpp) - The interface does not change (same address) This manifests as simulation timeouts (5400s) in multi-region configs with single replication after datacenter kills. Seen in recent gcc nightlies (tests: AtomicOps.toml seed 309473476, DataLossRecovery.toml seed 3721859193, MaxGrvQueueDelay.toml seed 3023304950, TxnStateStoreCycleTest.toml seed 2843566457) and in local reproduction. Fix: in LogSystemPeekCursor::serverPeekGetMoreImpl, the existing race(peekReply, interf->onChange()) now includes a third branch: delay(PEEK_REPLY_TIMEOUT). When the timeout fires, the loop continues (re-sends the peek request) rather than throwing. Why retry (continue) instead of throw: throwing timed_out() propagated up and killed the storage server (SSUpdateError/StorageServerFailed), causing false failures in clog tests (ClogRemoteTLog, GcGenerations) where TLogs are intentionally unreachable for extended periods. Why this approach over receiver-side ENDPOINT_NOT_FOUND: a receiver- side fix was attempted (sending ENDPOINT_NOT_FOUND for unknown tokens) but abandoned because the receiver cannot distinguish "dead endpoint" from "clogged endpoint" -- both appear as packets to an unknown token. This caused widespread false failures (71/6760 runs, 1%) in tests that inject network clogging (ClogRemoteTLog, DcLag, GcGenerations). How the fix resolves the dead TLog hang: 1. Peek request sent to dead TLog -> silently dropped 2. 30s timeout fires -> peek re-sent (new request, same dead endpoint) 3. Also silently dropped -> timeout fires again 4. Meanwhile, cluster controller detects the dead TLog 5. Interface updated -> interf->onChange() fires -> cursor gets new TLog endpoint -> recovery/consistency check proceeds Tested: 100,000 Joshua correctness runs, 99,997 passed. 3 failures all unrelated (RocksDB file lock bug, TracedTooManyLines in long test).
Result of foundationdb-pr-macos-m1 on macOS Ventura 13.x
|
Result of foundationdb-pr-clang-ide on Linux RHEL 9
|
Result of foundationdb-pr-macos on macOS Ventura 13.x
|
Result of foundationdb-pr-clang-arm on Linux CentOS 7
|
Result of foundationdb-pr-macos-m1 on macOS Ventura 13.x
|
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
|
Result of foundationdb-pr-clang-arm on Linux CentOS 7
|
Result of foundationdb-pr-cluster-tests on Linux RHEL 9
|
Result of foundationdb-pr on Linux RHEL 9
|
Result of foundationdb-pr-clang-ide on Linux RHEL 9
|
Result of foundationdb-pr-clang on Linux RHEL 9
|
Result of foundationdb-pr-macos on macOS Ventura 13.x
|
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-cluster-tests on Linux RHEL 9
|
Result of foundationdb-pr on Linux RHEL 9
|
Result of foundationdb-pr-clang-ide on Linux RHEL 9
|
Result of foundationdb-pr-clang-ide on Linux RHEL 9
|
Result of foundationdb-pr-clang-arm on Linux CentOS 7
|
Result of foundationdb-pr-macos on macOS Ventura 13.x
|
Result of foundationdb-pr-macos-m1 on macOS Ventura 13.x
|
Result of foundationdb-pr-cluster-tests on Linux RHEL 9
|
Result of foundationdb-pr on Linux RHEL 9
|
Result of foundationdb-pr-clang 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
|
|
I ran 100k again:
Looking at trace logs after rerunning the failure the startMoveKeys exhausted its 51-retry limit because buggified TLog unavailability prevented commits (transaction_too_old), which is write path — unrelated to the peek read path which this PR modifies, confirmed by zero PeekReplyTimeout events in the trace. and
Ditto. A dual-region MachineAttrition test ran for 22K simulated seconds with a storage server unable to reach a replica (unreachable_storage_replica, 43K events), flooding the trace log until it hit the 1M line limit and aborted — zero PeekReplyTimeout events in the trace. |
* Extend PEEK_REPLY_TIMEOUT to parallel peek path (LogRouter fix) The sender-side peek timeout added in 446079c (PR #13248) only covers the non-parallel peek path (serverPeekGetMoreImpl), used by storage servers. LogRouters use the parallel peek path (serverPeekParallelGetMoreImpl) via peekLogRouter/SetPeekCursor, which still had the old wait-forever behavior. Add the same PEEK_REPLY_TIMEOUT race branch to serverPeekParallelGetMoreImpl. When the timeout fires, clear the pending futures and re-send the peek (same retry-without-throw approach as the non-parallel path). Extract peekReplyTimeout() helper used by both paths to compute the timeout future consistently. Both sites cross-reference each other in comments. This fixes the live-TLog LogRouter hang where a TLog is re-recruited with new endpoint tokens. The LogRouter's peek request is silently dropped (same root cause as the dead-TLog hang), but the parallel path never detected it. Seed 408543238 (TxnStateStoreCycleTest.toml, buggify=on) reproduces on x86_64 linux. Passes with this fix (206s vs 24000+ hang). Also fix fdb_c_wiggle_only hang on shutdown due to stats timer race. The fdb_c_api_tester process hangs on shutdown after all workloads complete, causing the test harness to SIGKILL it and report failure. Root cause: schedulePrintStatistics() re-schedules itself inside its timer callback. When the last workload finishes, workloadDone() calls statsTimer->cancel() then scheduler->stop(). But if the timer fires and the callback creates a new timer between cancel() and stop() (or just after stop()), the new timer keeps io_ctx.run() alive indefinitely since the work guard has already been released but there is still an outstanding async operation. This race is more likely to trigger now because the sender-side peek timeout -- this and #13248 -- changes recovery timing during the cluster wiggle, causing more transient transaction errors (connection_failed, commit_unknown_result, not_committed). Workloads take longer to drain their in-flight transactions after receiving STOP, giving the 5-second stats timer more opportunities to fire and race with shutdown. Fix: add an atomic flag checked by the timer callback before re-scheduling. Set the flag before cancelling the timer to guarantee no new timer is created after shutdown begins.
One fix for a category of problems that I've labelled 'dead TLog' where tests pass but fail anyways because the database never quiesces; the cluster has been damaged in simulation such it can't recover. #13227 is one and mentions a few other case. The below mentions others.
BEHAVIOR CHANGE: Non-parallel TLog peek requests now have a sender-side timeout (PEEK_REPLY_TIMEOUT knob, default 30s). Previously, a peek would wait indefinitely for a reply or an interface change. Now, if no reply arrives within PEEK_REPLY_TIMEOUT seconds, the peek is re-sent. Set PEEK_REPLY_TIMEOUT to 0 to disable and restore the old wait-forever behavior.
Problem: when a TLog is killed with data destruction (KillType=6) and reboots at the same address, FlowTransport silently drops requests to old endpoint tokens. The sender (LogRouter/SS/consistency checker) waits forever because:
This manifests as simulation timeouts (5400s) in multi-region configs with single replication after datacenter kills. Seen in recent gcc nightlies (tests: AtomicOps.toml seed 309473476, DataLossRecovery.toml seed 3721859193, MaxGrvQueueDelay.toml seed 3023304950, TxnStateStoreCycleTest.toml seed 2843566457) and in local reproduction.
Fix: in LogSystemPeekCursor::serverPeekGetMoreImpl, the existing race(peekReply, interf->onChange()) now includes a third branch: delay(PEEK_REPLY_TIMEOUT). When the timeout fires, the loop continues (re-sends the peek request) rather than throwing.
Why retry (continue) instead of throw: throwing timed_out() propagated up and killed the storage server (SSUpdateError/StorageServerFailed), causing false failures in clog tests (ClogRemoteTLog, GcGenerations) where TLogs are intentionally unreachable for extended periods.
Why this approach over receiver-side ENDPOINT_NOT_FOUND: a receiver- side fix was attempted (sending ENDPOINT_NOT_FOUND for unknown tokens) but abandoned because the receiver cannot distinguish "dead endpoint" from "clogged endpoint" -- both appear as packets to an unknown token. This caused widespread false failures (71/6760 runs, 1%) in tests that inject network clogging (ClogRemoteTLog, DcLag, GcGenerations).
How the fix resolves the dead TLog hang:
Tested: 100,000 Joshua correctness runs, 99,997 passed. 3 failures all unrelated (RocksDB file lock bug, TracedTooManyLines in long test).
20260520-001835-stack_dead_tlog-ea137360b7a91210 compressed=True data_size=41116969 duration=3731822 ended=100000 fail=3 max_runs=100000 pass=99997 priority=100 remaining=0 runtime=2:27:48 sanity=False started=100000 stopped=20260520-024623 submitted=20260520-001835 timeout=5400 username=stack_dead_tlogRandomSeed="1774749498" SourceVersion="b1fc4d938d0e6ac09ca2a11fc11459ff31f9798e" Time="1779240835" BuggifyEnabled="1" DeterminismCheck="0" FaultInjectionEnabled="1" TestFile="tests/slow/GcGenerations.toml"
RandomSeed="1680132275" SourceVersion="b1fc4d938d0e6ac09ca2a11fc11459ff31f9798e" Time="1779242782" BuggifyEnabled="1" DeterminismCheck="0" FaultInjectionEnabled="1" TestFile="tests/slow/SwizzledCycleTest.toml"
RandomSeed="2248809336" SourceVersion="b1fc4d938d0e6ac09ca2a11fc11459ff31f9798e" Time="1779243800" BuggifyEnabled="0" DeterminismCheck="0" FaultInjectionEnabled="1" TestFile="tests/fast/MaxGrvQueueDelay.toml"