[Bug]: LogService Append waits 60s on an isolated replica despite a healthy Raft majority

Description

A LogService Append can remain on a TCP connection to an isolated replica until the caller's full 1-minute deadline, even while the other two Raft voters are reachable and advancing the log. Retrying then succeeds, but the first timed-out Append may already have committed and can occupy a second physical LSN.

Environment

MatrixOne upstream/main at d61a7206c16b30baa4efc525eb6067c4364035aa.
Three isolated LogService processes, three voting replicas of data shard 1 and HAKeeper shard 0, distinct data directories and Linux network namespaces on test host 10.222.1.51. No TN/CN was started.
Default log-store-timeout = "5m". A direct three-address LogService client ran sequential unique-payload Append → Read checks with a 1-minute deadline per attempt and a 3-minute retry continuation window, matching the tested MO WAL retry timing.
Reproducer and analysis tools: test/logservice-chaos.

Reproduction

Start the three-node isolated cluster and continuous chaos-client -op cycle -count 0 -try-timeout 1m -retry-window 3m against all three RPC addresses.
Use ss -tnp on the test host to identify the replica to which this client currently holds an established TCP connection. Confirm all three voters are present.
Run netns.sh <cluster-root> down <connected-node-index> for 75 seconds, keeping the other two nodes running and mutually reachable; then run netns.sh <cluster-root> up <connected-node-index>.
After the three-member view returns, inspect the client's new connection and repeat for other connected replicas. Read back the retained range from each address and compare LSN/payload.

The key trigger is isolating the client's existing connection. Isolating an arbitrary other replica is not equivalent.

Actual Result

Three consecutive injections against connections to node1, node2 and node0 reproduced the same long tail (3/3). The affected seq=79/235/378 Append attempts returned context deadline exceeded after 60001.127 / 60000.663 / 60001.011 ms. The corresponding logical Append → Read cycles completed after 60.505 / 60.520 / 61.325 s on retry. The surviving nodes' latest LSN continued advancing throughout.

All 491 logical cycles eventually succeeded; three-address reads matched and every acknowledged LSN/payload was verified. Each timed-out first Append had in fact committed: the same payload appeared at LSN 3263 and 3267, 3423 and 3427, and 3570 and 3573, respectively. These are physical LogService duplicates; this test did not run TN replay and does not establish duplicate SQL execution.

Expected Result

With two reachable voters, the client should detect an unusable established RPC connection and retry another replica without routinely consuming the caller's entire 1-minute attempt deadline. A timeout must still be treated as an unknown Append result; any fix or retry must preserve reconciliation/idempotency semantics.

Code Evidence and Scope

pkg/logservice/client.go passes read timeout 0 to getRPCClient, which sets morpc.WithBackendReadTimeout(readTimeout). client.request waits on future.Get(); managedClient.Append resets its RPC client only after an error returns. This is consistent with the observed wait, but a connection-level trace is needed to attribute every millisecond.

Full timeline, reproduction commands and retained-data analysis: LogService three-node failure report. Raw evidence is retained on the test host under /home/mo/jxm/logservice-chaos-fresh-20261104/tail-repeat-a-20261104.*.

Related #29687 reports production LogService latency with an undetermined root cause; this issue records a controlled, repeatable connection-isolation mechanism. Search of existing issues for LogService Append 60-second timeout and this exact mechanism found no duplicate.

Follow-up: Read also waited for the full per-attempt timeout after leader crash (2026-11-04)

On a fresh three-voter cluster with distinct leaders (HAKeeper shard 0 on node0; data shard 1 on node1), I killed the data leader node1 just after its exported snapshot was renamed into the final directory. node0/node2 stayed online and mutually reachable; data leadership moved to node2. A separate client connected only to those two survivors completed 100/100 Append→Read cycles with zero retries and a 0.550-second maximum. Truncate(150) also succeeded with node1 down.

