diff --git a/.wolf/buglog.json b/.wolf/buglog.json index f3b502d6..9786f1a8 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -16302,7 +16302,7 @@ "error_message": "controller_unit_test: test_conf_trim_keeps_only_n_versions and test_conf_get_saved_tag_no_config (test_config_repl.c) FAIL during an unrelated ASAN controller build/test run (bug-451 fix session)", "file": "src/controller/testsuite/test_config_repl.c", "root_cause": "Not investigated -- discovered incidentally while verifying an unrelated fix (bug-451, persist_job_hook_fun's RUSAGE arm). Neither test_config_repl.c nor config_repl.c were touched this session (confirmed via git diff, zero changes). Coincides with a burst of 'persist: flusher fdatasync FAILED (errno=5 Input/output error)' ERROR lines in the same test run, matching this project's well-documented overlayfs sandbox fdatasync artifact class (same family as bug-924, bug-1470, bug-1553) rather than a genuine regression.", - "fix": "NOT FIXED -- out of scope for the bug-451 session that surfaced it. Needs confirmation this is the same overlayfs artifact (re-run on a real fs) before treating it as a real regression in test_config_repl.c's config-version-trim/tag-save logic. Re-observed 2026-08-17 during resource-value-verification task 1.1 (resval_typeresolve extraction) full controller ASAN build/test run: same 2 tests (test_conf_trim_keeps_only_n_versions Expected 2 Was 3, test_conf_get_saved_tag_no_config Expected 0 Was ), same accompanying persist_flush/flusher fdatasync errno=5 burst. Zero diff in test_config_repl.c/config_repl.c this session either (task 1.1 boundary was testsuite/resval_typeresolve.{c,h}, testsuite/test_resval_typeresolve.c, meson.build only) -- further corroborates the overlayfs sandbox artifact theory over a genuine regression, still unconfirmed on a real fs. Re-observed again 2026-08-17 during resource-value-verification task 2.1 (resupdate fallback + -t flag wiring, GREEN phase): identical 2 tests, identical Expected/Was values, identical fdatasync errno=5 burst, in the same full `/xce-build controller` run that also confirmed resval_typeresolve_unit_test's own Unity summary at 4 Tests 0 Failures (task 2.1's GREEN evidence). Task 2.1's diff was scoped to testsuite/resval_typeresolve.{c,h} and testsuite/test.c only (confirmed via git diff --stat) -- test_config_repl.c/config_repl.c untouched, per this bug's own do-not-chase guidance in tasks.md's Implementation Notes.\n\nRe-observed a 5th time 2026-08-18 during a full `nix develop ./src --command bash src/tools/xce-build.sh all asan build-asan --incremental` verification run on the scheduler-framework branch (post bug-1584/1585 scheduler fixes). Identical signature: same 2 tests, same Expected/Was values (test_conf_trim_keeps_only_n_versions Expected 2 Was 3; test_conf_get_saved_tag_no_config Expected 0 Was large-garbage-uint64), same accompanying persist_flush/flusher fdatasync errno=5 burst. This run recompiled ZERO C source files (ninja reported \"no work to do\" for all C targets -- only the xceadmin custom target/wheel regenerated), so the failure cannot be attributed to any change in this session -- strongest evidence yet that this is purely an environment (overlayfs fdatasync) artifact, not a code regression. Scheduler suite's own single failure in the same run (test_recordstart_symlink_escape_replies_error, bug-1560) is separate and expected. Re-observed a 6th time 2026-08-19 during a controller ASAN build/test run verifying the StartTime/FinishTime persist.c fix (raft-apply-decoupling job-fact timestamp stamping, unrelated files persist.c/test_apply_committed_entry.c) -- identical 2 tests, identical Expected/Was values, identical fdatasync errno=5 burst. Session diff confirmed scoped to persist.c/test_apply_committed_entry.c only -- further corroborates environment-artifact theory.", + "fix": "NOT FIXED -- out of scope for the bug-451 session that surfaced it. Needs confirmation this is the same overlayfs artifact (re-run on a real fs) before treating it as a real regression in test_config_repl.c's config-version-trim/tag-save logic. Re-observed 2026-08-17 during resource-value-verification task 1.1 (resval_typeresolve extraction) full controller ASAN build/test run: same 2 tests (test_conf_trim_keeps_only_n_versions Expected 2 Was 3, test_conf_get_saved_tag_no_config Expected 0 Was ), same accompanying persist_flush/flusher fdatasync errno=5 burst. Zero diff in test_config_repl.c/config_repl.c this session either (task 1.1 boundary was testsuite/resval_typeresolve.{c,h}, testsuite/test_resval_typeresolve.c, meson.build only) -- further corroborates the overlayfs sandbox artifact theory over a genuine regression, still unconfirmed on a real fs. Re-observed again 2026-08-17 during resource-value-verification task 2.1 (resupdate fallback + -t flag wiring, GREEN phase): identical 2 tests, identical Expected/Was values, identical fdatasync errno=5 burst, in the same full `/xce-build controller` run that also confirmed resval_typeresolve_unit_test's own Unity summary at 4 Tests 0 Failures (task 2.1's GREEN evidence). Task 2.1's diff was scoped to testsuite/resval_typeresolve.{c,h} and testsuite/test.c only (confirmed via git diff --stat) -- test_config_repl.c/config_repl.c untouched, per this bug's own do-not-chase guidance in tasks.md's Implementation Notes.\n\nRe-observed a 5th time 2026-08-18 during a full `nix develop ./src --command bash src/tools/xce-build.sh all asan build-asan --incremental` verification run on the scheduler-framework branch (post bug-1584/1585 scheduler fixes). Identical signature: same 2 tests, same Expected/Was values (test_conf_trim_keeps_only_n_versions Expected 2 Was 3; test_conf_get_saved_tag_no_config Expected 0 Was large-garbage-uint64), same accompanying persist_flush/flusher fdatasync errno=5 burst. This run recompiled ZERO C source files (ninja reported \"no work to do\" for all C targets -- only the xceadmin custom target/wheel regenerated), so the failure cannot be attributed to any change in this session -- strongest evidence yet that this is purely an environment (overlayfs fdatasync) artifact, not a code regression. Scheduler suite's own single failure in the same run (test_recordstart_symlink_escape_replies_error, bug-1560) is separate and expected. Re-observed a 6th time 2026-08-19 during a controller ASAN build/test run verifying the StartTime/FinishTime persist.c fix (raft-apply-decoupling job-fact timestamp stamping, unrelated files persist.c/test_apply_committed_entry.c) -- identical 2 tests, identical Expected/Was values, identical fdatasync errno=5 burst. Session diff confirmed scoped to persist.c/test_apply_committed_entry.c only -- further corroborates environment-artifact theory.\n\nRe-observed a 7th time 2026-08-21 verifying a pure output-formatting edit to src/controller/testsuite/test.c (raw %lu jobid printf sites replaced with fmt_jobid()+%s, 10 call sites, zero logic change) via `xce-build.sh controller asan --incremental` on the scheduler-framework branch. Identical signature: same 2 tests (test_conf_trim_keeps_only_n_versions Expected 2 Was 3; test_conf_get_saved_tag_no_config Expected 0 Was large-garbage-uint64), same accompanying persist_flush/flusher fdatasync errno=5 burst. Session diff confirmed scoped to test.c only (git diff --stat) -- test_config_repl.c/config_repl.c untouched. controller/xce_test (the binary test.c itself compiles into) built and linked cleanly with zero warnings/errors tied to the fmt_jobid change; only controller_unit_test (a separate binary, testsuite_test_config_repl.c.o) carries these 2 pre-existing failures. Further corroborates environment-artifact theory over regression.", "tags": [ "controller", "testsuite", @@ -16318,8 +16318,8 @@ "bug-1470", "bug-1553" ], - "occurrences": 6, - "last_seen": "2026-08-19T21:10:00Z" + "occurrences": 7, + "last_seen": "2026-08-21T16:03:00Z" }, { "id": "bug-912", @@ -17444,7 +17444,7 @@ "error_message": "User feedback (UX/observability, not a functional defect), from logs/ctrl-1.log: job IDs printed in controller log lines are large, non-sequential-looking 64-bit numbers (e.g. `4631574334564990976`, `4631574334564990977`, `4631574334633148416`) that are hard to visually scan/compare/diff -- would be better rendered in a more human-readable form. Affected call sites (src/controller/job.c): `dispatch_a_job_()` (job.c:841, 'dispatch_a_job_ jobid '), `on_job_start()` (job.c:1662, 'on_job_start jobid '), `on_job_finish()` (job.c:1766, 'on_job_finish job finish jobid exit code '). Likely other job.c/controller log call sites print the same raw jobid and would benefit from the same treatment (not yet enumerated).", "file": "src/controller/job.c (dispatch_a_job_ ~841, on_job_start ~1662, on_job_finish ~1766) -- likely more sites, not yet grepped exhaustively; PLUS (open, not yet fixed) src/worker/src/{xcecd_dbus_manager,xcecd,main,xcecd_worker,controller_connector,uv_ipc,xcecd_cgroups,xcecd_worker_utils}.c and src/controller/testsuite/test.c -- see fix field for full enumeration", "root_cause": "CONFIRMED, FIXED. The codebase already has a well-established human-readable jobid formatter -- fmt_jobid()/fmt_jobid_ex() (src/lib/utils.c:466-507, declared src/include/utils.h:132-133) -- used consistently across scheduler.c, handler.c, plugins/limit.c, plugins/fcfs.c, repl_info.c (scheduler), process_manager.c, uv_proc.c, xcecd_worker_utils.c (worker), and xce_test/waldump.c (controller testsuite tooling). It renders idgen()'s packed 64-bit jobid (src/lib/idgen.c, bit layout in src/include/config.h: 2 tag bits + 6 cluster-id bits + 4 apiserver-id bits + 32 timestamp-seconds bits + 20 sequence bits, packed via MAKE_JOBID/unpacked via the EXTRACT_ID_* macros in src/include/utils.h) as 'cluster-apiserver-timestamp-sequence' (e.g. '3-1-1755590313-976'), the SAME format REGEX_JOBID/parse_jobid() already parse back from user input and xcecli already displays to end users -- there is no separate 'new' human-readable scheme to design, job.c was simply the one place that never adopted the existing one, printing the raw packed integer via a mismatched `%ld` (a uint64_t formatted as a signed long -- a latent type/format mismatch, incidentally fixed as a side effect since the fix replaces the whole format specifier with %s).", - "fix": "Fixed. src/controller/job.c: all 8 TRACE() call sites that printed a raw jobid now call fmt_jobid(jobidStr, sizeof(jobidStr), ) into a local `char jobidStr[64]` (matching scheduler.c's established buffer-size convention) immediately before the TRACE() call, and print `%s` instead of `%ld`: dispatch_a_job_() (~841), on_job_start() (~1662), on_job_finish() (~1766), on_job_fail() (~2026), on_job_stop() (~2055), on_job_resume() (~2090), on_job_postdone() (~2123), set_preason() (~2297). fmt_jobid is already transitively visible in job.c via request.h's #include \"utils.h\" -- no new include needed. Purely a log-formatting change, zero logic/behavior change -- verified via /xce-build controller asan --incremental: job.c compiles with zero errors/warnings (compiled twice, for xce_controller and controller_unit_test), full controller suite green (1104/1104 Unity assertions, 5/5 meson test cases), git diff confirms job.c is the only file touched in src/controller/. Not live-validated against a real deployment's log output (no functional/behavioral risk to validate beyond the build+test suite, since this only changes what a string looks like) -- if desired, a live run would show e.g. 'dispatch_a_job_ jobid 3-1-1755590313-976' instead of 'dispatch_a_job_ jobid 4631574334564990976'.\n\n---\n\nRemaining sites enumerated 2026-08-21 via `ag -i job src | grep '%lu'` (job.c's 8 sites from this bug are already fixed; these are NOT yet fixed):\n\nWORKER (src/worker/src/) -- still print the raw uint64 jobid via %lu instead of calling fmt_jobid():\n- xcecd_dbus_manager.c:423\n- xcecd.c:60\n- main.c:167,227,245\n- xcecd_worker.c: ~25 sites between lines 83-1314 (rusage, VNC, exdata, port assignment, signal/pause/resume, CRIU checkpoint status messages)\n- controller_connector.c: ~20 sites between lines 508-1857 (job dispatch, remote task, job-control action, rusage-to-controller messages)\n- uv_ipc.c: ~20 sites between lines 77-1541 (client mapping, signal/checkpoint ack, rusage, job completion/failure)\n- xcecd_cgroups.c:1703 (rusage summary log line; xcecd_cgroups.c:1405's `xcecd-worker-%lu.service` unit name and xcecd_worker.c:1209's `%s/%lu` checkpoint dir / xcecd_exdata.c:408's numeric-string exdata substitution are identifier/path construction, not human-facing log text -- left as-is pending a decision on whether those should change too)\n- xcecd_worker_utils.c: 8 sites between lines 240-504 -- correction to this bug's original note: original text claimed xcecd_worker_utils.c \"already use fmt_jobid() consistently\", but `grep -c fmt_jobid( src/worker/src/xcecd_worker_utils.c` now returns 0; that claim does not hold for the current file state (process_manager.c and uv_proc.c's fmt_jobid() usage, also cited in the original note, is still confirmed correct)\n\nCONTROLLER TESTSUITE (src/controller/testsuite/test.c) -- interactive test-tool printf() output, lower priority than production daemon logs:\n- lines 2599, 2649, 3966, 4043, 4048, 4053, 4155, 4180, 4294, 4353\n\nExplicitly OUT of scope -- these matched the `%lu` grep but are not job IDs, so must NOT be converted: src/controller/job.c:1332 and src/controller/persist.c:6376,6530 all format `lsn` (WAL log sequence number), not a jobid; src/worker/src/main.c:160 formats a `client ID`, not a jobid.\n\nSuggested fix pattern (matches this bug's job.c fix): at each site, add `char jobidStr[64]; fmt_jobid(jobidStr, sizeof(jobidStr), );` immediately before the log call, and replace the `%lu` for that argument with `%s` / jobidStr. utils.h (which declares fmt_jobid) needs to be confirmed reachable in each of these worker files (uv_ipc.c, controller_connector.c, xcecd_worker.c, xcecd_dbus_manager.c, xcecd.c, main.c, xcecd_worker_utils.c) before starting -- not yet verified.\n\nNot yet fixed. Logged as a follow-up scope expansion of this same bug per user request (\"log an issue to fix all job ids which are shown as uint64 to human readable string via fmt_jobid()\"), 2026-08-21.", + "fix": "Fixed. src/controller/job.c: all 8 TRACE() call sites that printed a raw jobid now call fmt_jobid(jobidStr, sizeof(jobidStr), ) into a local `char jobidStr[64]` (matching scheduler.c's established buffer-size convention) immediately before the TRACE() call, and print `%s` instead of `%ld`: dispatch_a_job_() (~841), on_job_start() (~1662), on_job_finish() (~1766), on_job_fail() (~2026), on_job_stop() (~2055), on_job_resume() (~2090), on_job_postdone() (~2123), set_preason() (~2297). fmt_jobid is already transitively visible in job.c via request.h's #include \"utils.h\" -- no new include needed. Purely a log-formatting change, zero logic/behavior change -- verified via /xce-build controller asan --incremental: job.c compiles with zero errors/warnings (compiled twice, for xce_controller and controller_unit_test), full controller suite green (1104/1104 Unity assertions, 5/5 meson test cases), git diff confirms job.c is the only file touched in src/controller/. Not live-validated against a real deployment's log output (no functional/behavioral risk to validate beyond the build+test suite, since this only changes what a string looks like) -- if desired, a live run would show e.g. 'dispatch_a_job_ jobid 3-1-1755590313-976' instead of 'dispatch_a_job_ jobid 4631574334564990976'.\n\n---\n\nRemaining sites enumerated 2026-08-21 via `ag -i job src | grep '%lu'` (job.c's 8 sites from this bug are already fixed; these are NOT yet fixed):\n\nWORKER (src/worker/src/) -- still print the raw uint64 jobid via %lu instead of calling fmt_jobid():\n- xcecd_dbus_manager.c:423\n- xcecd.c:60\n- main.c:167,227,245\n- xcecd_worker.c: ~25 sites between lines 83-1314 (rusage, VNC, exdata, port assignment, signal/pause/resume, CRIU checkpoint status messages)\n- controller_connector.c: ~20 sites between lines 508-1857 (job dispatch, remote task, job-control action, rusage-to-controller messages)\n- uv_ipc.c: ~20 sites between lines 77-1541 (client mapping, signal/checkpoint ack, rusage, job completion/failure)\n- xcecd_cgroups.c:1703 (rusage summary log line; xcecd_cgroups.c:1405's `xcecd-worker-%lu.service` unit name and xcecd_worker.c:1209's `%s/%lu` checkpoint dir / xcecd_exdata.c:408's numeric-string exdata substitution are identifier/path construction, not human-facing log text -- left as-is pending a decision on whether those should change too)\n- xcecd_worker_utils.c: 8 sites between lines 240-504 -- correction to this bug's original note: original text claimed xcecd_worker_utils.c \"already use fmt_jobid() consistently\", but `grep -c fmt_jobid( src/worker/src/xcecd_worker_utils.c` now returns 0; that claim does not hold for the current file state (process_manager.c and uv_proc.c's fmt_jobid() usage, also cited in the original note, is still confirmed correct)\n\nCONTROLLER TESTSUITE (src/controller/testsuite/test.c) -- interactive test-tool printf() output, lower priority than production daemon logs:\n- lines 2599, 2649, 3966, 4043, 4048, 4053, 4155, 4180, 4294, 4353\n\nExplicitly OUT of scope -- these matched the `%lu` grep but are not job IDs, so must NOT be converted: src/controller/job.c:1332 and src/controller/persist.c:6376,6530 all format `lsn` (WAL log sequence number), not a jobid; src/worker/src/main.c:160 formats a `client ID`, not a jobid.\n\nSuggested fix pattern (matches this bug's job.c fix): at each site, add `char jobidStr[64]; fmt_jobid(jobidStr, sizeof(jobidStr), );` immediately before the log call, and replace the `%lu` for that argument with `%s` / jobidStr. utils.h (which declares fmt_jobid) needs to be confirmed reachable in each of these worker files (uv_ipc.c, controller_connector.c, xcecd_worker.c, xcecd_dbus_manager.c, xcecd.c, main.c, xcecd_worker_utils.c) before starting -- not yet verified.\n\nNot yet fixed. Logged as a follow-up scope expansion of this same bug per user request (\"log an issue to fix all job ids which are shown as uint64 to human readable string via fmt_jobid()\"), 2026-08-21.\n\n--- FOLLOW-UP FIXED 2026-08-21 ---\n\nAll remaining sites enumerated above are now fixed too (user request: \"make sure that all job ids which have been shown will use human readable format ... please also include src/controller/testsuite/test.c, as we use it test controller heavily\"). Same fmt_jobid()+%s pattern as job.c, applied via 5 parallel edit passes (one per file/group) each independently instructed with the exact site list and the exclusion list below, then independently reviewed line-by-line against the originals by the orchestrating session (not just trusted on the subagents' self-reports) before building.\n\nFiles fixed (99 call sites total across 9 files):\n- src/worker/src/xcecd_worker.c -- 30 sites (worker_signal_callback needed two buffers, jobidStr + curJobidStr, for its two distinct job-id values on one line)\n- src/worker/src/controller_connector.c -- 21 sites (handle_fetchfile: only the jobid= half of a two-%lu line converted, offset= left alone)\n- src/worker/src/uv_ipc.c -- ~20 sites (add_job_client_mapping: only the job_id half of a two-%lu line converted, client->id left alone)\n- src/worker/src/xcecd_worker_utils.c -- 9 sites\n- src/worker/src/controller_connector.c, xcecd_dbus_manager.c, xcecd.c, main.c, xcecd_cgroups.c -- remaining small sites (main.c's 4 sites all genuine job ids despite one message's misleading \"client ID\" wording -- verified against the function parameter type/usage, not just the string)\n- src/controller/testsuite/test.c -- 10 sites, matching this file's own pre-existing fmt_jobid()-with-'- 1'-sizeof convention\n\nDeliberately left unconverted (confirmed non-jobid or non-log-text, do not touch):\n- src/controller/job.c:1332 and src/controller/persist.c:6376,6530 -- format `lsn` (WAL log sequence number), not a jobid\n- src/worker/src/controller_connector.c:1376 -- the `offset=%lu` half of a fetchfile log line\n- src/worker/src/uv_ipc.c -- the `client->id` half of `add_job_client_mapping`'s log line\n- src/worker/src/xcecd_worker.c:1231 (ckpt_dir path), xcecd_cgroups.c:1405 (`xcecd-worker-%lu.service` unit name), xcecd_exdata.c:408 (`XCE_JOBID` env var set for the job's own process) -- all raw-numeric identifier/path/protocol construction, not human-facing log text; changing these would be a behavioral change (on-disk paths, systemd unit names, a documented env var format), not a log-formatting change\n\nVerification:\n- /xce-build worker asan --incremental: SUCCESS, 430/430 ninja targets, zero warnings/errors related to fmt_jobid/jobidStr in any of the 8 edited worker files, worker meson test suite 4/4 OK (resource_sync, xcecd_startup_order, dbus_workers_update, controller_connector tests).\n- /xce-build controller asan --incremental: SUCCESS, test.c compiled with zero warnings/errors, controller meson test suite 4/5 OK -- the 1 failure (test_config_repl.c, 2 Unity assertions) is the pre-existing, previously-logged bug-1561 overlayfs-sandbox fdatasync flake (7th occurrence, `git diff --stat` confirms config_repl.c/test_config_repl.c untouched by this change) -- not caused by this fix.\n- Every diff was read and checked line-by-line against the pre-edit originals by the orchestrating session (argument-to-specifier order, buffer scoping/reuse correctness, exclusion list respected) before either build ran -- not just accepted on the editing subagents' self-reports.\n\nNot fixed / explicitly out of scope: no attempt was made to reconcile the on-disk checkpoint-dir/systemd-unit-name/XCE_JOBID raw-numeric conventions with fmt_jobid() -- flagged above as a separate judgment call if ever wanted, not part of this fix.", "tags": [ "controller", "logging", @@ -17459,7 +17459,7 @@ "partial-fix" ], "related_bugs": [], - "occurrences": 3, + "occurrences": 4, "last_seen": "2026-08-21T00:00:00Z" }, { @@ -18161,7 +18161,9 @@ "worker", "stale-build-dir" ], - "related_bugs": ["bug-1565"], + "related_bugs": [ + "bug-1565" + ], "occurrences": 1, "last_seen": "2026-08-21T15:56:00Z" }