fix(provision): clean, definitive fduty self-update logs

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 <cmd>`); 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 <cmd>`). 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 ""
 }

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")
 }