make test-stress never ends

[p-alik]

make test-stress
stress.echo.echo                                        0:000422052 [ ok ]

The same result on Ubuntu 14.04 and 16.04.

[p-alik]

I actually reproduced this live on current master (commit 6682868b), almost a decade after it was filed — it's still exactly as described.

$ make test-stress
stress.echo.echo                                        0:001716974 [ ok ]

...and then nothing. I let it run for 10+ minutes; it never progresses past that line. ps shows the t/.libs/stress process sitting in S (sleeping) state, blocked in poll_schedule_timeout (i.e. parked in poll()), holding two open sockets — consistent with tests/burnin.cc's single-process design where the worker runs on its own thread inside the same test binary rather than a forked child. The generated stress.xml confirms exactly where it gets stuck:

<testsuites name="stress">
	<testsuite name="echo">
		<testcase name="echo" time="0:002499864">
		</testcase>
	</testsuite>
	<testsuite name="burnin">

The echo suite (tests/burnin.cc:343-346, echo_TEST at line 170) completes fine and closes its tag. The burnin suite (burnin_TESTS at line 337, first burnin_TEST at line 186) opens and never closes — so it hangs either in burnin_setup() (tests/burnin.cc:298, which spins up the worker thread via test_worker_start()) or in the first burnin_TEST iteration itself (gearman_client_add_task/gearman_client_run_tasks loop at tests/burnin.cc:229-282).

Worth noting for triage: test-stress is noinst_PROGRAMS only (tests/stress.am:22-23, check_PROGRAMS line is commented out) and isn't invoked anywhere in .github/workflows/, so this has had zero CI coverage this whole time — nothing would have caught it if it got fixed or got worse.

So: confirmed still valid, not stale. I killed my hung test run + the orphaned gearmand child it left behind rather than let it sit. Given t/cycle's similar "gearmand won't die" symptom (#50/#51) turned out to be a port-reservation race in libtest::Server::start() (just fixed in #471/#472), it's plausible this shares a root cause in the shared libtest/worker-startup plumbing — but I haven't dug into burnin_setup()/test_worker_start() deeply enough yet to confirm that's the same bug versus something specific to burnin.cc's task-submission loop.

[p-alik]

Follow-up with a root cause and a concrete fix proposal, found by attaching strace -f -k directly to a fresh t/stress run (spawning it as strace's own child sidesteps the ptrace-scope restriction that blocks attaching to an already-running process).

Confirmed hang location, live stack trace from the stuck worker thread, captured mid-hang:

poll([{fd=-1}, {fd=7, events=POLLIN}], 2, 1000)   <- returns 0 (timeout), forever, every ~1s
 > libgearman.so.8.0.0(gearman_wait(gearman_universal_st&)+0xfb)
 > libgearman.so.8.0.0(gearman_worker_grab_job+0x6e8)
 > libgearman.so.8.0.0(gearman_worker_work+0x26d)
 > t/.libs/stress(thread_runner(context_st*)+0x156)
 > t/.libs/stress(libtest::thread::Thread::entry_func(void*)+0xd)

So it's the worker thread from tests/start_worker.cc's thread_runner(), inside gearman_worker_work() → gearman_worker_grab_job()'s GEARMAN_WORKER_STATE_PRE_SLEEP case (libgearman/worker.cc:998, *ret_ptr= gearman_wait(worker->universal);), which calls into gearman_wait() (libgearman/universal.cc:275 onward).

The mechanism: the poll set has two entries — the shared wakeup pipe (fd 7, legitimately watched for POLLIN) and one connection slot with fd=-1. A pollfd with a negative fd is permanently ignored by poll() per POSIX (revents always comes back 0 for it), so that slot can never wake the loop. Since nothing ever writes to the wakeup pipe either, every call just times out after universal.timeout (1000ms) and gearman_worker_grab_job()'s state machine loops back and calls gearman_wait() again — forever, identically, every second.

Where the invalid fd sneaks into the poll set: gearman_wait()'s pollfd-array builder (libgearman/universal.cc:301-309) is:

for (gearman_connection_st *con= universal.con_list; con; con= con->next_connection())
{
  if (con->events())
  {
    con->set_pollfd(pfds[x]);
    x++;
  }
}

con->events() (libgearman/connection.hpp:73-76) only reflects whether set_events() was last called with a nonzero mask — it says nothing about whether the connection's underlying socket is actually open. set_pollfd() (connection.hpp:66-71) then blindly copies socket_descriptor() into the array even when that's -1. Compare this to every other place in worker.cc that calls set_events() — e.g. worker.cc:930 and worker.cc:958 both guard with if (worker->con->socket_descriptor_is_valid()) first. gearman_wait()'s own poll-set builder is the one place that doesn't apply that same guard, so if a connection's _events mask is left set from an earlier iteration while its fd has since gone invalid, this loop happily hands poll() a dead slot instead of catching it. The existing GEARMAN_NO_ACTIVE_FDS safety net (universal.cc:311-314, if (x == 0) return ...) doesn't catch this either, because the dead connection slot (and/or the wakeup pipe) keeps x above zero.

I haven't fully pinned down why _events stays nonzero on this specific connection while its fd is simultaneously invalid on every single pass through the state machine (that'd need single-stepping through gearman_worker_grab_job's CONNECT/GRAB_JOB_SEND/PRE_SLEEP transitions with a debugger, which I couldn't attach here) — logging output at YATL_WORKER_LOGGING=1 showed nothing, consistent with this being a silent state-desync rather than a logged error path.

