From 44173f74aed9b92ee029d2541d642fbb0e305701 Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Mon, 28 Sep 2026 04:35:19 +0000 Subject: [PATCH] fix: spurious errors/warnings from a pc13v HA deploy (bug-1872..1877) - bug-1872 (worker): "Failed to find any disk statistics in /proc/diskstats" ERROR every 15 s on an NVMe-only host. The whole-disk filter guessed from the name and skipped anything ending in a digit or containing 'p' -- every nvmeXnY, mmcblkN, even sdp -- so io was never reported. diskstats.h now counts a device only when /sys/block//device exists (real disks; not partitions, loop, dm, md, zram), and a host with no disk warns once. - bug-1873 (worker): "Failed to get worker pid" WARN on job start. MainPID reads 0 until systemd has forked the new transient unit; xcecd.c already retries, so the miss is DEBUG and the final failure names the unit. - bug-1874 (scheduler): deprecation WARN for the legacy xce_sched_fcfs on every start, though builtin_fcfs is the picker. Registration still wraps a job_elect_fn plugin but no longer warns; selecting one warns once. - bug-1875 (apiserver): "Not running as root -- PAM authentication will not work" with the default provider config_file; now only for provider pam. - bug-1876 (controller): standbys logged "cluster_init_phase2 ... failed (rc=-22)" WARN every 3 s while waiting for the primary's config push, a state the function itself calls normal. It returns -EAGAIN for that wait; callers log it at INFO, other failures still WARN. - bug-1877 (controller): "WAL/snapshot stored unencrypted" warned without looking. persist_path_encrypted() checks fscrypt (statx) and dm-crypt (sysfs dm/uuid CRYPT-, through LVM slaves); the warning stays when the storage is not shown to be encrypted (e.g. a plain /tmp). Tests: worker diskstats_test (2 of 4 RED on the old filter with pc13v's /proc/diskstats), controller test_phase2_cold_boot and test_persist_encryption, scheduler picker tests, apiserver TestRootWarning. Full ASAN build: all 113 suites pass (controller 319/0, harness 141/0). Co-Authored-By: Claude Opus 5.5 (1M context) --- src/controller/cluster.c | 2 +- src/controller/ha.c | 10 +- src/controller/ha.h | 9 ++ src/controller/meson.build | 2 + src/controller/myapp.c | 8 +- src/controller/persist.c | 93 +++++++++++- src/controller/testsuite/controller_test.c | 4 + .../testsuite/test_persist_encryption.c | 115 +++++++++++++++ .../testsuite/test_phase2_cold_boot.c | 40 +++++ .../apiserver/middleware/startserver.go | 19 ++- .../apiserver/middleware/startserver_test.go | 25 ++++ src/include/persist.h | 8 + src/scheduler/include/plugin.h | 6 + src/scheduler/src/plugin.c | 10 +- src/scheduler/src/schedobj.c | 8 + src/scheduler/testsuite/test_picker_wiring.c | 29 ++++ .../test_plugin_picker_registration.c | 15 +- src/worker/include/diskstats.h | 64 ++++++++ src/worker/src/node_information.c | 55 ++----- src/worker/src/xcecd.c | 3 +- src/worker/src/xcecd_dbus_manager.c | 5 +- src/worker/testsuite/meson.build | 13 ++ src/worker/testsuite/test_diskstats.c | 139 ++++++++++++++++++ 23 files changed, 619 insertions(+), 63 deletions(-) create mode 100644 src/controller/testsuite/test_persist_encryption.c create mode 100644 src/controller/testsuite/test_phase2_cold_boot.c create mode 100644 src/frontend/apiserver/middleware/startserver_test.go create mode 100644 src/worker/include/diskstats.h create mode 100644 src/worker/testsuite/test_diskstats.c diff --git a/src/controller/cluster.c b/src/controller/cluster.c index 9ef321e1..59600fe9 100644 --- a/src/controller/cluster.c +++ b/src/controller/cluster.c @@ -1934,7 +1934,7 @@ int cluster_init_phase2(cluster_t* c) INFO("cluster_init_phase2: cluster_config not loaded yet — normal " "during cold boot while awaiting the primary's config-push; " "will retry once it arrives"); - return -EINVAL; + return -EAGAIN; /* bug-1876: a wait, not -EINVAL */ } SSL_CTX* ssl_ctx = (SSL_CTX*)c->ha.ssl_ctx; diff --git a/src/controller/ha.c b/src/controller/ha.c index f32fac4d..7d63447f 100644 --- a/src/controller/ha.c +++ b/src/controller/ha.c @@ -433,8 +433,14 @@ int ha_phase2_retry_fn(void *arg) INFO("HA: cluster_init_phase2 retry succeeded — commit engine now " "wired (bug-1477)"); } else { - WARN("HA: cluster_init_phase2 retry rc=%d — member stays alive and " - "will retry again (bug-1477, never self-terminate)", rc); + if (ha_phase2_rc_is_waiting(rc)) { + /* bug-1876: still waiting for the primary's config push */ + INFO("HA: cluster_init_phase2 still waiting for the primary's " + "config push — will retry"); + } else { + WARN("HA: cluster_init_phase2 retry rc=%d — member stays alive " + "and will retry again (bug-1477, never self-terminate)", rc); + } ha_schedule_phase2_retry(c); } return rc; diff --git a/src/controller/ha.h b/src/controller/ha.h index 67a13481..6178ef50 100644 --- a/src/controller/ha.h +++ b/src/controller/ha.h @@ -18,6 +18,7 @@ * The watchdog (P1-3) will include netio.h directly where it needs endpoint_t. */ +#include #include #include #include @@ -952,6 +953,14 @@ int ha_phase2_retry_fn(void *arg); */ int ha_schedule_phase2_retry(cluster_t *c); +/* bug-1876: cluster_init_phase2()'s "cluster_config not pushed yet" result + * (-EAGAIN) -- the normal cold-boot wait of a standby, retried, not a + * failure; callers log it at INFO, everything else at WARN. */ +static inline int ha_phase2_rc_is_waiting(int rc) +{ + return rc == -EAGAIN; +} + /* * ha_apply_wal_catchup_entry: apply a single WAL catch-up entry to local * persistent storage and advance ha->applied_lsn on success. diff --git a/src/controller/meson.build b/src/controller/meson.build index 0f7b7fe7..9a4a21af 100644 --- a/src/controller/meson.build +++ b/src/controller/meson.build @@ -154,6 +154,8 @@ controller_unit_test_src = [ 'testsuite/test_wal_job_start_fact.c', 'testsuite/test_wal_job_finish_fact.c', 'testsuite/test_wal_job_fail_fact.c', + 'testsuite/test_phase2_cold_boot.c', + 'testsuite/test_persist_encryption.c', 'testsuite/test_config_queue_reconcile.c', 'testsuite/test_wal_job_rusage_fact.c', 'testsuite/test_wal_job_ckpt_fact.c', diff --git a/src/controller/myapp.c b/src/controller/myapp.c index b0edc9e5..b967fb05 100644 --- a/src/controller/myapp.c +++ b/src/controller/myapp.c @@ -438,7 +438,13 @@ skip_election:; * node already loaded its config from disk pre-election. */ if (!c.ha.phase2_done) { int prc = cluster_init_phase2(&c); - if (prc != 0) { + if (ha_phase2_rc_is_waiting(prc)) { + /* bug-1876: the normal cold-boot wait, not a failure */ + INFO("myapp_run: standby waiting for the primary's " + "config push before cluster_init_phase2; will " + "retry"); + ha_schedule_phase2_retry(&c); + } else if (prc != 0) { WARN("myapp_run: cluster_init_phase2 on standby rejoin " "failed (rc=%d) — WAL not recovered; member stays " "alive and will retry (bug-1477: this passive " diff --git a/src/controller/persist.c b/src/controller/persist.c index 539765b5..da59d97f 100644 --- a/src/controller/persist.c +++ b/src/controller/persist.c @@ -27,6 +27,7 @@ #include #include #include +#include /* major/minor -- bug-1877 */ #include #include #include @@ -1147,6 +1148,85 @@ void persist_set_workdir(persist_t* p, const char* workdir, const char* name) snprintf(p->snap_path, sizeof(p->snap_path), "%s/data/snap", effective); } +static int dmcrypt_walk(const char* sysfs, unsigned maj, unsigned min, + int depth) +{ + char path[512]; + char uuid[128] = ""; + FILE* fp; + DIR* d; + struct dirent* de; + int found = 0; + + if (depth > 8) { + return 0; + } + + snprintf(path, sizeof(path), "%s/dev/block/%u:%u/dm/uuid", sysfs, maj, min); + fp = fopen(path, "r"); + if (fp != NULL) { + if (fgets(uuid, sizeof(uuid), fp) == NULL) { + uuid[0] = '\0'; + } + fclose(fp); + if (strncmp(uuid, "CRYPT-", 6) == 0) { + return 1; + } + } + + /* a stacked device (LVM, md, ...) is encrypted if what it sits on is */ + snprintf(path, sizeof(path), "%s/dev/block/%u:%u/slaves", sysfs, maj, min); + d = opendir(path); + if (d == NULL) { + return 0; + } + while (!found && (de = readdir(d)) != NULL) { + char devpath[512]; + unsigned smaj, smin; + + if (de->d_name[0] == '.') { + continue; + } + snprintf(devpath, sizeof(devpath), "%s/class/block/%s/dev", sysfs, + de->d_name); + fp = fopen(devpath, "r"); + if (fp == NULL) { + continue; + } + if (fscanf(fp, "%u:%u", &smaj, &smin) == 2) { + found = dmcrypt_walk(sysfs, smaj, smin, depth + 1); + } + fclose(fp); + } + closedir(d); + return found; +} + +int persist_dev_is_dmcrypt(const char* sysfs, unsigned maj, unsigned min) +{ + return dmcrypt_walk(sysfs, maj, min, 0); +} + +int persist_path_encrypted(const char* path) +{ + struct statx stx; + struct stat st; + +#ifdef STATX_ATTR_ENCRYPTED + if ((statx(AT_FDCWD, path, 0, STATX_BASIC_STATS, &stx) == 0) + && (stx.stx_attributes_mask & STATX_ATTR_ENCRYPTED) + && (stx.stx_attributes & STATX_ATTR_ENCRYPTED)) { + return 1; /* fscrypt */ + } +#else + (void)stx; +#endif + if (stat(path, &st) != 0) { + return 0; + } + return persist_dev_is_dmcrypt("/sys", major(st.st_dev), minor(st.st_dev)); +} + int persist_init(persist_t* p, persist_config_t* cfg, cluster_t* c) { p->cluster = c; @@ -1288,9 +1368,16 @@ int persist_init(persist_t* p, persist_config_t* cfg, cluster_t* c) pthread_cond_init(&p->fsync_cond, NULL); repl_init(&p->repl); /* P2-4: fan-out replicator lifecycle */ - WARN("WAL/snapshot stored unencrypted in %s — " - "ensure filesystem is encrypted if job payloads contain sensitive data", - p->wal_path); + /* bug-1877: only warn when the storage is not shown to be encrypted; + * this used to warn on every start without looking */ + if (persist_path_encrypted(p->wal_path)) { + INFO("WAL/snapshot in %s is on encrypted storage", p->wal_path); + } else { + WARN("WAL/snapshot stored unencrypted in %s — " + "ensure filesystem is encrypted if job payloads contain " + "sensitive data", + p->wal_path); + } return 0; } diff --git a/src/controller/testsuite/controller_test.c b/src/controller/testsuite/controller_test.c index 7ed4fe79..22cf59f1 100644 --- a/src/controller/testsuite/controller_test.c +++ b/src/controller/testsuite/controller_test.c @@ -85,6 +85,8 @@ extern void test_wal_job_dispatch_fact(void); extern void test_wal_job_start_fact(void); extern void test_wal_job_finish_fact(void); extern void test_wal_job_fail_fact(void); +extern void test_phase2_cold_boot(void); +extern void test_persist_encryption(void); extern void test_config_queue_reconcile(void); extern void test_wal_job_rusage_fact(void); extern void test_wal_job_ckpt_fact(void); @@ -272,6 +274,8 @@ int main(int argc, char* argv[]) TEST(test_wal_job_start_fact); TEST(test_wal_job_finish_fact); TEST(test_wal_job_fail_fact); + TEST(test_phase2_cold_boot); + TEST(test_persist_encryption); TEST(test_config_queue_reconcile); TEST(test_wal_job_rusage_fact); TEST(test_wal_job_ckpt_fact); diff --git a/src/controller/testsuite/test_persist_encryption.c b/src/controller/testsuite/test_persist_encryption.c new file mode 100644 index 00000000..7cecb254 --- /dev/null +++ b/src/controller/testsuite/test_persist_encryption.c @@ -0,0 +1,115 @@ +/* + * test_persist_encryption.c -- bug-1877: persist_init() warned "WAL/snapshot + * stored unencrypted" on every start without looking, so the warning also + * fired on encrypted storage. persist_dev_is_dmcrypt() now checks the WAL's + * block device in sysfs for a dm-crypt (LUKS) layer, directly or under LVM + * (via `slaves`); the warning stays for storage it cannot show is encrypted. + */ +#include +#include +#include +#include +#include +#include + +#include + +#include "persist.h" + +static char g_sysfs[256]; + +static void mkdirs(const char* rel) +{ + char path[512]; + char cmd[640]; + + snprintf(path, sizeof(path), "%s/%s", g_sysfs, rel); + snprintf(cmd, sizeof(cmd), "mkdir -p '%s'", path); + TEST_ASSERT_EQUAL_INT(0, system(cmd)); +} + +static void put(const char* rel, const char* text) +{ + char path[512]; + FILE* fp; + + snprintf(path, sizeof(path), "%s/%s", g_sysfs, rel); + fp = fopen(path, "w"); + TEST_ASSERT_NOT_NULL(fp); + fputs(text, fp); + fclose(fp); +} + +static void fake_sysfs(void) +{ + char cmd[300]; + + snprintf(g_sysfs, sizeof(g_sysfs), "/tmp/test_persist_enc.%d", (int)getpid()); + snprintf(cmd, sizeof(cmd), "rm -rf %s", g_sysfs); + TEST_ASSERT_EQUAL_INT(0, system(cmd)); + + /* 259:2 nvme0n1p2, a plain partition */ + mkdirs("dev/block/259:2"); + mkdirs("class/block/nvme0n1p2"); + put("class/block/nvme0n1p2/dev", "259:2\n"); + /* 253:0 dm-0 = LUKS on nvme0n1p2 */ + mkdirs("dev/block/253:0/dm"); + mkdirs("dev/block/253:0/slaves/nvme0n1p2"); + put("dev/block/253:0/dm/uuid", "CRYPT-LUKS2-0123abcd-luks-0123\n"); + mkdirs("class/block/dm-0"); + put("class/block/dm-0/dev", "253:0\n"); + /* 253:1 dm-1 = LVM volume on dm-0 */ + mkdirs("dev/block/253:1/dm"); + mkdirs("dev/block/253:1/slaves/dm-0"); + put("dev/block/253:1/dm/uuid", "LVM-abcdefabcdef\n"); + /* 253:2 dm-2 = LVM volume straight on the plain partition */ + mkdirs("dev/block/253:2/dm"); + mkdirs("dev/block/253:2/slaves/nvme0n1p2"); + put("dev/block/253:2/dm/uuid", "LVM-fedcbafedcba\n"); +} + +static void drop_sysfs(void) +{ + char cmd[300]; + + snprintf(cmd, sizeof(cmd), "rm -rf %s", g_sysfs); + TEST_ASSERT_EQUAL_INT(0, system(cmd)); +} + +static void test_luks_device_is_encrypted(void) +{ + fake_sysfs(); + TEST_ASSERT_EQUAL_INT(1, persist_dev_is_dmcrypt(g_sysfs, 253, 0)); + drop_sysfs(); +} + +static void test_lvm_on_luks_is_encrypted(void) +{ + fake_sysfs(); + TEST_ASSERT_EQUAL_INT(1, persist_dev_is_dmcrypt(g_sysfs, 253, 1)); + drop_sysfs(); +} + +static void test_plain_partition_and_plain_lvm_are_not(void) +{ + fake_sysfs(); + TEST_ASSERT_EQUAL_INT(0, persist_dev_is_dmcrypt(g_sysfs, 259, 2)); + TEST_ASSERT_EQUAL_INT(0, persist_dev_is_dmcrypt(g_sysfs, 253, 2)); + drop_sysfs(); +} + +static void test_unknown_device_is_not_claimed_encrypted(void) +{ + fake_sysfs(); + TEST_ASSERT_EQUAL_INT(0, persist_dev_is_dmcrypt(g_sysfs, 8, 99)); + drop_sysfs(); +} + +void test_persist_encryption(void) +{ + UnitySetTestFile(__FILE__); + RUN_TEST(test_luks_device_is_encrypted); + RUN_TEST(test_lvm_on_luks_is_encrypted); + RUN_TEST(test_plain_partition_and_plain_lvm_are_not); + RUN_TEST(test_unknown_device_is_not_claimed_encrypted); +} diff --git a/src/controller/testsuite/test_phase2_cold_boot.c b/src/controller/testsuite/test_phase2_cold_boot.c new file mode 100644 index 00000000..053fb662 --- /dev/null +++ b/src/controller/testsuite/test_phase2_cold_boot.c @@ -0,0 +1,40 @@ +/* + * test_phase2_cold_boot.c -- bug-1876: while a standby waits for the + * primary's config push, cluster_init_phase2() has nothing to build yet. + * That is the normal cold-boot state, but it returned -EINVAL, and its + * callers logged it as a WARN ("cluster_init_phase2 on standby rejoin + * failed (rc=-22)") every 3 s until the config arrived. It now returns + * -EAGAIN, which the callers log at INFO. + */ +#include +#include + +#include + +#include "cluster.h" +#include "ha.h" +#include "myconf.h" +#include "xce/cluster_def.h" + +extern int cluster_init_phase2(cluster_t* c); + +static void test_phase2_without_config_is_a_wait_not_an_error(void) +{ + cluster_t c; + myconf_t conf; + + memset(&c, 0, sizeof(c)); + memset(&conf, 0, sizeof(conf)); + c.myconf = &conf; /* cluster_config not pushed yet */ + + TEST_ASSERT_EQUAL_INT(-EAGAIN, cluster_init_phase2(&c)); + TEST_ASSERT_TRUE(ha_phase2_rc_is_waiting(-EAGAIN)); + TEST_ASSERT_FALSE(ha_phase2_rc_is_waiting(-EINVAL)); + TEST_ASSERT_FALSE(ha_phase2_rc_is_waiting(0)); +} + +void test_phase2_cold_boot(void) +{ + UnitySetTestFile(__FILE__); + RUN_TEST(test_phase2_without_config_is_a_wait_not_an_error); +} diff --git a/src/frontend/apiserver/middleware/startserver.go b/src/frontend/apiserver/middleware/startserver.go index 9c47f61f..02bd6afb 100644 --- a/src/frontend/apiserver/middleware/startserver.go +++ b/src/frontend/apiserver/middleware/startserver.go @@ -1,6 +1,7 @@ package middleware import ( + "apiserver/backend/auth" "apiserver/utils" logger "apiserver/utils" "fmt" @@ -14,6 +15,16 @@ import ( "go.uber.org/zap" ) +// rootWarning is the start-up warning for running as uid under the given +// auth provider, or "" when there is nothing to warn about: only the PAM +// provider needs root (bug-1875: this warned for every provider). +func rootWarning(uid, provider string) string { + if uid == "0" || provider != "pam" { + return "" + } + return "Not running as root — PAM authentication will not work. OK for dev/testing." +} + // openssl req -x509 -nodes -days 365 -newkey rsa:2048 -keyout server.key -out server.crt -config openssl.cnf -extensions v3_req func StartServer(r *gin.Engine) error { logger.Debug("Enter StartServer() function") @@ -24,8 +35,12 @@ func StartServer(r *gin.Engine) error { logger.Error("Failed to get current user:", zap.Error(err)) os.Exit(1) } - if currentUser.Uid != "0" { - logger.Warn("Not running as root — PAM authentication will not work. OK for dev/testing.") + provider := "" + if auth.GlobalProvider != nil { + provider = auth.GlobalProvider.Name() + } + if msg := rootWarning(currentUser.Uid, provider); msg != "" { + logger.Warn(msg) } } diff --git a/src/frontend/apiserver/middleware/startserver_test.go b/src/frontend/apiserver/middleware/startserver_test.go new file mode 100644 index 00000000..9040996d --- /dev/null +++ b/src/frontend/apiserver/middleware/startserver_test.go @@ -0,0 +1,25 @@ +package middleware + +import "testing" + +// bug-1875: the apiserver warned "Not running as root — PAM authentication +// will not work" on every non-root start, even with the default +// provider: config_file, where PAM is never used. +func TestRootWarning(t *testing.T) { + cases := []struct { + uid, provider string + warn bool + }{ + {"1000", "pam", true}, + {"0", "pam", false}, + {"1000", "config_file", false}, + {"1000", "ldap", false}, + {"1000", "", false}, + } + for _, c := range cases { + got := rootWarning(c.uid, c.provider) + if (got != "") != c.warn { + t.Errorf("rootWarning(%q, %q) = %q, want warning=%v", c.uid, c.provider, got, c.warn) + } + } +} diff --git a/src/include/persist.h b/src/include/persist.h index 8f95d428..c37cb62d 100644 --- a/src/include/persist.h +++ b/src/include/persist.h @@ -1695,3 +1695,11 @@ int persist_load_snapshot(persist_t* p, const char* path, uint64_t lsn, bool job_is_terminal(const job_t* j); bool job_should_retain(const job_t* j, const persist_config_t* cfg); bool worker_should_retain(const xce_worker_t* w, const persist_config_t* cfg); + +/* bug-1877: is the WAL's storage encrypted? persist_dev_is_dmcrypt() walks + * /dev/block/: (and its `slaves`, for LVM on LUKS) for a + * dm-crypt layer (dm/uuid "CRYPT-..."); persist_path_encrypted() also + * accepts an fscrypt-encrypted directory (statx STATX_ATTR_ENCRYPTED). + * Both return 1 when encrypted, 0 when not shown to be. */ +int persist_dev_is_dmcrypt(const char* sysfs, unsigned maj, unsigned min); +int persist_path_encrypted(const char* path); diff --git a/src/scheduler/include/plugin.h b/src/scheduler/include/plugin.h index c935910d..87312b0e 100644 --- a/src/scheduler/include/plugin.h +++ b/src/scheduler/include/plugin.h @@ -99,6 +99,12 @@ typedef struct { * matching) reads `core`, never `sched`, so it works identically * whichever registration path registered it. */ xce_sched_core_t* core; + /* bug-1874: set by plugin_register() when it adapted a job_elect_fn-only + * plugin via the legacy wrapper; the deprecation is reported (once, + * legacy_picker_warned) when such a plugin is SELECTED as the picker, + * not merely registered. */ + int legacy_picker; + int legacy_picker_warned; } xce_sched_plugin_t; extern int plugin_register(void*, void*); diff --git a/src/scheduler/src/plugin.c b/src/scheduler/src/plugin.c index 5a260e6e..3d17be39 100644 --- a/src/scheduler/src/plugin.c +++ b/src/scheduler/src/plugin.c @@ -146,11 +146,11 @@ int plugin_register(void* arg1, void* arg2) * registration time (Req 5 "Migration from old job_elect_fn"). A * plugin that already provides picker_iface is left untouched. */ if ((plugin->picker_iface == NULL) && (plugin->job_elect_fn != NULL)) { - plugin->picker_iface = &legacy_picker_wrapper_iface; - WARN("plugin '%s' selects jobs via the deprecated job_elect_fn " - "hook; migrate to xce_job_picker_iface_t (scheduler-core spec, " - "Req 5 'Migration from old job_elect_fn')", - plugin->name); + plugin->picker_iface = &legacy_picker_wrapper_iface; + plugin->legacy_picker = 1; + /* bug-1874: no warning here -- the legacy "xce_sched_fcfs" is + * registered on every start but is not the normal-mode picker; + * sched_resolve_job_picker() warns when one is actually selected. */ } if (plugin->init_fn != NULL) { diff --git a/src/scheduler/src/schedobj.c b/src/scheduler/src/schedobj.c index b8cc143b..bc812cce 100644 --- a/src/scheduler/src/schedobj.c +++ b/src/scheduler/src/schedobj.c @@ -440,6 +440,14 @@ int sched_resolve_job_picker(xce_sched_core_t* core, xce_sched_plugin_t** out) return -EINVAL; } + if (plugin->legacy_picker && !plugin->legacy_picker_warned) { + plugin->legacy_picker_warned = 1; + WARN("job picker '%s' selects jobs via the deprecated job_elect_fn " + "hook; migrate to xce_job_picker_iface_t (scheduler-core spec, " + "Req 5 'Migration from old job_elect_fn')", + plugin->name); + } + *out = plugin; return 0; diff --git a/src/scheduler/testsuite/test_picker_wiring.c b/src/scheduler/testsuite/test_picker_wiring.c index 2a1017b3..7f692801 100644 --- a/src/scheduler/testsuite/test_picker_wiring.c +++ b/src/scheduler/testsuite/test_picker_wiring.c @@ -375,6 +375,33 @@ static void test_registered_but_not_a_picker_fails_with_einval_not_enoent(void) TEST_ASSERT_NULL(resolved); } +/* bug-1874: plugin_register() warned about the deprecated job_elect_fn hook + * for every legacy plugin it wrapped -- so the legacy "xce_sched_fcfs", + * registered on every scheduler start but never the normal-mode picker + * (builtin_fcfs is), logged a deprecation WARN on every start. The warning + * belongs to selecting such a plugin as the picker, and only once. */ +static void +test_legacy_picker_deprecation_flagged_on_selection_not_registration(void) +{ + xce_scheduler_t sched; + xce_sched_plugin_t* legacy = NULL; + xce_sched_plugin_t* resolved = NULL; + + fixture_init(&sched); + legacy = make_legacy_plugin("legacy_picker_1874"); + TEST_ASSERT_GREATER_OR_EQUAL(0, plugin_register(&sched, legacy)); + TEST_ASSERT_NOT_NULL_MESSAGE(legacy->picker_iface, + "still adapted to the picker interface"); + TEST_ASSERT_FALSE_MESSAGE(legacy->legacy_picker_warned, + "registration alone must not warn"); + + sched.core.job_pick_plugin = "legacy_picker_1874"; + TEST_ASSERT_EQUAL_INT(0, sched_resolve_job_picker(&sched.core, &resolved)); + TEST_ASSERT_EQUAL_PTR(legacy, resolved); + TEST_ASSERT_TRUE_MESSAGE(legacy->legacy_picker_warned, + "selecting it as the picker warns"); +} + /* Unset job_pick_plugin, and the caller never called * sched_set_default_job_pick_plugin() either -- -EINVAL (scheduler.h's * documented contract), distinct from both cases above. */ @@ -504,5 +531,7 @@ int main(void) RUN_TEST( test_resolved_builtin_fcfs_has_job_elect_fn_null_selecting_native_branch); RUN_TEST(test_legacy_and_native_pickers_coexist_and_resolve_independently); + RUN_TEST( + test_legacy_picker_deprecation_flagged_on_selection_not_registration); return UNITY_END(); } diff --git a/src/scheduler/testsuite/test_plugin_picker_registration.c b/src/scheduler/testsuite/test_plugin_picker_registration.c index 8af078ac..3c8acc6f 100644 --- a/src/scheduler/testsuite/test_plugin_picker_registration.c +++ b/src/scheduler/testsuite/test_plugin_picker_registration.c @@ -139,10 +139,13 @@ static void legacy_plugin_init(xce_sched_plugin_t* plugin, char* name) } /* Req 5 "Migration from old job_elect_fn": an old-style, job_elect_fn-only - * plugin registers successfully via the compatibility wrapper and logs a - * deprecation warning exactly once, at registration time. */ + * plugin registers successfully via the compatibility wrapper. bug-1874: + * registration itself no longer warns -- the legacy "xce_sched_fcfs" is + * registered on every start without being the picker; the deprecation is + * reported when such a plugin is selected (sched_resolve_job_picker(), see + * test_picker_wiring.c). */ static void -test_register_legacy_job_elect_fn_only_plugin_uses_wrapper_and_warns(void) +test_register_legacy_job_elect_fn_only_plugin_uses_wrapper_without_warning(void) { xce_scheduler_t sched; xce_sched_plugin_t plugin; @@ -156,7 +159,9 @@ test_register_legacy_job_elect_fn_only_plugin_uses_wrapper_and_warns(void) stop_log_capture(); TEST_ASSERT_GREATER_OR_EQUAL(0, rc); - TEST_ASSERT_EQUAL_INT(1, g_warn_count); + TEST_ASSERT_EQUAL_INT(0, g_warn_count); + TEST_ASSERT_TRUE(plugin.legacy_picker); + TEST_ASSERT_FALSE(plugin.legacy_picker_warned); TEST_ASSERT_NOT_NULL(plugin.picker_iface); TEST_ASSERT_EQUAL_PTR(&legacy_picker_wrapper_iface, plugin.picker_iface); } @@ -243,7 +248,7 @@ int main(void) { UNITY_BEGIN(); RUN_TEST( - test_register_legacy_job_elect_fn_only_plugin_uses_wrapper_and_warns); + test_register_legacy_job_elect_fn_only_plugin_uses_wrapper_without_warning); RUN_TEST(test_legacy_wrapper_next_job_calls_job_elect_fn); RUN_TEST( test_register_new_style_picker_plugin_skips_wrapper_and_does_not_warn); diff --git a/src/worker/include/diskstats.h b/src/worker/include/diskstats.h new file mode 100644 index 00000000..602ec079 --- /dev/null +++ b/src/worker/include/diskstats.h @@ -0,0 +1,64 @@ +#pragma once +/* + * diskstats.h -- sum the sector counters of the physical disks listed in + * /proc/diskstats (node_information.c's io metric). + */ +#include +#include +#include + +/* A whole physical disk has /sys/block//device (a link to its + * hardware). Partitions are not in /sys/block, and loop, ram, zram, dm- + * and md devices have no `device` -- counting dm/md would also count the + * same I/O twice, once more through their member disks. */ +static inline int diskstats_is_physical(const char* sysblock, const char* name) +{ + char path[512]; + struct stat st; + + if (strchr(name, '/') != NULL || name[0] == '.') { + return 0; + } + snprintf(path, sizeof(path), "%s/%s/device", sysblock, name); + return stat(path, &st) == 0; +} + +/* Sum sectors read/written over the physical disks in `fp` (a + * /proc/diskstats stream). `sysblock` is the /sys/block directory. + * Returns the number of disks counted. + * + * bug-1872: this used to guess from the name (skip names ending in a digit + * or containing 'p'), which dropped every NVMe disk (nvme0n1), mmc disks + * (mmcblk0) and even sdp. */ +static inline int diskstats_sum_physical(FILE* fp, const char* sysblock, + unsigned long long* sectors_read, + unsigned long long* sectors_written) +{ + char line[512]; + int ndisks = 0; + + *sectors_read = 0; + *sectors_written = 0; + + while (fgets(line, sizeof(line), fp)) { + int major, minor; + char name[64]; + unsigned long long rc, rm, rd, rt, wc, wm, wr, wt, inprog, iot, wiot; + + if (sscanf(line, + "%d %d %63s %llu %llu %llu %llu %llu %llu %llu %llu %llu " + "%llu %llu", + &major, &minor, name, &rc, &rm, &rd, &rt, &wc, &wm, &wr, &wt, + &inprog, &iot, &wiot) + < 14) { + continue; + } + if (!diskstats_is_physical(sysblock, name)) { + continue; + } + *sectors_read += rd; + *sectors_written += wr; + ndisks++; + } + return ndisks; +} diff --git a/src/worker/src/node_information.c b/src/worker/src/node_information.c index c3cb7bba..5df3aec9 100644 --- a/src/worker/src/node_information.c +++ b/src/worker/src/node_information.c @@ -1,4 +1,5 @@ #include "node_information.h" +#include "diskstats.h" #include "xcelog.h" #include #include @@ -888,7 +889,6 @@ static int read_disk_io_rate(double* io_rate) static time_t last_read_time = 0; FILE* fp; - char line[512]; unsigned long long total_read_sectors = 0, total_write_sectors = 0; unsigned long long prev_total, current_total, sector_diff; time_t current_time = time(NULL); @@ -906,50 +906,21 @@ static int read_disk_io_rate(double* io_rate) return -1; } - // Parse /proc/diskstats to accumulate I/O statistics for all physical disks - while (fgets(line, sizeof(line), fp)) { - int major, minor; - char device_name[64]; - unsigned long long reads_completed, reads_merged, sectors_read, - read_time; - unsigned long long writes_completed, writes_merged, sectors_written, - write_time; - unsigned long long ios_in_progress, total_ios_time, weighted_ios_time; - - // Parse diskstats line format - int parsed = sscanf( - line, - "%d %d %s %llu %llu %llu %llu %llu %llu %llu %llu %llu %llu %llu", - &major, &minor, device_name, &reads_completed, &reads_merged, - §ors_read, &read_time, &writes_completed, &writes_merged, - §ors_written, &write_time, &ios_in_progress, &total_ios_time, - &weighted_ios_time); - - if (parsed >= 14) { - // Only count physical disks (skip partitions and virtual devices) - // Physical disks typically have names like sda, sdb, hda, etc. (no - // numbers at end) Skip loop devices, ram disks, and partitions - if (strncmp(device_name, "loop", 4) == 0 - || strncmp(device_name, "ram", 3) == 0 - || strncmp(device_name, "dm-", 3) == 0 - || strstr(device_name, "p") != NULL - || // nvme partitions (nvme0n1p1) - (strlen(device_name) > 3 - && device_name[strlen(device_name) - 1] >= '0' - && device_name[strlen(device_name) - 1] <= '9')) { - continue; - } - - total_read_sectors += sectors_read; - total_write_sectors += sectors_written; - found_disk = 1; - } - } + /* bug-1872: physical disks are decided by /sys/block, not by name */ + found_disk = diskstats_sum_physical(fp, "/sys/block", &total_read_sectors, + &total_write_sectors); fclose(fp); if (!found_disk) { - XCECD_LOG(XCE_LOG_ERROR, - "Failed to find any disk statistics in /proc/diskstats"); + /* nothing to measure on this host; say so once, not every 15 s */ + static int warned = 0; + + if (!warned) { + XCECD_LOG(XCE_LOG_WARN, + "No physical disk found in /proc/diskstats " + "(/sys/block//device); io will not be reported"); + warned = 1; + } return -1; } diff --git a/src/worker/src/xcecd.c b/src/worker/src/xcecd.c index 6ae86b25..8dbc7ebd 100644 --- a/src/worker/src/xcecd.c +++ b/src/worker/src/xcecd.c @@ -156,7 +156,8 @@ void xcecd_process_command(void* arg) } if (pid < 0) { - XCECD_LOG(XCE_LOG_ERROR, "Failed to get worker pid"); + XCECD_LOG(XCE_LOG_ERROR, "Failed to get worker pid of %s after %d " + "retries", unit_name, retry); xcecd_job_start_error(ctx->xce_jobid); return; diff --git a/src/worker/src/xcecd_dbus_manager.c b/src/worker/src/xcecd_dbus_manager.c index fbe4daaa..259902e1 100644 --- a/src/worker/src/xcecd_dbus_manager.c +++ b/src/worker/src/xcecd_dbus_manager.c @@ -136,7 +136,10 @@ pid_t dbus_get_worker_pid(const char* unit_name) pid_t pid = get_systemd_job_pid(unit_name); if (pid <= 0) { - XCECD_LOG(XCE_LOG_WARN, "Failed to get worker pid"); + /* bug-1873: MainPID reads 0 until systemd has forked the unit just + * started, so a miss here is expected and the caller (xcecd.c) + * retries; it logs the real failure once its retries run out. */ + XCECD_LOG(XCE_LOG_DEBUG, "worker pid of %s not known yet", unit_name); return -1; } diff --git a/src/worker/testsuite/meson.build b/src/worker/testsuite/meson.build index bc4bcc1a..d4b9d495 100644 --- a/src/worker/testsuite/meson.build +++ b/src/worker/testsuite/meson.build @@ -206,3 +206,16 @@ test('worker xcecd_tmpfile test', xcecd_tmpfile_test, suite: 'worker', timeout: 60, env: ['ASAN_OPTIONS=detect_leaks=0']) + +# bug-1872: which /proc/diskstats lines are physical disks (diskstats.h); +# NVMe and mmc disks were never counted. +diskstats_test = executable('diskstats_test', + 'test_diskstats.c', + include_directories: [worker_test_incdir], + dependencies: worker_test_deps, + install: false) + +test('worker diskstats test', diskstats_test, + suite: 'worker', + timeout: 60, + env: ['ASAN_OPTIONS=detect_leaks=0']) diff --git a/src/worker/testsuite/test_diskstats.c b/src/worker/testsuite/test_diskstats.c new file mode 100644 index 00000000..164da1d7 --- /dev/null +++ b/src/worker/testsuite/test_diskstats.c @@ -0,0 +1,139 @@ +/* + * test_diskstats.c -- which /proc/diskstats lines count as physical disks + * (diskstats.h). The old filter skipped any name ending in a digit or + * containing 'p', so a host whose only disks are NVMe (nvme0n1) reported + * no disk at all and logged an ERROR every 15 s. + */ +#include +#include +#include +#include +#include +#include + +#include + +#include "diskstats.h" + +static char sysblock[256]; + +static void make_disk(const char* name, int physical) +{ + char path[512]; + + snprintf(path, sizeof(path), "%s/%s", sysblock, name); + TEST_ASSERT_EQUAL_INT(0, mkdir(path, 0755)); + if (physical) { + /* a real disk has a `device` link to its hardware; loop, dm-, md, + * zram and ram devices have none, and partitions are not listed + * in /sys/block at all */ + snprintf(path, sizeof(path), "%s/%s/device", sysblock, name); + TEST_ASSERT_EQUAL_INT(0, mkdir(path, 0755)); + } +} + +void setUp(void) +{ + snprintf(sysblock, sizeof(sysblock), "/tmp/test_diskstats.%d", (int)getpid()); + TEST_ASSERT_EQUAL_INT(0, mkdir(sysblock, 0755)); +} + +void tearDown(void) +{ + char cmd[300]; + + snprintf(cmd, sizeof(cmd), "rm -rf %s", sysblock); + TEST_ASSERT_EQUAL_INT(0, system(cmd)); +} + +static FILE* diskstats(const char* text) +{ + FILE* fp = fmemopen((void*)text, strlen(text), "r"); + + TEST_ASSERT_NOT_NULL(fp); + return fp; +} + +/* pc13v's /proc/diskstats (2026-09-28): one NVMe disk, its partitions, + * and idle loop devices. */ +static const char PC13V[] = + " 259 0 nvme0n1 152421 98489 7165957 15288 250739 83553 21142411 167803 0 37190 206665 0 0 0 0 190349 23574\n" + " 259 1 nvme0n1p1 177 2028 14619 16 13 0 11 0 0 10 17 0 0 0 0 0 0\n" + " 259 2 nvme0n1p2 152156 96461 7149330 15265 250723 83553 21142400 167802 0 43488 183067 0 0 0 0 0 0\n" + " 7 0 loop0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0\n" + " 7 1 loop1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0\n"; + +static void test_nvme_disk_is_counted_and_its_partitions_are_not(void) +{ + unsigned long long rd = 0, wr = 0; + FILE* fp; + + make_disk("nvme0n1", 1); + make_disk("loop0", 0); + make_disk("loop1", 0); + + fp = diskstats(PC13V); + TEST_ASSERT_EQUAL_INT(1, diskstats_sum_physical(fp, sysblock, &rd, &wr)); + fclose(fp); + TEST_ASSERT_EQUAL_UINT64(7165957ULL, rd); + TEST_ASSERT_EQUAL_UINT64(21142411ULL, wr); +} + +static void test_sd_mmc_and_names_with_p_are_disks_virtual_ones_are_not(void) +{ + static const char text[] = + " 8 0 sda 1 0 10 0 1 0 100 0 0 0 0\n" + " 8 1 sda1 1 0 5 0 1 0 50 0 0 0 0\n" + " 8 240 sdp 1 0 20 0 1 0 200 0 0 0 0\n" + " 179 0 mmcblk0 1 0 30 0 1 0 300 0 0 0 0\n" + " 179 1 mmcblk0p1 1 0 15 0 1 0 150 0 0 0 0\n" + " 253 0 dm-0 1 0 4000 0 1 0 4000 0 0 0 0\n" + " 9 0 md0 1 0 5000 0 1 0 5000 0 0 0 0\n"; + unsigned long long rd = 0, wr = 0; + FILE* fp; + + make_disk("sda", 1); + make_disk("sdp", 1); + make_disk("mmcblk0", 1); + make_disk("dm-0", 0); + make_disk("md0", 0); + + fp = diskstats(text); + TEST_ASSERT_EQUAL_INT(3, diskstats_sum_physical(fp, sysblock, &rd, &wr)); + fclose(fp); + TEST_ASSERT_EQUAL_UINT64(10ULL + 20 + 30, rd); + TEST_ASSERT_EQUAL_UINT64(100ULL + 200 + 300, wr); +} + +static void test_no_physical_disk_returns_zero(void) +{ + unsigned long long rd = 0, wr = 0; + FILE* fp; + + make_disk("loop0", 0); + fp = diskstats(" 7 0 loop0 0 0 0 0 0 0 0 0 0 0 0\n"); + TEST_ASSERT_EQUAL_INT(0, diskstats_sum_physical(fp, sysblock, &rd, &wr)); + fclose(fp); +} + +static void test_short_or_garbage_lines_are_skipped(void) +{ + unsigned long long rd = 0, wr = 0; + FILE* fp; + + make_disk("sda", 1); + fp = diskstats("garbage\n 8 0 sda 1 2\n 8 0 sda 1 0 10 0 1 0 100 0 0 0 0\n"); + TEST_ASSERT_EQUAL_INT(1, diskstats_sum_physical(fp, sysblock, &rd, &wr)); + fclose(fp); + TEST_ASSERT_EQUAL_UINT64(10ULL, rd); +} + +int main(void) +{ + UNITY_BEGIN(); + RUN_TEST(test_nvme_disk_is_counted_and_its_partitions_are_not); + RUN_TEST(test_sd_mmc_and_names_with_p_are_disks_virtual_ones_are_not); + RUN_TEST(test_no_physical_disk_returns_zero); + RUN_TEST(test_short_or_garbage_lines_are_skipped); + return UNITY_END(); +}