From 25e280735541091db960f69237a4cb0d39a135aa Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Sat, 3 Oct 2026 06:04:19 +0000 Subject: [PATCH] feat(controller-peers-env-fallback): flush the controller's log before every early exit (task 2.2) Co-Authored-By: Claude Opus 5.5 (1M context) --- .../controller-peers-env-fallback/tasks.md | 4 ++- src/controller/main.c | 9 +++++ src/tools/verify-controller-peers-env.sh | 35 +++++++++++++++++++ 3 files changed, 47 insertions(+), 1 deletion(-) diff --git a/.kiro/specs/controller-peers-env-fallback/tasks.md b/.kiro/specs/controller-peers-env-fallback/tasks.md index b1377df9..2aef5aea 100644 --- a/.kiro/specs/controller-peers-env-fallback/tasks.md +++ b/.kiro/specs/controller-peers-env-fallback/tasks.md @@ -29,7 +29,7 @@ - Done when the full controller suite (including the HA and listener tests) passes unchanged - _Requirements: 1.6_ -- [ ] 2.2 Flush the controller's log before every early exit +- [x] 2.2 Flush the controller's log before every early exit - Add a regression-script case first: a controller run with scratch work, certificate and log paths stops at the certificate pre-flight, and its last startup line (today's "No --peers flag" line) must already be in the log file. The loss is a race with the log's background writer, so the case repeats the run 20 times and fails if any run is missing the line; run it before the fix and record whether it failed (if no run fails, note that the race did not reproduce here and keep the case as a regression guard) - Flush the log before every early return after the log is opened: name lookup failure, lock init failure, `--peers` parse error, even candidate count, and the certificate pre-flight; flushing is a no-op before the log is opened and safe to repeat - Done when, after rebuilding the controller, the controller suite passes and that case shows the line in the log file in all 20 runs @@ -132,3 +132,5 @@ - (1.3 → 3.3) `start_bg`/`run_to_completion` feed stdin from `/dev/null`, but `xce_test` reads its script only from stdin; add an optional stdin file to `run_to_completion` (e.g. `RUN_STDIN`) rather than the `sh -c 'exec "$0" --norc <"$1"'` workaround. - (1.3 → 3.2) The worker's early "HA cluster config"/"No --peers flag" lines go to stdout before its log file is set up; confirm they are not stdio-buffered when stdout is a file (else `wait_for_line` on stdout times out while it runs) — wait for exit or use line buffering if so. - (1.3) Drop the file-wide `shellcheck disable=SC2329,SC2034` once cases call the helpers, so real unused-variable warnings surface. +- (2.2) The tlog early-exit race did not reproduce on this machine (0/20 before the fix, 0/200 ad hoc); `case_controller_log_flushed_on_early_exit` is kept as a regression guard, not proof of the fix. +- (2.2 → 2.3) That case matches the text "No --peers flag; running as single-node primary"; when 2.3 extends the line (1.8), keep that text intact or update the case's pattern. diff --git a/src/controller/main.c b/src/controller/main.c index 1fb1d81c..ed3faae3 100644 --- a/src/controller/main.c +++ b/src/controller/main.c @@ -392,6 +392,10 @@ int main(int argc, char* argv[]) mylog_init(logfile, loglevel, logsize, logcount); + /* tlog writes the log file from a background thread and has no atexit + * flush, so every early return below calls mylog_fini() (tlog_exit()) + * first; otherwise lines logged just before the return can be lost. */ + if (arguments.workdir == NULL) { INFO("no cluster work directory specified. The default work directory " "`" DEFAULT_WORKDIR "' will be used."); @@ -401,6 +405,7 @@ int main(int argc, char* argv[]) if (arguments.myname == NULL) { if (get_myname(myname, sizeof(myname) - 1) < 0) { ERROR("get_myname"); + mylog_fini(); return -1; } arguments.myname = myname; @@ -449,6 +454,7 @@ int main(int argc, char* argv[]) * cluster_run/myapp_run can ever call it. */ if (mylock_init(&myconf.lock) != 0) { ERROR("Failed to initialize myconf lock"); + mylog_fini(); return -1; } @@ -458,6 +464,7 @@ int main(int argc, char* argv[]) "xce_controller: --peers parse error: expected " "host:port,... got: %s\n", arguments.peers_str); + mylog_fini(); return 1; } @@ -468,6 +475,7 @@ int main(int argc, char* argv[]) "allowed; Raft quorum requires an odd number of nodes " "(1, 3, 5, ...)\n", myconf.peers_cfg.candidates_count); + mylog_fini(); return 1; } @@ -492,6 +500,7 @@ int main(int argc, char* argv[]) if (validate_cert_files(cert_file, key_file, cert_err, sizeof(cert_err)) != 0) { fprintf(stderr, "xce_controller: %s\n", cert_err); + mylog_fini(); return 1; } } diff --git a/src/tools/verify-controller-peers-env.sh b/src/tools/verify-controller-peers-env.sh index b7add110..f9c7b702 100755 --- a/src/tools/verify-controller-peers-env.sh +++ b/src/tools/verify-controller-peers-env.sh @@ -300,6 +300,41 @@ on_exit() { # them with add_case, in the order they should run. # ════════════════════════════════════════════════════════════════════════════ +# Task 2.2 (Req 1.3): the controller logs through tlog's background writer, +# so a line logged just before an early return is only in the log file if the +# return flushes the log first. With an empty --certdir and no --peers (and +# no XCE_CONTROLLER_PEERS) the controller stops at the certificate pre-flight +# right after its "No --peers flag" line. The loss is a race, so repeat the +# run and fail if any single run is missing the line. +FLUSH_RUNS=20 +case_controller_log_flushed_on_early_exit() { + local i d missing=0 + for i in $(seq 1 "$FLUSH_RUNS"); do + d="$(new_scratch controller-flush)" + mkdir -p "$d/work" "$d/certs" + run_to_completion "$d" 10 -u XCE_CONTROLLER_PEERS \ + "$CONTROLLER_BIN" --myname ctrl-flush --workdir "$d/work" \ + --certdir "$d/certs" --logfile "$d/controller.log" + if [ "$RUN_RC" -eq 0 ] || [ "$RUN_RC" -ge 124 ]; then + red " run $i: expected the certificate pre-flight to stop the controller, exit status $RUN_RC" + _show_tail "$d/stderr" + return 1 + fi + if ! grep -Eq -- 'No --peers flag; running as single-node primary' \ + "$d/controller.log" 2>/dev/null; then + missing=$((missing + 1)) + red " run $i: last startup line missing from $d/controller.log" + fi + done + if [ "$missing" -ne 0 ]; then + red " $missing/$FLUSH_RUNS run(s) lost the last startup line" + return 1 + fi + log " all $FLUSH_RUNS runs had the last startup line in the log file" +} +add_case case_controller_log_flushed_on_early_exit \ + "controller: log flushed before the certificate pre-flight exit ($FLUSH_RUNS runs)" + # ════════════════════════════════════════════════════════════════════════════ # main