feat(v1.99 PR-20): update logging observability (G3-U15/U16/U17)

cmd/nftban-installer/update_apply.go

@@ -45,6 +45,7 @@ import (
 	"context"
 	"fmt"
 	"os"
+	"time"
 
 	"github.com/itcmsgr/nftban/internal/installer/executor"
 	"github.com/itcmsgr/nftban/internal/installer/logging"
@@ -98,7 +99,11 @@ const (
 // If rebuild passes but validator fails, runUpdateApply returns the
 // validator's non-zero code. No coercion. No masking. The two phase
 // failures are ALWAYS distinguishable by exit code + log phase marker.
-func runUpdateApply(_ context.Context, exec executor.Executor, sf *state.StateFile, cfg *config, log *logging.Logger) int {
+func runUpdateApply(_ context.Context, exec executor.Executor, sf *state.StateFile, cfg *config, log *logging.Logger) (rc int) {
+	// PR-20 G3-U15/U17: track run metadata for the end-of-run trailer.
+	meta := newRunMeta("upgrade")
+	defer meta.emitTrailer(log, &rc, sf)
+
 	log.Info("update apply starting (mode=upgrade, dry-run=false)")
 
 	// 1. Preflight — read-only, identical to dry-run surface.
@@ -107,9 +112,29 @@ func runUpdateApply(_ context.Context, exec executor.Executor, sf *state.StateFi
 		origin = update.DetectInstallOrigin(exec, log)
 	}
 
+	// PR-20 G3-U15: emit the intended transition BEFORE any mutation so
+	// operators see from→to in the log even if a later phase fails.
+	// DetectVersions uses only whitelisted probes (VERSION file + rpm/dpkg
+	// query) — no new contract surface.
+	current, target, _ := update.DetectVersions(exec, cfg.sourceDir, origin, log)
+	meta.from = current
+	meta.to = target
+	log.Info("update apply: %s → %s (origin=%s)",
+		displayVer(current), displayVer(target), displayOrigin(origin))
+
+	// PR-20 G3-U16: observability-only idempotency marker. Apply still
+	// invokes rebuild in the no-op case — rebuild owns the authoritative
+	// "is this a no-op" decision (v1.96 atomic switch produces identical
+	// kernel state for identical input).
+	if current != "" && target != "" && current == target {
+		log.Info("update apply: already up-to-date (current == target == %s) — rebuild will no-op", current)
+	}
+
+	meta.beginPhase("Preflight")
 	log.Phase("Preflight")
 	pre := update.Preflight(exec, log, origin)
 	log.PhaseEnd("Preflight")
+	meta.endPhase(log, "Preflight", pre.Passed)
 
 	if !pre.Passed {
 		log.Error("update apply: preflight FAILED — apply blocked before rebuild invocation")
@@ -134,9 +159,11 @@ func runUpdateApply(_ context.Context, exec executor.Executor, sf *state.StateFi
 	// 2. Canonical rebuild entrypoint — the ONLY mutation path.
 	// Recovery, rollback, authority enforcement, config rendering: all
 	// owned by firewall_rebuild (v1.96 pipeline). PR-18 owns NONE of them.
+	meta.beginPhase("Rebuild")
 	log.Phase("Rebuild")
 	rebuildRes := exec.Run(rebuildCmd, rebuildArg1, rebuildArg2)
 	log.PhaseEnd("Rebuild")
+	meta.endPhase(log, "Rebuild", rebuildRes.ExitCode == 0)
 
 	if rebuildRes.ExitCode != 0 {
 		// Rebuild failed. Its own recovery/rollback path already ran
@@ -157,9 +184,11 @@ func runUpdateApply(_ context.Context, exec executor.Executor, sf *state.StateFi
 	// 3. Validator gate — truth gate per G3-U8.
 	// A rebuild that succeeds but produces a kernel state the validator
 	// rejects is a FAILED apply. No success coercion — validator wins.
+	meta.beginPhase("Validate")
 	log.Phase("Validate")
 	valRes := exec.Run(validatorCmd, validatorArg1)
 	log.PhaseEnd("Validate")
+	meta.endPhase(log, "Validate", valRes.ExitCode == 0)
 
 	if valRes.ExitCode != 0 {
 		// Rebuild SUCCEEDED but validator rejected the post-state. This
@@ -252,6 +281,91 @@ func stateForValidatorExit(rc int) state.InstallState {
 	return state.StateFailedRebuild
 }
 
+// runMeta carries observability state for a single runUpdateApply call.
+// Populated as phases progress; emitted as a one-line trailer at function
+// return via defer. Pure observability — never inspected to make control
+// decisions (PR-20 contract).
+type runMeta struct {
+	mode          string
+	from          string
+	to            string
+	start         time.Time
+	currentPhase  string
+	phaseStart    time.Time
+	phasesPassed  int
+	phasesFailed  int
+}
+
+func newRunMeta(mode string) *runMeta {
+	return &runMeta{mode: mode, start: time.Now()}
+}
+
+func (m *runMeta) beginPhase(name string) {
+	m.currentPhase = name
+	m.phaseStart = time.Now()
+}
+
+func (m *runMeta) endPhase(log *logging.Logger, name string, passed bool) {
+	d := time.Since(m.phaseStart)
+	log.Info("  phase %s duration_ms=%d result=%s",
+		name, d.Milliseconds(), passedStr(passed))
+	if passed {
+		m.phasesPassed++
+	} else {
+		m.phasesFailed++
+	}
+	m.currentPhase = ""
+}
+
+// emitTrailer writes a single machine-parseable key=value summary line
+// at function return. Safe to call regardless of early exit — every
+// field has a defined zero value.
+func (m *runMeta) emitTrailer(log *logging.Logger, rc *int, sf *state.StateFile) {
+	d := time.Since(m.start)
+	finalState := "UNSET"
+	if sf != nil {
+		finalState = string(sf.State)
+	}
+	exitCode := 0
+	if rc != nil {
+		exitCode = *rc
+	}
+	log.Info("update apply trailer: mode=%s from=%s to=%s phases_passed=%d phases_failed=%d duration_ms=%d exit=%d final_state=%s",
+		m.mode,
+		displayVer(m.from),
+		displayVer(m.to),
+		m.phasesPassed,
+		m.phasesFailed,
+		d.Milliseconds(),
+		exitCode,
+		finalState,
+	)
+}
+
+// displayVer returns a placeholder for empty version strings so log lines
+// never contain blank fields.
+func displayVer(v string) string {
+	if v == "" {
+		return "unknown"
+	}
+	return v
+}
+
+// displayOrigin returns a placeholder for empty origin strings.
+func displayOrigin(o string) string {
+	if o == "" {
+		return "unknown"
+	}
+	return o
+}
+
+func passedStr(p bool) string {
+	if p {
+		return "pass"
+	}
+	return "fail"
+}
+
 // truncate returns s clipped to n runes with an ellipsis appended. Used
 // for bounded stderr snippets in error logs — must not be verbose enough
 // to dump validator secrets or environment. Operates on runes (not bytes)

cmd/nftban-installer/update_apply_logging_test.go

@@ -0,0 +1,217 @@
+// =============================================================================
+// NFTBan v1.99 PR-20 — Update Apply Logging Tests (G3-U15/U16/U17)
+// =============================================================================
+// SPDX-License-Identifier: MPL-2.0
+// meta:name="nftban-installer-update-apply-logging-test"
+// meta:type="test"
+// meta:owner="Antonios Voulvoulis <contact@nftban.com>"
+// meta:created_date="2026-04-19"
+// meta:description="Verify PR-20 adds observability without changing behavior"
+// meta:inventory.files="cmd/nftban-installer/update_apply_logging_test.go"
+// meta:inventory.binaries=""
+// meta:inventory.env_vars=""
+// meta:inventory.config_files=""
+// meta:inventory.systemd_units=""
+// meta:inventory.network=""
+// meta:inventory.privileges="none"
+// =============================================================================
+//
+// PR-20 is observability only. These tests assert:
+//
+//   T-L1  from → to version line emitted after preflight detection
+//   T-L2  "already up-to-date" marker when current == target
+//   T-L3  per-phase duration_ms + result line at PhaseEnd
+//   T-L4  end-of-run trailer with key=value pairs
+//   T-L5  trailer fires on every exit branch (preflight-fail / rebuild-fail /
+//         validator-fail / happy) via defer
+//   T-L6  call-path purity preserved — no new commands added by logging
+//
+// =============================================================================
+package main
+
+import (
+	"context"
+	"os"
+	"path/filepath"
+	"strings"
+	"testing"
+
+	"github.com/itcmsgr/nftban/internal/installer/executor"
+	"github.com/itcmsgr/nftban/internal/installer/logging"
+	"github.com/itcmsgr/nftban/internal/installer/state"
+	"github.com/itcmsgr/nftban/internal/installer/update"
+)
+
+// newLoggingTestLogger returns a Logger that writes to a tempfile inside
+// the test's own dir. The returned path is where the test reads logs back
+// from.
+func newLoggingTestLogger(t *testing.T) (*logging.Logger, string) {
+	t.Helper()
+	logPath := filepath.Join(t.TempDir(), "test.log")
+	return logging.New(logPath, true), logPath
+}
+
+// readLog returns the captured log contents as a single string.
+func readLog(t *testing.T, logPath string) string {
+	t.Helper()
+	data, err := os.ReadFile(logPath)
+	if err != nil {
+		t.Fatalf("read log: %v", err)
+	}
+	return string(data)
+}
+
+// T-L1 — from → to version line emitted after preflight detection.
+func TestUpdateApplyLog_EmitsFromToLine(t *testing.T) {
+	mock := executor.NewMockExecutor()
+	seedHappyApplyHost(mock)
+	// Source install — DetectVersions reads VERSION from sourceDir too.
+	mock.Files["/tmp/srcdir/VERSION"] = []byte("2.0.0\n")
+	mock.Files["/usr/lib/nftban/VERSION"] = []byte("1.99.0\n")
+
+	cfg := &config{mode: "upgrade", stateDir: t.TempDir(), source: true, sourceDir: "/tmp/srcdir"}
+	sf := state.NewStateFile(cfg.stateDir)
+
+	log, logPath := newLoggingTestLogger(t)
+	_ = runUpdateApply(context.Background(), mock, sf, cfg, log)
+	log.Close()
+
+	content := readLog(t, logPath)
+	if !strings.Contains(content, "update apply: 1.99.0 → 2.0.0") {
+		t.Errorf("log missing from→to line:\n%s", content)
+	}
+}
+
+// T-L2 — "already up-to-date" marker when current == target.
+func TestUpdateApplyLog_AlreadyUpToDateMarker(t *testing.T) {
+	mock := executor.NewMockExecutor()
+	seedHappyApplyHost(mock)
+	// current == target == 1.99.0
+	mock.Files["/tmp/srcdir/VERSION"] = []byte("1.99.0\n")
+	mock.Files["/usr/lib/nftban/VERSION"] = []byte("1.99.0\n")
+
+	cfg := &config{mode: "upgrade", stateDir: t.TempDir(), source: true, sourceDir: "/tmp/srcdir"}
+	sf := state.NewStateFile(cfg.stateDir)
+
+	log, logPath := newLoggingTestLogger(t)
+	_ = runUpdateApply(context.Background(), mock, sf, cfg, log)
+	log.Close()
+
+	content := readLog(t, logPath)
+	if !strings.Contains(content, "already up-to-date") {
+		t.Errorf("log missing idempotency marker when current == target:\n%s", content)
+	}
+	if !strings.Contains(content, "rebuild will no-op") {
+		t.Error("idempotency marker should clarify rebuild handles no-op")
+	}
+}
+
+// T-L3 — per-phase duration_ms + result line at PhaseEnd.
+func TestUpdateApplyLog_PhaseDurationAndResult(t *testing.T) {
+	mock := executor.NewMockExecutor()
+	seedHappyApplyHost(mock)
+
+	cfg := &config{mode: "upgrade", stateDir: t.TempDir()}
+	sf := state.NewStateFile(cfg.stateDir)
+
+	log, logPath := newLoggingTestLogger(t)
+	_ = runUpdateApply(context.Background(), mock, sf, cfg, log)
+	log.Close()
+
+	content := readLog(t, logPath)
+	for _, phase := range []string{"Preflight", "Rebuild", "Validate"} {
+		needle := "phase " + phase + " duration_ms="
+		if !strings.Contains(content, needle) {
+			t.Errorf("log missing duration marker for phase %q:\n%s", phase, content)
+		}
+	}
+	if !strings.Contains(content, "result=pass") {
+		t.Error("log missing phase pass/fail marker")
+	}
+}
+
+// T-L4 — trailer contains the documented key=value pairs.
+func TestUpdateApplyLog_TrailerFields(t *testing.T) {
+	mock := executor.NewMockExecutor()
+	seedHappyApplyHost(mock)
+
+	cfg := &config{mode: "upgrade", stateDir: t.TempDir()}
+	sf := state.NewStateFile(cfg.stateDir)
+
+	log, logPath := newLoggingTestLogger(t)
+	_ = runUpdateApply(context.Background(), mock, sf, cfg, log)
+	log.Close()
+
+	content := readLog(t, logPath)
+	if !strings.Contains(content, "update apply trailer:") {
+		t.Fatalf("log missing trailer line:\n%s", content)
+	}
+	for _, key := range []string{
+		"mode=", "from=", "to=",
+		"phases_passed=", "phases_failed=",
+		"duration_ms=", "exit=", "final_state=",
+	} {
+		if !strings.Contains(content, key) {
+			t.Errorf("trailer missing key %q", key)
+		}
+	}
+}
+
+// T-L5 — trailer fires on every exit branch (defer coverage).
+func TestUpdateApplyLog_TrailerFiresOnEveryBranch(t *testing.T) {
+	branches := []struct {
+		name  string
+		setup func(*executor.MockExecutor)
+	}{
+		{"happy", func(m *executor.MockExecutor) {}},
+		{"preflight-fail", func(m *executor.MockExecutor) {
+			delete(m.NftTables, "ip:nftban")
+		}},
+		{"rebuild-fail", func(m *executor.MockExecutor) {
+			m.RunResults["nftban:firewall:rebuild"] = executor.Result{ExitCode: 2}
+		}},
+		{"validator-fail", func(m *executor.MockExecutor) {
+			m.RunResults["nftban-validate:--json"] = executor.Result{ExitCode: 2}
+		}},
+	}
+	for _, b := range branches {
+		b := b
+		t.Run(b.name, func(t *testing.T) {
+			mock := executor.NewMockExecutor()
+			seedHappyApplyHost(mock)
+			b.setup(mock)
+			cfg := &config{mode: "upgrade", stateDir: t.TempDir()}
+			sf := state.NewStateFile(cfg.stateDir)
+
+			log, logPath := newLoggingTestLogger(t)
+			_ = runUpdateApply(context.Background(), mock, sf, cfg, log)
+			log.Close()
+
+			content := readLog(t, logPath)
+			if !strings.Contains(content, "update apply trailer:") {
+				t.Errorf("[%s] trailer not emitted:\n%s", b.name, content)
+			}
+		})
+	}
+}
+
+// T-L6 — logging additions did not broaden the call path.
+func TestUpdateApplyLog_CallPathPurityPreserved(t *testing.T) {
+	mock := executor.NewMockExecutor()
+	seedHappyApplyHost(mock)
+
+	cfg := &config{mode: "upgrade", stateDir: t.TempDir()}
+	sf := state.NewStateFile(cfg.stateDir)
+
+	log, _ := newLoggingTestLogger(t)
+	_ = runUpdateApply(context.Background(), mock, sf, cfg, log)
+	log.Close()
+
+	trace := cmdTrace(mock)
+	if v := update.AuditRecordedCommands(trace); len(v) != 0 {
+		t.Errorf("PR-20 logging additions broke call-path purity:\n%s", strings.Join(v, "\n"))
+	}
+	if v := update.AuditWrittenFiles(writtenPaths(mock)); len(v) != 0 {
+		t.Errorf("PR-20 logging additions broke write-path purity:\n%s", strings.Join(v, "\n"))
+	}
+}