The original three-address client had already acknowledged Append for seq=46 at LSN 158. Its subsequent Read on the existing connection waited 60,000.820 ms before returning EOF; the retry then read and verified the record. That whole Append→Read cycle took 61.623 seconds. This extends the issue's observed one-minute tail to Read. I have not traced this Read's exact MORPC backend state, so I am reporting the matching client-visible failure mode, not claiming a separately proven internal cause.

The full run ended 555/555 cycles successful, with zero Append retries and one Read retry. After restart, all three addresses returned the original members and identical retained reads; 347 confirmed retained records matched by LSN and payload. Evidence: test report and /home/mo/jxm/logservice-chaos-snapshot-leader-20261104/leader-snapshot-crash.load on the test host.

Controlled Read timeout comparison (2026-11-04)

I added a test-only pause after a successful Append and before Read in the same LogService client. For each run, ss -tnp identified its established TCP peer; I isolated that peer's test veth, then released Read while the other two voters stayed connected. This removes ambiguity about whether the failure occurred during Append or Read. No production timeout setting was changed.

Per-attempt Read timeout	First Read failure	Read phase through successful retry
2 seconds, connected node0 isolated	`context deadline exceeded` after 2000.734 ms	3204.537 ms
2 seconds, connected node2 isolated	`context deadline exceeded` after 2000.961 ms	3330.323 ms
Current 1-minute default, connected node2 isolated	`context deadline exceeded` after 60000.428 ms	60291.560 ms

All three Appends had succeeded before isolation; each Read succeeded on its second attempt. The cycle's overall time includes the intentional pause and must not be used as the failure latency. A separate healthy 2-second-timeout control completed 150/150 Append→Read cycles with zero retries (maximum cycle 638.310 ms). After network restoration, all three addresses returned identical data, including the three tested payloads at LSN 789, 945, and 949.

Code path: LogService managedClient.Read resets its connection on RPC error but internally retries only shard-not-found errors; EOF/deadline errors return to the WAL read loop. The TN WAL readFromBackend loop gives each attempt DefaultOneTryTimeout = 1m and retries afterward. MORPC backend read timeout is configured as zero for this data client. Therefore a blackholed established connection can consume the full caller deadline before retrying, as this test observed. The 2-second setting is an experimental caller timeout, not a production recommendation based on a full latency study.

Report and reproducible test hook: test report, raw logs under /home/mo/jxm/logservice-chaos-snapshot-leader-20261104/ on the test host.

补充真实 TN WAL driver 路径的稳定复现（没有启动 TN/CN）：

在 51 的独立三投票副本 LogService 集群中，测试程序直接复用 logservicedriver.NewLogServiceDriver、ReplayForWrite、Append 和 Entry.WaitDone，按真实默认 DefaultOneTryTimeout = 1m 写入。测试代码：tn_driver_probe。
每轮先用 ss -tnp 确认 driver 进程已连接的副本，再将该副本 SIGSTOP 70 秒，另两台保持运行。第二轮明确确认目标 node1 是普通副本，数据 leader 在 node2。
两次受阻的下一条 WAL 写入分别等待 60.587 秒（DSN 681）和 60.648 秒（DSN 807）；WAL-Commit-Append 都记录内部重试 1 次，最终成功。目标副本仍暂停时，driver 已分别继续推进到 DSN 724/848，说明存活两票可以服务。
独立新 driver 最终顺序回放 DSN 392–899 共 508 条；本次保留完整确认清单的 DSN 650–899 共 250 条逐条匹配 payload，没有缺口。三个测试节点最终都在运行。

这证明 #32133 的 60 秒长尾也会直接影响 TN WAL driver，而不只是复刻超时配置的测试客户端。pkg/logservice/client.go 建连时传 WithBackendReadTimeout(0)，已有连接直到请求返回错误才重置；driver 每次 Append 尝试的 1 分钟 deadline 到期后才换连接。当前实现行为可解释，但在两票仍可写入时，单条 WAL 被阻塞一分钟不符合故障切换的延迟预期。修复要处理超时 Append 结果未知、可能已提交的语义。

完整时间线和原始证据位置见测试报告。

结论

