kvcache-ai/Mooncake

Fork 0

mirror of https://github.com/kvcache-ai/Mooncake.git synced 2026-11-05 01:17:55 +00:00

[GH-ISSUE #3740] [Bug]: Store clients take ~2 minutes to reattach after a master failover, though promotion itself takes ~10s #951

New issue

Open

opened 2026-10-29 21:21:14 +00:00 by bsakaguchi · 3 comments

bsakaguchi commented

2026-10-29 21:21:14 +00:00

Owner

Originally created by @gongwei-130 on GitHub (Aug 27, 2026).
Original GitHub issue: https://github.com/kvcache-ai/Mooncake/issues/3740

Originally assigned to: @Icedcoco on GitHub.

Bug Report

On 0.3.13 with -enable_ha=true -enable_oplog=true -ha_backend_type=etcd, master failover
itself works well: promotion is fast and no metadata is lost — this is a clear improvement
over 0.3.12.post1. But the pool is unreadable for roughly two minutes afterwards, because the
store clients do not reattach for that long. The master serves an intact 200-object index to
nobody.

Reproduced twice, with near-identical timing both times.

Setup

Kubernetes, 1 etcd (v3.5.21), 2 mooncake_master (primary + hot standby), 3 mooncake_client
store nodes contributing 200 GiB each (600 GiB pool)
Image: docker.io/kvcacheai/mooncake:0.3.13
Master: -enable_ha=true -ha_backend_type=etcd -enable_oplog=true -etcd_endpoints=<etcd>:2379
Client: -master_server_address=etcd://<etcd>:2379 -protocol=rdma -global_segment_size=200GB
Workload: 200 objects × 4 MiB, seeded and verified by a small deterministic probe
Failover triggered with kubectl delete pod <primary>

What works

17:49:57.752  Promoting Standby to Primary. Applied seq_id: 206, lag: 0 entries
17:49:57.755  Standby promoted to Primary successfully
17:50:02.755  Starting serve phase...
17:50:02.778  Restored from standby: 200 objects, 2 segments, initial_seq_id=206

~4 s from pod deletion to promotion, ~10 s to serving, lag=0 throughout, and a verify run
after both failovers found 200/200 objects present and intact.

What does not

The new primary serves an index it has no clients for:

17:50:02.7   new leader serving — Keys: 200, Clients: 0, Mem Storage 0 B / 0 B
17:50:30     verify -> present+intact = 0/200, missing = 200
~17:52       Clients: 2, Mem Storage 800.00 MB / 400.00 GB    (~2 min after the kill)

So the metadata survived and the data survived, but for ~2 minutes every read fails.

First cause: the view is published before the RPC port is bound

The new primary writes its master_view entry to etcd when it wins the election, then spends
~5 s in warmup before it binds :50051. Since #2484 made the client's view watch event-driven,
clients now wake up inside that window and connect to a port nobody is listening on. From a
store client (a different run of the same test):

17:46:10.229  master_client.cpp:361     Client not available
17:46:10.230  client_service.cpp:755    Failed to switch to leader 10.245.103.224:50051: RPC_FAIL

The new leader began serving 0.7 s later. This first failure looks like a straightforward
ordering problem: publish the view after the RPC port is accepting connections, not before.
Before #2484 the 200 ms/1 s polling cadence would usually have hidden it; making discovery fast
made the race reliable.

Second, and the part we cannot explain: recovery then takes ~120 s

A single lost race should cost a retry, not two minutes. Reading v0.3.13, every retry path
looks like it should recover in seconds:

Client::LeaderMonitorThreadMain (client_service.cpp:720) sleeps
kErrorRetryInterval = 1 s after a failed SwitchLeader, then loops. It does not need a
fresh watch event to retry: EtcdLeaderCoordinator::WaitForViewChange re-reads the view at
the top of each iteration and returns changed = true whenever it differs from the version
the client last committed (etcd_leader_coordinator.cpp:434-440) — and a failed
SwitchLeader deliberately does not commit one.
The ping thread reconnects independently after max_ping_fail_count = 3 failures at
fail_ping_interval_ms = 1000 (client_service.cpp:4726,4730), then remounts segments
when the master answers NEED_REMOUNT.

Either path should have the client back within single-digit seconds. We measured ~120 s, twice,
and could not determine which path stalls or why. Clients: 0 on the master for the whole
window suggests pings are not landing rather than the switch never being retried, but we did
not confirm that.

Happy to run instrumented builds, raise client log verbosity, or test a patch — this is a test
cluster and the failover is a one-command reproduction.

Expected

Promotion is ~10 s. Clients should reattach on that order, not 12× later.

Suggested fixes

Bind the RPC port before publishing the master_view entry, so a client that reacts
immediately to the watch reaches a listening socket. This alone removes the trigger.
Independently, find out why the retry path takes ~120 s rather than ~1 s — a client that
loses the race for any other reason (a slow node, a network blip) hits the same stall.

#2484 made the master-view watch event-driven. That change is good and we want it; it is what
turns this ordering window from unlikely into reliable.
#2188, #2971, #3561 cover master-side metadata durability. This report is specifically about
the client side after a successful promotion — the metadata was fine in every run here.

Before submitting a new issue...

Searched existing issues and read the documentation.

Originally created by @gongwei-130 on GitHub (Aug 27, 2026). Original GitHub issue: https://github.com/kvcache-ai/Mooncake/issues/3740 Originally assigned to: @Icedcoco on GitHub. ### Bug Report On `0.3.13` with `-enable_ha=true -enable_oplog=true -ha_backend_type=etcd`, master failover itself works well: promotion is fast and **no metadata is lost** — this is a clear improvement over `0.3.12.post1`. But the pool is unreadable for roughly two minutes afterwards, because the store clients do not reattach for that long. The master serves an intact 200-object index to nobody. Reproduced twice, with near-identical timing both times. ### Setup - Kubernetes, 1 etcd (v3.5.21), 2 `mooncake_master` (primary + hot standby), 3 `mooncake_client` store nodes contributing 200 GiB each (600 GiB pool) - Image: `docker.io/kvcacheai/mooncake:0.3.13` - Master: `-enable_ha=true -ha_backend_type=etcd -enable_oplog=true -etcd_endpoints=<etcd>:2379` - Client: `-master_server_address=etcd://<etcd>:2379 -protocol=rdma -global_segment_size=200GB` - Workload: 200 objects × 4 MiB, seeded and verified by a small deterministic probe - Failover triggered with `kubectl delete pod <primary>` ### What works ``` 17:49:57.752 Promoting Standby to Primary. Applied seq_id: 206, lag: 0 entries 17:49:57.755 Standby promoted to Primary successfully 17:50:02.755 Starting serve phase... 17:50:02.778 Restored from standby: 200 objects, 2 segments, initial_seq_id=206 ``` ~4 s from pod deletion to promotion, ~10 s to serving, `lag=0` throughout, and a verify run after both failovers found **200/200 objects present and intact**. ### What does not The new primary serves an index it has no clients for: ``` 17:50:02.7 new leader serving — Keys: 200, Clients: 0, Mem Storage 0 B / 0 B 17:50:30 verify -> present+intact = 0/200, missing = 200 ~17:52 Clients: 2, Mem Storage 800.00 MB / 400.00 GB (~2 min after the kill) ``` So the metadata survived and the data survived, but for ~2 minutes every read fails. ### First cause: the view is published before the RPC port is bound The new primary writes its `master_view` entry to etcd when it wins the election, then spends ~5 s in warmup before it binds `:50051`. Since #2484 made the client's view watch event-driven, clients now wake up *inside* that window and connect to a port nobody is listening on. From a store client (a different run of the same test): ``` 17:46:10.229 master_client.cpp:361 Client not available 17:46:10.230 client_service.cpp:755 Failed to switch to leader 10.245.103.224:50051: RPC_FAIL ``` The new leader began serving 0.7 s later. This first failure looks like a straightforward ordering problem: **publish the view after the RPC port is accepting connections, not before.** Before #2484 the 200 ms/1 s polling cadence would usually have hidden it; making discovery fast made the race reliable. ### Second, and the part we cannot explain: recovery then takes ~120 s A single lost race should cost a retry, not two minutes. Reading v0.3.13, every retry path looks like it should recover in seconds: - `Client::LeaderMonitorThreadMain` (`client_service.cpp:720`) sleeps `kErrorRetryInterval` = **1 s** after a failed `SwitchLeader`, then loops. It does not need a fresh watch event to retry: `EtcdLeaderCoordinator::WaitForViewChange` re-reads the view at the top of each iteration and returns `changed = true` whenever it differs from the version the client last committed (`etcd_leader_coordinator.cpp:434-440`) — and a failed `SwitchLeader` deliberately does not commit one. - The ping thread reconnects independently after `max_ping_fail_count` = **3** failures at `fail_ping_interval_ms` = **1000** (`client_service.cpp:4726,4730`), then remounts segments when the master answers `NEED_REMOUNT`. Either path should have the client back within single-digit seconds. We measured ~120 s, twice, and could not determine which path stalls or why. `Clients: 0` on the master for the whole window suggests pings are not landing rather than the switch never being retried, but we did not confirm that. Happy to run instrumented builds, raise client log verbosity, or test a patch — this is a test cluster and the failover is a one-command reproduction. ### Expected Promotion is ~10 s. Clients should reattach on that order, not 12× later. ### Suggested fixes 1. Bind the RPC port before publishing the `master_view` entry, so a client that reacts immediately to the watch reaches a listening socket. This alone removes the trigger. 2. Independently, find out why the retry path takes ~120 s rather than ~1 s — a client that loses the race for any other reason (a slow node, a network blip) hits the same stall. ### Related - #2484 made the master-view watch event-driven. That change is good and we want it; it is what turns this ordering window from unlikely into reliable. - #2188, #2971, #3561 cover master-side metadata durability. This report is specifically about the **client** side after a successful promotion — the metadata was fine in every run here. ### Before submitting a new issue... - [x] Searched existing issues and read the documentation.

bsakaguchi commented

2026-10-29 21:21:15 +00:00

Author

Owner

@github-actions[bot] commented on GitHub (Aug 27, 2026):

Thanks for opening this issue, @gongwei-130!

Field	Value
Issue	#3740
GitHub user ID	`56567052`
Reporter	@gongwei-130

A maintainer will triage this when possible. To help us respond faster, please include:

Mooncake version or commit SHA
Environment (OS, CUDA/driver, RDMA stack if relevant)
Steps to reproduce and expected vs. actual behavior

Useful links: Documentation · Contributing guide

This message was posted automatically by the issue bot.

@github-actions[bot] commented on GitHub (Aug 27, 2026): Thanks for opening this issue, @gongwei-130! | Field | Value | |-------|-------| | **Issue** | #3740 | | **GitHub user ID** | `56567052` | | **Reporter** | @gongwei-130 | A maintainer will triage this when possible. To help us respond faster, please include: - Mooncake version or commit SHA - Environment (OS, CUDA/driver, RDMA stack if relevant) - Steps to reproduce and expected vs. actual behavior Useful links: [Documentation](https://kvcache-ai.github.io/Mooncake/) · [Contributing guide](https://github.com/kvcache-ai/Mooncake/blob/main/CONTRIBUTING.md) > This message was posted automatically by the issue bot.

bsakaguchi commented

2026-10-29 21:21:15 +00:00

Author

Owner

@Icedcoco commented on GitHub (Aug 28, 2026):

Thanks for the detailed reproduction and timing data. The metadata and promotion path look healthy; this appears to be a client-side reattachment problem.

From the v0.3.13 code, the first race is confirmed: the new master publishes master_view during TryAcquireLeadership() before its RPC server has completed warmup and async_start(). With the event-driven watch from #2484, clients can therefore try the advertised endpoint while nothing is listening yet.

The ~120-second delay is most likely caused by the RPC client pool retrying synchronously inside MasterClient::Connect(). SwitchLeader() cannot return to LeaderMonitorThreadMain() until the ServiceReady RPC finishes. The pinned YLT defaults are one initial connection plus three retries, with a 30-second connection timeout, which can result in roughly four 30-second attempts. The client-side 1-second retry interval only starts after Connect() returns, so it does not bound this delay.

This is still a high-probability diagnosis rather than a fully confirmed explanation for the reported run. An immediate ECONNREFUSED would normally return quickly and, with the internal one-second waits, would explain only a few seconds. To distinguish these cases, could you provide:

The full client log around failover with timestamps, including YLT connection messages such as begin to connect, connect timeout, failed, and out of max limit.
The values of MC_RPC_PROTOCOL, MC_RPC_CONNECT_TIMEOUT_MS, and MC_RPC_TIMEOUT_MS, if set, plus the exact v0.3.13 image digest or commit.
Master-side logs for async_start, ServiceReady, Ping, and ReMountSegment during the same interval.
Whether Ping requests stop completely during the two-minute window, or whether they succeed and return NEED_REMOUNT.
If possible, a short packet capture or connection check from a client pod to the new master during warmup, showing whether SYN packets receive RST or simply time out.

Four approximately 30-second connection timeouts would confirm the retry explanation. Immediate refusals followed by ~1-second gaps would point to the pool’s retry wait instead, while successful pings followed by delayed remounts would indicate a separate storage-control-plane issue.

PR #3743 addresses the likely blocking behavior by setting the master RPC pool to a single connection attempt with no internal retry wait, leaving retries to the existing HA monitor and heartbeat loops. It should reduce the stall substantially, but it does not remove the startup ordering race or the remaining per-attempt timeout.

The long-term fix should publish a ready service endpoint only after the RPC listener is accepting connections, while keeping election/fencing state separate from service discovery. Simply moving the existing master_view write after async_start() would need to be evaluated carefully because that key currently also represents leadership ownership.

@Icedcoco commented on GitHub (Aug 28, 2026): Thanks for the detailed reproduction and timing data. The metadata and promotion path look healthy; this appears to be a client-side reattachment problem. From the v0.3.13 code, the first race is confirmed: the new master publishes `master_view` during `TryAcquireLeadership()` before its RPC server has completed warmup and `async_start()`. With the event-driven watch from #2484, clients can therefore try the advertised endpoint while nothing is listening yet. The ~120-second delay is most likely caused by the RPC client pool retrying synchronously inside `MasterClient::Connect()`. `SwitchLeader()` cannot return to `LeaderMonitorThreadMain()` until the `ServiceReady` RPC finishes. The pinned YLT defaults are one initial connection plus three retries, with a 30-second connection timeout, which can result in roughly four 30-second attempts. The client-side 1-second retry interval only starts after `Connect()` returns, so it does not bound this delay. This is still a high-probability diagnosis rather than a fully confirmed explanation for the reported run. An immediate `ECONNREFUSED` would normally return quickly and, with the internal one-second waits, would explain only a few seconds. To distinguish these cases, could you provide: 1. The full client log around failover with timestamps, including YLT connection messages such as `begin to connect`, `connect timeout`, `failed`, and `out of max limit`. 2. The values of `MC_RPC_PROTOCOL`, `MC_RPC_CONNECT_TIMEOUT_MS`, and `MC_RPC_TIMEOUT_MS`, if set, plus the exact v0.3.13 image digest or commit. 3. Master-side logs for `async_start`, `ServiceReady`, `Ping`, and `ReMountSegment` during the same interval. 4. Whether `Ping` requests stop completely during the two-minute window, or whether they succeed and return `NEED_REMOUNT`. 5. If possible, a short packet capture or connection check from a client pod to the new master during warmup, showing whether SYN packets receive `RST` or simply time out. Four approximately 30-second connection timeouts would confirm the retry explanation. Immediate refusals followed by ~1-second gaps would point to the pool’s retry wait instead, while successful pings followed by delayed remounts would indicate a separate storage-control-plane issue. PR #3743 addresses the likely blocking behavior by setting the master RPC pool to a single connection attempt with no internal retry wait, leaving retries to the existing HA monitor and heartbeat loops. It should reduce the stall substantially, but it does not remove the startup ordering race or the remaining per-attempt timeout. The long-term fix should publish a ready service endpoint only after the RPC listener is accepting connections, while keeping election/fencing state separate from service discovery. Simply moving the existing `master_view` write after `async_start()` would need to be evaluated carefully because that key currently also represents leadership ownership.

bsakaguchi commented

2026-10-29 21:21:16 +00:00

Author

Owner

@gongwei-130 commented on GitHub (Aug 29, 2026):

Thanks — this is a much better diagnosis than what we had, and we can now confirm the timing half of it to sub-millisecond precision. Your discriminating test came out cleanly in favour of the retry-blocking explanation, and the data also narrows which connection is blocking in a way that changes what a fix has to cover.

Everything below is from the two kubectl delete pod <leader> runs on 2026-08-27 already described in the issue. Log lines are the complete set from both store clients over that window — the client log really is this sparse (224 lines total across both pods for 17:44–17:56Z), which is itself part of the answer to Q1.

The number you asked for: 121.0 s, four times, deterministic

Gaps between consecutive client_service.cpp:4857 Failed to ping master lines (thread 153, the ping thread), on both store pods across both failovers:

pod	from	to	gap
A	17:46:02.193627	17:48:03.195081	121.001454 s
A	17:49:54.249010	17:51:55.250379	121.001369 s
B	17:46:02.029592	17:48:03.030292	121.000700 s
B	17:49:54.249737	17:51:55.250494	121.000757 s

120 s + 1 s, reproducible to under 1 ms on two independent pods across two separate failovers. That spread rules out network variance — this is a fixed timer, and it matches your 1 initial + 3 retries × 30 s connect timeout plus the 1 s retry interval exactly.

(The intervening 17:48:03 → 17:49:54 gaps of 111.05 s / 111.22 s are not retry cycles — that is where we issued the second kubectl delete, which interrupted the loop with an immediate RPC call failed: End of file.)

Your alternative is ruled out. Immediate refusals with ~1 s gaps would have produced ~113 log lines in that window. We have zero: the ping thread emits nothing at all between the two lines above.

The refinement: the master was ready for 113.6 s of those 121 s

This is the part that changes the shape of the problem. Master-side admin metrics, 10 s cadence, from the promoted pod:

17:49:57.755215  Entering warmup phase...
17:50:02.755231  Starting serve phase...            (warmup = 5.000016 s, exactly)
17:50:02.778113  Restored from standby: 200 objects, 2 segments, initial_seq_id=206
17:50:02.778329  Master runtime state -> serving, role=leader
17:50:06.364      role=leader, state=serving, service_ready=true | Clients: 0 | Keys: 200 | Mem 0 B / 0 B
17:50:16.364  …   Clients: 0     (same line, unchanged, every 10 s)
   …  eleven consecutive samples, all Clients: 0  …
17:51:46.366  …   Clients: 0
17:51:56.366      role=leader, state=serving, service_ready=true | Clients: 2 | Keys: 200 | Mem 800.00 MB / 400.00 GB

service_ready=true with Clients: 0 for 113.587671 s. The master finished warmup, restored the index, and was accepting — and then sat idle while the clients were stuck. So the outage length is set by the client's retry budget and is essentially independent of when the master becomes ready.

Q5, without a packet capture: the two failures have different latencies

We can separate refusal from timeout by timing alone, and they disagree with each other:

17:50:02.024817  82 master_client.cpp:361   Client not available
17:50:02.024899  92 client_service.cpp:755  Failed to switch to leader 10.245.52.167:50051: RPC_FAIL

82 microseconds apart. That is an immediate RST, i.e. the new leader's :50051 genuinely was not accepting — this is your startup ordering race, and it cost 0.732601 s (the attempt landed that far before Starting serve phase...).

The 30 s-per-attempt timeouts therefore cannot be against the new leader. The reading that fits all six numbers: the ping thread is retrying the old leader's address, and that is a deleted pod IP — so SYNs are silently dropped rather than refused, which is precisely the condition that turns an instant failure into a 30 s connect timeout. Four of those plus the 1 s interval is the 121 s.

Marking clearly what is inference: the 121 s timer, its start anchor (the first ping failure) and the 113.6 s of idle-but-ready master are measured; that the blocked connect targets the old address specifically is inferred from the latency difference, since we have no per-attempt log line naming the peer.

Which thread gates recovery

The leader-monitor thread (92) fails once, instantly, at 17:50:02.024899 — and then logs nothing until recovery. It is not looping at 1 s. Meanwhile Mem Storage stays at 0 B through the whole window, i.e. the segments are never remounted, and remount is driven off the ping path answering NEED_REMOUNT. Recovery lands within the same second the ping thread's 121 s expires (Clients: 0 → 2 between the 17:51:46 and 17:51:56 samples; ping thread returns 17:51:55.250).

So the blocking ping call is what holds the whole reattachment, and the leader monitor's 1 s retry loop — the thing we originally expected to bound this to single-digit seconds — is irrelevant because the remount does not go through it.

Answers to the rest

Q1 — YLT connection log lines: we cannot supply these. Not "we did not capture them": there are zero matches for begin to connect / connect timeout / failed / out of max limit / coro_rpc / client_pool / ylt across 3 hours and 2551 log lines of both store containers. The published image appears to emit glog only, with YLT's own logger silent. If you tell us the knob (build flag, ylt log-level env, or a easylog init call) we will rebuild or reconfigure and rerun the same experiment — this is the one thing you asked for that we genuinely do not have.

Q2 — all three are unset, so the pinned YLT defaults are in force, which is exactly the condition your diagnosis assumes:

var	value
`MC_RPC_PROTOCOL`	unset
`MC_RPC_CONNECT_TIMEOUT_MS`	unset
`MC_RPC_TIMEOUT_MS`	unset

Image: kvcacheai/mooncake:0.3.13, digest sha256:51d695314243f3a35615784634ac4fd4bfd5f1aca316df997383a0617169b780, identical on master and store pods. Clients use etcd:// for master discovery (not a fixed address), replica_num=1, 2 store clients, 200 objects × 4 MiB.

Q3 — master side, full sequence is quoted above. Note there is no async_start or ServiceReady line in the master log either, so the only observable boundary is Entering warmup phase... → Starting serve phase..., measured at 5.000016 s. Also present, and possibly relevant to you separately:

17:49:57.745801  etcd_helper.cpp:75  key=…/master_view, error=key not found in etcd
17:50:02.770654  etcd_helper.cpp:75  key=/oplog/mooncake_cluster/latest, error=key not found in etcd
17:50:02.778113  Restored from standby: 200 objects, 2 segments, initial_seq_id=206, invalid_endpoints=4

The clients observe the same master_view absence during the election gap — the key is deleted, not stale, so a client reading it mid-election gets a not-found rather than the old address.

Q4 — Ping stops completely. It does not succeed, and it never returns NEED_REMOUNT. Two lines, 121 s apart, nothing in between; Mem Storage flat at 0 B for the duration.

What this implies for #3743

It should fix the observed outage, and for the right reason: a single attempt with no internal retry wait turns the 121 s into roughly the 1 s monitor interval, regardless of which address is being probed or whether it black-holes.

The one thing worth flagging is that fixing the ordering race alone would not be sufficient in general, even though it would have avoided this particular run. The race window is 5 s (the warmup) and the retry budget is 121 s. Any first attempt that fails for any reason — mid-election master_view not-found, a rescheduled pod, a brief network drop — costs the full budget, and the master's readiness has no influence on it. Bounding the client retry is the load-bearing fix; the ready-endpoint separation you describe is the correctness fix. They are not substitutes.

Happy to rerun the failover with a capture from a client pod to both the old and new master addresses if that would settle the black-hole-vs-refusal inference, and to retest on #3743 once it lands — we have this on two clusters and can reproduce on demand.

@gongwei-130 commented on GitHub (Aug 29, 2026): Thanks — this is a much better diagnosis than what we had, and we can now confirm the timing half of it to sub-millisecond precision. Your discriminating test came out cleanly in favour of the retry-blocking explanation, and the data also narrows *which* connection is blocking in a way that changes what a fix has to cover. Everything below is from the two `kubectl delete pod <leader>` runs on 2026-08-27 already described in the issue. Log lines are the complete set from both store clients over that window — the client log really is this sparse (224 lines total across both pods for 17:44–17:56Z), which is itself part of the answer to Q1. ## The number you asked for: 121.0 s, four times, deterministic Gaps between consecutive `client_service.cpp:4857 Failed to ping master` lines (thread 153, the ping thread), on both store pods across both failovers: | pod | from | to | gap | |---|---|---|---| | A | 17:46:02.193627 | 17:48:03.195081 | **121.001454 s** | | A | 17:49:54.249010 | 17:51:55.250379 | **121.001369 s** | | B | 17:46:02.029592 | 17:48:03.030292 | **121.000700 s** | | B | 17:49:54.249737 | 17:51:55.250494 | **121.000757 s** | `120 s + 1 s`, reproducible to under 1 ms on two independent pods across two separate failovers. That spread rules out network variance — this is a fixed timer, and it matches your `1 initial + 3 retries × 30 s connect timeout` plus the 1 s retry interval exactly. (The intervening `17:48:03 → 17:49:54` gaps of 111.05 s / 111.22 s are not retry cycles — that is where we issued the second `kubectl delete`, which interrupted the loop with an immediate `RPC call failed: End of file`.) **Your alternative is ruled out.** Immediate refusals with ~1 s gaps would have produced ~113 log lines in that window. We have zero: the ping thread emits nothing at all between the two lines above. ## The refinement: the master was ready for 113.6 s of those 121 s This is the part that changes the shape of the problem. Master-side admin metrics, 10 s cadence, from the promoted pod: ``` 17:49:57.755215 Entering warmup phase... 17:50:02.755231 Starting serve phase... (warmup = 5.000016 s, exactly) 17:50:02.778113 Restored from standby: 200 objects, 2 segments, initial_seq_id=206 17:50:02.778329 Master runtime state -> serving, role=leader 17:50:06.364 role=leader, state=serving, service_ready=true | Clients: 0 | Keys: 200 | Mem 0 B / 0 B 17:50:16.364 … Clients: 0 (same line, unchanged, every 10 s) … eleven consecutive samples, all Clients: 0 … 17:51:46.366 … Clients: 0 17:51:56.366 role=leader, state=serving, service_ready=true | Clients: 2 | Keys: 200 | Mem 800.00 MB / 400.00 GB ``` **`service_ready=true` with `Clients: 0` for 113.587671 s.** The master finished warmup, restored the index, and was accepting — and then sat idle while the clients were stuck. So the outage length is set by the *client's* retry budget and is essentially independent of when the master becomes ready. ## Q5, without a packet capture: the two failures have different latencies We can separate refusal from timeout by timing alone, and they disagree with each other: ``` 17:50:02.024817 82 master_client.cpp:361 Client not available 17:50:02.024899 92 client_service.cpp:755 Failed to switch to leader 10.245.52.167:50051: RPC_FAIL ``` 82 **microseconds** apart. That is an immediate `RST`, i.e. the new leader's `:50051` genuinely was not accepting — this is your startup ordering race, and it cost **0.732601 s** (the attempt landed that far before `Starting serve phase...`). The 30 s-per-attempt timeouts therefore cannot be against the new leader. The reading that fits all six numbers: the ping thread is retrying the **old** leader's address, and that is a deleted pod IP — so SYNs are silently dropped rather than refused, which is precisely the condition that turns an instant failure into a 30 s connect timeout. Four of those plus the 1 s interval is the 121 s. Marking clearly what is inference: the 121 s timer, its start anchor (the first ping failure) and the 113.6 s of idle-but-ready master are **measured**; that the blocked connect targets the old address specifically is **inferred** from the latency difference, since we have no per-attempt log line naming the peer. ## Which thread gates recovery The leader-monitor thread (92) fails once, instantly, at 17:50:02.024899 — and then logs nothing until recovery. It is not looping at 1 s. Meanwhile `Mem Storage` stays at `0 B` through the whole window, i.e. **the segments are never remounted**, and remount is driven off the ping path answering `NEED_REMOUNT`. Recovery lands within the same second the ping thread's 121 s expires (`Clients: 0 → 2` between the 17:51:46 and 17:51:56 samples; ping thread returns 17:51:55.250). So the blocking ping call is what holds the whole reattachment, and the leader monitor's 1 s retry loop — the thing we originally expected to bound this to single-digit seconds — is irrelevant because the remount does not go through it. ## Answers to the rest **Q1 — YLT connection log lines: we cannot supply these.** Not "we did not capture them": there are **zero** matches for `begin to connect` / `connect timeout` / `failed` / `out of max limit` / `coro_rpc` / `client_pool` / `ylt` across 3 hours and 2551 log lines of both store containers. The published image appears to emit glog only, with YLT's own logger silent. If you tell us the knob (build flag, `ylt` log-level env, or a `easylog` init call) we will rebuild or reconfigure and rerun the same experiment — this is the one thing you asked for that we genuinely do not have. **Q2 — all three are unset**, so the pinned YLT defaults are in force, which is exactly the condition your diagnosis assumes: | var | value | |---|---| | `MC_RPC_PROTOCOL` | unset | | `MC_RPC_CONNECT_TIMEOUT_MS` | unset | | `MC_RPC_TIMEOUT_MS` | unset | Image: `kvcacheai/mooncake:0.3.13`, digest `sha256:51d695314243f3a35615784634ac4fd4bfd5f1aca316df997383a0617169b780`, identical on master and store pods. Clients use `etcd://` for master discovery (not a fixed address), `replica_num=1`, 2 store clients, 200 objects × 4 MiB. **Q3 — master side, full sequence** is quoted above. Note there is no `async_start` or `ServiceReady` line in the master log either, so the only observable boundary is `Entering warmup phase...` → `Starting serve phase...`, measured at 5.000016 s. Also present, and possibly relevant to you separately: ``` 17:49:57.745801 etcd_helper.cpp:75 key=…/master_view, error=key not found in etcd 17:50:02.770654 etcd_helper.cpp:75 key=/oplog/mooncake_cluster/latest, error=key not found in etcd 17:50:02.778113 Restored from standby: 200 objects, 2 segments, initial_seq_id=206, invalid_endpoints=4 ``` The clients observe the same `master_view` absence during the election gap — the key is deleted, not stale, so a client reading it mid-election gets a not-found rather than the old address. **Q4 — Ping stops completely.** It does not succeed, and it never returns `NEED_REMOUNT`. Two lines, 121 s apart, nothing in between; `Mem Storage` flat at `0 B` for the duration. ## What this implies for #3743 It should fix the observed outage, and for the right reason: a single attempt with no internal retry wait turns the 121 s into roughly the 1 s monitor interval, regardless of which address is being probed or whether it black-holes. The one thing worth flagging is that fixing the **ordering race alone would not be sufficient in general**, even though it would have avoided this particular run. The race window is 5 s (the warmup) and the retry budget is 121 s. Any first attempt that fails for any reason — mid-election `master_view` not-found, a rescheduled pod, a brief network drop — costs the full budget, and the master's readiness has no influence on it. Bounding the client retry is the load-bearing fix; the ready-endpoint separation you describe is the correctness fix. They are not substitutes. Happy to rerun the failover with a capture from a client pod to both the old and new master addresses if that would settle the black-hole-vs-refusal inference, and to retest on #3743 once it lands — we have this on two clusters and can reproduce on demand.

bsakaguchi referenced this issue

2026-10-29 21:31:24 +00:00

[PR #951] [MERGED] feat(store_service): support load config from env for mooncake store_service #1920