From b7250c2ec6a7e8831141a45a636cff95af497d49 Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Tue, 15 Sep 2026 02:46:52 +0000 Subject: [PATCH] fix(scheduler): downgrade routine EEXIST resync log, dedup hash_string xce_core_push_events() WARNed on every JOBS_PUSH resync redelivery (sched_add_job rc=-EEXIST), which is the expected outcome under on_scheduler_join()'s full resync or the array-push dedup race (bug-1734/bug-1714) and flooded operational logs. Only that case now logs via a new DBG() macro (utils.h); any other add_rc (e.g. -ENOMEM) still WARNs. DBG is named to avoid colliding with the build's own -DDEBUG command-line define (debug/asan buildtypes). Also collapsed hash_string()'s duplicated djb2 loop to delegate to hash_block(), which already implements the same RUN_HASH loop. Logged as bug-1809 in .wolf/buglog.json. Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_01RLSNJhNoULvVcUhXEFafQC --- .wolf/anatomy-index.json | 37 ++++++++++++++++++++++++++++----- .wolf/anatomy.md | 7 +++++-- .wolf/buglog.json | 33 +++++++++++++++++++++++++++++ .wolf/memory.md | 14 +++++++++++++ src/include/utils.h | 6 ++++++ src/lib/utils.c | 9 +------- src/scheduler/src/core_events.c | 28 +++++++++++++++++++++---- 7 files changed, 115 insertions(+), 19 deletions(-) diff --git a/.wolf/anatomy-index.json b/.wolf/anatomy-index.json index a3b6b8b4..be9545d9 100644 --- a/.wolf/anatomy-index.json +++ b/.wolf/anatomy-index.json @@ -1,13 +1,13 @@ { "version": 1, "meta": { - "lastScanned": "2026-09-14T15:07:50.753Z", - "fileCount": 559, + "lastScanned": "2026-09-15T02:34:37.112Z", + "fileCount": 562, "hits": 0, "misses": 0, - "renderedHash": "fa0ccc6a5e22b9c3ea839f6af7edb6a4e2e0c854e5dbcfa8e3efa2923b5ff5da", - "storeUpdatedAt": "2026-09-14T15:07:50.761Z", - "rootHash": "2113d381173797cb" + "renderedHash": "54b2e66594a769b4176755032afcc65e9009684d6c9b649e2e021d28c2b7f11f", + "storeUpdatedAt": "2026-09-15T02:34:37.121Z", + "rootHash": "cda4e7e066f4e166" }, "files": { ".agent-shell/transcripts/2026-08-11-11-39-59.md": { @@ -10237,6 +10237,33 @@ "mtimeMs": 1789398458927.6282, "updatedAt": "2026-09-14T15:07:38.971Z", "source": "hook" + }, + "src/include/utils.h": { + "description": "if !defined(_UTILS_H_)", + "tokens": 2810, + "hash": "403aa4d8df678a9b", + "size": 10558, + "mtimeMs": 1789439662648.9136, + "updatedAt": "2026-09-15T02:34:22.692Z", + "source": "hook" + }, + "src/scheduler/src/core_events.c": { + "description": "include ", + "tokens": 16287, + "hash": "658f318636cb3ead", + "size": 61075, + "mtimeMs": 1789439677074.2285, + "updatedAt": "2026-09-15T02:34:37.112Z", + "source": "hook" + }, + "src/lib/utils.c": { + "description": "include ", + "tokens": 7015, + "hash": "41554dd9aaeadade", + "size": 26308, + "mtimeMs": 1789428659757.0122, + "updatedAt": "2026-09-14T23:30:59.805Z", + "source": "hook" } } } \ No newline at end of file diff --git a/.wolf/anatomy.md b/.wolf/anatomy.md index 9c57a0dc..ec54805a 100644 --- a/.wolf/anatomy.md +++ b/.wolf/anatomy.md @@ -1,7 +1,7 @@ # anatomy.md -> Auto-maintained by OpenWolf. Last scanned: 2026-09-14T15:07:50.753Z -> Files: 559 tracked | Anatomy hits: 0 | Misses: 0 +> Auto-maintained by OpenWolf. Last scanned: 2026-09-15T02:34:37.112Z +> Files: 562 tracked | Anatomy hits: 0 | Misses: 0 ## ./ @@ -887,11 +887,13 @@ ## src/include/ - `resreq.h` — if !defined(_RESREQ_H_) (~3310 tok) +- `utils.h` — if !defined(_UTILS_H_) (~2810 tok) ## src/lib/ - `misc.c` — include (~486 tok) - `resreq.c` — define _XOPEN_SOURCE 700 (~6663 tok) +- `utils.c` — include (~7015 tok) ## src/lib/testsuite/ @@ -904,6 +906,7 @@ ## src/scheduler/src/ +- `core_events.c` — include (~16287 tok) - `plugin.c` — include (~4554 tok) - `repl_break.c` — include (~9921 tok) - `repl_info.c` — include (~16226 tok) diff --git a/.wolf/buglog.json b/.wolf/buglog.json index e4ae4699..4e4c7c04 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -21943,6 +21943,39 @@ ], "occurrences": 1, "last_seen": "2026-09-14T15:50:00Z" + }, + { + "id": "bug-1809", + "timestamp": "2026-09-14T16:20:00Z", + "error_message": "User-reported: live scheduler logs are flooded with WARN lines for every ordinary XCE_CORE_EVENT_JOBS_PUSH resync redelivery: \"xce_core_push_events JOBS_PUSH: sched_add_job failed for jobid (rc=-17), merging state into existing tracked job instead of discarding\" (src/scheduler/src/core_events.c). rc=-17 is -EEXIST -- the expected, routine outcome of on_scheduler_join()'s full resync (bug-1734) or the array-push dedup race (bug-1714), already correctly handled by the bug-1734/bug-1738/bug-1739 merge logic in the same branch, not a functional defect.", + "file": "src/scheduler/src/core_events.c (XCE_CORE_EVENT_JOBS_PUSH duplicate-jobid merge branch, ~line 845)", + "root_cause": "Not a defect -- a UX/observability request. sched_add_job() (core.c) wraps key_add()->kvtab_add() (lib/kv.c), whose only failure modes for the core->jobs table (KVMGR_KEY_INT, no keyops->assign) are -EEXIST (duplicate jobid) or -ENOMEM (allocation failure). The EEXIST case is therefore the near-universal, routine shape of this branch under a reconnect/resync storm (confirmed live in bug-1714's own investigation: 700+ of these WARNs fired from a single 8-reconnect burst) -- WARN was the wrong level for an outcome the code already handles correctly by design; it was originally added at WARN by bug-1734's own fix pass without considering steady-state log volume under the reconnect-storm conditions that same session's investigation had just captured.", + "fix": "FIXED (2026-09-14). Split the single WARN call in the JOBS_PUSH EEXIST branch (core_events.c) on add_rc: when add_rc == -EEXIST, log via a new DBG(...) macro (utils.h, wraps tlog_debug() -- DEBUG level, silent by default, visible with -vvv) instead of WARN -- preserves the message (still valuable forensic evidence per bug-1734/bug-1714) without flooding default-verbosity operational logs. Any OTHER negative add_rc (e.g. -ENOMEM) still logs at WARN, since that would be a genuine anomaly, not a routine resync artifact. The new macro is named DBG, not DEBUG, matching the existing TRACE/INFO/WARN/ERROR one-line wrapper convention in utils.h: a first attempt to name it DEBUG(...) collided with the build's own bare -DDEBUG command-line define (src/meson.build, set for BOTH the debug and asan buildtypes -- confirmed via build warning \"DEBUG redefined ... this is the location of the previous definition \" across every file that includes utils.h under either profile), so DBG was used instead per user decision after the tradeoff was surfaced. Verified: xce-build.sh scheduler debug --incremental and xce-build.sh scheduler asan --incremental both compile clean (zero DBG/DEBUG-redefinition warnings in either profile); full scheduler suite 77/77 Ok, zero regressions.", + "tags": [ + "scheduler", + "logging", + "observability", + "core_events-c", + "jobs_push", + "sched_add_job", + "eexist", + "log-level", + "noise-reduction", + "not-a-defect", + "session-sibling-of-bug-1734", + "session-sibling-of-bug-1714", + "fixed", + "DBG-macro", + "utils-h" + ], + "related_bugs": [ + "bug-1734", + "bug-1714", + "bug-1739", + "bug-1738" + ], + "occurrences": 1, + "last_seen": "2026-09-14T16:20:00Z" } ] } diff --git a/.wolf/memory.md b/.wolf/memory.md index 08c1ad5d..ff8f17b8 100644 --- a/.wolf/memory.md +++ b/.wolf/memory.md @@ -4707,3 +4707,17 @@ | 08:07 | Edited src/harness/testsuite/test_test_cli.c | added 1 condition(s) | ~86 | | 08:07 | Edited src/harness/testsuite/test_test_cli.c | added 1 condition(s) | ~95 | | 08:07 | Edited src/harness/testsuite/harness_test.c | modified that() | ~184 | +| 16:16 | Session end: 6 writes across 3 files (SKILL.md, test_test_cli.c, harness_test.c) | 6 reads | ~7319 tok | + +## Session: 2026-09-14 16:16 + +| Time | Action | File(s) | Outcome | ~Tokens | +|------|--------|---------|---------|--------| +| 16:22 | Edited src/include/utils.h | 3→5 lines | ~35 | +| 16:22 | Edited src/scheduler/src/core_events.c | added 1 condition(s) | ~371 | +| 16:22 | Edited src/scheduler/src/core_events.c | 1804 → 1809 | ~20 | +| 16:23 | Edited src/include/utils.h | 5→3 lines | ~23 | +| 16:24 | Edited src/scheduler/src/core_events.c | modified if() | ~347 | +| 16:30 | Edited src/lib/utils.c | modified hash_string() | ~24 | +| 19:34 | Edited src/include/utils.h | expanded (+6 lines) | ~113 | +| 19:34 | Edited src/scheduler/src/core_events.c | DEBUG() → DBG() | ~325 | diff --git a/src/include/utils.h b/src/include/utils.h index 38d35312..bb1019cd 100644 --- a/src/include/utils.h +++ b/src/include/utils.h @@ -141,6 +141,12 @@ #define TRACE(...) tlog_debug3(__VA_ARGS__) +/* Named DBG, not DEBUG -- DEBUG is a bare command-line macro (-DDEBUG, + * src/meson.build) defined for both the debug and asan buildtypes, so + * `#define DEBUG(...)` here would trigger a "DEBUG redefined" warning in + * every translation unit that includes this header under either profile. */ +#define DBG(...) tlog_debug(__VA_ARGS__) + #define INFO(...) tlog_info(__VA_ARGS__) #define ERROR(...) tlog_error(__VA_ARGS__) diff --git a/src/lib/utils.c b/src/lib/utils.c index 29e8a022..33250220 100644 --- a/src/lib/utils.c +++ b/src/lib/utils.c @@ -802,12 +802,5 @@ uint32_t hash_block(char* buf, size_t len) uint32_t hash_string(const char* key) { - uint32_t hc = 5381; - int c; - - while ((c = *key++)) { - hc = RUN_HASH(hc, c); - } - - return hc; + return hash_block((char*)key, strlen(key)); } diff --git a/src/scheduler/src/core_events.c b/src/scheduler/src/core_events.c index 2088c023..d019493c 100644 --- a/src/scheduler/src/core_events.c +++ b/src/scheduler/src/core_events.c @@ -842,10 +842,30 @@ int xce_core_push_events(xce_sched_core_t* core, xce_core_event_t* events, * fmt_jobid(), referenced at each other call site below), * instead of a raw numeric jobid. */ fmt_jobid(jobidStr, sizeof(jobidStr), job->jobid); - WARN("%s JOBS_PUSH: sched_add_job failed for jobid %s " - "(rc=%d), merging state into existing tracked job " - "instead of discarding", - __func__, jobidStr, add_rc); + + /* bug-1809 follow-up: -EEXIST here is the expected, + * routine shape of a resync redelivery (on_scheduler_ + * join()'s full resync, or the array-push dedup race + * bug-1714 documents) -- not an anomaly -- so it is + * logged at DBG (utils.h's tlog_debug() wrapper -- named + * DBG rather than DEBUG to avoid colliding with the + * build's own -DDEBUG command-line define) instead of + * WARN, to stop it from flooding operational logs under + * the reconnect-storm conditions bug-1734/bug-1714 both + * captured live. Any OTHER negative add_rc (e.g. -ENOMEM + * from key_add()'s allocation path) is a genuine anomaly + * and still WARNs. */ + if (add_rc == -EEXIST) { + DBG("%s JOBS_PUSH: sched_add_job failed for jobid %s " + "(rc=%d), merging state into existing tracked " + "job instead of discarding", + __func__, jobidStr, add_rc); + } else { + WARN("%s JOBS_PUSH: sched_add_job failed for jobid %s " + "(rc=%d), merging state into existing tracked " + "job instead of discarding", + __func__, jobidStr, add_rc); + } if ((existing != NULL) && (existing->state != job->state)) { /* bug-1738: never let a resync redelivery regress an