feat(controller-status): render responderTime in cmd_ctrlstatus, log-comparable format (task 6.3)

Add ctrlstatus_fmt.h (ctrlstatus_format_time_ms): renders responder_time_ms as
local YYYY-MM-DD HH:MM:SS,mmm, byte-equivalent to the controller log prefix
(tlog/my_tlog_format) so a captured ctrlstatus lines up against ctrl-N.log.
cmd_ctrlstatus prints a responderTime line; TZ-pinned exact-string unit test.
Req 11.2, 11.3. ctrlstatus group passes.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This commit is contained in:
Rongsong Shen 2026-06-20 09:28:49 +00:00
parent 3799bd6af4
commit ee30765d31
4 changed files with 115 additions and 1 deletions

View file

@ -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.

View file

@ -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 <stdint.h>
#include <stdio.h>
#include <string.h>
#include <time.h>
/* 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_ */

View file

@ -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;

View file

@ -8,7 +8,9 @@
* 5.1, 5.2, 5.3, 6.1, 6.2, 6.3, 6.4.
*/
#include <stdatomic.h>
#include <stdint.h>
#include <stdio.h>
#include <stdlib.h> /* setenv */
#include <string.h>
#include <time.h>
@ -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);