aarch64: master wedges inside TServer::Shutdown() — GracefulShutdownUnresponsiveSlave fails intermittently on the arm job

[ohohoreilly]

import_replication.test's GracefulShutdownUnresponsiveSlave fails intermittently on the aarch64 CI job. I first read this as load-sensitive flakiness; scoping the logs properly says otherwise. The master begins graceful shutdown and never finishes it.

Evidence

Latest occurrence: run 35281215846, master at dd770ac5.

The fixture gets all the way through its setup — its own markers are all present:

Suspending the slave
Slave state before interrupting the master: alive, state [T]
Interrupting the master

state [T] is stopped, so the slave was correctly frozen and the replication push was parked against it. The failure is in what happens after SIGINT.

Scoping to that fixture's own master log (the dump contains two fixtures' scratch dirs; this is the one that failed):

marker	present
TServer::Shutdown() begin	yes
TServer::Shutdown() draining [1] live client connections (#460)	yes — and it is the last line
RunReplicationQueue shutting down (#461)	no
TServer::Shutdown() complete	no

So the master entered Shutdown(), logged the connection drain, and then produced nothing further. Not even the drain's own deadline warning, which is bounded at 10s and would have appeared. The fixture's first assertion after SIGINT is EXPECT_TRUE(master.Reap(seconds(60))) — it wedged and was reaped by force.

That is a hang in TServer::Shutdown(), not a slow test.

Rate

Across the 16 most recent ci.yml runs: aarch64 1 failure, amd64 0. The same fixture also failed on aarch64 on 2026-09-16; I re-ran that job to get a second sample, which replaced the logs, so I cannot show that one had the same signature — only that it was the same fixture on the same architecture. (Lesson noted: re-running a failed job to confirm a flake destroys the evidence you would need if it turns out not to be one.)

Nothing like it has been seen on amd64.

Why this should not be assumed a flake

The symptom is the same family as #554: a hang inside TServer::Shutdown() on aarch64 and nowhere else. That one turned out to be a fiber reading a cached thread pointer after migrating OS threads, which made a runner switch onto another thread's stack — fixed in #555 by routing the three fiber thread-locals through noipa accessors.

Three thread-locals in the same hazard class were deliberately left unaudited by that fix, because none was implicated and each is its own piece of work:

• Disk::Util::TDiskController::TEvent::LocalEventPool
• TLocalReadFileCache::Cache
• Disk::TLocalWalkerCache::Cache

All three are read from fiber context and can be read after a switch. A stale read of any of them hands a fiber another thread's pool or cache. That is the first place I would look, though it is a hypothesis and not a diagnosis — the wedge could equally be an ordinary teardown-ordering bug that only arm's scheduling exposes.

What would make this diagnosable

Right now a failure yields log tails and nothing else, and the position in Shutdown() has to be inferred from which syslog lines are missing:

1. Capture stacks when Reap times out. TChildServer::Reap failing is the moment to gdb -p the child, or at minimum dump /proc/<pid>/task/*/wchan and /proc/<pid>/task/*/syscall, before killing it. For orlyc hangs on aarch64 when compiling a package (embedded mem-sim server never returns) #554, field 8 of syscall — the user stack pointer — is what identified the bug when gdb was actively misleading on an LTO binary.
2. The aarch64 job is continue-on-error, so this failure does not turn the run red and is invisible unless someone opens the job. That is the right setting for an unsupported-platform job and the wrong one now that v0.1.0 ships an arm64 image. Related: CI: guard the aarch64 orlyc path with a release build (debug does not reproduce arm bugs) #556.

Not urgent, but not nothing

Low frequency, and it is a graceful-shutdown path rather than a data path. But the project now publishes an arm64 image as part of a numbered release, and this is the second arm-only hang in TServer::Shutdown() in three days.

[ohohoreilly]

Narrowed, and it is not where I said to look

Correcting my own first suspect above. The wedge is before the teardown jumper, so the fiber thread-local class from #554/#555 is not implicated and the three unaudited thread-locals are the wrong first lead.

Where it actually stops

Between the drain log and TServer::Shutdown() complete the only other syslog in server.cc is the drain deadline warning at line 1399, which did not fire. So the master log alone cannot place the wedge — but the fixture's other missing assertion can.

TManager::RunReplicationQueue shutting down (#461) (manager.cc:223) never appeared. That is logged by the replication queue loop as it exits, and the calls that make it exit are:

RepoManager->StopReplicationServices();     // sets the flag, pushes 3 sems, hard-closes the socket
RepoManager->StopLayerCleaner();
DurableManager->StopLayerCleaner();
RepoManager->JoinReplicationServices();     // <-- blocking Pop(), once per started loop

all of which sit between the drain log and the jumper. JoinReplicationServices() is:

for (size_t n = ReplicationServicesStarted; n > 0; --n) {
  ReplicationServicesExited.Pop();          // Base::TEventSemaphore -- a blocking read()
}

One replication loop that never returns wedges that loop forever, with no further logging. That matches the observed log exactly: last line is the drain, nothing after, process had to be SIGKILLed.

The counting itself looks sound — each loop does ++ReplicationServicesStarted then Base::TPushOnExit exit_latch(ReplicationServicesExited), so every entered loop pushes on every exit path including exceptions, and both variables are std::atomic. So this is a loop genuinely not returning, not a miscount.

The state it wedges from

The master log's last replication lines are the fixture's whole point:

Write TSlave::PushNotificationsId took [0.000312s]
Write TSlave::PushNotificationsId acked
Write TSlave::PushNotificationsId took [0.000037s]     <- written, never acked
TServer::Shutdown() begin
TServer::Shutdown() draining [1] live client connections (#460)

An outstanding push against the frozen slave — precisely the #461 scenario, and precisely what StopReplicationServices()'s hard close exists to break:

void TCommonContext::Shutdown() noexcept {
  shutdown(Device->GetFd(), SHUT_RDWR);
}

The intended chain is: socket shutdown → the reader loop's Read() errors → it collapses → every outstanding future fails → a replicate loop parked in future->Sync() wakes → returns → pushes Exited.

So the hypothesis worth testing is that this wake chain does not complete on aarch64, i.e. #461's fix is not as reliable as the amd64 record suggests. Candidates within it, none yet demonstrated: Context being null at the moment StopReplicationServices() reads it under ContextLock (no close happens at all); the reader collapsing without failing the futures; or the woken loop being a fiber whose runner does not schedule it again.

What is still missing

Which of the three loops (RunReplicationQueue, RunReplicationWork, RunReplicateTransaction) fails to return, and where it is parked. That needs stacks from a wedged master, the same way #554 was settled. I have a local native-aarch64 reproduction running the fixture under the CI runner's four-core topology with a watcher that dumps per-thread wchan and backtraces if a master survives its SIGINT; it has not reproduced yet.

Until those stacks exist, everything in the paragraph above is a hypothesis and should not be fixed against.

[ohohoreilly]

83 samples, no reproduction — and the harness was lying to me

Reporting a negative result plus a self-correction, so the next person does not repeat either.

The hunt did not reproduce it

harness	samples	graceful wedges
local arm64 container, one binary at a time	12	0
local arm64 container, cores oversubscribed	10	0
CI arm runner, one binary behind CPU spinners	35	0
CI arm runner, 4 concurrent copies	48	0

83 CI samples on the runner class that produces this failure, zero reproductions, against an observed rate of roughly one per ci.yml arm run. Expected yield at that rate was about five. Getting zero says the harness does not recreate the condition, not that the bug has gone away.

The ImportReplication failures it did catch were my fault

Two runs failed with could not connect to server; Connection refused right after a clean TServer::Shutdown() complete. I nearly filed that as a second arm flake. It is an artifact of running four copies of the same binary concurrently, which nothing in CI does:

in_port_t ProbeFreePort() {
  TFd sock(socket(AF_INET, SOCK_STREAM, 0));
  ...
  Util::IfLt0(::bind(sock, ...));          // port 0 -> kernel picks
  Util::IfLt0(getsockname(sock, ...));     // read which one
  return ntohs(addr.sin_port);             // ...and CLOSE it on the way out
}

The port is free when probed and bound for real later, so two concurrent copies can be handed the same ephemeral port and one loses. That is a fine assumption for a test that runs alone, and a broken one for my harness. The fixture is not at fault and neither is the engine.

I also tested and refuted the tidier hypothesis that the server had shut itself down via the scheduler's permanently-quiescent ctrl-c: no permanently quiescent line in either log.

What I would do instead

Stop trying to synthesise the load. The only demonstrated reproducer is make test itself — 203 binaries, four at a time, with the disk, memory and scheduler contention that comes with them — and that is exactly what the arm CI job already runs on every push.

#565 is merged, so the fixture now interrogates a master that will not die and prints every thread's state, wait channel and stack pointer. The next natural occurrence produces the diagnosis for free. At roughly one in eighteen arm runs, normal traffic should surface one within days.

That is a better trade than burning arm runner time on a harness that has now failed to reproduce it 83 times.

Status of the hunt workflow

arm-wedge-hunt.yml should be deleted or reworked before anyone trusts it again: its concurrency model manufactures port collisions, and it has not once produced the failure it was built for. It is dispatch-only, so it costs nothing sitting there, but it should not be read as evidence of anything.

[ohohoreilly]

Reproduced under real make test load — and here is exactly how the evidence escaped

First reproduction after 83 samples across four harnesses. Two dispatches of the reworked hunt (5 full suite passes each, jhm --test looped, 203 binaries four at a time):

• Batch 1 (35305033273): 5 clean passes, ~3.7 min each.
• Batch 2 (35305056091): never finished round 1. Hung for 110 minutes until the job hit its 120-minute cap.

Batch 2's suite log ends, with 61 tests still queued, on exactly:

TESTS: 4 running, 61 queued
TEST: orly/server/import_replication.test

So looping the real suite does reproduce it, at roughly one suite run in six on this evidence. Synthetic load never did.

All three catch signals came up empty, for three different reasons

signal	why it did not fire
#565's thread dump	only runs inside the fixture on a failed Reap(); the fixture never reached that line
#568's join warning	it is orlyi syslog, landing in the child's log file — the fixture only dumps those tails when it fails its own assertions, so a job cancelled from outside discards them with the scratch dir
jhm's 600s per-test timeout	did not fire at all, which is the part worth chasing

The timeout not firing is a lead of its own

jhm.cc prints the header, then echoes the child's output, then reports the timeout:

cout << "TEST: " << test << endl;          // <- our log stops HERE
EchoOutput(subprocess->TakeStdOutFromChild());
...
cout << "TIMEOUT: " << test << " killed after " ...

We have the header and nothing after it for 110 minutes. Hypothesis, not a diagnosis: jhm was not waiting on the test but blocked reading its output pipe. EchoOutput reads the child's stdout to EOF, and if the test's own orlyi grandchildren survived holding the write end open, that read never returns — which would produce precisely this shape, including the missing TIMEOUT: line. If that is right it is a second defect, in the test runner rather than the engine, and it is what swallowed the evidence here.

I have been wrong twice on this issue by reasoning ahead of evidence, so that stays a hypothesis until someone looks.

What the hunt needs before it is dispatched again

Three changes, all in the workflow rather than the product:

1. Bound each round with its own timeout well under the job cap, so the kill is ours and the loop continues to the next round instead of the job dying mid-evidence.
2. Archive /tmp/import_repl_test_* unconditionally. Those scratch dirs hold the orlyi logs where indy: make a stalled replication join name the loop it is waiting for (#564) #568's join warning actually lands. Today they are only surfaced when the fixture itself fails.
3. Line-buffer jhm's output so a cancelled round still yields everything written up to the kill.

Until then, dispatching more batches buys reproductions without evidence, which is the one outcome worse than not reproducing it.

[ohohoreilly]

Rate correction, and the harness is now sound

Two more batches after the evidence fixes landed — 8 more suite runs, all clean.

So the running tally for make test on arm is 1 reproduction in 14 full suite runs, not the ~1-in-6 I quoted off a single catch. That was one sample and it did not hold up; I am correcting it here because it changes what hunting costs. A 4-round batch is about 40 minutes of arm runner time for roughly a 1-in-4 shot.

What these batches did confirm is that the harness is no longer the problem. Every round now finishes in a consistent ~4 minutes:

round 1 rc=0    round 2 rc=0    round 3 rc=0    round 4 rc=0

Before #571, a single round could silently consume the entire job — which is exactly what happened on the one reproduction, and why its evidence was lost. That hole is closed, and #572 archives the orlyi child logs unconditionally, so a catch now keeps the join warning that names the stalled loop.

Recommendation: stop buying samples

The economics have inverted. Every push to master already runs an arm suite, the instrumentation is complete on all three signals, and a natural occurrence now arrives self-described — #568's loop name plus #565's per-thread stacks. Dispatching batches costs real runner time for a coin flip; waiting costs nothing and catches the same thing.

Someone picking this up should start from the next natural arm failure, not from arm-wedge-hunt.yml.

Where the diagnosis stands

Unchanged from the narrowing above, and still open: the wedge is in JoinReplicationServices(), blocked on ReplicationServicesExited because one replication loop never returned, from #461's written-but-never-acked state against a frozen slave. Four links of that wake chain are eliminated by test rather than by argument. What is missing is only which of the three loops it is — which is now a single log line away, whenever it next happens.

[ohohoreilly]

Last swing: one solid structural finding, two more hypotheses killed

Nothing shipped from this round — no fix, and I discarded the change I prototyped because the test for it came back negative. What is worth keeping:

The whole graceful shutdown of a replicating master hangs on one call

Disabling context->Shutdown() in StopReplicationServices() and nothing else makes the wedge deterministic — 2 runs out of 2 — and #568's instrumentation reports:

TManager::JoinReplicationServices() still waiting after 15000ms;
  replication loop(s) that have not returned:
  [RunReplicationQueue, RunReplicationWork, RunReplicateTransaction] (#564)

So the entire teardown depends on a single best-effort shutdown(fd, SHUT_RDWR) whose return value is ignored, with no backstop. All three loops are parked in something only that close can free: the reader inside Read(), the work loop inside Work(), and the replicate loop behind them. Any race that neutralises that one call — reader already gone, Context null, fd already reused — reproduces this bug exactly.

This also gives a discriminating signature for the next natural failure:

loops named in the join warning	what it means
all three	the close was lost or neutralised
one only	that loop has its own hole; the close worked

That distinction costs one log line to read and splits the remaining search space in half.

Two more hypotheses eliminated

"The reader exits on its sem push before the close, so nobody observes the collapse." Structurally real — the stopping flag and all three sem pushes happen before context->Shutdown(), and FailAllFutures is only ever reached from inside Queue()/Work(). But injecting a 3-second delay before the close, which should make that window certain, did not reproduce it (0/3). The reader is normally parked inside Read() on the socket, where its semaphore cannot reach it, so it does not in fact leave early.

ContextLock held across future->Sync(), which would deadlock against StopReplicationServices() needing that lock to fetch the context. Checked the brace structure: the guard is released at manager.cc:447 and the Sync() is at :466, outside it. No circular wait.

I also prototyped failing the futures directly inside Shutdown() so a parked Sync() would not depend on the reader noticing. With the close disabled it still reported all three loops outstanding, i.e. it provides no independent wake path — the loops genuinely need the socket closed. So it would harden nothing, and I threw it away rather than ship an engine change with no evidence behind it.

Running total of eliminated links

The OS-level wake (100,000 iterations), the eventfd store/wake ordering, the EOF path, #520's orphan-future window, the early-reader-exit window, and the ContextLock deadlock. Every one closed by test or by reading rather than by argument.

What remains is which loop fails to return in the real failure — one log line, whenever it next happens.

[ohohoreilly]

Reopening. This was closed by hand on 2026-09-18, before #566–#572 landed, and it was never fixed.

Two weeks of waiting: arm nightlies 09-18 → 10-01 are 14 runs with zero recurrences. The arm job failed twice in that window, and neither failure is this wedge:

• 09-19: durable_manager.test SemFiresOnlyAfterFlush (the flake: durable_manager.test SemFiresOnlyAfterFlush races its own 300ms flush cadence #551 flake).
• 09-25 (run 36122879439): import_replication.test case ImportReplication. The slave's connection was reset, the slave fell back to SOLO, then RPC [NewFastPrivatePov] unanswered after 240s (#537). GracefulShutdownUnresponsiveSlave passed in that run with a clean Shutdown() complete.

Leaving this open and parked. The instrumentation stays in place, so a natural occurrence will still name the stalled loop.