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 ["));