补充完整 SQL 服务链路的定位证据，不是修复验收结论：约 60 秒等待不等于 Raft 选主耗时，也不宜全部归因于已退出节点上的 TCP 连接。 自然停止 WAL leader 后，存活 LOG 的服务端仍可有 SyncPropose 长时间等待；TN WAL 重试完成后提交恢复，部分新连接此前等待 Logtail 读屏障。Raft 内部为何没有及时完成该提案，尚未确定。

关键证据

2026-11-05，固定官方 main 80224b0314c6008ecb4de82d1e37b019d5e355df；实际二进制同 SHA、vcs.modified=false。本地独占 3 LOG / 1 TN / 1 CN，正常停止目标 leader，无分区注入、无生产源码/超时修改；不是多机部署。另有独立测试同机运行，时延不作为独占性能基准。
10 轮 leader 切换中，3 轮记录 WAL Append 60.243033 / 60.271688 / 60.163966 秒，均内部重试 1 次后成功。前三轮固定观察 75 秒、写入间隔 1 秒；后七轮写入间隔 0.1 秒、30–85 秒自适应观察。不是独立新集群 3/3，也不能据此给出固定条件故障概率。
一轮详细时间线（北京时间）：

13:06:48.045399  停止 l0（WAL leader）
13:06:50.606085  l2 成为 WAL leader（约 2.56 秒）
故障后 10/30/55 秒 TN 同一 Future 0x1827be485960 持续等待 Append
13:07:48.132276  存活 l1: propose failed, error=timeout
13:07:48.374827  TN WAL-Commit-Append:
                 psn=2887, size=1741, retry-times=1,
                 duration=1m0.243032792s
13:07:48.380018  SQL COMMIT 成功，elapsed=60.250436042s

同步采集的调用栈：

TN: groupCommitter.Commit → wrappedClient.Append → managedClient.Append
    → client.request → Future.Get
存活 l1: Service.handleAppend → store.append → store.propose
         → NodeHost.SyncPropose → getRequestState
CN 新连接: prepareAuthenticationSnapshot → acquireLogtailReadBarrier
           → LogtailClient.ReadBarrier

TN 在途 payload 为 0x6d9，l1 服务端在途 Append 也是该长度，与 1741 字节 WAL payload 加 12 字节头一致；这是调用栈/长度/时间相关证据，尚无跨进程逐请求 Raft 消息追踪。另一轮在故障后 50.9 秒采样，已当选新 leader 的 l2 也有服务端 SyncPropose 等待。

正常无故障对照 24 笔提交，最大 53.25ms；停止 follower 对照 25 笔，最大 16.26ms。所有场景旧连接读取 590 次成功；新连接 359 次成功、24 次约 6 秒客户端连接超时。共 1424 笔本轮确认提交（含各库初始数据），每笔 fsync 账本；两表同事务写入 INT/DECIMAL/VARCHAR/NULL。全部 LOG/TN/CN 停机冷启动后逐行比较，没有确认提交缺失、值错、额外行或双表部分提交；重复键多行 INSERT 的失败原子性及 DELETE/ROLLBACK 对照正常。
WAL 单次超时默认 1m，Append 等错误返回才重试，服务端 SyncPropose，新连接认证快照读屏障。既有读屏障、有序发布及 WAL Append 失败完成 waiter 的 UT 各重复 3 次通过；不等于本次集群长尾已解决。

待解决点

需进一步关联 Raft proposal key/term 和完成事件，确认为什么选主后该在途提案仍等到 deadline；目前不能断言丢失、覆盖或具体通知遗漏。
这是 [Bug]: LogService Append waits 60s on an isolated replica despite a healthy Raft majority #32133 等待方向的定位补充，与 [Bug]: 单个 LogService Pod 故障后两个 CN 握手超时并返回 20508 #32145 的新连接超时有相邻传播路径，但没有证明其现场完全同因。未新建重复 issue、未调整标签。
两小时连续故障恢复仍独立运行，尚未完成，不将本次短时切换/冷启动结果替代多小时恢复结论。完整本地脚本及证据保留在 /private/tmp/mo-longpartition-HeXEtq/ 的 switch-results.md、switch-trace.log、switch-repeat.log、switch-persistent-audit.log、switch_*.stack；关键证据已摘录在上面，不依赖读者访问本地路径。

