From cf2324ea19f166d1cbb34febf40e9f1a2933bda8 Mon Sep 17 00:00:00 2001 From: Patrick O'Reilly Date: Thu, 17 Sep 2026 16:17:26 -0700 Subject: [PATCH] import_replication.test: interrogate a master that will not die (#564) GracefulShutdownUnresponsiveSlave has failed twice on the aarch64 job, and neither failure could be diagnosed afterwards. The only syslog between the connection drain and "TServer::Shutdown() complete" is the drain's own deadline warning, so a wedge anywhere in that stretch -- the replication stop/join, the layer cleaners, the teardown jumper -- produces an identical log tail. By the time anyone reads the CI output the process is gone. A failed Reap() is the one moment the wedged process still exists. Dump each thread's state, wchan and syscall line there, before the assertion that ends the fixture. wchan names the kernel function a thread is blocked in, which separates a runner loop sleeping on its timer from a genuinely blocked wait. The syscall line matters more: its last two fields are the user stack pointer and PC, and in #554 the stack pointer is what proved two OS threads were executing one stack while gdb reported the same bogus frame for both. On an optimised build that file is more trustworthy than any userspace unwinder. Verified against a live 69-thread orlyi rather than shipped on the assumption that it works -- it reports rt_sigsuspend for the main thread, futex_wait, hrtimer_nanosleep for the runner loops, inet_csk_accept for the accept loop and epoll_pwait for the discard runners. Best-effort and noexcept: this runs on a path that has already failed and must not turn a diagnosable failure into a crash. Fixture still passes (2/2). --- changelog.d/564-wedge-diagnostics.md | 1 + orly/server/import_replication.test.cc | 70 +++++++++++++++++++++++++- 2 files changed, 70 insertions(+), 1 deletion(-) create mode 100644 changelog.d/564-wedge-diagnostics.md diff --git a/changelog.d/564-wedge-diagnostics.md b/changelog.d/564-wedge-diagnostics.md new file mode 100644 index 00000000..6a19b94f --- /dev/null +++ b/changelog.d/564-wedge-diagnostics.md @@ -0,0 +1 @@ +- **Changed**: `import_replication.test`'s `GracefulShutdownUnresponsiveSlave` now interrogates the master before asserting on a failed `Reap()`, dumping each thread's state, kernel wait channel and `syscall` line. A wedged graceful shutdown is otherwise undiagnosable after the fact: the only syslog between the connection drain and `TServer::Shutdown() complete` is the drain's own deadline warning, so a wedge anywhere in between looks identical from the log tails, and the process is dead by the time anyone reads CI. Two aarch64 occurrences have already been lost that way (#564). diff --git a/orly/server/import_replication.test.cc b/orly/server/import_replication.test.cc index 451a2fff..d75651ad 100644 --- a/orly/server/import_replication.test.cc +++ b/orly/server/import_replication.test.cc @@ -65,6 +65,7 @@ limitations under the License. */ #include +#include #include #include #include @@ -292,6 +293,64 @@ class TChildServer final { return "alive, state [" + state + "]"; } + /* Everything the kernel will say about a child that would not die. + + A Reap() timeout means a shutdown that wedged, and the log tails alone + cannot say WHERE: the only syslog between the connection drain and + "TServer::Shutdown() complete" is the drain's own deadline warning, so a + wedge anywhere in between looks identical from the log (#564). + + Per-thread `wchan` names the kernel function each thread is blocked in, + which separates a runner loop sleeping on its timer from a genuinely + blocked wait. `syscall` is the more valuable half: its last two fields + are the user stack pointer and PC, and in #554 the stack pointer was what + identified two OS threads sharing one stack while gdb was confidently + reporting the same bogus frame for both. Read it before trusting any + userspace unwinder on an optimised build. + + Best-effort and noexcept throughout -- this runs on a path that has + already failed, and must not turn a diagnosable failure into a crash. */ + void DumpWedge(ostream &strm) const noexcept { + try { + if (Pid <= 0) { + strm << " (no live child to interrogate)" << endl; + return; + } + const string task_dir = "/proc/" + to_string(Pid) + "/task"; + DIR *dir = opendir(task_dir.c_str()); + if (!dir) { + strm << " (cannot open " << task_dir << ")" << endl; + return; + } + while (const dirent *ent = readdir(dir)) { + const string tid = ent->d_name; + if (tid == "." || tid == "..") { + continue; + } + const string base = task_dir + "/" + tid; + string state = "?", wchan, syscall_line; + /* State: from status */ { + ifstream status(base + "/status"); + for (string line; getline(status, line); ) { + if (line.rfind("State:", 0) == 0) { + const auto tab = line.find_first_not_of(" \t", 6); + state = (tab == string::npos) ? "?" : line.substr(tab, 1); + break; + } + } + } + { ifstream w(base + "/wchan"); getline(w, wchan); } + { ifstream sc(base + "/syscall"); getline(sc, syscall_line); } + strm << " tid " << tid << " state=" << state + << " wchan=" << (wchan.empty() ? "-" : wchan) + << " syscall=" << (syscall_line.empty() ? "-" : syscall_line) << endl; + } + closedir(dir); + } catch (...) { + strm << " (interrogation threw; ignoring)" << endl; + } + } + /* True iff the child has been reaped and exited zero. This sees what no log EXPECT can: a post-Shutdown() abort in static destructors leaves every log marker in place and still exits 134 (#522). */ @@ -922,7 +981,16 @@ FIXTURE(GracefulShutdownUnresponsiveSlave) { cout << "Slave state before interrupting the master: " << slave.Describe() << endl; cout << "Interrupting the master" << endl; master.Interrupt(); - EXPECT_TRUE(master.Reap(seconds(60))); + /* Interrogate BEFORE asserting: a failed Reap is the only moment the wedged + process still exists, and #564 has so far cost two CI failures that could + not be diagnosed afterwards from log tails. Reap() leaves Pid set when it + times out, so the child is still there to read. */ + const bool master_reaped = master.Reap(seconds(60)); + if (!master_reaped) { + cout << "master did not exit within 60s of SIGINT -- interrogating before it dies (#564)" << endl; + master.DumpWedge(cout); + } + EXPECT_TRUE(master_reaped); EXPECT_TRUE(LogContains(master_log, "RunReplicationQueue shutting down (#461)")); /* The drain must have seen the silent connection (#460)... */ EXPECT_TRUE(LogContains(master_log, "draining ["));