diff --git a/.kiro/specs/controller-status/tasks.md b/.kiro/specs/controller-status/tasks.md index 1086531e..1a11f853 100644 --- a/.kiro/specs/controller-status/tasks.md +++ b/.kiro/specs/controller-status/tasks.md @@ -77,7 +77,7 @@ - _Requirements: 10.1, 10.2, 10.3, 10.4, 11.1_ - _Boundary: ctrlstatus_fill_ - _Depends: 6.1_ -- [ ] 6.3 Render the responder snapshot timestamp in the `ctrlstatus` client command +- [x] 6.3 Render the responder snapshot timestamp in the `ctrlstatus` client command - Add one printed line to `cmd_ctrlstatus` (`src/controller/testsuite/test.c`) rendering the responder snapshot timestamp as a local `YYYY-MM-DD HH:MM:SS,mmm` string in the same form the controller logger uses, so it can be compared directly against `ctrl-N.log`. Confirm and reuse (or match) the exact wall-clock formatter in `src/include/xcelog.h`. The committed lines need no rendering change — task 6.2 only changed their values. - Observable: piping `ctrlstatus` through the client prints a responder-timestamp line in the log timestamp format alongside the other status fields. - _Requirements: 11.2, 11.3_ @@ -102,3 +102,6 @@ - 2.1 LEARNING + SCHEMA AMENDMENT: capnp `Data` in THIS schema maps to the project's STRUCTURED `xce_data_t` union (table-switched), NOT raw bytes — `encode_Data_ptr` can't serialize a SHA-256 blob. So `configChecksum @6` was changed `Data → Text` (a 64-char lowercase-hex string of the full 32-byte `config_sha256`); typemap member is `char*`; freed in `ctrlstatus_free_fields`. Ordinal @6 unchanged, no released decoder yet → safe. Handler lives in NEW `src/controller/ctrlstatus.c` (`ctrlstatus_fill`/`ctrlstatus_free_fields`/`handle_ctrlstatus`), proto in `src/controller/include/cluster.h`, routed at `cluster.c` opcode switch, test `src/controller/testsuite/test_ctrlstatus.c` (registered in `controller_test.c`, built via `controller/meson.build`). `primary_host` read under `ha->lock`; peer name/host strings are BORROWED from myconf (not freed). The libxce client (3.x) decodes `configChecksum` as Text. - 3.1 LEARNING: the ctx-side reply union `xce_ctx_t.reply.u` (in `src/include/xcectx.h`) is SEPARATE from `xce_reply_t.data` (typemap.h) — the decode path needs BOTH a `ctrlstatus` member there AND a `case OPCode_ctrlstatus` in `xcectx.c` handle_reply (mirror clusterconf). Free: clusterconf's `xce_free_clusterconf` macro is a LATENT-BROKEN alias (undefined symbol, never expanded); use the REAL generated free — `xce_free_ctrlstatus(s) → free_CtrlStatus(s)`, `xcecli_free_ctrlstatus(s) → xce_free_ctrlstatus(s)` (any TU expanding it must include the generated `controller.capnp.h`). `xcecli_ctrlstatus` is is_write=false; NULL ctx → `-EINVAL`. - 3.2: `xcecli_ctrlstatus_primary` = bounded loop (cap `failover.retry.max_retries`) reusing `xcecli_ctrlstatus` + `xce_ctx_capture_redirect_hint` (map `primaryName`→addr via `peers[]`, else master rotation); authoritative iff `responderRole == CTRL_PRIMARY` (== 0; `ctrl_role_t` PRIMARY=0/STANDBY=1/INIT=2/ELECTING=3 in `ha.h` — REVALIDATION TRIGGER: a role-enum reorder breaks the pinned wire ordinal `XCECLI_CTRLSTATUS_ROLE_PRIMARY=0`). On exhaustion → `-E_XCE_NOT_READY`, `*status` untouched (never a hint). Pure helpers `xcecli_ctrlstatus_is_authoritative`/`_primary_addr` unit-tested; live standby→primary redirect is 5.1. +- 6.1: `responderTimeMs @13: UInt64` appended to `CtrlStatus` (after `peerCount @12`, append-only) + matching `uint64_t responder_time_ms` in the hand-authored `xce_ctrlstatus_t` (`src/include/typemap.h`); codec wire offset 48, round-trips. Commit 65ddafe. +- 6.2: `ctrlstatus_fill` role-branches committed sourcing — PRIMARY → own `persist.committed_lsn`/`committed_config_tag` (atomic acquire); else → `ha->last_known_committed_lsn` (atomic acquire) + `ha->last_known_committed_config_tag` (plain aligned read, NO `ha->lock` per design — `ha.h:172` is non-atomic, written under lock at `ha_convergence.c:377`). `appliedLsn` unchanged. Timestamp stamped from `CLOCK_REALTIME` (NOT monotonic). Read-only. STALENESS CAVEAT (in-boundary): `last_known_committed_lsn` refreshes at CtrlHello join/RDHUP, not per heartbeat — off-primary committed can lag; live-fresh = OUT of boundary → ha-heartbeat-liveness/ha-repl-hardening. Commit 3799bd6. +- 6.3 LEARNING: the controller log timestamp formatter is NOT in `xcelog.h` (an 85-line thin wrapper that just `#include "tlog.h"`); the `YYYY-MM-DD HH:MM:SS,mmm` prefix is assembled inline in vendored tinylog (`tlog.c` `_tlog_root_default_format` ~393/398, via `my_tlog_format` in `src/lib/utils.c:221/228`) — no caller-facing helper, so it was REPLICATED byte-equivalently (`localtime_r` + `strftime "%Y-%m-%d %H:%M:%S"` + `,%03u` of `ms%1000`) in a new header-only `src/controller/testsuite/ctrlstatus_fmt.h` (`ctrlstatus_format_time_ms`), shared by `test.c` (`cmd_ctrlstatus` prints `responderTime:` after `fenced`) and `test_ctrlstatus.c` (TZ=UTC-pinned exact-string unit test). LOCAL time on both sides — comparable to `ctrl-N.log` under the same TZ. diff --git a/src/controller/testsuite/ctrlstatus_fmt.h b/src/controller/testsuite/ctrlstatus_fmt.h new file mode 100644 index 00000000..842dbd12 --- /dev/null +++ b/src/controller/testsuite/ctrlstatus_fmt.h @@ -0,0 +1,61 @@ +#ifndef _CTRLSTATUS_FMT_H_ +#define _CTRLSTATUS_FMT_H_ + +/* ctrlstatus_fmt.h — render a responder snapshot timestamp (epoch-millis) in + * the EXACT wall-clock string the controller logger emits, so the test client's + * `ctrlstatus` output is byte-comparable against ctrl-N.log (controller-status + * task 6.3, Req 11.2/11.3). + * + * The tlog prefix (vendored tinylog, _tlog_root_default_format) is built inline + * as: + * + * snprintf(... "[%.4d-%.2d-%.2d %.2d:%.2d:%.2d,%.3d]...", + * tm->year, tm->mon, tm->mday, tm->hour, tm->min, tm->sec, + * tm->usec / 1000, ...); + * + * where the broken-down time comes from gettimeofday() + localtime_r() — i.e. + * LOCAL time, with sub-second precision rendered as zero-padded MILLISECONDS + * (usec / 1000). tlog exposes no reusable formatter for callers, so this helper + * REPLICATES that construction: localtime_r + strftime("%Y-%m-%d %H:%M:%S") + * (byte-identical to "%.4d-%.2d-%.2d %.2d:%.2d:%.2d") then ",%03u" for the + * millisecond fraction. Both the logger and this helper use local time, so the + * rendered value matches the log line under the same TZ. */ + +#include +#include +#include +#include + +/* Render `ms` (epoch milliseconds, e.g. xce_ctrlstatus_t.responder_time_ms) + * into `buf` as local-time "YYYY-MM-DD HH:MM:SS,mmm". Needs at least 24 bytes. + * Returns `buf` on success, NULL if buf is NULL / too small / time conversion + * fails. */ +static inline char* ctrlstatus_format_time_ms(uint64_t ms, char* buf, size_t n) +{ + /* "YYYY-MM-DD HH:MM:SS,mmm" + NUL == 24 bytes. */ + if (buf == NULL || n < 24) { + return NULL; + } + + time_t secs = (time_t)(ms / 1000u); + unsigned msec = (unsigned)(ms % 1000u); + struct tm tm; + + if (localtime_r(&secs, &tm) == NULL) { + return NULL; + } + + char datetime[20]; /* "YYYY-MM-DD HH:MM:SS" + NUL */ + if (strftime(datetime, sizeof(datetime), "%Y-%m-%d %H:%M:%S", &tm) == 0) { + return NULL; + } + + /* Match tlog's ",%.3d" millisecond fraction (zero-padded to 3 digits). */ + if (snprintf(buf, n, "%s,%03u", datetime, msec) < 0) { + return NULL; + } + + return buf; +} + +#endif /* _CTRLSTATUS_FMT_H_ */ diff --git a/src/controller/testsuite/test.c b/src/controller/testsuite/test.c index c4e5ec90..4c33728a 100644 --- a/src/controller/testsuite/test.c +++ b/src/controller/testsuite/test.c @@ -18,6 +18,7 @@ #include "client.h" #include "config.h" /* XCE_MAXNAME_LEN */ #include "controller.capnp.h" +#include "ctrlstatus_fmt.h" /* ctrlstatus_format_time_ms (task 6.3) */ #include "delay.h" #include "idgen.h" #include "preason.h" @@ -1334,6 +1335,20 @@ int cmd_ctrlstatus(int argc, char* argv[]) printf("appliedLsn: %llu\n", (unsigned long long)status->appliedLsn); printf("fenced: %s\n", status->fenced ? "true" : "false"); + /* Responder snapshot timestamp (Req 11.2/11.3): render the responder's + * sample-time wall clock (epoch ms) in the SAME local-time + * "YYYY-MM-DD HH:MM:SS,mmm" form the controller logger emits, so it can be + * compared directly against ctrl-N.log. */ + { + char tbuf[64]; + if (ctrlstatus_format_time_ms(status->responder_time_ms, tbuf, + sizeof(tbuf)) != NULL) { + printf("responderTime: %s\n", tbuf); + } else { + printf("responderTime: unknown\n"); + } + } + xcecli_free_ctrlstatus(status); return 0; diff --git a/src/controller/testsuite/test_ctrlstatus.c b/src/controller/testsuite/test_ctrlstatus.c index d8b67800..23015be6 100644 --- a/src/controller/testsuite/test_ctrlstatus.c +++ b/src/controller/testsuite/test_ctrlstatus.c @@ -8,7 +8,9 @@ * 5.1, 5.2, 5.3, 6.1, 6.2, 6.3, 6.4. */ #include +#include #include +#include /* setenv */ #include #include @@ -20,6 +22,8 @@ #include "persist.h" #include "xce/cluster_def.h" +#include "ctrlstatus_fmt.h" /* ctrlstatus_format_time_ms (task 6.3) */ + /* ── helpers ────────────────────────────────────────────────── */ static ha_config_t cs_valid_cfg(void) @@ -474,10 +478,41 @@ static void test_ctrlstatus_responder_time_ms(void) printf("test_ctrlstatus_responder_time_ms: PASS\n"); } +/* (j) Responder snapshot timestamp rendering (Req 11.2, 11.3): the test client + * renders responder_time_ms (epoch-millis) into the SAME wall-clock string the + * controller logger (tlog) emits — local-time "YYYY-MM-DD HH:MM:SS,mmm" — so it + * is byte-comparable against ctrl-N.log. Pin TZ=UTC for determinism, then assert + * the exact rendered string for a known epoch-millis. */ +static void test_ctrlstatus_format_time_ms(void) +{ + setenv("TZ", "UTC", 1); + tzset(); + + /* 1781939830000 ms == 2026-06-20 07:17:10 UTC; +911 ms of fractional part. + * Renders local time (TZ=UTC) in the tlog prefix shape "%.4d-%.2d-%.2d + * %.2d:%.2d:%.2d,%.3d". */ + char buf[64]; + uint64_t ms = UINT64_C(1781939830000) + 911u; + + char* ret = ctrlstatus_format_time_ms(ms, buf, sizeof(buf)); + + TEST_ASSERT_EQUAL_PTR(buf, ret); + TEST_ASSERT_EQUAL_STRING("2026-06-20 07:17:10,911", buf); + + /* zero-millis fractional part must still be zero-padded to 3 digits */ + char* ret2 = ctrlstatus_format_time_ms(UINT64_C(1781939830000), buf, + sizeof(buf)); + TEST_ASSERT_EQUAL_PTR(buf, ret2); + TEST_ASSERT_EQUAL_STRING("2026-06-20 07:17:10,000", buf); + + printf("test_ctrlstatus_format_time_ms: PASS\n"); +} + /* ── suite entry point ─────────────────────────────────────── */ void test_ctrlstatus(void) { + RUN_TEST(test_ctrlstatus_format_time_ms); RUN_TEST(test_ctrlstatus_primary); RUN_TEST(test_ctrlstatus_standby_known_primary); RUN_TEST(test_ctrlstatus_unknown_primary);