结论

继续补充约一分钟等待的内部定位证据，不是修复验收结论：存活 LOG 接收的提案即使已确定无法发送，也可能继续挂在 pending 中，直到超时才让 WAL 重试。选出新 leader，甚至该请求所在节点自己成为 leader，都不会自动结束这个旧等待。这为前一条评论中的 SyncPropose 长时间等待补上了逐 key 证据；不声称原 issue 所有连接隔离样本都只有这一根因。

关键证据

固定 main 80224b0314c6008ecb4de82d1e37b019d5e355df，本地隔离 3 LOG / 1 TN / 1 CN。上轮官方二进制的自然 leader 停止已出现约 60 秒长尾；本轮为定位使用同提交、同 Dragonboat 依赖的仅加日志诊断构建，未改选举、超时、重试语义。新增日志会影响时序，不能将诊断复现频率当作官方概率。同机还有独立长稳，不作为独占性能基准。
两组共 10 轮 leader 停止，另有两轮无故障、两轮 follower 停止对照。关键原始日志摘录如下，时间均为北京时间。

路径一：传输直接拒绝，但旧提案仍等到超时

14:27:18.289050  停止 WAL leader l2
14:27:20.562112  l1 REQUEST key=17096056497528125585 size=4031
14:27:20.562171  l1 FORWARD term=37 to=l2
14:27:20.562205  l1 TRANSPORT accepted=false reason=2 (unknownTarget)
14:27:20.852344  l0 当选新 WAL leader，term=38
14:28:18.226714  l1 同一个 key EXPIRE
14:28:18.527364  TN WAL psn=6765 size=4019 retry-times=1
                 duration=60.114451583s

该 key 的请求到超时为 57.664602 秒，整个 WAL 尝试及重试为 60.114452 秒，两者起点不同。另一轮 key 6067060892054681742 同样 accepted=false reason=2，等待 60.040240 秒才 EXPIRE，WAL 用时 60.242908 秒。三 LOG 日志均未见这两个 key 的 leader 接收、入日志、复制或应用事件。

路径二：发送入队后连接写失败，原请求节点当选 leader 也没有结束旧等待

14:25:55.782312  停止 WAL leader l0
14:25:55.865855  l2 REQUEST key=15793671311024166122 size=1753
14:25:55.870728  l2 FORWARD term=36 to=l0
14:25:55.870847  l2 TRANSPORT accepted=true（仅表示入发送队列）
14:25:55.871715  l2 同一目标连接 send batch failed: broken pipe
14:25:55.872045  l2 目标 unreachable
14:25:58.300657  l2 自己成为 WAL leader，term=37
14:26:55.789513  l2 同一个 key EXPIRE（59.923658 秒）
14:26:56.034578  TN WAL psn=6670 retry-times=1 duration=60.176273208s

同 key 同样未见入日志或应用。broken pipe 的 batch 日志没有逐 entry key，因此批次内容关联仍限于同目标、相邻时间及生命周期证据，不把它写成额外的完整网络包证明。

