From 4e1e50709992ae72b2e64f0165876288c808f560 Mon Sep 17 00:00:00 2001 From: ysyneu Date: Mon, 15 Jun 2026 19:57:00 +0800 Subject: [PATCH] fix(provision): emit clean, definitive fduty self-update logs The success path logged head(out,300) of `fduty update`'s raw multi-line output, which surfaced in logs as literal `\n` escapes truncated mid-string (a colleague reported messy/cut-off logs). Replace it with single-line, definitive logging: - verifyFdutyOnPath now returns the resolved version line; ensureFdutyCLI passes the pre-update version into fdutySelfUpdate(prevVersion). - after a successful `fduty update`, re-read the version and log the actual outcome: "fduty CLI upgraded" from->to, or "already up to date". - the failure path logs the last output line (the real error) via lastLine instead of a truncated head. - firstLine/lastLine helpers replace the head() byte-truncator. --- cmd/provision.go | 89 +++++++++++++++++++++++++++++++------------ cmd/provision_test.go | 8 ++-- 2 files changed, 69 insertions(+), 28 deletions(-) diff --git a/cmd/provision.go b/cmd/provision.go index bcbd260..f73e9bb 100644 --- a/cmd/provision.go +++ b/cmd/provision.go @@ -67,7 +67,8 @@ func ensureFdutyCLI() { } } - if err := verifyFdutyOnPath(); err != nil { + version, err := verifyFdutyOnPath() + if err != nil { slog.Info("fduty CLI is NOT available on the bash PATH — the runner will start, "+ "but agent commands that call `fduty` will fail until you install it. To fix: place an "+ "executable `fduty` in the runner's tools dir ($FLASHDUTY_RUNNER_HOME/bin, default ~/.flashduty/bin) "+ @@ -77,7 +78,7 @@ func ensureFdutyCLI() { // fduty is present → keep it current via its OWN self-update, off the hot // path. No-op when already latest; all failures are swallowed. - fdutySelfUpdate() + fdutySelfUpdate(version) } // fdutySelfUpdate runs the CLI's built-in `fduty update`, which resolves the @@ -87,7 +88,7 @@ func ensureFdutyCLI() { // at the runner's own mirror when known (so a private/regional deployment // upgrades from where it was provisioned). Best-effort: a missing network, curl, // or write permission just logs and returns. -func fdutySelfUpdate() { +func fdutySelfUpdate(prevVersion string) { dir := environment.BundledToolsDir() if dir == "" { return @@ -111,10 +112,23 @@ func fdutySelfUpdate() { var out bytes.Buffer cmd.Stdout, cmd.Stderr = &out, &out if err := cmd.Run(); err != nil { - slog.Info("fduty self-update skipped (non-fatal)", "error", err, "output_head", head(out.String(), 300)) + slog.Info("fduty self-update skipped (non-fatal)", "error", err, "detail", lastLine(out.String())) return } - slog.Info("fduty self-update checked", "output_head", head(out.String(), 300)) + + // Log the definitive outcome by re-reading the resolved version, NOT a + // truncated slice of mid-install output (which read as "still installing" + // even after success). `fduty update` reinstalls in place, so the new version + // is authoritative for what agents will now run. + newVersion, verr := fdutyVersion() + switch { + case verr != nil: + slog.Info("fduty self-update finished (version re-check failed, non-fatal)", "error", verr) + case prevVersion != "" && newVersion != "" && newVersion != prevVersion: + slog.Info("fduty CLI upgraded", "from", prevVersion, "to", newVersion) + default: + slog.Info("fduty CLI already up to date", "version", newVersion) + } } // fdutyUpdateBaseURL derives the mirror base `fduty update` should pull from, so @@ -246,36 +260,61 @@ func installFdutyFromCDN(dir, target string) error { return nil } -// verifyFdutyOnPath runs `fduty version` through the EXACT environment the bash -// tool uses (environment.BashToolEnv: secrets scrubbed, bundled-tools dir first -// on PATH) and asserts exit 0. This is the load-bearing gate: it catches the -// real failure mode — fduty installed somewhere that is not on the bash PATH, so -// bare `fduty` 127s at agent call time — which a plain os.Stat would miss. -func verifyFdutyOnPath() error { +// fdutyVersion runs `fduty version` through the EXACT environment the bash tool +// uses (environment.BashToolEnv: secrets scrubbed, bundled-tools dir first on +// PATH) and returns its first output line. We resolve `fduty` through bash +// exactly like the bash tool does (`bash -c `); running +// exec.Command("fduty", ...) directly would let Go's LookPath resolve against the +// PARENT process PATH, ignoring cmd.Env and missing the bundled-tools dir. A +// non-nil error means fduty is not usable on the bash PATH (bare `fduty` 127s at +// agent call time) — which a plain os.Stat would miss. +func fdutyVersion() (string, error) { ctx, cancel := context.WithTimeout(context.Background(), 15*time.Second) defer cancel() - // Resolve `fduty` through bash exactly like the bash tool does - // (environment.executeBashCommand runs `bash -c `). We must NOT run - // exec.Command("fduty", ...) directly: Go's LookPath resolves the program - // against the PARENT process PATH, ignoring cmd.Env — so it would miss the - // bundled-tools dir and not mirror the real call-time resolution. cmd := exec.CommandContext(ctx, "bash", "-c", "fduty version") cmd.Env = environment.BashToolEnv() var out bytes.Buffer cmd.Stdout, cmd.Stderr = &out, &out if err := cmd.Run(); err != nil { - return fmt.Errorf("fduty CLI self-check failed (`fduty version` did not exit 0 on the bash PATH; "+ - "agent CLI calls would 127): %w; output: %s", err, out.String()) + return "", fmt.Errorf("`fduty version` did not exit 0 on the bash PATH: %w; output: %s", err, out.String()) } - slog.Info("fduty CLI self-check passed", "output_head", head(out.String(), 200)) - return nil + return firstLine(out.String()), nil } -// head returns at most n bytes of s, for terse log lines. -func head(s string, n int) string { - if len(s) > n { - return s[:n] +// verifyFdutyOnPath asserts fduty resolves + exits 0 on the bash PATH and returns +// its version line. This is the load-bearing gate: it catches the real failure +// mode — fduty installed somewhere that is not on the bash PATH, so bare `fduty` +// 127s at agent call time. +func verifyFdutyOnPath() (string, error) { + version, err := fdutyVersion() + if err != nil { + return "", fmt.Errorf("fduty CLI self-check failed (agent CLI calls would 127): %w", err) } - return s + slog.Info("fduty CLI self-check passed", "version", version) + return version, nil +} + +// firstLine returns the first non-empty, trimmed line of s — used to log a CLI's +// version banner without trailing build/usage noise. +func firstLine(s string) string { + for _, line := range strings.Split(s, "\n") { + if t := strings.TrimSpace(line); t != "" { + return t + } + } + return "" +} + +// lastLine returns the last non-empty, trimmed line of s — the part of a failed +// CLI invocation's output that usually carries the actual error. Logged on a +// single line instead of a truncated multi-line dump. +func lastLine(s string) string { + lines := strings.Split(s, "\n") + for i := len(lines) - 1; i >= 0; i-- { + if t := strings.TrimSpace(lines[i]); t != "" { + return t + } + } + return "" } diff --git a/cmd/provision_test.go b/cmd/provision_test.go index 520febc..10b0630 100644 --- a/cmd/provision_test.go +++ b/cmd/provision_test.go @@ -144,7 +144,7 @@ func TestFdutySelfUpdate_RunsAgainstStubAndIsNonFatal(t *testing.T) { t.Setenv("FLASHDUTY_RUNNER_BIN_DIR", binDir) t.Setenv("FLASHDUTY_CLI_INSTALL_URL", "") - fdutySelfUpdate() // must return without panicking + fdutySelfUpdate("v0.0.0-prev") // must return without panicking; exercises the upgrade-detected log branch } // verifyFdutyOnPath runs `fduty version` through the bash tool env and gates on @@ -158,7 +158,9 @@ func TestVerifyFdutyOnPath_PassesWithStubOnPath(t *testing.T) { writeStubFduty(t, binDir, 0) t.Setenv("FLASHDUTY_RUNNER_BIN_DIR", binDir) - require.NoError(t, verifyFdutyOnPath()) + version, err := verifyFdutyOnPath() + require.NoError(t, err) + assert.Contains(t, version, "fduty stub version", "must return the resolved version line") } // verifyFdutyOnPath must return an error when the resolved fduty exits non-zero @@ -171,7 +173,7 @@ func TestVerifyFdutyOnPath_FailsWhenStubExitsNonZero(t *testing.T) { writeStubFduty(t, binDir, 3) t.Setenv("FLASHDUTY_RUNNER_BIN_DIR", binDir) - err := verifyFdutyOnPath() + _, err := verifyFdutyOnPath() require.Error(t, err) assert.Contains(t, err.Error(), "self-check failed") }