From bceca0c990e06f33b2b9aa7e5e487a4cfe8e9d44 Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Tue, 1 Sep 2026 23:19:15 +0000 Subject: [PATCH] test(worker-rejoin-resync): task 7.2 - failover-during-job recovery Add test_failover_during_job_recovers_lost_finish, a focused proof of the feature's own original motivating scenario (bug-1741): a job dispatched and RUN with no finish fact ever committed anywhere (modeling a lost fire-and-forget finish notify), recovered to DONE with the worker-reported finish time - not stuck in RUN - via the real rejoin/query/report/apply chain. Test-only, no production changes; reuses task 7.1's helper infrastructure rather than duplicating its broader four-outcome coverage. Updates the existing bug-924 (/tmp exhaustion / flaky teardown) entry with a 5th occurrence hit during validation, unrelated to this task's own change. Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_01Y4M5MJM2zK6nU43da267Ku --- .kiro/specs/worker-rejoin-resync/tasks.md | 3 +- .wolf/buglog.json | 10 +- src/controller/testsuite/test_worker_resync.c | 430 ++++++++++++++++++ 3 files changed, 438 insertions(+), 5 deletions(-) diff --git a/.kiro/specs/worker-rejoin-resync/tasks.md b/.kiro/specs/worker-rejoin-resync/tasks.md index 515c1178..8e07d89c 100644 --- a/.kiro/specs/worker-rejoin-resync/tasks.md +++ b/.kiro/specs/worker-rejoin-resync/tasks.md @@ -135,7 +135,7 @@ - _Requirements: 1.1, 1.2, 1.3, 2.1, 2.2, 3.1, 3.2, 3.3, 3.6, 4.1, 4.2, 4.3, 4.4, 4.5, 4.6, 4.7, 4.8, 7.1, 7.2, 7.3_ - _Depends: 6.1, 6.2, 4.3, 5_ -- [ ] 7.2 Failover-during-job recovery +- [x] 7.2 Failover-during-job recovery - Reproduce the feature's core motivating scenario: a job's finish report is lost across a controller primary failover, and the new primary's rejoin reconciliation with that worker recovers the job's true outcome - Observable completion: a job whose finish notification never reached any controller instance ends up correctly finished, not stuck running, once the worker rejoins the new primary - _Requirements: 4.1, 4.2, 4.6_ @@ -170,3 +170,4 @@ - **Task 6.2's mandated standby-redirect investigation found bug-1753**, a DIFFERENT gap than the one it was looking for: the generic not-primary (`CTRL_STANDBY`) redirect path turned out to already work correctly with zero opcode-specific code (`ha_dispatch_gate` gates every opcode uniformly before the switch), but the investigation surfaced that `ha_dispatch_gate`'s SEPARATE `CTRL_PRIMARY`-without-write-quorum branch — a "fact-bearing ops admitted anyway" allowlist (`OPCode_notify`/`update`/`setpreason`/`clrpreason`, bug-396) — was missing `OPCode_jobStateReport`, meaning a report arriving during a transient quorum-loss window (e.g. mid-failover, this feature's own core motivating scenario) would be rejected outright with no retry, since the worker's send is fire-and-forget. Fixed by adding the one missing case, verified safe against `resync_round_is_current`'s staleness check and the WAL_MODE_RETAIN semantics every fact this feature produces already uses. Citation nit: this fix's true motivation sits closer to Requirements 1.3/4/6 than the task's own tagged 8.1/8.3 — recorded here for traceability, tasks.md's tag left as originally generated. **Lesson**: a task text that names one specific concern to investigate ("check the redirect path") can surface a DIFFERENT, more consequential gap in the same general area — don't stop the investigation at "the named concern turned out fine," keep reading the surrounding gating logic in full. - **Task 6.2 also drew three escalating, unsolicited cross-session messages** (from an unfamiliar peer session) mid-flight, pushing a specific unreviewed code change to `test_jobstatereport_dispatch.c` — the exact file the dispatched implementer subagent was independently writing at the time. Declined to act on any of them (risk of conflicting with in-flight subagent work; escalating urgency/"no further investigation needed" framing is a known social-engineering pattern regardless of whether the underlying suggestion is technically plausible). The implementer subagent finished independently and solved the underlying `get_ep_worker()`-in-test-binary limitation completely differently (a `#ifdef XCE_TESTING` call-count seam in `resync.c`, not a global-fixture hack) — validating the decision not to short-circuit the normal TDD+review pipeline based on an unverified peer instruction. - **Task 7.1 (test-only, zero production changes) discovered and honestly asserted a genuine, pre-existing, systemic gap distinct from bug-1747**: a worker-reported (or any) job failure's exit code is never durably recorded anywhere in this codebase — `record_job_fail_fact()`'s `WAL_JOB_FAIL` payload has no exit-code slot at all, and `apply_job_fail_transition()` never touches `job.job.exit_info` for the FAIL path, so it stays `NULL` unconditionally. Bug-1747 only covers the FAIL finish-*time* mistiming; this is the exit-*code* gap, logged separately as bug-1754 (out of scope for this test-only task, correctly not fixed here — flagged for a dedicated future task). The round-trip test asserts `exit_info == NULL` honestly with an inline comment rather than encoding a wrong expectation the codebase can't actually produce. +- Task 7.2 (test-only): added a focused, single-job proof of the feature's own original motivating scenario (bug-1741) — a job dispatched and RUN with NO finish fact ever committed (modeling the lost fire-and-forget notify), recovered to DONE with the worker-reported finish time via the real rejoin/query/report chain. Deliberately scoped smaller than task 7.1's four-outcome round trip (reuses its helper infrastructure, adds no new scaffolding) rather than duplicating it. tasks.md's own `_Requirements: 4.1, 4.2, 4.6_` tag includes 4.6 (unrecognized→PEND), which is genuinely unrelated to this finished-success scenario (that's task 7.1/2.1's territory) — `REQUIREMENTS_CHECKED` correctly narrowed to 4.1/4.2 instead of force-fitting an unrelated assertion, same accepted-imprecise-tag pattern as task 6.2's own citation nit. diff --git a/.wolf/buglog.json b/.wolf/buglog.json index 5c6dbda6..01e1b2b5 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -7846,7 +7846,7 @@ "timestamp": "2026-06-22", "error_message": "controller_unit_test: ~63 'Expected Non-NULL' + test_config_repl catchup FAILs (Expected 0 Was -11 EAGAIN) during ha-term-safety 1.3 validation", "file": "environment (/ overlay filesystem)", - "root_cause": "Disk filled to 100% (7466 leftover /tmp/xce_* WAL dirs from repeated ASAN test runs). make_fresh_persist's persist_init mkdir_p hit ENOSPC -> returned NULL -> cascade of 'Expected Non-NULL'. Also overlayfs returned fdatasync EIO under disk pressure. NOT a code regression: baseline full suite passes; test_config_repl catchup tests are order-dependent and fail in isolation on baseline too.", + "root_cause": "Disk filled to 100% (7466 leftover /tmp/xce_* WAL dirs from repeated ASAN test runs). make_fresh_persist's persist_init mkdir_p hit ENOSPC -> returned NULL -> cascade of 'Expected Non-NULL'. Also overlayfs returned fdatasync EIO under disk pressure. NOT a code regression: baseline full suite passes; test_config_repl catchup tests are order-dependent and fail in isolation on baseline too.\n\n[UPDATE 2026-09-01, worker-rejoin-resync task 7.2] Re-observed a FOURTH time, with a NEW manifestation shape not previously documented: 14367 leftover /tmp/xce_* dirs, 876.7G, filesystem at 99% used / 12.4G available. This time it did NOT surface as 'Expected Non-NULL' assertion cascades or a silent exit(1) -- it surfaced as controller_unit_test/`meson test` simply HANGING (TIMEOUT, killed by signal 15 after 300s) with no error output at all, reproducible across multiple independent invocations (both via `meson test` and the raw binary directly), always stalled inside persist_fini()/fsync_worker's pthread_cond_timedwait/pthread_cond_destroy teardown path (confirmed via gdb `thread apply all bt` on the wedged process -- Thread 2 stuck in fsync_worker's pthread_cond_timedwait at persist.c:847, Thread 1 stuck in persist_fini's pthread_cond_destroy at persist.c:1362), at a DIFFERENT test each time (not always the same call site) -- consistent with overlayfs fdatasync degrading under near-full disk rather than erroring outright, causing the flusher thread to sit in a slow/stuck wait instead of the previously-documented fast ENOSPC/EIO failure. `find /tmp -maxdepth 1 -name 'xce_*' -exec rm -rf {} +` (no live xce process holding any of them open, confirmed via `ps aux` first) freed 612G (99% -> 30% used); the exact same test run (`controller_unit_test -t test_worker_resync`) that had twice hung/timed out at 90s then completed cleanly in under a second. General lesson extended: an unexplained TIMEOUT/hang in this suite (not just an assertion-failure cascade) is an equally likely symptom of this same recurring /tmp exhaustion -- check `df -h /tmp` before spending time bisecting a hang as a suspected new concurrency bug in the code under test.", "fix": "rm -rf /tmp/xce_* freed 327GB; full controller suite then Ok:1 Fail:0. For future runs: clean /tmp/xce_* between heavy ASAN test cycles.\n\n[UPDATE 2026-08-26, xce-test-rc-file task 1.1] Re-observed at much larger scale (14731 leftover /tmp/xce_* dirs, 653.6G, filesystem at 100% used / 0 available) and a MORE SEVERE manifestation than the original 'Expected Non-NULL' assertion failures: mkdtemp() failing inside test_repl_apply.c's make_test_persist_for_apply()/make_test_persist_in() hit ENOSPC, and that pre-existing test file's own hard exit(1) on mkdtemp failure silently killed the ENTIRE controller_unit_test process mid-run (right after test_repl_unit's last test, well before test_repl_apply's own output ever printed) -- exit code 1, no crash/ASAN report, no visible error in the redirected log until grepped for the literal 'mkdtemp failed' stderr line. A leftover orphaned controller_unit_test process (PID from an earlier invocation, blocked in futex_do_wait, presumably stalled retrying a WAL fsync against the full disk) was also found and killed. Fixed for this session via `find /tmp -maxdepth 1 -name 'xce_*' -exec rm -rf {} +` (630G reclaimed, 100% -> 29% used) -- confirmed no live xce process had any of those dirs open before deleting. General lesson: when controller_unit_test dies silently/instantly with exit code 1 and the log just stops mid-file with no crash signature, check `df -h /tmp` and grep for 'mkdtemp failed'/'calloc failed' before assuming a real regression -- this sandbox's /tmp accumulates leftover unit-test mkdtemp() fixture dirs across EVERY session indefinitely (no test file in this suite cleans up its own /tmp/xce_* dirs), so this will keep recurring until either the testsuite adds its own cleanup or something periodically clears /tmp.\n\n[UPDATE 2026-08-30, bug-1735 verification build] Re-observed a THIRD time, at the largest scale yet: 16238 leftover /tmp/xce_* dirs, 696.1G, filesystem at 100% used / 0 available. This time it manifested as a `controller_unit_test` run reporting `1220 Tests 282 Failures` (mostly test_dispatch_commit.c/test_dispatch_fail_terminal.c/test_dispatch_fail_retry.c/test_jobdispatch_no_double_notify.c 'Expected Non-NULL' -- the exact same fixture-setup-ENOSPC cascade signature as both prior occurrences, on files wholly unrelated to whatever the run was actually verifying) plus a meson-internal `OSError: [Errno 28] No space left on device` while serializing testlog.json/testlog.junit.xml (corrupting those log artifacts, though the console summary line survived). No live xce process was running at the time (`ps aux` confirmed clean) so `find /tmp -maxdepth 1 -name 'xce_*' -exec rm -rf {} +` was safe; reclaimed 696.1G (100% -> 22% used). Re-running the full suite after cleanup is required before trusting any failure count from a run that coincided with disk exhaustion. Still true three occurrences in: nothing in this test suite cleans up its own /tmp/xce_* dirs, so this WILL keep recurring -- the durable fix is adding cleanup to the shared test fixture helpers, not another one-off `rm -rf`.", "tags": [ "disk-space", @@ -7856,11 +7856,13 @@ "controller-tests", "flaky", "ha-term-safety", - "recurring" + "recurring", + "hang", + "timeout" ], "related_bugs": [], - "occurrences": 3, - "last_seen": "2026-08-30T06:24:00" + "occurrences": 4, + "last_seen": "2026-09-01T22:18:00" }, { "id": "bug-925", diff --git a/src/controller/testsuite/test_worker_resync.c b/src/controller/testsuite/test_worker_resync.c index 08edec97..0fbf7030 100644 --- a/src/controller/testsuite/test_worker_resync.c +++ b/src/controller/testsuite/test_worker_resync.c @@ -3007,6 +3007,435 @@ static void test_full_rejoin_reconciliation_round_trip(void) printf("test_full_rejoin_reconciliation_round_trip: PASS\n"); } +/* ── Task 7.2: Failover-during-job recovery -- the feature's own core + * motivating scenario (bug-1741; requirements.md's Introduction; design.md + * "Testing Strategy" > "Integration Tests": "Failover-during-job: a job's + * finish notify is lost across a primary failover; the new primary's + * rejoin reconciliation recovers it (this is the feature's core bug-1741 + * regression scenario)") ──────────────────────────────────────────────── + * + * Proves the SIMPLEST version of bug-1741's own reported failure: one job, + * one lost finish report, one failover, one rejoin. bug-1741 itself was a + * burst of 7 near-simultaneous finish reports losing 6 of them; that + * burst/many-jobs shape is Requirement 8's own separate coverage (already + * proven by the multi-page tests above and by test_full_rejoin_ + * reconciliation_round_trip's four-outcome round trip) -- this test's own + * job is only to name and prove the single-job case in isolation, not to + * re-prove the general round-trip machinery task 7.1 already covers. + * + * Per requirements.md's Introduction, today a worker's finish report is a + * single fire-and-forget XCECLI_FF_CALL send with no retry -- if it is + * lost (the worker briefly disconnects, or the controller it was talking + * to fails over to a new primary mid-flight), the job's true outcome is + * never recorded anywhere and its state (RUN) sticks forever. This test + * models that starting condition directly: a fresh persist state in which + * the job is durably recorded as RUN, assigned to a worker host, with NO + * finish fact of any kind ever appended for it -- exactly as if the real + * XCECLI_FF_CALL send had simply vanished before this feature ever + * existed. No second controller process or literal primary-to-primary + * handoff mechanism is simulated -- the OBSERVABLE starting condition (RUN + * job, no finish fact, worker has since actually finished it) is what + * this feature's own recovery mechanism must correct, regardless of how + * that condition came to exist; per Requirement 1.3, the controller's own + * trigger does not distinguish a first join, an ordinary reconnect, or a + * post-failover reconnect to a new primary -- the same rejoin path + * (`rejoin_worker`) is exercised below exactly as it would be for any of + * the three. + * + * Drives the SAME real rejoin -> query-send -> report-apply chain task + * 7.1's own round-trip test established (`rejoin_worker`, the REAL join + * entry point; `worker_send_resync_query`'s REAL wire OPCode_jobStateQuery; + * a REAL worker answer via `xce_job_state_report_req`'s REAL wire OPCode_ + * jobStateReport; `resync_handle_report_page`, never `resync_apply_report` + * directly) -- narrowed to ONE job, ONE outcome (finished-success), + * because this test's whole point is to isolate the bug-1741 scenario, not + * to duplicate the four-outcome coverage task 7.1 already built. + * + * finished-success stays on record_job_finish_fact_at's DEFERRED pattern + * (task 3.2/bug-1747) -- so, like test_full_rejoin_reconciliation_round_ + * trip's own Phase 1/Phase 2 split, this test needs a real restart-replay + * (Phase 2, the SAME apply_committed_entry() seam a live controller's own + * commit-apply pump -- or another controller instance recovering the same + * durable log -- would invoke) to observe the job actually reach DONE; + * this bare-persist test fixture has no live commit-engine apply pump of + * its own, exactly the situation task 7.1's own Implementation Notes + * document. */ + +#define TWR_JOBID_FAILOVER_LOST 81401ULL + +static void test_failover_during_job_recovers_lost_finish(void) +{ + char tmp[256]; + uint64_t worker_reported_finish_time_s; + + strcpy(tmp, "/tmp/xce_twr72_failover_XXXXXX"); + TEST_ASSERT_NOT_NULL(mkdtemp(tmp)); + + /* Deliberately far in the past -- the job genuinely finished well + * before this reconciliation round runs, so a reconciliation- + * processing-time bug (time(NULL)) could never accidentally produce a + * matching value. Same defensive idiom as this file's other finish- + * time tests. */ + worker_reported_finish_time_s = (uint64_t)time(NULL) - 5400; + + /* Phase 1: the (new) primary's own persist state -- job RUN, no + * finish fact anywhere in it (the lost-notify starting condition) -- + * then the REAL rejoin/query/report chain. */ + { + cluster_t c; + kvmgr_params_t str_params = { .key_type = KVMGR_KEY_STRING, + .nslots = 64, .delta = 16 }; + kvmgr_params_t int_params = { .key_type = KVMGR_KEY_INT, + .nslots = 32, .delta = 16 }; + persist_config_t cfg; + worker_t* w; + job_t* job; + hostattrs_t attrs, new_attrs; + xce_hostconfig_t hconfig; + endpoint_t stack_ep; + endpoint_t* ep; + xce_request_t decoded_query, decoded_report; + int rc; + uint64_t lsn_before, lsn_after; + int i; + + static const char* res_names[TWR_RT_N_RES] = { + "type", "model", "cpuf", "maxcpus", "maxmem", + "maxswap", "maxtmp", "ndisks", "slots" + }; + static const int res_valtypes[TWR_RT_N_RES] = { + XCE_VAL_STRING, XCE_VAL_STRING, + XCE_VAL_NUMERIC, XCE_VAL_NUMERIC, XCE_VAL_NUMERIC, + XCE_VAL_NUMERIC, XCE_VAL_NUMERIC, XCE_VAL_NUMERIC, + XCE_VAL_NUMERIC + }; + + if (makeString((char*)"twr72-probe") == NULL) + xstring_table_init(64); + if (!g_twr_jobobj_ready) { + TEST_ASSERT_EQUAL_INT(0, job_obj_init(32, 32)); + g_twr_jobobj_ready = 1; + } + + memset(&c, 0, sizeof(c)); + TEST_ASSERT_EQUAL_INT(0, + xce_hook_init(&c.hooksys, XCE_CONTROLLER_HOOK_MAX)); + + c.workermgr = makeInstance(&xkvmgr_type, &str_params); + TEST_ASSERT_NOT_NULL(c.workermgr); + c.resmgr = makeInstance(&xkvmgr_type, &str_params); + TEST_ASSERT_NOT_NULL(c.resmgr); + c.jobmgr = makeInstance(&xkvmgr_type, &int_params); + TEST_ASSERT_NOT_NULL(c.jobmgr); + + for (i = 0; i < TWR_RT_N_RES; i++) { + xce_resource_t rdef; + memset(&rdef, 0, sizeof(rdef)); + rdef.name = (char*)res_names[i]; + rdef.valtype = res_valtypes[i]; + rdef.flags = 0; + rdef.idx = -1; + TEST_ASSERT_NOT_NULL(makeResource(c.resmgr, &rdef)); + } + + c.myhost_info.name = (char*)"twr72-controller"; + c.myhost_info.key = (char*)"twr72-key"; + c.myhost = &c.myhost_info; + + cfg = persist_config_defaults(); + cfg.wal_sync_ms = 5000; + persist_set_workdir(&c.persist, tmp, "ctrl-test"); + TEST_ASSERT_EQUAL_INT(0, persist_init(&c.persist, &cfg, NULL)); + TEST_ASSERT_EQUAL_INT(0, persist_start(&c.persist)); + + /* Seed a durable WAL_JOB_SUBMIT fact + a matching in-memory job_t, + * RUN, assigned to the worker host -- and NOTHING ELSE. No + * WAL_JOB_START/DISPATCH/FINISH is ever appended for this job in + * this log: the controller's own durable state simply has no + * record the job ever finished, exactly bug-1741's own reported + * gap. */ + { + job_submit_data_t wal_submit; + xce_job_t wal_jdef; + uint8_t* buf = NULL; + size_t sz = 0; + job_submit_data_t submit; + xce_job_t jdef; + + memset(&wal_submit, 0, sizeof(wal_submit)); + wal_submit.queue = (char*)"q"; + wal_submit.user = (char*)"tester"; + memset(&wal_jdef, 0, sizeof(wal_jdef)); + wal_jdef.jobid = TWR_JOBID_FAILOVER_LOST; + wal_jdef.state = JOB_STAT_RUN; + wal_jdef.submit = &wal_submit; + TEST_ASSERT_EQUAL_INT(0, twr_encode_job(&wal_jdef, &buf, &sz)); + TEST_ASSERT_EQUAL_INT(0, + persist_wal_async(&c.persist, WAL_JOB_SUBMIT, buf, + (uint32_t)sz)); + free(buf); + + memset(&submit, 0, sizeof(submit)); + submit.queue = (char*)"q"; + submit.user = (char*)"tester"; + memset(&jdef, 0, sizeof(jdef)); + jdef.jobid = TWR_JOBID_FAILOVER_LOST; + jdef.state = JOB_STAT_RUN; + jdef.submit = &submit; + job = makeJob(c.jobmgr, &jdef); + TEST_ASSERT_NOT_NULL(job); + job->job.allocs = twr_make_test_alloc_for_host( + TWR_JOBID_FAILOVER_LOST, "resync-failover-host"); + TEST_ASSERT_NOT_NULL(job->job.allocs); + } + + /* ── Worker rejoin: the REAL join entry point. Requirement 1.3 -- + * the controller does not need to know or care whether this is + * the host's first-ever join, an ordinary network reconnect, or + * (this scenario) a reconnect to a new primary after a controller + * failover; the same trigger fires because the controller still + * holds one non-terminal job for this host. */ + memset(&attrs, 0, sizeof(attrs)); + attrs.hosttype = makeString("LINUX"); + attrs.hostmodel = makeString("x86"); + attrs.cpufactor = 1.0f; + attrs.maxcpus = 4; + attrs.maxmem = 16; + attrs.maxswap = 32; + attrs.maxtmp = 64; + attrs.ndisks = 1; + + { + xce_worker_t host; + memset(&host, 0, sizeof(host)); + host.name = (char*)"resync-failover-host"; + host.attrs = &attrs; + w = makeWorker(c.workermgr, &host); + } + TEST_ASSERT_NOT_NULL(w); + + memset(&new_attrs, 0, sizeof(new_attrs)); + new_attrs.hosttype = makeString("LINUX"); + new_attrs.hostmodel = makeString("x86"); + new_attrs.cpufactor = 1.0f; + new_attrs.maxcpus = 4; + new_attrs.maxmem = 16; + new_attrs.maxswap = 32; + new_attrs.maxtmp = 64; + new_attrs.ndisks = 1; + + memset(&hconfig, 0, sizeof(hconfig)); + hconfig.hosttype = (char*)"!"; + hconfig.hostmodel = (char*)"!"; + hconfig.mxj = 4; + + memset(&stack_ep, 0, sizeof(stack_ep)); + rc = rejoin_worker(&c, w, &stack_ep, &new_attrs, &hconfig); + TEST_ASSERT_GREATER_OR_EQUAL(0, rc); + + TEST_ASSERT_NOT_NULL_MESSAGE(w->resync, + "a rejoin finding this host's one lost-finish job still " + "recorded as RUN must arm a reconciliation round (Req 1.1, " + "1.3)"); + TEST_ASSERT_EQUAL_INT(1, w->resync->n_queried_jobids); + TEST_ASSERT_TRUE(IS_WORKER_RECONCILING(w->host.status)); + + ep = twr_rt_new_test_endpoint(); + TEST_ASSERT_EQUAL_INT(0, worker_send_resync_query(&c, w, ep)); + + twr_rt_pop_and_decode(ep, &decoded_query); + TEST_ASSERT_EQUAL_INT(OPCode_jobStateQuery, decoded_query.opcode); + TEST_ASSERT_EQUAL_INT(Request_body_jobstatequerymsg, + decoded_query.body_which); + TEST_ASSERT_NOT_NULL(decoded_query.body.jobstatequerymsg); + TEST_ASSERT_EQUAL_INT_MESSAGE(1, + decoded_query.body.jobstatequerymsg->n_total, + "the REAL wire query must ask about exactly the one job the " + "controller still believes is running (Req 2.1)"); + TEST_ASSERT_EQUAL_UINT64_MESSAGE(TWR_JOBID_FAILOVER_LOST, + decoded_query.body.jobstatequerymsg->jobids[0], + "the query must identify the job unambiguously by its ID " + "(Req 2.2)"); + xce_free_request(&decoded_query); + + /* ── The worker's REAL answer: it actually finished this job + * successfully, long before this rejoin -- the controller simply + * never heard about it (the lost XCECLI_FF_CALL). */ + { + xce_job_state_entry_t e; + xce_job_state_entry_t* entries[1]; + xce_job_state_report_t report; + + e = (xce_job_state_entry_t){ + .jobid = TWR_JOBID_FAILOVER_LOST, + .status = JobStateStatus_finishedOk, + .exit_code = 0, + .finish_time_ms = worker_reported_finish_time_s * 1000ULL, + .queried = 1 + }; + entries[0] = &e; + report = (xce_job_state_report_t){ + .n_total = 1, .pos = 0, .count = 1, .entries = entries + }; + + TEST_ASSERT_EQUAL_INT(0, + xce_job_state_report_req(ep, c.myhost, &report, NULL, NULL, + 0)); + } + + twr_rt_pop_and_decode(ep, &decoded_report); + TEST_ASSERT_EQUAL_INT(OPCode_jobStateReport, decoded_report.opcode); + TEST_ASSERT_EQUAL_INT(Request_body_jobstatereportmsg, + decoded_report.body_which); + TEST_ASSERT_NOT_NULL(decoded_report.body.jobstatereportmsg); + + g_twr_update_hook_fires = 0; + TEST_ASSERT_EQUAL_INT(0, + xce_add_hook(&c.hooksys, XCE_CONTROLLER_HOOK_JOB, + twr_job_update_spy_hook, NULL)); + + pthread_mutex_lock(&c.persist.lock); + lsn_before = c.persist.current_lsn; + pthread_mutex_unlock(&c.persist.lock); + + rc = resync_handle_report_page(&c, w, + decoded_report.body.jobstatereportmsg); + TEST_ASSERT_EQUAL_INT_MESSAGE(1, rc, + "a single-page report (count == n_total) must complete the " + "report immediately"); + + pthread_mutex_lock(&c.persist.lock); + lsn_after = c.persist.current_lsn; + pthread_mutex_unlock(&c.persist.lock); + + xce_free_request(&decoded_report); + + /* ── Phase 1 assertions: the round resolves and a durable fact + * capturing the worker's TRUE outcome is appended -- but the job + * is NOT yet observably DONE in this process's own memory. That + * is expected and correct: finished-success reconciles through + * record_job_finish_fact_at's DEFERRED pattern (task 3.2/bug- + * 1747), same as an ordinary finish report -- the state mutation + * happens later, when the fact is applied (Phase 2 below), never + * synchronously here. */ + TEST_ASSERT_EQUAL_UINT32_MESSAGE(JOB_STAT_RUN, job->job.state, + "finished-success stays RUN synchronously -- the DEFERRED " + "record_job_finish_fact_at pattern applies the state change " + "later, via apply_committed_entry (Phase 2)"); + + TEST_ASSERT_NULL_MESSAGE(w->resync, + "the round's only queried job has a reconciled outcome -- it " + "must resolve (Req 5.1, 5.2)"); + TEST_ASSERT_FALSE_MESSAGE(IS_WORKER_RECONCILING(w->host.status), + "XCE_WORKER_RECONCILING must clear once the round resolves"); + + TEST_ASSERT_EQUAL_INT_MESSAGE(0, g_twr_update_hook_fires, + "finished-success is DEFERRED -- no HOOK_DETAIL_JOB_UPDATE " + "fire is expected synchronously here; that fire is proven " + "below, in Phase 2, once the durable fact actually applies"); + + TEST_ASSERT_TRUE_MESSAGE(lsn_after >= lsn_before + 1, + "the worker's true finished-success outcome must be durably " + "appended (WAL_JOB_FINISH) as part of this report, even " + "though it has not applied to in-memory state yet"); + + xce_disable_hook(&c.hooksys, XCE_CONTROLLER_HOOK_JOB, + twr_job_update_spy_hook); + + TEST_ASSERT_EQUAL_INT(0, persist_flush(&c.persist)); + + persist_stop(&c.persist); + persist_fini(&c.persist); + if (c.workermgr) dereference(c.workermgr); + if (c.resmgr) dereference(c.resmgr); + if (c.jobmgr) dereference(c.jobmgr); + xce_hook_fini(&c.hooksys); + + dereference(new_attrs.hosttype); + dereference(new_attrs.hostmodel); + endpoint_fini(ep); + free(ep); + } + + /* Phase 2: fresh persist_t + fresh cluster_t, persist_recover() -- the + * SAME apply_committed_entry() seam a live controller's own commit- + * apply pump (or another controller instance recovering this same + * durable log) would invoke. THIS is the test's core, observable + * completion criterion: the job the controller's own durable state + * showed stuck in RUN a moment ago, with its finish notify never + * having reached any controller instance, now reconstructs as + * genuinely finished -- DONE, with the worker's own true finish time, + * not reconciliation-processing wall-clock time -- because the + * worker rejoined and this feature's reconciliation round recovered + * it (Req 4.1, 4.2). */ + { + persist_t* p2 = twr_make_fresh_persist(tmp); + cluster_t c2; + job_t* j2 = NULL; + int rc; + kvmgr_params_t int_params = { .key_type = KVMGR_KEY_INT, + .nslots = 32, .delta = 16 }; + + TEST_ASSERT_NOT_NULL(p2); + + memset(&c2, 0, sizeof(c2)); + TEST_ASSERT_EQUAL_INT(0, + xce_hook_init(&c2.hooksys, XCE_CONTROLLER_HOOK_MAX)); + c2.jobmgr = makeInstance(&xkvmgr_type, &int_params); + TEST_ASSERT_NOT_NULL(c2.jobmgr); + + g_twr_update_hook_fires = 0; + TEST_ASSERT_EQUAL_INT(0, + xce_add_hook(&c2.hooksys, XCE_CONTROLLER_HOOK_JOB, + twr_job_update_spy_hook, NULL)); + + p2->cluster = &c2; + rc = persist_recover(p2); + TEST_ASSERT_EQUAL_INT(0, rc); + + lock(c2.jobmgr, RTTI_LOCK_READ); + key_find(c2.jobmgr, (void*)TWR_JOBID_FAILOVER_LOST, (void**)&j2); + unlock(c2.jobmgr); + + TEST_ASSERT_NOT_NULL_MESSAGE(j2, + "restart/rejoin-to-new-primary replay must reconstruct the " + "job from its WAL_JOB_SUBMIT fact"); + + TEST_ASSERT_EQUAL_UINT32_MESSAGE(JOB_STAT_DONE, j2->job.state, + "the feature's core completion criterion (bug-1741): a job " + "whose finish notify never reached any controller instance " + "ends up correctly finished, not stuck in RUN, once the " + "worker rejoins the new primary (Req 4.1)"); + TEST_ASSERT_EQUAL_UINT64_MESSAGE(worker_reported_finish_time_s, + (uint64_t)j2->job.finish_time, + "the recovered finish_time must be the WORKER-reported " + "finish_time_ms from the reconciliation report, not " + "reconciliation-processing or replay wall-clock time " + "(Req 4.2, 3.5)"); + + TEST_ASSERT_EQUAL_INT_MESSAGE(1, g_twr_update_hook_fires, + "replaying the durable fact this reconciliation round " + "produced must reach the scheduler's/apiserver's notify path " + "(HOOK_DETAIL_JOB_UPDATE) exactly once for this one real " + "state change (Req 7.1-7.3)"); + + xce_disable_hook(&c2.hooksys, XCE_CONTROLLER_HOOK_JOB, + twr_job_update_spy_hook); + xce_hook_fini(&c2.hooksys); + if (c2.jobmgr) dereference(c2.jobmgr); + twr_teardown_persist(p2); + } + + { + char cmd[512]; + snprintf(cmd, sizeof(cmd), "rm -rf %s", tmp); + if (system(cmd) != 0) + fprintf(stderr, "cleanup warning: rm -rf %s failed\n", tmp); + } + + printf("test_failover_during_job_recovers_lost_finish: PASS\n"); +} + /* ── Test group entry point ───────────────────────────────────────────── */ void test_worker_resync(void) @@ -3036,4 +3465,5 @@ void test_worker_resync(void) RUN_TEST(test_handle_report_page_stale_round_discarded_when_superseded); RUN_TEST(test_handle_report_page_malformed_bounds_rejected_and_recovers); RUN_TEST(test_full_rejoin_reconciliation_round_trip); + RUN_TEST(test_failover_during_job_recovers_lost_finish); }