白盒对应：Dragonboat handleFollowerPropose 向当前 leader 转发；sendMessage 未处理 transport.Send 的 false 返回。传输层的目标解析失败立即返回，异步写失败则走无 proposal key 的 Unreachable；这些路径不会直接完成原 pending。processLeaderUpdate 只更新 leader 信息。pending 可由 apply/drop/close/expiry 结束，不是无限等待或已证明的内存泄漏。
MO store.propose在 SyncPropose 返回前无法进入重试；WAL 单次默认一分钟。依赖副本上的临时组件测试分别验证正常转发、丢失转发后换届、Unreachable、apply/drop/close/timeout、取消后晚到应用/超时清理，以及 gossip leave/rejoin 地址解析，均重复 3 次；没有修改仓库测试。
数据核验：本轮新增 568 笔确认提交（含 112 笔初始数据），没有新增结果未知事务；最终停掉全部诊断进程，换回未加日志的官方二进制完整冷启动，累计 2079 笔 ACK 的两表 INT/DECIMAL/VARCHAR/NULL 完整值全部匹配，没有缺失、额外行或部分提交。历史 7 笔 unknown 单列核对：1 笔完整提交、6 笔未写入，不把 unknown 当回滚。32 个库的重复键多行 INSERT 失败原子性、DELETE/ROLLBACK 及后续查询均正常。正常无故障提交最大 32.08/198.01ms，停止 follower 对照最大 20.48/31.82ms；旧连接读取 891 次成功，新连接读取 469 次成功、52 次连接阶段约 6 秒超时，恢复后可用。
原始证据保留在 /private/tmp/mo-proposal-trace-hfswkf/（overlay、组件测试、proposals-all.json、combined-summary.json、results.md）和 /private/tmp/mo-longpartition-HeXEtq/（diagnostic-switch.log、transport-switch.log、raft-proposal-persistent-audit.log、三 LOG 日志及 fsync 账本）。关键逐 key 原始记录已摘录于上，不依赖读者访问本地目录。

待解决点

需评估如何让确定的发送失败及时反馈给提案调用方，同时正确处理已经入日志或结果未知的尝试。不能把“缩短超时/无条件重投”直接作为已验证修复；NoOPSession 下重试需要保留 WAL 去重和结果核对语义。
本轮是现有等待问题的深入定位，未新建重复 issue、未调整标签。两小时连续隔离任务独立运行，到点再核验，不以这些短轮次替代长稳结论。

结论

补充同一等待机制的定位证据，不是修复验收结论：已将一组 unknownTarget 串到具体 gossip 地址删除事件；另捕获了失败发送批次中的 proposal key。两类发送失败都未立即结束旧 pending。本轮没有发现确认提交的数据缺失，也不另拆重复 issue。

关键证据

固定 main 80224b0314c6008ecb4de82d1e37b019d5e355df，本地隔离 3 LOG / 1 TN / 1 CN。诊断构建只增加日志，未改选举、超时或重试；正常停止 leader 6 轮、突然停止 leader 3 轮，加无故障和两种 follower 停止共 12 组。沿用隔离集群、每组新建库，不是独立新集群 3/3；日志和同机任务会影响时延，不能据此比较故障概率。
地址失效链路（同一 l2 进程、同一个 store、同一目标 l1，时间为北京时间）：

14:54:34.019452 GOSSIP_LEAVE target=l1 store=0x476459484600
14:54:34.029596 REQUEST key=10420288179807746019 size=1753
14:54:34.029717 RESOLVE node=262149 stage=gossip_address
               target=l1 store=0x476459484600
14:54:34.029730 TRANSPORT same-key accepted=false reason=2 (unknownTarget)
14:54:36.436804 l0 当选 WAL leader
14:55:34.054506 同一 key EXPIRE（60.024910 秒）
14:55:34.274464 TN WAL size=1741 retry-times=1 duration=60.244681s

Resolve 已经越过 replica→NodeHost 映射，失败在 gossip 地址层；与源码中 NodeLeave 删除地址、保留 replica 映射相符。另一轮突然停止 leader 后，key 13831047832024122340 返回 reason=1 (circuitBreakerNotReady)，仍等待 59.846349 秒 EXPIRE，WAL 重试完成用 60.221947 秒。不同拒绝原因仍落到同一 pending 等待机制。

异步失败终于有批次逐 key 证据：

15:01:50.532888 l0 REQUEST key=10388835975475822994 size=12 timeoutTick=24
15:01:50.535739 l0 FORWARD same-key to=l2
15:01:50.536656 l0 TRANSPORT same-key accepted=true
15:01:50.536691 l0 BATCH_FAILED same-key to=l2 batchMessages=1
15:01:55.424033 l0 EXPIRE same-key（4.891145 秒）

另一 key 12755473332290716539 同样入队→批次失败→4.804758 秒后超时。这两个是 12 字节短请求，不是前述一分钟 WAL 样本；此前大请求的相邻 broken pipe 仍不能直接认作包含该 key 的失败批次。