Proposed fix — make gearman_wait()'s poll-set builder apply the same fd-validity guard used everywhere else in the codebase:

for (gearman_connection_st *con= universal.con_list; con; con= con->next_connection())
{
  if (con->events() and con->socket_descriptor_is_valid())
  {
    con->set_pollfd(pfds[x]);
    x++;
  }
}

This doesn't fix whatever leaves _events stale on a dead connection, but it does convert the current infinite silent hang into a fast, correct GEARMAN_NO_ACTIVE_FDS/GEARMAN_TIMEOUT return from gearman_wait(), which gearman_worker_grab_job()'s existing STATE_START/CONNECT retry logic is already built to handle (it already retries connects and treats GEARMAN_COULD_NOT_CONNECT/GEARMAN_LOST_CONNECTION as recoverable). That alone should turn this from "process never terminates" into "worker reconnects or reports a real error" — worth trying against test-stress to confirm before merging, since I couldn't get a debugger attached in this sandbox to verify beyond the strace evidence above.

[p-alik]

Small correction to my previous comment: I wrote that the GEARMAN_NO_ACTIVE_FDS guard (universal.cc:311-314) doesn't fire because "the dead connection slot (and/or the wakeup pipe) keeps x above zero." The wakeup-pipe part of that is wrong — dropping it.

Looking at the actual code order in gearman_wait():

nfds_t x= 0;
for (gearman_connection_st *con= universal.con_list; con; con= con->next_connection())
{
  if (con->events())
  {
    con->set_pollfd(pfds[x]);
    x++;
  }
}

if (x == 0)
{
  return gearman_error(universal, GEARMAN_NO_ACTIVE_FDS, "no active file descriptors");
}

// Wakeup handling, we only make use of this if we have active connections
if (have_shutdown_pipe)
{
  pfds[x].fd= universal.wakeup_fd[0];
  ...
  x++;
}

The x == 0 check runs before the wakeup pipe is ever added to x — that happens afterward, at the have_shutdown_pipe block. So the wakeup pipe can't be what's defeating the guard; it isn't in the count yet at that point.

What actually defeats it is the dead connection by itself: the loop only tests con->events(), never the fd's validity, so the one connection with fd=-1 and a stale _events mask makes x = 1 on its own and the guard never trips. Correct version of that sentence: "...doesn't catch this either, because the dead connection slot itself keeps x above zero."

[p-alik]

Opened #478 with two fixes found while digging further into this — both verified live against the test-stress reproducer, not just by inspection.

Fix 1 — the original permanent hang. gearman_wait()'s poll-set builder (libgearman/universal.cc) added any connection with a nonzero _events mask without checking socket_descriptor_is_valid(), unlike every other set_events() call site in the codebase. If a connection's fd ever went invalid while _events was still set, poll() got an fd=-1 entry, which POSIX permanently ignores — so gearman_worker_grab_job() spun through gearman_wait() forever, once a second, waiting on a socket that could never wake it. Confirmed via strace -k before/after: the exact hang signature is gone after the fix.

Fix 2 — a second bug the first fix exposed. With the hang gone, test-stress still didn't complete, and reproducibly stalled on WORK_FAIL packets specifically. Traced with gdb against a -O0 debug build (the normal -O2 build's inlining made naive breakpoint inspection give misleading values — worth knowing if anyone else debugs this codebase, strncmp/strlen calls in gdb also need an explicit (int) cast since gdb can't resolve the AVX2-optimized libc symbols' return type otherwise). _client_run_tasks()'s packet-to-task matching (libgearman/client.cc) used an asymmetric length check: arg_size[0] - 1 for normal packets, but exact arg_size[0] for WORK_FAIL. Raw byte dump confirmed WORK_FAIL's job-handle argument is NUL-terminated on the wire exactly like everything else, so the .failed() branch was always off by one byte — even when strncmp() confirmed a perfect match on the handle. The packet got silently discarded ("client has stopped waiting for the response"), permanently orphaning that task, so gearman_client_run_tasks()'s wait on running_tasks == 0 never resolved.

Where this leaves things. Together these get test-stress substantially further — I watched running_tasks reach 0 for a full submit/complete batch for the first time, and saw 5+ full batches (20 jobs) go through cleanly where previously it never got past the first 4. But it still doesn't reach full completion. The next stall is different in kind from either fix above: a job gets assigned to the worker and then simply never produces any completion packet — no WORK_COMPLETE/WORK_FAIL/WORK_EXCEPTION, not even a failed match attempt, nothing. That points at job dispatch (worker or server side) rather than client-side packet handling, and I haven't root-caused it yet.

Leaving this open for that remaining piece — #478 is a real, verified improvement but not a full fix.

[p-alik]

#478 is green across all 19 CI jobs and I believe this is now fully resolved. Recap of the full chain, since it ended up being two independent bugs plus one self-inflicted detour:

Bug 1 — permanent hang in gearman_wait() (libgearman/universal.cc): the poll-set builder added any connection with a nonzero _events mask without checking whether its socket was actually valid, unlike every other set_events() call site in the codebase. A connection whose fd went invalid while _events was still set got handed to poll() as fd=-1, which POSIX permanently ignores — so gearman_worker_grab_job() spun through gearman_wait() forever, once a second, on a socket that could never wake it. Confirmed via strace -k before/after.

Bug 2 — silently dropped WORK_FAIL packets (libgearman/client.cc): _client_run_tasks()'s packet-to-task matching inferred the job handle's expected length from arg_size[0], using a formula that differed by packet type. Turns out arg_size[0]'s relationship to the handle's actual string length isn't fixed — it depends on how the job was dispatched (plain JOB_ASSIGN vs. reduce-job assignment give different byte counts). Whichever formula was wrong for a given WORK_FAIL packet caused it to be silently discarded, permanently orphaning that task and hanging gearman_client_run_tasks()'s wait on running_tasks reaching 0. Fixed by trusting job_handle's own strlen() (reliably NUL-terminated) instead of inferring a length from arg_size[0].

The detour: my first attempt at bug 2 unconditionally applied one of the two formulas, which fixed the test-stress case but broke tests/libgearman-1.0/worker_test.cc's GEARMAN_FAIL_return_TEST (a reduce-job scenario needing the opposite formula) — hung every CI job for 10 minutes. Reverted within the hour, root-caused properly by testing against both scenarios this time, and the length-agnostic fix above passes both.

Verification: make test-stress now completes end-to-end — running_tasks reaches 0, every task finishes, both burnin.burnin sub-tests pass. That never happened once in the entire investigation before this PR. Wall-clock is ~4.2s (mostly gearmand startup/teardown), so it's cheap enough to consider adding to CI — separate discussion happening on the PR with @esabol.

Once #478 merges I think this can close.