新增 486 笔 ACK、无新增 unknown。随后全部停止诊断进程，使用未加日志的正式二进制完整冷启动：累计 2565 ACK、44 库双表完整值均匹配，每表共 2566 行；7 笔历史 unknown 单列核对。44 组重复键失败原子性、DELETE 回滚和后续可用性正常。运行中旧连接读取 785 次成功，新连接 398 次成功、47 次连接阶段超时；不把连接失败写成查询值错误。
原始证据：/private/tmp/mo-proposal-trace-hfswkf/delivery-results.md、delivery-summary.json、delivery-proposals-all.json、gossip-delivery-links.json、v3 overlay，以及 /private/tmp/mo-longpartition-HeXEtq/proposal-delivery.log、delivery-persistent-audit.log 和三 LOG 逐 key 日志。关键记录已摘录如上，不要求读者访问本地目录。

待解决点

这是既有问题的内部定位，不是已验证修复。大 WAL 请求入队后的批次去向还不能全部闭合，不将短请求证据扩大为所有样本结论。
更正上条评论的长稳状态：原两小时轮次后来查实在约 80 分钟因本机磁盘保护退出，并未完成；其 88 ACK 冷核验正常。一次重试在启动阶段失败，尚未排除环境因素。清理可重建缓存后的独立重跑于 14:56:40 开始，至少 16:56:41 才满两小时，之后仍需恢复及冷启动核验；不拼接时长，也不作为本轮已通过门槛。

fix(logservice): bound stalled RPCs and stale HAKeeper startup (#32147)

合并范围补充：#32147 已合入 main，merge SHA d2dab99，最终 head 4c901ec。它完成了 LogService data RPC 的 8 秒响应不活动窗口；超时 Append 仍是结果未知，未增加 managed-client 自动重投。原连接黑洞场景可以据此做有界回归，但本 issue 暂保留研发归属。

原因是 6651454890 明确提出的开发后续仍未完成：如何将确定的传输发送失败安全反馈给 pending proposal 调用方，同时区分已入日志/未知结果并保留 WAL 去重与核对语义。6651970743 延续了这一定位，尚未给出该后续已完成或被替代的结论。当前合并未改动这条 Dragonboat failure-feedback 路径。

已读全部 6 条评论；这些反例使用旧提交，不能写成 d2dab99 上的已验证失败。保留研发的理由是上述明确未完开发范围，不是长稳结果未公布或未重跑测试。本轮仅远端与源码核对，没有本地实测。最终 head CI 的 shared build 和 PROXY/PESSIMISTIC BVT 成功，UT/SCA/UT Coverage 取消、Coverage 跳过、CI Required 失败，不记为完整通过；作者 focused/owning/race 报告也不替代原三 voter 场景验收。

Navigation Menu

Repository navigation

[Bug]: LogService Append waits 60s on an isolated replica despite a healthy Raft majority #32133

Description

Environment

Reproduction

Actual Result

Expected Result

Code Evidence and Scope

Follow-up: Read also waited for the full per-attempt timeout after leader crash (2026-11-04)

Controlled Read timeout comparison (2026-11-04)

结论

关键证据

待解决点

结论

关键证据

待解决点

结论

关键证据

待解决点

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[Bug]: LogService Append waits 60s on an isolated replica despite a healthy Raft majority #32133

Description

Description

Environment

Reproduction

Actual Result

Expected Result

Code Evidence and Scope

Activity

jiangxinmeng1 commented on Nov 4, 2026

Follow-up: Read also waited for the full per-attempt timeout after leader crash (2026-11-04)

jiangxinmeng1 commented on Nov 4, 2026

Controlled Read timeout comparison (2026-11-04)

jiangxinmeng1 commented on Nov 4, 2026

Ariznawlll commented on Nov 5, 2026

结论

关键证据

待解决点

Ariznawlll commented on Nov 5, 2026

结论

关键证据

待解决点

Ariznawlll commented on Nov 5, 2026

结论

关键证据

待解决点

XuPeng-SH commented on Nov 5, 2026

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions