diff --git a/cmd/proxsave/backup_stream.go b/cmd/proxsave/backup_stream.go index e951c9f5..f12134ad 100644 --- a/cmd/proxsave/backup_stream.go +++ b/cmd/proxsave/backup_stream.go @@ -27,6 +27,40 @@ var backupStreamSteps = runBackupModeSteps // session so the emitted lines and the outcome can be asserted. var backupAdoptSession = adoptDashboardSession +// dashboardStreamBacklogMaxLines bounds the pre-viewport backlog. A run's early +// phase (banner -> environment -> security preflight, before the backup steps) +// logs on the order of a few dozen lines at INFO and a couple hundred at DEBUG, so +// this never drops in practice; it only backstops a pathological producer. +const dashboardStreamBacklogMaxLines = 4096 + +// dashboardStreamBacklog holds the run logger's colored line stream captured +// BEFORE the graphical viewport exists (wired by initializeRunLogger on a +// dashboard handoff). runBackupStreamed drains it into the viewport, then detaches +// the mirror so the live stream is not double-captured. Single-use per process +// (proxsave runs once); nil when there is no handoff (CLI/cron/daemon). +var dashboardStreamBacklog *logging.LineBacklog + +// replayDashboardStreamBacklog flushes the pre-viewport backlog into the streamed +// panel, in order, BEFORE the live capture is installed, so the viewport shows the +// SAME complete flow the on-disk log has instead of starting mid-run. It first +// detaches the logger mirror, THEN emits each retained line; the caller installs +// captureRunOutput only after this returns, so no line can ever reach both the +// backlog and the live pipe. A nil backlog (no handoff) is a no-op. Called once. +func replayDashboardStreamBacklog(emit func(line string)) { + backlog := dashboardStreamBacklog + dashboardStreamBacklog = nil + if backlog == nil { + return + } + // Detach the mirror while the console is still muted and before the live pipe + // exists: from here the run's remaining lines reach the panel only through the + // capture the caller installs next, so nothing is double-captured. + logging.GetDefaultLogger().SetMirror(nil) + for _, line := range backlog.Lines() { + emit(line) + } +} + // captureRunOutput routes BOTH the loggers (default + colored bootstrap mirror) // AND raw os.Stdout through a SINGLE pipe into emit, so everything a run prints - // colored logger lines AND the raw fmt.Println blank spacers between sections - @@ -115,6 +149,13 @@ func runBackupStreamed(opts backupModeOptions) backupModeResult { var res backupModeResult streamErr := components.RunStreamTask(opts.ctx, session, "Running backup", func(taskCtx context.Context, emit func(line string)) (string, error) { + // Replay everything logged BEFORE this viewport existed (banner, + // environment, identity, security preflight) so the panel shows the + // same complete run the on-disk log has. Done FIRST - it detaches the + // mirror before captureRunOutput installs the live pipe, so no line can + // ever reach both the backlog and the live capture (no double). + replayDashboardStreamBacklog(emit) + // Route the default + COLORED bootstrap-mirror loggers AND raw os.Stdout // (the fmt.Println section spacers the CLI prints) through one pipe into // the panel; restored on return/panic. So the panel shows the SAME lines - diff --git a/cmd/proxsave/backup_stream_test.go b/cmd/proxsave/backup_stream_test.go index 50aef40f..e2356384 100644 --- a/cmd/proxsave/backup_stream_test.go +++ b/cmd/proxsave/backup_stream_test.go @@ -4,6 +4,7 @@ import ( "context" "io" "os" + "path/filepath" "strings" "testing" "time" @@ -516,6 +517,87 @@ func TestRunBackupStreamedHandsOffInStream(t *testing.T) { _ = pumpEnterBackup(t, session, resCh) } +// TestRunBackupStreamedReplaysPreStreamBacklog is the guard for the fix: the +// streamed viewport must show the lines logged BEFORE it existed (banner -> +// environment -> preflight), not start mid-run at "Initializing backup +// orchestrator". It reproduces the pre-viewport phase the way initializeRunLogger +// wires it on a dashboard handoff - the run logger mirrors its full colored stream +// into a backlog while the console is muted - including a RAW banner line flushed +// via AppendRaw (which the console path deliberately skips, so only the mirror +// carries it). runBackupStreamed must replay that backlog into the panel ahead of +// the live step line. +func TestRunBackupStreamedReplaysPreStreamBacklog(t *testing.T) { + prevLogger := logging.GetDefaultLogger() + lg := logging.New(types.LogLevelInfo, false) + lg.SetOutput(io.Discard) // muted console, as during a dashboard handoff + logging.SetDefaultLogger(lg) + t.Cleanup(func() { logging.SetDefaultLogger(prevLogger) }) + + // Wire the mirror + backlog exactly like initializeRunLogger, then log the + // early lines: a raw banner (file/mirror only, never on the console path) and a + // normal INFO line. An open log file lets AppendRaw exercise its file branch too. + backlog := logging.NewLineBacklog(1024) + lg.SetMirror(backlog) + if err := lg.OpenLogFile(filepath.Join(t.TempDir(), "run.log")); err != nil { + t.Fatalf("open log file: %v", err) + } + lg.AppendRaw("===== ProxSaveBanner =====") + logging.Info("Environment: dual pve=9.1.9") + dashboardStreamBacklog = backlog + t.Cleanup(func() { dashboardStreamBacklog = nil }) + + prevSteps := backupStreamSteps + backupStreamSteps = func(opts backupModeOptions) backupModeResult { + logging.Info("Initializing backup orchestrator") + return backupModeResult{ + exitCode: types.ExitSuccess.Int(), + supportStats: &orchestrator.BackupStats{FilesCollected: 1, LocalStatus: "ok"}, + } + } + t.Cleanup(func() { backupStreamSteps = prevSteps }) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + + var buf shell.SyncBuffer + session := shell.StartForTestWithOutput(ctx, shell.Config{AppName: "ProxSave", Subtitle: "Backup"}, &buf) + + bootstrap := logging.NewBootstrapLogger() + stashDashboardSession(session, bootstrap) + t.Cleanup(releaseDashboardLeftovers) + + resCh := make(chan backupModeResult, 1) + go func() { + resCh <- runBackupStreamed(backupModeOptions{ctx: ctx, bootstrap: bootstrap, cfg: &config.Config{}}) + }() + + // The pre-viewport backlog (banner via AppendRaw + the environment line) must + // stream into the panel, followed by the live step line. + waitFor(t, &buf, "ProxSaveBanner") + waitFor(t, &buf, "Environment: dual") + waitFor(t, &buf, "Initializing backup orchestrator") + + // Presence is not enough: the whole point is order. The replayed backlog must + // precede the live step line, exactly as the on-disk log records it + // (banner -> environment -> orchestrator init). A regression that streamed the + // step line first would still satisfy the three waitFor calls above. + frame := ansi.Strip(buf.String()) + iBanner := strings.Index(frame, "ProxSaveBanner") + iEnv := strings.Index(frame, "Environment: dual") + iInit := strings.Index(frame, "Initializing backup orchestrator") + if iBanner < 0 || iBanner >= iEnv || iEnv >= iInit { + t.Fatalf("stream out of order: banner=%d environment=%d init=%d (want banner < environment < init)", iBanner, iEnv, iInit) + } + + _ = pumpEnterBackup(t, session, resCh) + + // The mirror is detached once the backlog is replayed, so a line logged after + // the run does not keep feeding the (now stale) backlog. + if got := logging.GetDefaultLogger(); got != nil { + got.SetMirror(nil) // idempotent; asserts the symbol exists / no panic + } +} + // pumpEnterBackup sends Enter until runBackupStreamed returns its result. func pumpEnterBackup(t *testing.T, s *shell.Session, done <-chan backupModeResult) backupModeResult { t.Helper() diff --git a/cmd/proxsave/daemon.go b/cmd/proxsave/daemon.go index b42c170a..38c1197c 100644 --- a/cmd/proxsave/daemon.go +++ b/cmd/proxsave/daemon.go @@ -5,7 +5,9 @@ import ( "context" "errors" "fmt" + "hash/fnv" "io" + "math" "os" "os/exec" "os/signal" @@ -77,11 +79,11 @@ type daemon struct { configPath string now func() time.Time - mu sync.Mutex - reporter backupReporter - fetchWarned bool // centralized fetch already warned once (throttle recurring WARN) - updateWarned bool // an update is already known available (WARN once per transition) - provisionLast time.Time // last relay-secret self-heal attempt (throttle); guarded by mu + mu sync.Mutex + reporter backupReporter + fetchWarned bool // centralized fetch already warned once (throttle recurring WARN) + updateWarned bool // an update is already known available (WARN once per transition) + provisionRetryAt time.Time // next relay-secret self-heal attempt; guarded by mu // newBackupCmd builds the child backup command; overridable in tests. newBackupCmd func(ctx context.Context) *exec.Cmd @@ -628,22 +630,25 @@ func (d *daemon) buildReporter(ctx context.Context) *health.Reporter { // centralized alive, backup, checks, secretUsed, err := d.fetchCentralized(ctx) if err != nil { - // A DEFINITIVE auth rejection (ErrHCAuth) means the on-disk relay secret no longer - // matches the server's stored hash (a server DB restore/rollback, or a lost - // double-issuance race). Clear it so the next throttled maybeProvisionRelaySecret - // mints a fresh one - restoring the Telegram path's self-heal. ONLY ErrHCAuth: a - // transient / unreachable / not-ready / unknown error must NOT churn a - // possibly-good secret (a working confirmed secret never returns 401/403). The clear - // is value-guarded under LockNotifySecret against the EXACT secret fetchCentralized - // used (secretUsed), so a concurrent hook that persisted+confirmed a fresh secret in - // the meantime is never clobbered (which would strand the host). - if errors.Is(err, health.ErrHCAuth) { + // A DEFINITIVE rejection means the on-disk relay secret is no longer usable: + // ErrHCAuth - the secret no longer matches the server's stored hash (a + // server DB restore/rollback, or a lost double-issuance race); + // ErrHCParked - the server purged this host's row (its unused account was + // parked, design 11.2), so the token authenticates nothing. + // Both clear the secret so the next throttled maybeProvisionRelaySecret mints a + // fresh one (a parked host is re-admitted as a recreation) - restoring the + // self-heal. ONLY these two: a transient / unreachable / not-ready / unknown + // error must NOT churn a possibly-good secret. The clear is value-guarded under + // LockNotifySecret against the EXACT secret fetchCentralized used (secretUsed), + // so a concurrent hook that persisted+confirmed a fresh secret is never + // clobbered (which would strand the host). + if errors.Is(err, health.ErrHCAuth) || errors.Is(err, health.ErrHCParked) { if cleared, rmErr := identity.RemoveNotifySecretIfMatches(d.cfg.BaseDir, secretUsed); rmErr != nil { logging.Debug("daemon: clear rejected relay secret failed: %v", rmErr) } else if cleared { - logging.Debug("daemon: relay secret rejected by server (auth); cleared for re-provisioning") + logging.Debug("daemon: relay secret rejected by server (auth/parked); cleared for re-provisioning") } else { - logging.Debug("daemon: relay secret rejected by server (auth) but on-disk secret changed concurrently; keeping it") + logging.Debug("daemon: relay secret rejected by server (auth/parked) but on-disk secret changed concurrently; keeping it") } } // The heartbeat loop retries this every interval; warn ONCE (so the @@ -710,61 +715,112 @@ func (d *daemon) fetchCentralized(ctx context.Context) (alive, backup string, ch return cfg.AliveURL, cfg.BackupURL, cfg.Checks, secret, nil } -// daemonProvisionRetryInterval throttles the daemon's relay-secret self-heal so a persistent -// provisioning failure (server down, or the host not yet known to the server) does not hit the -// server on every heartbeat interval. -const daemonProvisionRetryInterval = 15 * time.Minute +const ( + // daemonProvisionRetryInterval is the local retry floor: a persistent failure + // must not hit the relay on every heartbeat interval. + daemonProvisionRetryInterval = 15 * time.Minute + // daemonProvisionMaxRetryJitter spreads clients released from the same global + // admission window without materially extending the server's Retry-After. + daemonProvisionMaxRetryJitter = 5 * time.Minute +) + +// daemonProvisionRetryJitter is deterministic per server_id, so no shared random +// source or persisted state is needed. It uses up to 10% of Retry-After, capped at +// five minutes. A stable spread is sufficient to avoid a synchronized retry herd. +func daemonProvisionRetryJitter(serverID string, retryAfter time.Duration) time.Duration { + window := retryAfter / 10 + if window > daemonProvisionMaxRetryJitter { + window = daemonProvisionMaxRetryJitter + } + if window <= 0 { + return 0 + } + h := fnv.New64a() + _, _ = h.Write([]byte(serverID)) + // Mask to 63 bits so the sum is a valid non-negative int64 (the conversion cannot + // overflow), then reduce it modulo the window in signed space. window is in + // (0, 5min], so int64(window)+1 is a small positive divisor and the remainder is a + // bounded Duration. + return time.Duration(int64(h.Sum64()&math.MaxInt64) % (int64(window) + 1)) +} // provisionRelaySecretFn is the relay-secret provisioner seam (stubbed in tests so the // self-heal logic is exercised without touching the network). var provisionRelaySecretFn = notify.ProvisionRelaySecret -// provisionRelaySecretBestEffort attempts one relay-secret provisioning for a centralized -// healthcheck host that has none on disk, so centralized monitoring works WITHOUT Telegram -// pairing. Best-effort and non-blocking: it returns the relay secret now on disk, or "" when -// provisioning is not applicable (self mode / disabled / no ServerID) or the attempt failed. -// It NEVER returns/propagates an error. When a secret is already present it returns it -// unchanged (never overwrites a possibly-confirmed secret). Callers gate frequency: the -// daemon throttles via provisionLast; the one-shot daemon-setup path runs it once. -func provisionRelaySecretBestEffort(ctx context.Context, cfg *config.Config, logger *logging.Logger) string { +// provisionRelaySecretAttempt performs the best-effort attempt and also returns +// server-directed backpressure. It never propagates an error: Retry-After is the +// only semantic detail the daemon needs from a handled 429. +func provisionRelaySecretAttempt( + ctx context.Context, cfg *config.Config, logger *logging.Logger, +) (string, time.Duration) { if cfg == nil || !cfg.HealthcheckEnabled || cfg.HealthcheckMode != config.HealthcheckModeCentralized { - return "" + return "", 0 } baseDir := strings.TrimSpace(cfg.BaseDir) if baseDir == "" { - return "" + return "", 0 } if s, _ := identity.LoadNotifySecret(baseDir); strings.TrimSpace(s) != "" { - return strings.TrimSpace(s) // already provisioned; do not churn + return strings.TrimSpace(s), 0 // already provisioned; do not churn } serverID := strings.TrimSpace(cfg.ServerID) if serverID == "" { - return "" + return "", 0 } if _, err := provisionRelaySecretFn(ctx, cfg.ServerAPIHost, serverID, baseDir, logger); err != nil { + var limited *notify.RelayProvisionRateLimitError + if errors.As(err, &limited) { + logging.Debug( + "daemon: relay-secret provisioning rate limited (server backoff honored)") + return "", limited.RetryAfter + } logging.Debug("daemon: relay-secret provisioning attempt failed (will retry later): %v", err) - return "" + return "", 0 } // Reload regardless of the provisioned flag: ProvisionRelaySecret returns false when it // adopts a secret a concurrent provisioner persisted under the cross-process lock, so a // usable secret may be on disk even then; LoadNotifySecret yields "" when there is // genuinely none, degrading gracefully. s, _ := identity.LoadNotifySecret(baseDir) - return strings.TrimSpace(s) + return strings.TrimSpace(s), 0 +} + +// provisionRelaySecretBestEffort keeps the one-shot setup callers' established +// string-only contract. They run once and therefore do not need Retry-After. +func provisionRelaySecretBestEffort( + ctx context.Context, cfg *config.Config, logger *logging.Logger, +) string { + secret, _ := provisionRelaySecretAttempt(ctx, cfg, logger) + return secret } // maybeProvisionRelaySecret is the daemon's throttled relay-secret self-heal (hook b). It // returns a freshly persisted secret, or "" when throttled / not applicable / failed. The -// throttle is recorded even on failure so a down server is not hit every heartbeat. +// local retry floor is installed BEFORE the network call so concurrent heartbeat +// paths cannot duplicate an attempt. A longer server Retry-After extends that +// deadline and adds bounded deterministic jitter. func (d *daemon) maybeProvisionRelaySecret(ctx context.Context) string { + now := d.now() d.mu.Lock() - if !d.provisionLast.IsZero() && d.now().Sub(d.provisionLast) < daemonProvisionRetryInterval { + if !d.provisionRetryAt.IsZero() && now.Before(d.provisionRetryAt) { d.mu.Unlock() return "" } - d.provisionLast = d.now() + d.provisionRetryAt = now.Add(daemonProvisionRetryInterval) d.mu.Unlock() - return provisionRelaySecretBestEffort(ctx, d.cfg, d.logger) + + secret, retryAfter := provisionRelaySecretAttempt(ctx, d.cfg, d.logger) + if retryAfter > daemonProvisionRetryInterval { + retryAt := d.now().Add( + retryAfter + daemonProvisionRetryJitter(d.cfg.ServerID, retryAfter)) + d.mu.Lock() + if retryAt.After(d.provisionRetryAt) { + d.provisionRetryAt = retryAt + } + d.mu.Unlock() + } + return secret } // provisionRelaySecretOnDaemonSetup is the one-shot relay-secret self-heal (hook a) run during diff --git a/cmd/proxsave/daemon_relay_provision_test.go b/cmd/proxsave/daemon_relay_provision_test.go index 9e10cd5d..f9c54830 100644 --- a/cmd/proxsave/daemon_relay_provision_test.go +++ b/cmd/proxsave/daemon_relay_provision_test.go @@ -2,6 +2,7 @@ package main import ( "context" + "io" "net/http" "net/http/httptest" "testing" @@ -10,6 +11,7 @@ import ( "github.com/tis24dev/proxsave/internal/config" "github.com/tis24dev/proxsave/internal/identity" "github.com/tis24dev/proxsave/internal/logging" + "github.com/tis24dev/proxsave/internal/notify" ) const relayTestSecret = "3h64-dyi8-q3d6-wcm5" @@ -113,6 +115,37 @@ func TestBuildReporterClearsSecretOnAuthReject(t *testing.T) { } } +// A 410 SERVER_PARKED (ErrHCParked) is as definitive as an auth reject: the row was +// purged, so the on-disk secret must be cleared for re-provisioning (design 11.2). +func TestBuildReporterClearsSecretOnParked(t *testing.T) { + base := t.TempDir() + if err := identity.PersistNotifySecret(context.Background(), base, relayTestSecret, nil); err != nil { + t.Fatalf("seed secret: %v", err) + } + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusGone) // parked -> ErrHCParked + _, _ = io.WriteString(w, `{"error":"SERVER_PARKED"}`) + })) + defer server.Close() + + d := &daemon{ + cfg: &config.Config{ + HealthcheckEnabled: true, + HealthcheckMode: config.HealthcheckModeCentralized, + BaseDir: base, + ServerID: "123456789012", + ServerAPIHost: server.URL, + }, + now: time.Now, + } + if r := d.buildReporter(context.Background()); r != nil { + t.Fatalf("expected nil reporter after parked (no cached URLs), got %v", r) + } + if s, _ := identity.LoadNotifySecret(base); s != "" { + t.Fatalf("relay secret must be cleared after ErrHCParked, still on disk: %q", s) + } +} + // A NON-auth fetch failure (503 -> ErrHCNotReady) must NOT churn the on-disk secret: a // possibly-good secret is preserved so a transient server hiccup does not force a re-mint. func TestBuildReporterKeepsSecretOnTransientFailure(t *testing.T) { @@ -170,3 +203,57 @@ func TestDaemonMaybeProvisionRelaySecretThrottle(t *testing.T) { t.Fatalf("after throttle window must re-attempt, called=%d", called) } } + +func TestDaemonMaybeProvisionRelaySecretHonorsLongerServerBackoff(t *testing.T) { + orig := provisionRelaySecretFn + t.Cleanup(func() { provisionRelaySecretFn = orig }) + called := 0 + provisionRelaySecretFn = func( + ctx context.Context, host, id, baseDir string, + logger *logging.Logger, + ) (bool, error) { + called++ + return false, ¬ify.RelayProvisionRateLimitError{ + RetryAfter: 2 * time.Hour, + } + } + start := time.Unix(1_700_000_000, 0) + now := start + d := &daemon{ + cfg: &config.Config{ + HealthcheckEnabled: true, + HealthcheckMode: config.HealthcheckModeCentralized, + BaseDir: t.TempDir(), + ServerID: "1234567890123456", + ServerAPIHost: "https://h", + }, + now: func() time.Time { return now }, + } + + d.maybeProvisionRelaySecret(context.Background()) + if called != 1 { + t.Fatalf("first attempt must call the provisioner, called=%d", called) + } + now = start.Add(2*time.Hour - time.Second) + d.maybeProvisionRelaySecret(context.Background()) + if called != 1 { + t.Fatalf("must not retry before server Retry-After, called=%d", called) + } + // The deterministic anti-herd jitter is bounded to five minutes. + now = start.Add(2*time.Hour + daemonProvisionMaxRetryJitter + time.Second) + d.maybeProvisionRelaySecret(context.Background()) + if called != 2 { + t.Fatalf("must retry after Retry-After plus max jitter, called=%d", called) + } +} + +func TestDaemonProvisionRetryJitterIsStableAndBounded(t *testing.T) { + a := daemonProvisionRetryJitter("1234567890123456", 2*time.Hour) + b := daemonProvisionRetryJitter("1234567890123456", 2*time.Hour) + if a != b { + t.Fatalf("jitter must be stable per server: %v != %v", a, b) + } + if a < 0 || a > daemonProvisionMaxRetryJitter { + t.Fatalf("jitter %v outside [0,%v]", a, daemonProvisionMaxRetryJitter) + } +} diff --git a/cmd/proxsave/dashboard.go b/cmd/proxsave/dashboard.go index 9c97b5f9..0e212133 100644 --- a/cmd/proxsave/dashboard.go +++ b/cmd/proxsave/dashboard.go @@ -83,7 +83,9 @@ func maybeShowWhatsnew(ctx context.Context, session *shell.Session, baseDir, too if err != nil { if errors.Is(err, whatsnew.ErrStateParse) { // Best-effort self-heal, stay silent. No dry-run gate here (unlike maybeWarnWhatsnew): - // the dashboard is bare-invocation-only, so the --dry-run flag can never coexist with it. + // both callers guarantee no --dry-run before reaching this point -- the dashboard is + // bare-invocation-only, and showWhatsnewScreen (the --show-whatsnew entry) returns early + // under args.DryRun -- so the --dry-run flag can never coexist with this write. _ = whatsnewSaveSeen(baseDir, toolVersion) } return @@ -99,6 +101,54 @@ func maybeShowWhatsnew(ctx context.Context, session *shell.Session, baseDir, too } } +// showWhatsnewScreen runs ONLY Screen 0 (what's new) and returns, without the dashboard +// menu. It is the body of the --show-whatsnew mode that the upgrade flow re-invokes on the +// freshly installed binary, so Screen 0 opens at the end of every interactive upgrade, +// rendered by the binary that actually carries the notes (each binary compiles in its own +// notes registry, so the download path -- where the OLD binary drives finalize -- MUST +// hand off to the installed binary to show the new release's notes). It builds its own +// shell.Session (the upgrade has none) using the same testDashboardSession seam as the +// dashboard, and delegates to maybeShowWhatsnew so the seen-flag gating, self-heal, timeout, +// and write-only-on-continue behavior are identical and the seen-flag write dedupes against +// the dashboard trigger. Interactive-gated so an automated/piped re-invocation is a no-op. +func showWhatsnewScreen(ctx context.Context, args *cli.Args, toolVersion string) { + if !dashboardIsInteractive() { + return + } + // --dry-run must not mutate the filesystem: maybeShowWhatsnew's self-heal and + // continue-write both write the seen-flag, so a dry-run invocation of this (non-bare) + // entry point skips Screen 0 entirely. The upgrade flow never passes --dry-run to the + // re-invoked child; this guards a manual `proxsave --show-whatsnew --dry-run`. + if args != nil && args.DryRun { + return + } + var session *shell.Session + if s := testDashboardSession; s != nil { + session = s(ctx) + } else { + buildSig := buildSignature() + if strings.TrimSpace(buildSig) == "" { + buildSig = "n/a" + } + configPath := "" + if args != nil { + configPath = args.ConfigPath + } + session = shell.Start(ctx, shell.Config{ + AppName: "ProxSave", + Subtitle: "Dashboard", + Version: toolVersion, + ConfigPath: configPath, + BuildSig: buildSig, + UseColor: true, + }) + } + defer func() { _ = session.Close() }() + + baseDir, _ := detectedBaseDirOrFallback() + maybeShowWhatsnew(ctx, session, baseDir, toolVersion) +} + // dashboardBareInvocationCheck: only a completely bare `proxsave` (no flags // at all) is eligible for the dashboard. func dashboardBareInvocationCheck() bool { return len(os.Args) <= 1 } diff --git a/cmd/proxsave/main_modes.go b/cmd/proxsave/main_modes.go index a195d352..12fab503 100644 --- a/cmd/proxsave/main_modes.go +++ b/cmd/proxsave/main_modes.go @@ -178,6 +178,7 @@ func enabledModes(modes []incompatibleMode) []string { func dispatchPreRuntimeModes(ctx context.Context, args *cli.Args, bootstrap *logging.BootstrapLogger, toolVersion string) (int, bool) { for _, handler := range []preRuntimeModeHandler{ + runShowWhatsnewMode, runUpgradeMode, runNewKeyMode, runDecryptOnlyMode, @@ -218,6 +219,20 @@ func runUpgradeMode(ctx context.Context, args *cli.Args, bootstrap *logging.Boot return runUpgrade(ctx, args, bootstrap), true } +// runShowWhatsnewMode handles --show-whatsnew: open Screen 0 (what's new) once and exit. +// This is the mode the upgrade flow re-invokes on the freshly installed binary so Screen 0 +// opens at the end of every interactive upgrade, rendered by the binary that carries the +// notes. It never fails the process (Screen 0 is best-effort and self-heals), so it always +// returns ExitSuccess. +func runShowWhatsnewMode(ctx context.Context, args *cli.Args, bootstrap *logging.BootstrapLogger, toolVersion string) (int, bool) { + if !args.ShowWhatsnew { + return types.ExitSuccess.Int(), false + } + logging.DebugStepBootstrap(bootstrap, "main run", "mode=show-whatsnew") + showWhatsnewScreen(ctx, args, toolVersion) + return types.ExitSuccess.Int(), true +} + // modeStdoutInteractive gates the sibling entrypoints onto their clean-stdout CLI // variant when stdout is not a real terminal, mirroring dispatchRestoreMode (C6). // It is a var so tests can force the non-interactive branch. diff --git a/cmd/proxsave/main_runtime.go b/cmd/proxsave/main_runtime.go index 3b367705..87d664bc 100644 --- a/cmd/proxsave/main_runtime.go +++ b/cmd/proxsave/main_runtime.go @@ -278,6 +278,14 @@ func initializeRunLogger(rt *appRuntime) *logging.Logger { // logger off the console until the flow adopts the session (the // adoption lifts the mute; the flow then applies its own). logger.SwapOutput(io.Discard) + // Tee the full colored stream into a backlog IN PARALLEL to the (muted) + // console AND the file, so the streamed backup can replay everything the + // on-disk log already has - banner, environment, preflight - captured from + // here (before bootstrap.Flush) instead of starting mid-run at + // "Initializing backup orchestrator". runBackupStreamed drains and detaches + // it once its viewport exists. + dashboardStreamBacklog = logging.NewLineBacklog(dashboardStreamBacklogMaxLines) + logger.SetMirror(dashboardStreamBacklog) } logging.SetDefaultLogger(logger) rt.bootstrap.SetLevel(rt.logLevel) diff --git a/cmd/proxsave/upgrade.go b/cmd/proxsave/upgrade.go index fd09c9c0..37c9cfa9 100644 --- a/cmd/proxsave/upgrade.go +++ b/cmd/proxsave/upgrade.go @@ -333,6 +333,18 @@ func upgradeFinalizePhase(ctx context.Context, args *cli.Args, bootstrap *loggin printUpgradeFooter(upgradeErr, versionInstalled, args.ConfigPath, baseDir, telegramCode, permStatus, permMessage, cfgUpgradeResult, cfgUpgradeErr, daemonRestart) + // After a FULLY successful upgrade (binary AND configuration), open Screen 0 (what's + // new) for the freshly installed release by re-invoking the installed binary with + // --show-whatsnew. The notes registry is compiled into each binary, so the INSTALLED + // binary -- not necessarily this process (the download path finalizes from the OLD + // binary) -- is the one that must render them. Best-effort and gated (interactive AND + // not auto-yes) inside the helper; never changes the exit code. A config-upgrade + // failure (cfgUpgradeErr) leaves the footer showing "Configuration: ERROR" and a + // nonzero exit, so opening a celebratory notes screen there would contradict it. + if upgradeErr == nil && cfgUpgradeErr == nil { + runWhatsnewAfterUpgrade(ctx, execPath, args, bootstrap) + } + // The workflow span error mirrors the exit code's reasoning: a binary-install // failure, or a config-upgrade failure after a good install (the footer already // shows "Configuration: ERROR"), so automation and the trace agree. @@ -971,3 +983,53 @@ func upgradeConfigWithBinary(ctx context.Context, execPath, configPath string) ( } return &result, nil } + +// whatsnewAfterUpgradeInteractive reports whether the terminal can drive the post-upgrade +// Screen 0. It is a var so tests can force the branch without a real TTY. +var whatsnewAfterUpgradeInteractive = isTerminalInteractive + +// shouldRunWhatsnewAfterUpgrade decides whether to open Screen 0 at the end of an upgrade. +// It requires an interactive terminal AND that the operator did NOT request auto-yes +// (`--upgrade y`). Auto-yes signals non-interactive intent even when a pty IS allocated +// (ssh -tt, Ansible with a pty, `script -c`), where isTerminalInteractive() alone is true; +// opening a screen that waits for a human keypress there would stall the process until the +// Screen 0 timeout on an otherwise successful automated upgrade, so auto-yes must skip it. +func shouldRunWhatsnewAfterUpgrade(args *cli.Args) bool { + if args == nil || args.UpgradeAutoYes { + return false + } + return whatsnewAfterUpgradeInteractive() +} + +// runWhatsnewAfterUpgrade re-invokes the freshly installed binary (execPath) with +// --show-whatsnew so Screen 0 (what's new) opens at the END of a successful interactive +// upgrade. It MUST be the installed binary that renders it: the notes registry is compiled +// into each binary, so on the download path -- where THIS process is still the OLD binary -- +// only execPath knows the new release's notes. Stdio is inherited so the child paints the +// TUI on the real terminal. Gated by shouldRunWhatsnewAfterUpgrade (interactive AND not +// auto-yes) so an automated upgrade never blocks, and best-effort so a render failure never +// changes the upgrade's exit code. +func runWhatsnewAfterUpgrade(ctx context.Context, execPath string, args *cli.Args, bootstrap *logging.BootstrapLogger) { + if !shouldRunWhatsnewAfterUpgrade(args) { + return + } + execPath = strings.TrimSpace(execPath) + if execPath == "" { + return + } + cmdArgs := []string{"--show-whatsnew"} + if configPath := strings.TrimSpace(args.ConfigPath); configPath != "" { + cmdArgs = append([]string{"--config", configPath}, cmdArgs...) + } + cmd, err := safeexec.TrustedCommandContext(ctx, execPath, cmdArgs...) + if err != nil { + logging.DebugStepBootstrap(bootstrap, "upgrade workflow", "what's-new screen skipped: %v", err) + return + } + cmd.Stdin = os.Stdin + cmd.Stdout = os.Stdout + cmd.Stderr = os.Stderr + if err := cmd.Run(); err != nil { + logging.DebugStepBootstrap(bootstrap, "upgrade workflow", "what's-new screen exited with error: %v", err) + } +} diff --git a/cmd/proxsave/whatsnew_upgrade_test.go b/cmd/proxsave/whatsnew_upgrade_test.go new file mode 100644 index 00000000..bec67090 --- /dev/null +++ b/cmd/proxsave/whatsnew_upgrade_test.go @@ -0,0 +1,269 @@ +package main + +import ( + "context" + "go/ast" + "go/parser" + "go/token" + "testing" + + "github.com/tis24dev/proxsave/internal/cli" + "github.com/tis24dev/proxsave/internal/types" + "github.com/tis24dev/proxsave/internal/ui/shell" +) + +// isErrNilCheck reports whether e is ` == nil`. +func isErrNilCheck(e ast.Expr, name string) bool { + be, ok := e.(*ast.BinaryExpr) + if !ok || be.Op != token.EQL { + return false + } + x, ok1 := be.X.(*ast.Ident) + y, ok2 := be.Y.(*ast.Ident) + return ok1 && ok2 && x.Name == name && y.Name == "nil" +} + +// ifGuardsUpgradeSuccessAndCallsWhatsnew reports whether ifs is +// `if upgradeErr == nil && cfgUpgradeErr == nil { ... runWhatsnewAfterUpgrade(...) ... }`: +// Screen 0 opens only after a FULLY successful upgrade (binary AND configuration), and its +// body directly calls the Screen 0 re-invocation helper. Gating on the binary result alone +// would open a celebratory notes screen even when the config upgrade failed (footer shows +// "Configuration: ERROR", nonzero exit). +func ifGuardsUpgradeSuccessAndCallsWhatsnew(ifs *ast.IfStmt) bool { + land, ok := ifs.Cond.(*ast.BinaryExpr) + if !ok || land.Op != token.LAND { + return false + } + // Both binary-install and config-upgrade success must be required, in either order. + forward := isErrNilCheck(land.X, "upgradeErr") && isErrNilCheck(land.Y, "cfgUpgradeErr") + reverse := isErrNilCheck(land.X, "cfgUpgradeErr") && isErrNilCheck(land.Y, "upgradeErr") + if !forward && !reverse { + return false + } + if ifs.Body == nil { + return false + } + for _, s := range ifs.Body.List { + es, ok := s.(*ast.ExprStmt) + if !ok { + continue + } + call, ok := es.X.(*ast.CallExpr) + if !ok { + continue + } + if id, ok := call.Fun.(*ast.Ident); ok && id.Name == "runWhatsnewAfterUpgrade" { + return true + } + } + return false +} + +// TestUpgradeShowsWhatsnewAfterFooter is a STRUCTURAL (AST) guard for the core requirement: +// Screen 0 (what's new) must open at the END of every FULLY successful upgrade. It parses +// upgradeFinalizePhase and pins that +// `if upgradeErr == nil && cfgUpgradeErr == nil { runWhatsnewAfterUpgrade(...) }` +// exists AND appears AFTER the printUpgradeFooter call. Parsing the AST -- not scanning text +// -- catches a commented-out call, a call moved out of the success gate (which would fire +// Screen 0 even on a failed upgrade), a call relocated before the footer, and outright +// deletion, all of which break the requirement. upgradeFinalizePhase itself cannot be +// unit-invoked cheaply (it does real config-upgrade, symlink, permission, and daemon work). +func TestUpgradeShowsWhatsnewAfterFooter(t *testing.T) { + fset := token.NewFileSet() + f, err := parser.ParseFile(fset, "upgrade.go", nil, 0) + if err != nil { + t.Fatalf("parse upgrade.go: %v", err) + } + + var fn *ast.FuncDecl + for _, d := range f.Decls { + if fd, ok := d.(*ast.FuncDecl); ok && fd.Name.Name == "upgradeFinalizePhase" { + fn = fd + break + } + } + if fn == nil || fn.Body == nil { + t.Fatal("upgradeFinalizePhase not found in upgrade.go") + } + + directCallName := func(s ast.Stmt) string { + es, ok := s.(*ast.ExprStmt) + if !ok { + return "" + } + call, ok := es.X.(*ast.CallExpr) + if !ok { + return "" + } + if id, ok := call.Fun.(*ast.Ident); ok { + return id.Name + } + return "" + } + + idxFooter, idxHook := -1, -1 + for i, s := range fn.Body.List { + if directCallName(s) == "printUpgradeFooter" { + idxFooter = i + } + if ifs, ok := s.(*ast.IfStmt); ok && ifGuardsUpgradeSuccessAndCallsWhatsnew(ifs) { + idxHook = i + } + } + + if idxFooter < 0 { + t.Fatal("printUpgradeFooter is not a direct statement in upgradeFinalizePhase") + } + if idxHook < 0 { + t.Fatal("Screen 0 hook missing: upgradeFinalizePhase must contain " + + "`if upgradeErr == nil && cfgUpgradeErr == nil { runWhatsnewAfterUpgrade(...) }` so Screen 0 opens only at the end of a fully successful upgrade") + } + if idxHook <= idxFooter { + t.Fatal("the Screen 0 hook (runWhatsnewAfterUpgrade) must come AFTER printUpgradeFooter") + } +} + +// TestShouldRunWhatsnewAfterUpgrade pins the post-upgrade gate: Screen 0 opens only on an +// interactive terminal AND when the operator did not request auto-yes. Auto-yes (`--upgrade +// y`) means non-interactive intent even under a pty (ssh -tt, Ansible, script -c), so it must +// skip the screen; otherwise a successful automated upgrade would stall until the Screen 0 +// timeout waiting for a keypress nobody sends. +func TestShouldRunWhatsnewAfterUpgrade(t *testing.T) { + orig := whatsnewAfterUpgradeInteractive + t.Cleanup(func() { whatsnewAfterUpgradeInteractive = orig }) + + cases := []struct { + name string + args *cli.Args + interactive bool + want bool + }{ + {"interactive human upgrade shows", &cli.Args{}, true, true}, + {"auto-yes under a pty skips (no stall)", &cli.Args{UpgradeAutoYes: true}, true, false}, + {"non-interactive skips", &cli.Args{}, false, false}, + {"auto-yes and non-interactive skips", &cli.Args{UpgradeAutoYes: true}, false, false}, + {"nil args skips", nil, true, false}, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + whatsnewAfterUpgradeInteractive = func() bool { return tc.interactive } + if got := shouldRunWhatsnewAfterUpgrade(tc.args); got != tc.want { + t.Fatalf("shouldRunWhatsnewAfterUpgrade = %v, want %v", got, tc.want) + } + }) + } +} + +// TestShowWhatsnewScreenSkipsWhenNonInteractive: a non-interactive re-invocation +// (--show-whatsnew piped or without a TTY) must return WITHOUT building a session or calling +// Decide, so an automated upgrade never blocks on a screen nobody can dismiss. +func TestShowWhatsnewScreenSkipsWhenNonInteractive(t *testing.T) { + origInter := dashboardIsInteractive + origDecide := whatsnewDecide + dashboardIsInteractive = func() bool { return false } + called := false + whatsnewDecide = func(baseDir, current string) (bool, string, error) { called = true; return false, "", nil } + t.Cleanup(func() { + dashboardIsInteractive = origInter + whatsnewDecide = origDecide + }) + + showWhatsnewScreen(context.Background(), &cli.Args{}, "0.30.0") + if called { + t.Fatal("non-interactive showWhatsnewScreen must not build a session or call Decide") + } +} + +// TestShowWhatsnewScreenSkipsUnderDryRun: a --dry-run invocation must not reach +// maybeShowWhatsnew (whose self-heal / continue write mutates the seen-flag), so Screen 0 is +// skipped even on an interactive terminal. Guards the FS-mutation-under-dry-run hole opened by +// making showWhatsnewScreen a non-bare caller of maybeShowWhatsnew. +func TestShowWhatsnewScreenSkipsUnderDryRun(t *testing.T) { + origInter := dashboardIsInteractive + origDecide := whatsnewDecide + dashboardIsInteractive = func() bool { return true } + called := false + whatsnewDecide = func(baseDir, current string) (bool, string, error) { called = true; return false, "", nil } + t.Cleanup(func() { + dashboardIsInteractive = origInter + whatsnewDecide = origDecide + }) + + showWhatsnewScreen(context.Background(), &cli.Args{DryRun: true}, "0.30.0") + if called { + t.Fatal("--dry-run showWhatsnewScreen must not call Decide or write the seen-flag") + } +} + +// TestShowWhatsnewScreenDelegatesWhenInteractive: on an interactive terminal showWhatsnewScreen +// builds a session and delegates to maybeShowWhatsnew, keyed on the RUNNING binary's version +// (the value passed in), so it renders from the binary's own compiled-in notes registry. +func TestShowWhatsnewScreenDelegatesWhenInteractive(t *testing.T) { + origInter := dashboardIsInteractive + origSess := testDashboardSession + origDecide := whatsnewDecide + dashboardIsInteractive = func() bool { return true } + testDashboardSession = func(ctx context.Context) *shell.Session { + return shell.StartForTest(ctx, shell.Config{AppName: "ProxSave", Subtitle: "Dashboard"}) + } + var gotVersion string + called := false + whatsnewDecide = func(baseDir, current string) (bool, string, error) { + called = true + gotVersion = current + return false, "", nil // no-show: maybeShowWhatsnew returns before touching the session + } + t.Cleanup(func() { + dashboardIsInteractive = origInter + testDashboardSession = origSess + whatsnewDecide = origDecide + releaseDashboardLeftovers() + }) + + showWhatsnewScreen(context.Background(), &cli.Args{}, "0.30.0-beta6") + if !called { + t.Fatal("interactive showWhatsnewScreen must delegate to maybeShowWhatsnew (Decide never called)") + } + if gotVersion != "0.30.0-beta6" { + t.Fatalf("Decide called with version %q, want the running binary version 0.30.0-beta6", gotVersion) + } +} + +// TestRunShowWhatsnewMode pins the --show-whatsnew mode gate: it falls through (handled=false) +// unless args.ShowWhatsnew is set, and when set it runs Screen 0 (delegates to Decide) and +// exits success. Screen 0 is best-effort, so the mode never returns a non-success code. +func TestRunShowWhatsnewMode(t *testing.T) { + origInter := dashboardIsInteractive + origSess := testDashboardSession + origDecide := whatsnewDecide + dashboardIsInteractive = func() bool { return true } + testDashboardSession = func(ctx context.Context) *shell.Session { + return shell.StartForTest(ctx, shell.Config{AppName: "ProxSave", Subtitle: "Dashboard"}) + } + decideCalls := 0 + whatsnewDecide = func(baseDir, current string) (bool, string, error) { decideCalls++; return false, "", nil } + t.Cleanup(func() { + dashboardIsInteractive = origInter + testDashboardSession = origSess + whatsnewDecide = origDecide + releaseDashboardLeftovers() + }) + + if code, handled := runShowWhatsnewMode(context.Background(), &cli.Args{ShowWhatsnew: false}, nil, "0.30.0"); handled { + t.Fatalf("mode must fall through when ShowWhatsnew=false (handled=%v, code=%d)", handled, code) + } + if decideCalls != 0 { + t.Fatalf("Decide must not run when ShowWhatsnew=false (calls=%d)", decideCalls) + } + + code, handled := runShowWhatsnewMode(context.Background(), &cli.Args{ShowWhatsnew: true}, nil, "0.30.0") + if !handled { + t.Fatal("mode must handle the run when ShowWhatsnew=true") + } + if code != types.ExitSuccess.Int() { + t.Fatalf("mode exit = %d, want success", code) + } + if decideCalls != 1 { + t.Fatalf("mode must run Screen 0 exactly once when ShowWhatsnew=true (Decide calls=%d)", decideCalls) + } +} diff --git a/internal/cli/args.go b/internal/cli/args.go index 695110ca..0c9418ae 100644 --- a/internal/cli/args.go +++ b/internal/cli/args.go @@ -46,7 +46,12 @@ type Args struct { UpgradeConfig bool UpgradeConfigDry bool UpgradeConfigJSON bool - CleanupGuards bool + // ShowWhatsnew runs ONLY Screen 0 (what's new) once and exits. Internal plumbing: + // the upgrade flow re-invokes the freshly installed binary with this flag so Screen 0 + // opens at the end of every upgrade, rendered by the binary that actually carries the + // notes (the notes registry is compiled into each binary). + ShowWhatsnew bool + CleanupGuards bool Backup bool Daemon bool DaemonSetup bool @@ -131,6 +136,9 @@ func Parse() *Args { flag.BoolVar(&args.UpgradeConfigJSON, "upgrade-config-json", false, "Upgrade configuration file using the embedded template and print JSON summary to stdout (for internal use by --upgrade)") + flag.BoolVar(&args.ShowWhatsnew, "show-whatsnew", false, + "Show the what's-new screen once and exit (for internal use by --upgrade)") + // Custom usage message flag.Usage = func() { printHelp(os.Stderr, os.Args[0]) diff --git a/internal/cli/args_test.go b/internal/cli/args_test.go index 82b2848b..a6ffe197 100644 --- a/internal/cli/args_test.go +++ b/internal/cli/args_test.go @@ -163,6 +163,33 @@ func TestParseUpgradeAutoYes(t *testing.T) { } } +// TestParseUpgradeAutoYesWithLocalfile pins the ordering contract upgrade-beta.sh depends on: +// `--upgrade y --localfile` must set BOTH UpgradeAutoYes (the `y` sits immediately after +// --upgrade, where extractUpgradeAutoYesArgs looks) AND LocalFile. If the token were placed +// after --localfile it would NOT be read as auto-yes, so this guards the script's finalize +// invocation against a silent regression that would re-introduce the pty stall. +func TestParseUpgradeAutoYesWithLocalfile(t *testing.T) { + args := parseWithArgs(t, []string{"--upgrade", "y", "--localfile"}) + if !args.Upgrade { + t.Fatal("Upgrade must be set") + } + if !args.UpgradeAutoYes { + t.Fatal("`--upgrade y --localfile` must set UpgradeAutoYes (y must sit immediately after --upgrade)") + } + if !args.LocalFile { + t.Fatal("`--upgrade y --localfile` must set LocalFile") + } +} + +func TestParseShowWhatsnew(t *testing.T) { + if args := parseWithArgs(t, nil); args.ShowWhatsnew { + t.Fatal("ShowWhatsnew must default to false") + } + if args := parseWithArgs(t, []string{"--show-whatsnew"}); !args.ShowWhatsnew { + t.Fatal("ShowWhatsnew should be true when --show-whatsnew is provided") + } +} + func parseWithArgs(t *testing.T, cliArgs []string) *Args { t.Helper() origCommandLine := flag.CommandLine diff --git a/internal/health/config.go b/internal/health/config.go index f56817b7..598bf613 100644 --- a/internal/health/config.go +++ b/internal/health/config.go @@ -25,6 +25,10 @@ var ( ErrHCNotReady = errors.New("healthcheck config: provisioning not ready") // ErrHCDisabled: healthcheck provisioning is turned off on the server. ErrHCDisabled = errors.New("healthcheck config: disabled on server") + // ErrHCParked: the server purged this host's row (its unused account was parked, + // design 11.2). Definitive like ErrHCAuth: the stale relay secret must be cleared + // so the next run re-provisions and the returning host is re-admitted. + ErrHCParked = errors.New("healthcheck config: server parked") ) // CentralizedConfig is the proxsave_server's answer for a client's two ping URLs. @@ -148,6 +152,11 @@ func fetchConfig(ctx context.Context, client *http.Client, serverAPIHost, server return CentralizedConfig{}, ErrHCAuth case http.StatusNotFound: return CentralizedConfig{}, ErrHCUnknown + case http.StatusGone: + // 410 SERVER_PARKED: the row was purged but this host still holds the old + // token. Treat like a definitive auth rejection so the daemon clears the + // stale secret and re-provisions (which re-admits the returning host). + return CentralizedConfig{}, ErrHCParked case http.StatusServiceUnavailable: // The server returns HC_DISABLED (feature off) or HC_NOT_READY (provisioning // not done yet). Distinguish so the daemon logs the right thing. diff --git a/internal/health/config_test.go b/internal/health/config_test.go index 6bdda343..704e48e7 100644 --- a/internal/health/config_test.go +++ b/internal/health/config_test.go @@ -97,6 +97,7 @@ func TestFetchCentralizedConfigErrors(t *testing.T) { {"auth 401", 401, `{"error":"AUTH_INVALID"}`, ErrHCAuth}, {"auth 403", 403, `{"error":"AUTH_INVALID"}`, ErrHCAuth}, {"unknown 404", 404, `{"error":"SERVER_UNKNOWN"}`, ErrHCUnknown}, + {"parked 410", 410, `{"error":"SERVER_PARKED"}`, ErrHCParked}, {"disabled 503", 503, `{"error":"HC_DISABLED"}`, ErrHCDisabled}, {"not ready 503", 503, `{"error":"HC_NOT_READY"}`, ErrHCNotReady}, } @@ -134,7 +135,7 @@ func TestFetchCentralizedConfigGenericStatus(t *testing.T) { if err == nil { t.Fatalf("expected error on HTTP 500") } - for _, sentinel := range []error{ErrHCAuth, ErrHCUnknown, ErrHCNotReady, ErrHCDisabled} { + for _, sentinel := range []error{ErrHCAuth, ErrHCUnknown, ErrHCNotReady, ErrHCDisabled, ErrHCParked} { if errors.Is(err, sentinel) { t.Fatalf("500 should be a generic error, not %v", sentinel) } diff --git a/internal/logging/capture.go b/internal/logging/capture.go index 06d5b99d..162474f4 100644 --- a/internal/logging/capture.go +++ b/internal/logging/capture.go @@ -62,6 +62,57 @@ func (w *lineWriter) Write(p []byte) (int, error) { return len(p), nil } +// LineBacklog is a bounded, thread-safe io.Writer that retains the most recent +// complete lines written to it (ANSI escapes PRESERVED, like NewLineWriterRaw), so +// a late-attaching consumer can replay everything produced before it existed. It +// is the buffer behind Logger.SetMirror: the run logger tees its colored stream +// here while the graphical viewport does not yet exist, then the viewport drains +// Lines() once it is on the stack. Retention is bounded: the newest max lines are +// always kept and the total never exceeds 2*max (older lines are dropped in an +// amortized compaction, since a wedged/absent consumer can only ever review the +// newest anyway). +type LineBacklog struct { + mu sync.Mutex + lines []string + max int + w io.Writer // NewLineWriterRaw(b.append): splits on '\n', keeps ANSI +} + +// NewLineBacklog returns a LineBacklog that always retains the newest max complete +// lines (and at most 2*max at any instant). A non-positive max is clamped to 1. +func NewLineBacklog(max int) *LineBacklog { + if max <= 0 { + max = 1 + } + b := &LineBacklog{max: max} + b.w = NewLineWriterRaw(b.append) + return b +} + +// Write feeds bytes through the line splitter; complete lines are retained. +func (b *LineBacklog) Write(p []byte) (int, error) { return b.w.Write(p) } + +func (b *LineBacklog) append(line string) { + b.mu.Lock() + b.lines = append(b.lines, line) + // Amortized trim: let the slice grow to 2*max, then compact to the newest max + // in one copy. This keeps the steady-state cost O(1) per line (instead of an + // O(max) copy on every line past the cap) while never retaining more than 2*max + // lines. The compaction copies into a fresh slice so the large backing array is + // released rather than pinned by a reslice. + if len(b.lines) > 2*b.max { + b.lines = append([]string(nil), b.lines[len(b.lines)-b.max:]...) + } + b.mu.Unlock() +} + +// Lines returns a snapshot copy of the retained lines, oldest first. +func (b *LineBacklog) Lines() []string { + b.mu.Lock() + defer b.mu.Unlock() + return append([]string(nil), b.lines...) +} + // CaptureConsole is the SINGLE place that wires the loggers to w so a full-screen // UI (or any phase that wants its own log lines) can stream them. It: // diff --git a/internal/logging/logger.go b/internal/logging/logger.go index 33f0b5fc..e149d35e 100644 --- a/internal/logging/logger.go +++ b/internal/logging/logger.go @@ -70,6 +70,14 @@ type Logger struct { issueLines []string // Captured WARNING/ERROR/CRITICAL lines for end-of-run summary exitFunc func(int) secrets []secretForm // registered secret values scrubbed from every log line + // mirror is an optional COLORED tap that receives a copy of every line the + // logger records, on BOTH the standard path (logWithLabel) AND the raw path + // (AppendRaw). It is parallel to the file sink, not to the console: the console + // can be muted (SwapOutput to io.Discard during a UI handoff) while the mirror + // still captures the full stream, so a late-attaching graphical viewport can + // replay everything the on-disk log already has (banner, environment, preflight) + // instead of starting mid-run. nil disables it. Guarded by mu. + mirror io.Writer } // RegisterSecret records a secret value so it is masked out of every subsequent @@ -136,6 +144,19 @@ func (l *Logger) SetOutput(w io.Writer) { l.output = w } +// SetMirror sets (or clears, with nil) the optional COLORED mirror tap. Every +// line the logger records is copied to w in the same colored "[ts] LEVEL msg" +// shape the console uses, on both the standard and the raw (AppendRaw) paths, +// independently of the console writer (which a UI handoff may mute). A late +// graphical consumer sets it before the run's early lines are logged, drains the +// captured lines when its viewport exists, then clears it (SetMirror(nil)) so the +// live stream is not double-captured. +func (l *Logger) SetMirror(w io.Writer) { + l.mu.Lock() + l.mirror = w + l.mu.Unlock() +} + // SetIOTimeout bounds subsequent log-file open/write/close operations so a dead or // stale LOG_PATH mount cannot wedge the logger in an uninterruptible syscall. A // non-positive value restores unbounded behaviour (the FS_IO_TIMEOUT=0 opt-out). @@ -448,6 +469,12 @@ func (l *Logger) logWithLabel(level types.LogLevel, label string, colorOverride // Write to stdout with colors. _, _ = fmt.Fprint(l.output, outputStdout) + // Mirror the COLORED line to the optional tap (parallel to the file sink, so a + // muted console never starves it). In-memory, non-blocking; never wedges l.mu. + if l.mirror != nil { + _, _ = io.WriteString(l.mirror, outputStdout) + } + // If a log file is open and not disabled, write there too (without colors), // bounded so a dead/stale mount cannot wedge logging while holding l.mu. if l.logFile != nil && !l.fileSinkDisabled { @@ -631,10 +658,18 @@ func (l *Logger) Fatal(exitCode types.ExitCode, format string, args ...interface func (l *Logger) AppendRaw(message string) { l.mu.Lock() defer l.mu.Unlock() + timestamp := time.Now().Format(l.timeFormat) + // Mirror the raw line to the COLORED tap as an INFO-level line (the same shape + // the file records it, and the same color logWithLabel gives Info), so a + // graphical viewport replays the early banner even though the console path + // deliberately skips raw lines. Done before the file-sink guard so a viewport + // never depends on the log file being open. + if l.mirror != nil { + _, _ = io.WriteString(l.mirror, FormatConsoleLogLine(timestamp, types.LogLevelInfo, message, l.useColor)) + } if l.logFile == nil || l.fileSinkDisabled { return } - timestamp := time.Now().Format(l.timeFormat) output := fmt.Sprintf("[%s] %-8s %s\n", timestamp, types.LogLevelInfo.String(), diff --git a/internal/notify/email.go b/internal/notify/email.go index 712e821e..93c04771 100644 --- a/internal/notify/email.go +++ b/internal/notify/email.go @@ -196,12 +196,12 @@ func (e *EmailNotifier) Send(ctx context.Context, data *NotificationData) (*Noti e.logger.Debug("Email recipient not configured, attempting auto-detection...") detectedRecipient, err := e.detectRecipient(ctx) if err != nil { - e.logger.Warning("WARNING: Failed to detect email recipient: %v", err) + e.logger.Debug("Email: recipient auto-detection failed (surfaced by the adapter on a terminal skip): %v", err) switch e.config.DeliveryMethod { case EmailDeliveryPMF: e.logger.Info(" Proceeding anyway because EMAIL_DELIVERY_METHOD=pmf routes via Proxmox Notifications; recipient is only used for the To: header") default: - e.logger.Warning("WARNING: Email notification skipped because no valid recipient is available") + e.logger.Debug("Email: skipped, no valid recipient (surfaced once by the notification adapter)") e.logger.Info(" Configure EMAIL_RECIPIENT or set an email address for root@pam inside Proxmox") result.Success = false result.Duration = time.Since(startTime) @@ -220,7 +220,7 @@ func (e *EmailNotifier) Send(ctx context.Context, data *NotificationData) (*Noti if recipient == "" { switch e.config.DeliveryMethod { case EmailDeliveryRelay, EmailDeliverySendmail: - e.logger.Warning("WARNING: Email recipient is empty after configuration/detection") + e.logger.Debug("Email: recipient empty after configuration/detection (surfaced once by the notification adapter)") e.logger.Info(" Configure EMAIL_RECIPIENT or set an email address for root@pam inside Proxmox") result.Success = false result.Duration = time.Since(startTime) @@ -246,9 +246,9 @@ func (e *EmailNotifier) Send(ctx context.Context, data *NotificationData) (*Noti e.logger.Debug("Email fallback decision: stage=preflight reason=%s cause=%v", preflightFallbackReason, preflightFallbackCause) } else { if autoDetected { - e.logger.Warning("WARNING: Auto-detected recipient %s belongs to root and will be rejected", redactedRecipient) + e.logger.Debug("Email: auto-detected recipient %s belongs to root and will be rejected (surfaced once by the notification adapter)", redactedRecipient) } else { - e.logger.Warning("WARNING: Configured email recipient %s belongs to root and will be rejected", redactedRecipient) + e.logger.Debug("Email: configured recipient %s belongs to root and will be rejected (surfaced once by the notification adapter)", redactedRecipient) } e.logger.Info(" Configure EMAIL_RECIPIENT with a non-root mailbox to enable notifications") result.Success = false @@ -273,7 +273,7 @@ func (e *EmailNotifier) Send(ctx context.Context, data *NotificationData) (*Noti redactedRecipient := redactEmail(recipient) switch e.config.DeliveryMethod { case EmailDeliveryRelay, EmailDeliverySendmail: - e.logger.Warning("WARNING: Invalid email recipient format: %s", redactedRecipient) + e.logger.Debug("Email: invalid recipient format %s (surfaced once by the notification adapter)", redactedRecipient) e.logger.Info(" Configure EMAIL_RECIPIENT with a valid email address") result.Success = false result.Duration = time.Since(startTime) @@ -345,7 +345,7 @@ func (e *EmailNotifier) Send(ctx context.Context, data *NotificationData) (*Noti if err != nil { // Both primary and fallback failed (or no fallback configured) - e.logger.Warning("WARNING: Failed to send email notification: %v", err) + e.logger.Debug("Email: send failed (surfaced once by the notification adapter): %v", err) result.Success = false result.Error = err return result, nil // Non-critical error @@ -353,8 +353,10 @@ func (e *EmailNotifier) Send(ctx context.Context, data *NotificationData) (*Noti // Success (either primary or fallback) if result.UsedFallback { - // Fallback succeeded after relay failure - e.logger.Warning("⚠️ Email sent via fallback after primary delivery failure") + // Fallback succeeded after relay failure. The adapter emits the single + // "sent via fallback" WARNING for the channel; keep this at Debug so it is + // not double-reported. + e.logger.Debug("Email: sent via fallback after primary delivery failure") } // Log according to delivery method to avoid implying guaranteed inbox delivery diff --git a/internal/notify/gotify.go b/internal/notify/gotify.go index d242c5a3..43123136 100644 --- a/internal/notify/gotify.go +++ b/internal/notify/gotify.go @@ -100,7 +100,7 @@ func (g *GotifyNotifier) Send(ctx context.Context, data *NotificationData) (*Not endpoint, err := g.buildEndpoint() if err != nil { - g.logger.Warning("WARNING: Invalid Gotify configuration: %v", err) + g.logger.Debug("Gotify: invalid configuration (surfaced once by the notification adapter): %v", err) result.Success = false result.Error = err result.Duration = time.Since(start) @@ -116,7 +116,7 @@ func (g *GotifyNotifier) Send(ctx context.Context, data *NotificationData) (*Not body, err := json.Marshal(payload) if err != nil { err = fmt.Errorf("failed to marshal Gotify payload: %w", err) - g.logger.Warning("WARNING: %v", err) + g.logger.Debug("Gotify send failed (surfaced once by the notification adapter): %v", err) result.Success = false result.Error = err result.Duration = time.Since(start) @@ -126,7 +126,7 @@ func (g *GotifyNotifier) Send(ctx context.Context, data *NotificationData) (*Not req, err := http.NewRequestWithContext(ctx, "POST", endpoint, bytes.NewReader(body)) if err != nil { err = fmt.Errorf("failed to create Gotify request: %w", err) - g.logger.Warning("WARNING: %v", err) + g.logger.Debug("Gotify send failed (surfaced once by the notification adapter): %v", err) result.Success = false result.Error = err result.Duration = time.Since(start) @@ -139,7 +139,7 @@ func (g *GotifyNotifier) Send(ctx context.Context, data *NotificationData) (*Not // The token is in the URL query, URL-encoded inside the *url.Error; // RedactSecrets masks both the raw and URL-encoded forms. err = fmt.Errorf("gotify request failed: %s", logging.RedactSecrets(err.Error(), g.config.Token)) - g.logger.Warning("WARNING: %v", err) + g.logger.Debug("Gotify send failed (surfaced once by the notification adapter): %v", err) result.Success = false result.Error = err result.Duration = time.Since(start) @@ -152,7 +152,7 @@ func (g *GotifyNotifier) Send(ctx context.Context, data *NotificationData) (*Not if resp.StatusCode < 200 || resp.StatusCode >= 300 { err = fmt.Errorf("gotify returned HTTP %d: %s", resp.StatusCode, strings.TrimSpace(string(respBody))) - g.logger.Warning("WARNING: %v", err) + g.logger.Debug("Gotify send failed (surfaced once by the notification adapter): %v", err) result.Success = false result.Error = err result.Duration = time.Since(start) diff --git a/internal/notify/relay_provision.go b/internal/notify/relay_provision.go index 539e3a75..03f0f853 100644 --- a/internal/notify/relay_provision.go +++ b/internal/notify/relay_provision.go @@ -4,55 +4,178 @@ import ( "context" "fmt" "net/http" + "strconv" "strings" + "time" "github.com/tis24dev/proxsave/internal/identity" "github.com/tis24dev/proxsave/internal/logging" + "github.com/tis24dev/proxsave/internal/serverbot" ) -// ProvisionRelaySecret performs the get-chat-id handshake WITH provision intent and, on a -// 200 that issues a notify_secret, persists it (immutable identity file) and confirms it -// back to the server so the centralized healthcheck fetch can authenticate WITHOUT any -// Telegram pairing. Now that the server issues the relay secret for a chat-less known -// ServerID, this is the generic, Telegram-independent provisioning entry point used by the -// healthcheck self-heal hooks. +// provisionTimeout bounds the relay-provision POST; callers retry on the next run. +const provisionTimeout = 5 * time.Second + +// relayProvisionMaxRetryAfter bounds a server-supplied Retry-After. The relay's +// longest rolling admission window is 24h; a larger value is treated as 24h so a +// malformed response cannot suppress self-healing indefinitely. +const relayProvisionMaxRetryAfter = 24 * time.Hour + +// RelayProvisionRateLimitError is returned for HTTP 429. RetryAfter is zero when +// the header is absent/invalid; callers then keep their existing local retry floor. +// A typed error lets the daemon honor server backpressure without exposing or +// logging the untrusted response body. +type RelayProvisionRateLimitError struct { + RetryAfter time.Duration +} + +func (e *RelayProvisionRateLimitError) Error() string { + if e != nil && e.RetryAfter > 0 { + return fmt.Sprintf("relay provision: rate limited (HTTP 429; retry after %s)", e.RetryAfter) + } + return "relay provision: rate limited (HTTP 429)" +} + +func parseRelayProvisionRetryAfter(raw string, now time.Time) time.Duration { + raw = strings.TrimSpace(raw) + if raw == "" { + return 0 + } + if seconds, err := strconv.ParseInt(raw, 10, 64); err == nil { + if seconds <= 0 { + return 0 + } + if seconds > int64(relayProvisionMaxRetryAfter/time.Second) { + return relayProvisionMaxRetryAfter + } + return time.Duration(seconds) * time.Second + } + when, err := http.ParseTime(raw) + if err != nil { + return 0 + } + d := when.Sub(now) + if d <= 0 { + return 0 + } + if d > relayProvisionMaxRetryAfter { + return relayProvisionMaxRetryAfter + } + return d +} + +// relayProvisionResponse is the JSON of POST /api/relay/provision: a 201 carries +// notify_secret; a 200 carries status=="already_provisioned". The RELAY_* error field +// is deliberately NOT decoded here (untrusted text); the status code drives the logic. +type relayProvisionResponse struct { + NotifySecret string `json:"notify_secret"` + Status string `json:"status"` +} + +// provisionViaRelay POSTs the dedicated, Telegram-independent provisioning endpoint +// POST /api/relay/provision (unauthenticated: the endpoint ISSUES the per-server token) +// with {server_id} plus the shared X-Proxsave-Version header. It returns: // -// It reuses the exact three bricks the Telegram path uses - -// checkTelegramRegistrationWithSecret(provision=true), identity.PersistNotifySecret, and -// confirmTelegramRelaySecret - so both paths share one wire contract and one log-masking -// path. The issued secret is registered with the logger's masker inside -// checkTelegramRegistrationWithSecret BEFORE any body preview is logged. +// (secret, false, nil) on 201 with a notify_secret -> adopt + confirm +// ("", true, nil) on 200 already_provisioned -> nothing to adopt +// ("", false, err) on 429 (retryable) / any other code / transport error +// +// The untrusted response body is NEVER embedded in the returned error (only the status +// code), and the issued secret is registered with the logger's masker before any later +// log line can preview it. +func provisionViaRelay(ctx context.Context, serverAPIHost, serverID string, logger *logging.Logger) (string, bool, error) { + resp, err := serverbot.New(serverAPIHost, http.DefaultClient, logger).Do(ctx, serverbot.Request{ + Method: http.MethodPost, + Path: "/api/relay/provision", + Body: struct { + ServerID string `json:"server_id"` + }{ServerID: serverID}, + Timeout: provisionTimeout, + MaxBytes: 8192, + }) + if err != nil { + return "", false, fmt.Errorf("relay provision: request failed: %w", err) + } + switch resp.Status { + case http.StatusCreated: // 201: fresh token issued + var body relayProvisionResponse + if jerr := resp.JSON(&body); jerr != nil { + return "", false, fmt.Errorf("relay provision: bad 201 JSON: %w", jerr) + } + secret := strings.TrimSpace(body.NotifySecret) + if secret == "" { + return "", false, fmt.Errorf("relay provision: 201 without notify_secret") + } + if logger != nil { + logger.RegisterSecret(secret) + } + return secret, false, nil + case http.StatusOK: // 200: already provisioned + confirmed server-side + var body relayProvisionResponse + if jerr := resp.JSON(&body); jerr != nil { + return "", false, fmt.Errorf("relay provision: bad 200 JSON: %w", jerr) + } + if body.Status != "already_provisioned" { + return "", false, fmt.Errorf("relay provision: unexpected 200 status") + } + // No new token is minted. We have nothing to adopt this run; a lost local + // secret is not recoverable here (the row self-heals via purge + recreation + // later, or a fresh recreation re-issues). Do NOT try to read a token that + // is not in the body. + return "", true, nil + case http.StatusTooManyRequests: // 429: rolling/total admission cap + // A TEMPORARY refusal. Persist nothing; the caller retries on the next run. + return "", false, &RelayProvisionRateLimitError{ + RetryAfter: parseRelayProvisionRetryAfter( + resp.Header.Get("Retry-After"), time.Now()), + } + default: + // 400 / 422 / 426 / 500 / 503 / ... The body is untrusted, so the error + // carries only the status code. + return "", false, fmt.Errorf("relay provision: unexpected status %d", resp.Status) + } +} + +// ProvisionRelaySecret provisions this host's per-server relay token WITHOUT any Telegram +// pairing, via the dedicated POST /api/relay/provision endpoint: on a 201 it persists the +// issued token (immutable identity file) and confirms it (/api/confirm-secret) so the +// centralized healthcheck fetch and the notify relay can authenticate. This is the generic +// provisioning entry point used by the healthcheck self-heal hooks and the SERVER_PARKED +// recovery path. +// +// The legacy /api/get-chat-id handshake is intentionally NOT used here: for a chat-less +// (Telegram-independent) server it returns 409 before ever issuing a token, so Option A +// could never provision through it. get-chat-id remains the Telegram/v0.29 path unchanged. // // Returns provisioned=true once the secret is on disk (a confirm failure is NON-FATAL: the // hash the server stored on issuance already authenticates the fetch, and the server // re-confirms on the next run). Every other outcome returns (false, err-or-nil): -// - a non-200 handshake -> (false, err) -// - a 200 that issued no secret -> (false, nil) [nothing to adopt] -// - an empty baseDir -> (false, err) -// - an issued secret < identity.NotifySecretMinLen runes -> (false, err) [defensive floor] -// - a persist failure -> (false, err) +// - a non-201 refusal (429 retryable, or another code) -> (false, err) +// - a 200 already_provisioned (nothing to adopt) -> (false, nil) +// - a 201 with no token -> (false, err) +// - an empty baseDir -> (false, err) +// - an issued secret < identity.NotifySecretMinLen runes -> (false, err) [defensive floor] +// - a persist failure -> (false, err) // // Callers MUST treat a non-nil err as "retry later" and NEVER block on it. func ProvisionRelaySecret(ctx context.Context, serverAPIHost, serverID, baseDir string, logger *logging.Logger) (bool, error) { if strings.TrimSpace(baseDir) == "" { return false, fmt.Errorf("relay provision: empty baseDir, cannot persist relay secret") } - // Serialize the entire issue -> persist -> confirm across processes. Hook a (installer) - // and hook b (an enable-now daemon) can run concurrently against the same server_id; - // two DISTINCT minted secrets would strand the host (last-write-wins on disk vs the - // server's confirm-locks-reissue). An exclusive advisory lock on the identity dir makes - // exactly one minter win; the loser adopts the winner's on-disk secret below. + // Serialize issue -> persist -> confirm across processes. Hook a (installer) and + // hook b (an enable-now daemon) can run concurrently against the same server_id; two + // DISTINCT minted secrets would strand the host (last-write-wins on disk vs the + // server's confirm-locks-reissue). An exclusive advisory lock on the identity dir + // makes exactly one minter win; the loser adopts the winner's on-disk secret below. unlock, err := identity.LockNotifySecret(baseDir) if err != nil { return false, fmt.Errorf("relay provision: lock: %w", err) } defer unlock() // Re-check UNDER the lock: if a concurrent minter already persisted a secret, adopt it - // instead of minting a competing one. Returns (false, nil) - nothing to provision - so - // the caller reads the winner's secret from disk on its next fetch. A real read error - // (the file exists but could not be read) is surfaced rather than swallowed: proceeding - // would mint a fresh secret OVER a value we failed to read. Missing/empty/malformed still - // yields ("", nil) per the loader contract, so we fall through and provision. + // instead of minting a competing one. A real read error (the file exists but could not + // be read) is surfaced rather than swallowed; missing/empty/malformed yields ("", nil) + // per the loader contract, so we fall through and provision. if s, err := identity.LoadNotifySecret(baseDir); err != nil { return false, fmt.Errorf("relay provision: re-check load: %w", err) } else if strings.TrimSpace(s) != "" { @@ -60,16 +183,27 @@ func ProvisionRelaySecret(ctx context.Context, serverAPIHost, serverID, baseDir return false, nil } - status, secret := checkTelegramRegistrationWithSecret(ctx, serverAPIHost, serverID, true, logger) - if status.Code != 200 { - // Do NOT wrap the raw server body (status.Error) into the returned error: it is - // untrusted text. The status code alone is enough for the caller to degrade/retry. - return false, fmt.Errorf("relay provision: get-chat-id returned status %d", status.Code) - } - if secret == "" { - // Linked/known but the server issued no (new) token - e.g. the secret is already - // confirmed server-side. Nothing to adopt; not an error. - logTelegramRegistrationDebug(logger, "relay provision: 200 without token (nothing to provision)") + secret, alreadyProvisioned, err := provisionViaRelay(ctx, serverAPIHost, serverID, logger) + if err != nil { + return false, err + } + if alreadyProvisioned { + // This branch is reached only with NO local secret (re-checked under the lock + // above) yet the server reports a CONFIRMED registration. The server re-mints for + // an UNCONFIRMED row (returning 201), so this is specifically the confirmed-then- + // lost case: the server keeps only the secret's sha256 and cannot hand back the + // plaintext, and re-minting a confirmed token for an unauthenticated caller would + // let anyone knowing the 16-digit server_id rotate another host's secret. There is + // therefore no safe in-band recovery, so surface it at WARNING (not a silent Debug) + // instead of returning a misleading success. An eligible chat-less row still self- + // heals through the server-side purge + recreation, which re-issues a fresh token. + if logger != nil { + logger.Warning("Relay provisioning: server_id is already provisioned server-side " + + "but no local relay secret is present; a confirmed token cannot be re-minted " + + "automatically. Centralized healthcheck config fetch and relay notifications stay " + + "unavailable until the server-side row is purged and recreated (automatic once the " + + "row is purge-eligible) or cleared by an operator.") + } return false, nil } // Defensive length floor (shared with the persistence sink): an issued secret shorter diff --git a/internal/notify/relay_provision_test.go b/internal/notify/relay_provision_test.go index 9d54fa39..1e6db92f 100644 --- a/internal/notify/relay_provision_test.go +++ b/internal/notify/relay_provision_test.go @@ -2,130 +2,285 @@ package notify import ( "context" + "encoding/json" + "errors" + "io" "net/http" "net/http/httptest" "os" + "path/filepath" "strings" "testing" + "time" "github.com/tis24dev/proxsave/internal/identity" ) -// These tests reuse routingSecretServer, provisionCapture, provisionTestSecret and -// newProvisionTestLogger from telegram_registration_provision_test.go (same package). +// These tests reuse provisionTestSecret and newProvisionTestLogger from +// telegram_registration_provision_test.go (same package). The provision path now targets +// POST /api/relay/provision, NOT the legacy GET /api/get-chat-id. -func TestProvisionRelaySecretHappyPath(t *testing.T) { +type relayCapture struct { + provisionHits int + method string + path string + version string + serverIDBody string + authHeader string // X-Server-Auth on the provision call (must stay empty) + retryAfter string // optional response Retry-After + confirmHits int + confirmAuth string +} + +// relayProvisionServer routes POST /api/relay/provision (returning provisionStatus + +// provisionBody) and POST /api/confirm-secret (returning confirmStatus), capturing the +// method/path/version/body of the provision call for the wire-contract assertions. +func relayProvisionServer(t *testing.T, provisionStatus int, provisionBody string, confirmStatus int, capt *relayCapture) *httptest.Server { + t.Helper() + return httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + switch r.URL.Path { + case "/api/relay/provision": + capt.provisionHits++ + capt.method = r.Method + capt.path = r.URL.Path + capt.version = r.Header.Get("X-Proxsave-Version") + capt.authHeader = r.Header.Get("X-Server-Auth") + var body struct { + ServerID string `json:"server_id"` + } + b, _ := io.ReadAll(r.Body) + _ = json.Unmarshal(b, &body) + capt.serverIDBody = body.ServerID + if capt.retryAfter != "" { + w.Header().Set("Retry-After", capt.retryAfter) + } + w.WriteHeader(provisionStatus) + _, _ = w.Write([]byte(provisionBody)) + case "/api/confirm-secret": + capt.confirmHits++ + capt.confirmAuth = r.Header.Get("X-Server-Auth") + w.WriteHeader(confirmStatus) + _, _ = w.Write([]byte(`{"status":"ok"}`)) + default: + t.Errorf("unexpected path: %s", r.URL.Path) + w.WriteHeader(http.StatusNotFound) + } + })) +} + +// Mandatory contract 1-5: POST, exact path, body carries server_id, X-Proxsave-Version +// sent (and no X-Server-Auth), a 201 with notify_secret persists AND confirms the token. +func TestProvisionRelaySecretPostsToRelayProvision(t *testing.T) { logger, buf := newProvisionTestLogger() baseDir := t.TempDir() - var capture provisionCapture - server := routingSecretServer(t, `{"notify_secret":"`+provisionTestSecret+`","status":200}`, http.StatusOK, &capture) + var capt relayCapture + server := relayProvisionServer(t, http.StatusCreated, `{"notify_secret":"`+provisionTestSecret+`"}`, http.StatusOK, &capt) defer server.Close() - provisioned, err := ProvisionRelaySecret(context.Background(), server.URL, "server-123", baseDir, logger) + provisioned, err := ProvisionRelaySecret(context.Background(), server.URL, "1234567890123456", baseDir, logger) if err != nil || !provisioned { t.Fatalf("provisioned=%v err=%v, want true/nil", provisioned, err) } - if loaded, _ := identity.LoadNotifySecret(baseDir); loaded != provisionTestSecret { - t.Fatalf("persisted secret = %q, want %q", loaded, provisionTestSecret) + if capt.method != http.MethodPost { + t.Fatalf("method = %q, want POST", capt.method) + } + if capt.path != "/api/relay/provision" { + t.Fatalf("path = %q, want /api/relay/provision", capt.path) } - if capture.provisionHeader != "1" { - t.Fatalf("X-Proxsave-Provision = %q, want 1", capture.provisionHeader) + if capt.serverIDBody != "1234567890123456" { + t.Fatalf("body server_id = %q, want 1234567890123456", capt.serverIDBody) } - if capture.confirmHits != 1 { - t.Fatalf("confirm hits = %d, want 1", capture.confirmHits) + if capt.version == "" { + t.Fatalf("X-Proxsave-Version header missing") } - if capture.confirmAuth != provisionTestSecret { - t.Fatalf("confirm X-Server-Auth = %q, want %q", capture.confirmAuth, provisionTestSecret) + if capt.authHeader != "" { + t.Fatalf("relay/provision must be unauthenticated, got X-Server-Auth=%q", capt.authHeader) + } + if loaded, _ := identity.LoadNotifySecret(baseDir); loaded != provisionTestSecret { + t.Fatalf("persisted secret = %q, want %q", loaded, provisionTestSecret) + } + if capt.confirmHits != 1 || capt.confirmAuth != provisionTestSecret { + t.Fatalf("confirm hits=%d auth=%q, want 1/%q", capt.confirmHits, capt.confirmAuth, provisionTestSecret) } if strings.Contains(buf.String(), provisionTestSecret) { t.Fatalf("plaintext secret leaked into logs:\n%s", buf.String()) } } +// Mandatory contract 6: a 200 already_provisioned does not try to read a non-existent +// token; nothing is persisted and confirm is not called. +func TestProvisionRelaySecretAlreadyProvisioned(t *testing.T) { + logger, buf := newProvisionTestLogger() + baseDir := t.TempDir() + var capt relayCapture + server := relayProvisionServer(t, http.StatusOK, `{"status":"already_provisioned"}`, http.StatusOK, &capt) + defer server.Close() + + provisioned, err := ProvisionRelaySecret(context.Background(), server.URL, "1234567890123456", baseDir, logger) + if provisioned || err != nil { + t.Fatalf("already_provisioned: want (false,nil), got (%v,%v)", provisioned, err) + } + if loaded, _ := identity.LoadNotifySecret(baseDir); loaded != "" { + t.Fatalf("nothing must be persisted, got %q", loaded) + } + if capt.confirmHits != 0 { + t.Fatalf("already_provisioned -> no confirm, got %d", capt.confirmHits) + } + // The stuck state (confirmed server-side, no local secret, not re-mintable) must be + // surfaced, not swallowed at Debug, so an operator can see a host that cannot recover + // in-band. + if !strings.Contains(buf.String(), "already provisioned server-side") { + t.Fatalf("already_provisioned with no local secret must WARN about the unrecoverable state; log was:\n%s", buf.String()) + } +} + +func TestProvisionRelaySecretRejectsMalformedAlreadyProvisioned200(t *testing.T) { + for _, body := range []string{ + `not-json`, + `{"status":"something_else"}`, + `{}`, + } { + t.Run(body, func(t *testing.T) { + logger, _ := newProvisionTestLogger() + baseDir := t.TempDir() + var capt relayCapture + server := relayProvisionServer( + t, http.StatusOK, body, http.StatusOK, &capt) + defer server.Close() + + provisioned, err := ProvisionRelaySecret( + context.Background(), server.URL, + "1234567890123456", baseDir, logger) + if provisioned || err == nil { + t.Fatalf("malformed 200 must fail: got (%v,%v)", provisioned, err) + } + if loaded, _ := identity.LoadNotifySecret(baseDir); loaded != "" { + t.Fatalf("malformed 200 must persist nothing, got %q", loaded) + } + }) + } +} + +// Mandatory contract 7: a 429 persists nothing and is a retryable failure. +func TestProvisionRelaySecretRateLimitedRetryable(t *testing.T) { + logger, _ := newProvisionTestLogger() + baseDir := t.TempDir() + capt := relayCapture{retryAfter: "7200"} + server := relayProvisionServer(t, http.StatusTooManyRequests, `{"error":"RELAY_RATE_LIMITED"}`, http.StatusOK, &capt) + defer server.Close() + + provisioned, err := ProvisionRelaySecret(context.Background(), server.URL, "1234567890123456", baseDir, logger) + if provisioned || err == nil { + t.Fatalf("429 must be a retryable failure: got (%v,%v)", provisioned, err) + } + var limited *RelayProvisionRateLimitError + if !errors.As(err, &limited) { + t.Fatalf("429 error type = %T, want *RelayProvisionRateLimitError", err) + } + if limited.RetryAfter != 2*time.Hour { + t.Fatalf("RetryAfter = %v, want 2h", limited.RetryAfter) + } + if loaded, _ := identity.LoadNotifySecret(baseDir); loaded != "" { + t.Fatalf("429 must persist nothing, got %q", loaded) + } + if capt.confirmHits != 0 { + t.Fatalf("429 -> no confirm, got %d", capt.confirmHits) + } +} + +func TestParseRelayProvisionRetryAfterClampsBeforeDurationOverflow(t *testing.T) { + // 2^55 seconds multiplied by 1e9ns wraps a time.Duration to zero. The + // parser must clamp in integer seconds before converting. + const wrapsDurationToZero = "36028797018963968" + if got := parseRelayProvisionRetryAfter( + wrapsDurationToZero, time.Unix(0, 0), + ); got != relayProvisionMaxRetryAfter { + t.Fatalf("huge Retry-After = %v, want clamp %v", + got, relayProvisionMaxRetryAfter) + } +} + func TestProvisionRelaySecretConfirmFailureIsNonFatal(t *testing.T) { logger, buf := newProvisionTestLogger() baseDir := t.TempDir() - var capture provisionCapture - server := routingSecretServer(t, `{"notify_secret":"`+provisionTestSecret+`","status":200}`, http.StatusForbidden, &capture) + var capt relayCapture + server := relayProvisionServer(t, http.StatusCreated, `{"notify_secret":"`+provisionTestSecret+`"}`, http.StatusForbidden, &capt) defer server.Close() - provisioned, err := ProvisionRelaySecret(context.Background(), server.URL, "server-123", baseDir, logger) + provisioned, err := ProvisionRelaySecret(context.Background(), server.URL, "1234567890123456", baseDir, logger) if err != nil || !provisioned { - t.Fatalf("confirm 403 must stay provisioned: provisioned=%v err=%v", provisioned, err) + t.Fatalf("confirm 403 must stay provisioned: (%v,%v)", provisioned, err) } if loaded, _ := identity.LoadNotifySecret(baseDir); loaded != provisionTestSecret { t.Fatalf("secret must persist despite confirm failure, got %q", loaded) } - if capture.confirmHits != 1 { - t.Fatalf("confirm hits = %d, want 1", capture.confirmHits) + if capt.confirmHits != 1 { + t.Fatalf("confirm hits = %d, want 1", capt.confirmHits) } if strings.Contains(buf.String(), provisionTestSecret) { t.Fatalf("plaintext secret leaked into logs:\n%s", buf.String()) } } -func TestProvisionRelaySecretNoTokenNoPersist(t *testing.T) { +func TestProvisionRelaySecret201NoTokenNoPersist(t *testing.T) { logger, _ := newProvisionTestLogger() baseDir := t.TempDir() - var capture provisionCapture - server := routingSecretServer(t, `{"status":200}`, http.StatusOK, &capture) + var capt relayCapture + server := relayProvisionServer(t, http.StatusCreated, `{}`, http.StatusOK, &capt) defer server.Close() - provisioned, err := ProvisionRelaySecret(context.Background(), server.URL, "server-123", baseDir, logger) - if provisioned || err != nil { - t.Fatalf("no token: want (false,nil), got (%v,%v)", provisioned, err) + provisioned, err := ProvisionRelaySecret(context.Background(), server.URL, "1234567890123456", baseDir, logger) + if provisioned || err == nil { + t.Fatalf("201 without token must fail: got (%v,%v)", provisioned, err) } if loaded, _ := identity.LoadNotifySecret(baseDir); loaded != "" { t.Fatalf("nothing must be persisted, got %q", loaded) } - if capture.confirmHits != 0 { - t.Fatalf("no token -> no confirm, got %d", capture.confirmHits) + if capt.confirmHits != 0 { + t.Fatalf("no token -> no confirm, got %d", capt.confirmHits) } } func TestProvisionRelaySecretShortSecretRefused(t *testing.T) { logger, _ := newProvisionTestLogger() baseDir := t.TempDir() - var capture provisionCapture + var capt relayCapture // "abc" is 3 runes (< identity.NotifySecretMinLen) and would NOT be masked in logs. - server := routingSecretServer(t, `{"notify_secret":"abc","status":200}`, http.StatusOK, &capture) + server := relayProvisionServer(t, http.StatusCreated, `{"notify_secret":"abc"}`, http.StatusOK, &capt) defer server.Close() - provisioned, err := ProvisionRelaySecret(context.Background(), server.URL, "server-123", baseDir, logger) + provisioned, err := ProvisionRelaySecret(context.Background(), server.URL, "1234567890123456", baseDir, logger) if provisioned || err == nil { t.Fatalf("short secret must be refused: got (%v,%v)", provisioned, err) } - if loaded, _ := identity.LoadNotifySecret(baseDir); loaded != "" { - t.Fatalf("short secret must NOT be persisted, got %q", loaded) - } if _, statErr := os.Stat(identity.NotifySecretPath(baseDir)); !os.IsNotExist(statErr) { t.Fatalf("secret file must be absent, got err=%v", statErr) } - if capture.confirmHits != 0 { - t.Fatalf("short secret -> no confirm, got %d", capture.confirmHits) + if capt.confirmHits != 0 { + t.Fatalf("short secret -> no confirm, got %d", capt.confirmHits) } } func TestProvisionRelaySecretEmptyBaseDir(t *testing.T) { logger, _ := newProvisionTestLogger() - var capture provisionCapture - server := routingSecretServer(t, `{"notify_secret":"`+provisionTestSecret+`","status":200}`, http.StatusOK, &capture) + var capt relayCapture + server := relayProvisionServer(t, http.StatusCreated, `{"notify_secret":"`+provisionTestSecret+`"}`, http.StatusOK, &capt) defer server.Close() - provisioned, err := ProvisionRelaySecret(context.Background(), server.URL, "server-123", "", logger) + provisioned, err := ProvisionRelaySecret(context.Background(), server.URL, "1234567890123456", "", logger) if provisioned || err == nil { t.Fatalf("empty baseDir must fail: got (%v,%v)", provisioned, err) } - if capture.confirmHits != 0 { - t.Fatalf("empty baseDir -> no confirm, got %d", capture.confirmHits) + if capt.provisionHits != 0 { + t.Fatalf("empty baseDir must not contact the server, got %d", capt.provisionHits) } } func TestProvisionRelaySecretAdoptsExistingSecretUnderLock(t *testing.T) { logger, _ := newProvisionTestLogger() baseDir := t.TempDir() - // A secret is already on disk (e.g. a concurrent minter won the race). The provisioner - // must adopt it under the lock and NOT contact the server nor mint a competing secret. + // A secret is already on disk (a concurrent minter won the race). The provisioner must + // adopt it under the lock and NOT contact the server nor mint a competing secret. if err := identity.PersistNotifySecret(context.Background(), baseDir, provisionTestSecret, nil); err != nil { t.Fatalf("seed secret: %v", err) } @@ -137,7 +292,7 @@ func TestProvisionRelaySecretAdoptsExistingSecretUnderLock(t *testing.T) { })) defer server.Close() - provisioned, err := ProvisionRelaySecret(context.Background(), server.URL, "server-123", baseDir, logger) + provisioned, err := ProvisionRelaySecret(context.Background(), server.URL, "1234567890123456", baseDir, logger) if provisioned || err != nil { t.Fatalf("adopt path must return (false,nil), got (%v,%v)", provisioned, err) } @@ -149,34 +304,149 @@ func TestProvisionRelaySecretAdoptsExistingSecretUnderLock(t *testing.T) { } } -func TestProvisionRelaySecretNon200(t *testing.T) { +// RelayProvisionRateLimitError.Error must mention the code and, only when present, the +// backoff; the nil receiver must still yield a non-empty string. +func TestRelayProvisionRateLimitErrorMessage(t *testing.T) { + withRA := &RelayProvisionRateLimitError{RetryAfter: 90 * time.Second} + if got := withRA.Error(); !strings.Contains(got, "429") || !strings.Contains(got, "1m30s") { + t.Fatalf("Error() with RetryAfter = %q, want 429 + 1m30s", got) + } + noRA := &RelayProvisionRateLimitError{} + if got := noRA.Error(); !strings.Contains(got, "429") || strings.Contains(got, "1m30s") { + t.Fatalf("Error() without RetryAfter = %q, want plain 429", got) + } + var nilErr *RelayProvisionRateLimitError + if got := nilErr.Error(); got == "" { + t.Fatalf("nil receiver Error() must be non-empty") + } +} + +// Exercise every parseRelayProvisionRetryAfter branch: absent, non-positive seconds, +// unparseable, integer seconds, and the HTTP-date path (future, past, beyond the cap). +func TestParseRelayProvisionRetryAfterBranches(t *testing.T) { + now := time.Unix(1_000_000, 0).UTC() + cases := []struct { + name string + raw string + want time.Duration + }{ + {"empty", "", 0}, + {"whitespace", " ", 0}, + {"zero", "0", 0}, + {"negative", "-5", 0}, + {"garbage", "not-a-date", 0}, + {"seconds", "120", 2 * time.Minute}, + {"httpdate-future", now.Add(3 * time.Minute).Format(http.TimeFormat), 3 * time.Minute}, + {"httpdate-past", now.Add(-time.Minute).Format(http.TimeFormat), 0}, + {"httpdate-beyond-max", now.Add(48 * time.Hour).Format(http.TimeFormat), relayProvisionMaxRetryAfter}, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + if got := parseRelayProvisionRetryAfter(tc.raw, now); got != tc.want { + t.Fatalf("parse(%q) = %v, want %v", tc.raw, got, tc.want) + } + }) + } +} + +// An unexpected status (e.g. 500) is a retryable failure whose error carries only the +// status code, never the untrusted response body. +func TestProvisionRelaySecretUnexpectedStatus(t *testing.T) { logger, _ := newProvisionTestLogger() baseDir := t.TempDir() - confirmHits := 0 - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - switch r.URL.Path { - case "/api/get-chat-id": - w.WriteHeader(http.StatusConflict) // 409: no relay secret issued (chat-less + server pre-change) - _, _ = w.Write([]byte("SERVER_NON_ASSOCIATO")) - case "/api/confirm-secret": - confirmHits++ - t.Errorf("confirm must not be hit on a non-200 handshake") - w.WriteHeader(http.StatusOK) - default: - t.Errorf("unexpected path: %s", r.URL.Path) - w.WriteHeader(http.StatusNotFound) - } - })) + var capt relayCapture + server := relayProvisionServer(t, http.StatusInternalServerError, `{"error":"boom-secret-detail"}`, http.StatusOK, &capt) + defer server.Close() + + provisioned, err := ProvisionRelaySecret(context.Background(), server.URL, "1234567890123456", baseDir, logger) + if provisioned || err == nil { + t.Fatalf("500 must fail: got (%v,%v)", provisioned, err) + } + if strings.Contains(err.Error(), "boom-secret-detail") { + t.Fatalf("error leaked the response body: %v", err) + } + if !strings.Contains(err.Error(), "500") { + t.Fatalf("error should carry the status code, got %v", err) + } + if loaded, _ := identity.LoadNotifySecret(baseDir); loaded != "" { + t.Fatalf("500 must persist nothing, got %q", loaded) + } +} + +// A 201 with a truncated JSON body fails the decode without persisting anything. +func TestProvisionRelaySecretBad201JSON(t *testing.T) { + logger, _ := newProvisionTestLogger() + baseDir := t.TempDir() + var capt relayCapture + server := relayProvisionServer(t, http.StatusCreated, `{"notify_secret":`, http.StatusOK, &capt) defer server.Close() - provisioned, err := ProvisionRelaySecret(context.Background(), server.URL, "server-123", baseDir, logger) + provisioned, err := ProvisionRelaySecret(context.Background(), server.URL, "1234567890123456", baseDir, logger) if provisioned || err == nil { - t.Fatalf("409 must fail: got (%v,%v)", provisioned, err) + t.Fatalf("bad 201 JSON must fail: got (%v,%v)", provisioned, err) } if loaded, _ := identity.LoadNotifySecret(baseDir); loaded != "" { - t.Fatalf("nothing persisted on 409, got %q", loaded) + t.Fatalf("bad 201 must persist nothing, got %q", loaded) + } +} + +// A transport failure (server closed before the call) is a retryable error and persists +// nothing. +func TestProvisionRelaySecretTransportError(t *testing.T) { + logger, _ := newProvisionTestLogger() + baseDir := t.TempDir() + var capt relayCapture + server := relayProvisionServer(t, http.StatusCreated, `{"notify_secret":"`+provisionTestSecret+`"}`, http.StatusOK, &capt) + url := server.URL + server.Close() // connection refused on the next dial + + provisioned, err := ProvisionRelaySecret(context.Background(), url, "1234567890123456", baseDir, logger) + if provisioned || err == nil { + t.Fatalf("transport error must fail: got (%v,%v)", provisioned, err) + } + if loaded, _ := identity.LoadNotifySecret(baseDir); loaded != "" { + t.Fatalf("transport error must persist nothing, got %q", loaded) + } +} + +// When baseDir is an existing regular file the identity lock cannot be created, so the +// provisioner fails before any network call. +func TestProvisionRelaySecretLockFailureOnFileBaseDir(t *testing.T) { + logger, _ := newProvisionTestLogger() + fileBaseDir := filepath.Join(t.TempDir(), "not-a-dir") + if err := os.WriteFile(fileBaseDir, []byte("x"), 0o600); err != nil { + t.Fatalf("seed file: %v", err) + } + var capt relayCapture + server := relayProvisionServer(t, http.StatusCreated, `{"notify_secret":"`+provisionTestSecret+`"}`, http.StatusOK, &capt) + defer server.Close() + + provisioned, err := ProvisionRelaySecret(context.Background(), server.URL, "1234567890123456", fileBaseDir, logger) + if provisioned || err == nil { + t.Fatalf("file baseDir must fail at the lock step: got (%v,%v)", provisioned, err) + } + if capt.provisionHits != 0 { + t.Fatalf("lock failure must not contact the server, got %d", capt.provisionHits) + } +} + +// A real read error on the under-lock re-check (the secret path is a directory, not a +// file) aborts before any network call, rather than being swallowed as "no secret". +func TestProvisionRelaySecretLoadErrorUnderLock(t *testing.T) { + logger, _ := newProvisionTestLogger() + baseDir := t.TempDir() + if err := os.MkdirAll(identity.NotifySecretPath(baseDir), 0o755); err != nil { + t.Fatalf("make secret path a directory: %v", err) + } + var capt relayCapture + server := relayProvisionServer(t, http.StatusCreated, `{"notify_secret":"`+provisionTestSecret+`"}`, http.StatusOK, &capt) + defer server.Close() + + provisioned, err := ProvisionRelaySecret(context.Background(), server.URL, "1234567890123456", baseDir, logger) + if provisioned || err == nil { + t.Fatalf("a re-check load error must fail: got (%v,%v)", provisioned, err) } - if confirmHits != 0 { - t.Fatalf("no confirm on 409, got %d", confirmHits) + if capt.provisionHits != 0 { + t.Fatalf("a load error must abort before contacting the server, got %d", capt.provisionHits) } } diff --git a/internal/notify/telegram.go b/internal/notify/telegram.go index d4e5863c..5b5df37b 100644 --- a/internal/notify/telegram.go +++ b/internal/notify/telegram.go @@ -24,6 +24,12 @@ import ( // rather than treated as a permanent delivery failure. var errRelayAuthRejected = errors.New("relay auth rejected") +// errRelayParked signals the relay purged this host's row (HTTP 410 SERVER_PARKED, +// design 11.2): the token authenticates nothing until the host is re-admitted, so it +// is handled exactly like errRelayAuthRejected (drop the in-memory secret + reprovision +// this run). The definitive on-disk clear happens on the healthcheck path (ErrHCParked). +var errRelayParked = errors.New("relay server parked") + // newNotifyID returns a random 32-hex-char id (<=128, matching the server's cap). // Generated ONCE per Send and reused across the relay POST + status poll (and any // relay retry) so the server-side idempotency dedupe never double-queues. @@ -200,19 +206,21 @@ func (t *TelegramNotifier) Send(ctx context.Context, data *NotificationData) (*N result.Duration = time.Since(startTime) return result, nil } - if !errors.Is(err, errRelayAuthRejected) { - t.logger.Warning("WARNING: Failed to send Telegram notification via relay: %v", err) + if !errors.Is(err, errRelayAuthRejected) && !errors.Is(err, errRelayParked) { + t.logger.Debug("Telegram: relay send failed (surfaced once by the notification adapter): %v", err) result.Metadata["relay_accepted"] = false result.Success = false result.Error = err result.Duration = time.Since(startTime) return result, nil // Non-critical error, don't abort backup } - // The relay rejected our per-server secret (stale/rotated). Drop it and fall - // through to the fetch path below, which reprovisions a fresh secret and - // relays this run (or falls back to the legacy bot-token path). Bounded: the - // fetch path retries the relay at most once and never loops back here. - t.logger.Warning("Telegram: relay auth rejected; dropping stale relay secret and reprovisioning") + // The relay rejected our per-server secret: stale/rotated (auth) or the host's + // row was purged and parked (410 SERVER_PARKED). Either way drop the in-memory + // secret and fall through to the fetch path below, which reprovisions a fresh + // secret (a parked host is re-admitted as a recreation) and relays this run (or + // falls back to the legacy bot-token path). Bounded: the fetch path retries the + // relay at most once and never loops back here. + t.logger.Warning("Telegram: relay rejected our secret (auth/parked); dropping it and reprovisioning") t.config.NotifySecret = "" } @@ -225,7 +233,7 @@ func (t *TelegramNotifier) Send(ctx context.Context, data *NotificationData) (*N var err error botToken, chatID, err = t.fetchCentralizedCredentials(ctx) // may TOFU-provision+persist+set NotifySecret if err != nil { - t.logger.Warning("WARNING: Failed to fetch Telegram credentials: %v", err) + t.logger.Debug("Telegram: failed to fetch credentials (surfaced once by the notification adapter): %v", err) result.Success = false result.Error = err result.Duration = time.Since(startTime) @@ -240,7 +248,7 @@ func (t *TelegramNotifier) Send(ctx context.Context, data *NotificationData) (*N message := t.buildMessage(data) status, loginURL, err := t.sendViaRelay(ctx, message, notifyID) if err != nil { - t.logger.Warning("WARNING: Failed to send Telegram notification via relay: %v", err) + t.logger.Debug("Telegram: relay send failed (surfaced once by the notification adapter): %v", err) result.Metadata["relay_accepted"] = false result.Success = false result.Error = err @@ -257,7 +265,7 @@ func (t *TelegramNotifier) Send(ctx context.Context, data *NotificationData) (*N // Validate credentials if botToken == "" || chatID == "" { err := fmt.Errorf("missing bot token or chat ID") - t.logger.Warning("WARNING: Telegram notification skipped: %v", err) + t.logger.Debug("Telegram: notification skipped (surfaced once by the notification adapter): %v", err) result.Success = false result.Error = err result.Duration = time.Since(startTime) @@ -271,7 +279,7 @@ func (t *TelegramNotifier) Send(ctx context.Context, data *NotificationData) (*N t.logger.Debug("Telegram: legacy direct send via bot token (token leaves host; mode=%s)", t.config.Mode) err := t.sendToTelegram(ctx, botToken, chatID, message) if err != nil { - t.logger.Warning("WARNING: Failed to send Telegram notification: %v", err) + t.logger.Debug("Telegram: legacy direct send failed (surfaced once by the notification adapter): %v", err) result.Success = false result.Error = err result.Duration = time.Since(startTime) @@ -420,6 +428,9 @@ func (t *TelegramNotifier) sendViaRelay(ctx context.Context, message, notifyID s return resp.Status, t.showPortalLink(resp.Body), nil case 401, 403: return resp.Status, "", fmt.Errorf("%w (HTTP %d)", errRelayAuthRejected, resp.Status) + case 410: + // SERVER_PARKED: the row was purged; the secret is dead until re-admission. + return resp.Status, "", fmt.Errorf("%w (HTTP 410)", errRelayParked) case 404: return resp.Status, "", fmt.Errorf("server unknown (HTTP 404)") case 409: diff --git a/internal/notify/telegram_test.go b/internal/notify/telegram_test.go index 3f7f95d8..8c8395e7 100644 --- a/internal/notify/telegram_test.go +++ b/internal/notify/telegram_test.go @@ -3,6 +3,7 @@ package notify import ( "context" "encoding/json" + "errors" "io" "net/http" "strings" @@ -393,3 +394,34 @@ func TestTelegramRelayErrorRedactsSecret(t *testing.T) { t.Fatalf("error string leaked the NotifySecret: %q", relayErr.Error()) } } + +func TestTelegramRelayParkedReturnsSentinel(t *testing.T) { + logger := logging.New(types.LogLevelDebug, false) + client := &http.Client{ + Transport: roundTripperFunc(func(req *http.Request) (*http.Response, error) { + return &http.Response{ + StatusCode: http.StatusGone, + Body: io.NopCloser(strings.NewReader(`{"error":"SERVER_PARKED"}`)), + Header: make(http.Header), + }, nil + }), + } + notifier, err := NewTelegramNotifier(TelegramConfig{ + Enabled: true, + Mode: TelegramModeCentralized, + ServerAPIHost: "https://central.test", + ServerID: "server-123", + NotifySecret: "relay-secret-value-parked-000001", + }, logger) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + notifier.client = client + status, _, relayErr := notifier.sendViaRelay(context.Background(), "hello", "notify-parked-1") + if status != http.StatusGone { + t.Fatalf("status = %d, want 410", status) + } + if !errors.Is(relayErr, errRelayParked) { + t.Fatalf("err = %v, want errRelayParked", relayErr) + } +} diff --git a/internal/notify/webhook.go b/internal/notify/webhook.go index ed65db58..27e47739 100644 --- a/internal/notify/webhook.go +++ b/internal/notify/webhook.go @@ -178,7 +178,11 @@ func (w *WebhookNotifier) Send(ctx context.Context, data *NotificationData) (*No err := w.sendToEndpoint(ctx, endpoint, data) if err != nil { - w.logger.Error("❌ Endpoint '%s' failed: %v", endpoint.Name, err) + // The notification adapter is the single terminal voice for the channel + // (it warns once on the aggregate outcome), so keep this per-endpoint line + // at Debug to avoid a double-reported failure. err can also carry a raw + // upstream body, which must not surface above Debug from here. + w.logger.Debug("❌ Endpoint '%s' failed: %v", endpoint.Name, err) failureCount++ lastErr = err } else { @@ -471,8 +475,10 @@ func (w *WebhookNotifier) sendToEndpoint(ctx context.Context, endpoint config.We } } - // All retries exhausted - w.logger.Error("❌ Webhook '%s' failed after %d attempt(s): %v", endpoint.Name, maxRetries+1, lastErr) + // All retries exhausted. The per-endpoint failure is surfaced ONCE by the caller + // loop ("Endpoint '' failed"); keep this inner line at Debug so a failed + // endpoint is not double-logged. + w.logger.Debug("Webhook '%s' failed after %d attempt(s): %v", endpoint.Name, maxRetries+1, lastErr) return fmt.Errorf("webhook failed after %d attempts: %w", maxRetries+1, lastErr) } diff --git a/internal/orchestrator/healthcheck_setup_classify.go b/internal/orchestrator/healthcheck_setup_classify.go index 1cb1fdc6..e427e6c9 100644 --- a/internal/orchestrator/healthcheck_setup_classify.go +++ b/internal/orchestrator/healthcheck_setup_classify.go @@ -60,6 +60,10 @@ func ClassifyHealthcheckSetupResult(res HealthcheckCheckResult) HealthcheckSetup st.Fatal, st.Level, st.Keyword = true, HealthcheckSetupLevelError, "NOT REGISTERED" st.Message = "This host is not registered on the server yet. It is registered automatically on the next daemon run (no Telegram pairing needed); if this persists the monitoring server is unreachable from this host." return st + case errors.Is(res.Err, health.ErrHCParked): + st.Fatal, st.Level, st.Keyword = true, HealthcheckSetupLevelError, "PARKED" + st.Message = "The monitoring server had removed this host's unused account. The relay credential is cleared and re-provisioned automatically on the next daemon run, which re-registers this host." + return st case errors.Is(res.Err, health.ErrHCDisabled): st.Fatal, st.Level, st.Keyword = true, HealthcheckSetupLevelError, "DISABLED" st.Message = "Centralized monitoring is currently disabled on the server; nothing to configure here." diff --git a/internal/orchestrator/healthcheck_setup_test.go b/internal/orchestrator/healthcheck_setup_test.go index c99dc6be..5a9f582f 100644 --- a/internal/orchestrator/healthcheck_setup_test.go +++ b/internal/orchestrator/healthcheck_setup_test.go @@ -150,6 +150,7 @@ func TestClassifyHealthcheckSetupResult(t *testing.T) { {"ready but not reachable -> retry", HealthcheckCheckResult{Err: nil, Reachable: false, LoginURL: "https://hc.proxsave.dev/L"}, false, false, "https://hc.proxsave.dev/L"}, {"auth fatal", HealthcheckCheckResult{Err: health.ErrHCAuth}, false, true, ""}, {"unknown fatal", HealthcheckCheckResult{Err: health.ErrHCUnknown}, false, true, ""}, + {"parked fatal", HealthcheckCheckResult{Err: health.ErrHCParked}, false, true, ""}, {"disabled fatal", HealthcheckCheckResult{Err: health.ErrHCDisabled}, false, true, ""}, {"not ready retry", HealthcheckCheckResult{Err: health.ErrHCNotReady}, false, false, ""}, {"network retry keeps login", HealthcheckCheckResult{Err: errors.New("dial"), LoginURL: "https://hc.proxsave.dev/L2"}, false, false, "https://hc.proxsave.dev/L2"}, diff --git a/internal/orchestrator/notification_adapter.go b/internal/orchestrator/notification_adapter.go index 7a6682ab..db1611be 100644 --- a/internal/orchestrator/notification_adapter.go +++ b/internal/orchestrator/notification_adapter.go @@ -76,10 +76,14 @@ func (n *NotificationAdapter) Notify(ctx context.Context, stats *BackupStats) er if n.notifier.Name() == "Telegram" && n.logTelegramOutcome(result) { // handled by the relay-aware two-line logger } else if !result.Success { - // Complete failure - n.logger.Warning("%s: failure reported", n.notifier.Name()) + // Complete failure. The adapter is the SINGLE voice for a channel's terminal + // outcome (each notifier demotes its own terminal-failure line to Debug). + // result.Error can carry raw upstream response bodies (a webhook endpoint's + // reply, etc.), so keep the WARNING generic -- like the fallback branch below -- + // and surface the unsanitized detail only at Debug. + n.logger.Warning("❌ %s: notification failed", n.notifier.Name()) if result.Error != nil { - n.logger.Debug(" Error: %v", result.Error) + n.logger.Debug(" %s failure detail: %v", n.notifier.Name(), result.Error) } } else if result.UsedFallback { // Fallback succeeded after primary method failed diff --git a/internal/serverbot/client.go b/internal/serverbot/client.go index 2808c325..0afeafe4 100644 --- a/internal/serverbot/client.go +++ b/internal/serverbot/client.go @@ -70,7 +70,8 @@ func refuseRedirect(_ *http.Request, via []*http.Request) error { // 3. headers: ALWAYS X-Proxsave-Version; X-Server-Auth iff Secret != ""; X-Proxsave- // Provision:"1" iff Provision; X-Notify-Id iff NotifyID != ""; Content-Type iff Body != nil // 4. execute; body = io.ReadAll(io.LimitReader(rc, req.MaxBytes or 8192)) -// 5. return (&Response{Status, Body}, nil) for ANY completed exchange, including non-2xx +// 5. return (&Response{Status, cloned Header, Body}, nil) for ANY completed exchange, +// including non-2xx // // LOAD-BEARING: an HTTP status is NEVER an error. err != nil only on an encode/build/ // dial/read failure, and that error is a *TransportError whose message is already @@ -139,5 +140,9 @@ func (c *Client) Do(ctx context.Context, req Request) (*Response, error) { // Debug only: method + path + status. NEVER the body, NEVER the secret. c.logger.Debug("serverbot: %s %s -> %d", method, req.Path, resp.StatusCode) } - return &Response{Status: resp.StatusCode, Body: body}, nil + return &Response{ + Status: resp.StatusCode, + Header: resp.Header.Clone(), + Body: body, + }, nil } diff --git a/internal/serverbot/client_test.go b/internal/serverbot/client_test.go index 1443543b..69223aa1 100644 --- a/internal/serverbot/client_test.go +++ b/internal/serverbot/client_test.go @@ -175,6 +175,30 @@ func TestDoNon2xxIsNotError(t *testing.T) { } } +func TestDoReturnsClonedResponseHeaders(t *testing.T) { + wireHeader := make(http.Header) + wireHeader.Set("Retry-After", "7200") + c := clientWithRT(func(r *http.Request) (*http.Response, error) { + resp := stubResp(http.StatusTooManyRequests, "limited") + resp.Header = wireHeader + return resp, nil + }) + + resp, err := c.Do(context.Background(), Request{Path: "/api/relay/provision"}) + if err != nil { + t.Fatalf("Do: %v", err) + } + if got := resp.Header.Get("Retry-After"); got != "7200" { + t.Fatalf("Retry-After = %q, want 7200", got) + } + // Response owns a clone: later transport mutation must not rewrite the + // endpoint-specific backoff decision. + wireHeader.Set("Retry-After", "1") + if got := resp.Header.Get("Retry-After"); got != "7200" { + t.Fatalf("Response.Header aliases transport header: got %q", got) + } +} + func TestDoTransportErrorRedacted(t *testing.T) { secret := "supersecret-token-value" // inner error also carries the secret in text (contrived) to prove RedactSecrets. diff --git a/internal/serverbot/request.go b/internal/serverbot/request.go index befc2a78..93b4719b 100644 --- a/internal/serverbot/request.go +++ b/internal/serverbot/request.go @@ -2,6 +2,7 @@ package serverbot import ( "encoding/json" + "net/http" "net/url" "strings" "time" @@ -23,12 +24,13 @@ type Request struct { MaxBytes int64 // response read cap; 0 -> 8192 } -// Response carries the RAW HTTP status (load-bearing: the caller maps semantics) and -// the bounded body. It never contains endpoint DTOs (e.g. login_url): the caller -// parses those from Body. +// Response carries the RAW HTTP status and a clone of the response headers +// (load-bearing: the caller maps endpoint semantics), plus the bounded body. It +// never contains endpoint DTOs (e.g. login_url): the caller parses those from Body. type Response struct { - Status int // raw HTTP status code - Body []byte // io.ReadAll(io.LimitReader(body, MaxBytes)); never unbounded + Status int // raw HTTP status code + Header http.Header // cloned before the transport response is closed + Body []byte // io.ReadAll(io.LimitReader(body, MaxBytes)); never unbounded } // JSON unmarshals the body into v. diff --git a/internal/ui/components/streamtask.go b/internal/ui/components/streamtask.go index b685809f..e3452ceb 100644 --- a/internal/ui/components/streamtask.go +++ b/internal/ui/components/streamtask.go @@ -172,9 +172,9 @@ func (t *StreamTask) Title() string { return t.title } func (t *StreamTask) Help() string { if t.done { - return "↑/↓ scroll · c copy log · enter continue" + return "↑/↓ scroll · c copy full log · shift/option+drag to select a section · enter continue" } - return "↑/↓ scroll · c copy log · esc cancel" + return "↑/↓ scroll · c copy full log · shift/option+drag to select a section · esc cancel" } // appendRaw appends one already-sanitized raw line to the ring, enforces the diff --git a/internal/ui/flows/install/audit.go b/internal/ui/flows/install/audit.go index 48aead2f..c4a9e6ae 100644 --- a/internal/ui/flows/install/audit.go +++ b/internal/ui/flows/install/audit.go @@ -132,11 +132,23 @@ func RunPostInstallAudit(ctx context.Context, session *shell.Session, execPath, } result.AppliedKeys = normalizeAuditKeys(keys) showAuditResult(ctx, session, "Post-install check", orchestrator.HealthcheckSetupLevelOk, - "UPDATED", fmt.Sprintf("Disabled %d component(s): %s", - len(result.AppliedKeys), strings.Join(result.AppliedKeys, ", ")), backToMenu) + "UPDATED", disabledComponentsSummary(result.AppliedKeys), backToMenu) return result, nil } +// disabledComponentsSummary renders the "UPDATED" explanation as a header line followed by +// ONE component key per line (a "- " bulleted column), so a long list stays readable instead +// of collapsing into a single truncated line. The result screen (auditResultPrompt -> +// SanitizeText -> theme.Subtle) preserves newlines, so each key gets its own row. +func disabledComponentsSummary(keys []string) string { + var b strings.Builder + fmt.Fprintf(&b, "Disabled %d component(s):", len(keys)) + for _, k := range keys { + b.WriteString("\n- " + k) + } + return b.String() +} + // auditResultAction is the single choice on a post-install audit outcome screen: // dismiss it and return to the caller (mirrors daemonResultAction on the dashboard). type auditResultAction int diff --git a/internal/ui/flows/install/audit_test.go b/internal/ui/flows/install/audit_test.go index df2f6ad3..95cfbb8b 100644 --- a/internal/ui/flows/install/audit_test.go +++ b/internal/ui/flows/install/audit_test.go @@ -52,6 +52,31 @@ func TestAuditResultPromptPreservesNewline(t *testing.T) { } } +// TestDisabledComponentsSummaryColumn pins the UPDATED explanation as a header line followed +// by ONE "- KEY" per line, so a long disabled-component list renders as a readable column +// instead of a single truncated comma-joined line. It also guards against a regression to the +// old ", "-joined format. +func TestDisabledComponentsSummaryColumn(t *testing.T) { + keys := []string{"BACKUP_CLUSTER_CONFIG", "BACKUP_DATASTORE_CONFIGS", "BACKUP_PBS_NODE_CONFIG"} + got := disabledComponentsSummary(keys) + + if !strings.HasPrefix(got, "Disabled 3 component(s):") { + t.Fatalf("summary must start with the count header, got %q", got) + } + for _, k := range keys { + if !strings.Contains(got, "\n- "+k) { + t.Fatalf("key %q must be on its own bulleted line, got %q", k, got) + } + } + if strings.Contains(got, ", ") { + t.Fatalf("keys must not be comma-joined on one line (column layout), got %q", got) + } + // One header line + one line per key. + if n := strings.Count(got, "\n"); n != len(keys) { + t.Fatalf("expected %d newlines (one per key), got %d in %q", len(keys), n, got) + } +} + // TestRunPostInstallAuditApplyFailure proves an ApplyAuditDisables write failure is now // recorded on the result (ApplyErr set, no keys applied), so the caller can distinguish it // from the benign "nothing selected" no-op instead of logging both as a clean run. The diff --git a/internal/ui/flows/install/install_test.go b/internal/ui/flows/install/install_test.go index 79317db1..0582fec0 100644 --- a/internal/ui/flows/install/install_test.go +++ b/internal/ui/flows/install/install_test.go @@ -475,11 +475,14 @@ func TestRunPostInstallAudit(t *testing.T) { d.keys("space down down down enter") // The outcome is now the shared styled "Post-install check" result screen (a // selector with a colored Status keyword), not a Notice. Assert the green - // "✓ UPDATED" keyword + the disabled-component line. In the install flow the - // leave item is "Continue" (mirrors the Telegram check that follows), NOT "Back". + // "✓ UPDATED" keyword + the disabled-component summary, which is now a header + // line plus one "- KEY" column row (so a long list is not truncated). In the + // install flow the leave item is "Continue" (mirrors the Telegram check that + // follows), NOT "Back". d.waitScreen("Post-install check") d.waitText("✓ UPDATED") - d.waitText("Disabled 1 component(s): BACKUP_X") + d.waitText("Disabled 1 component(s):") + d.waitText("- BACKUP_X") d.waitText("Continue") d.keys("enter") diff --git a/upgrade-beta.sh b/upgrade-beta.sh index 5c8789ab..46717fc4 100644 --- a/upgrade-beta.sh +++ b/upgrade-beta.sh @@ -368,12 +368,22 @@ fi ############################################### cd "${TARGET_DIR}" +# Propagate the script's unattended -y to the finalize so the freshly installed binary does +# NOT open the interactive what's-new screen under an allocated pty (ssh -tt, CI, Ansible): +# proxsave treats a `y` token IMMEDIATELY AFTER --upgrade as auto-yes (non-interactive +# intent), so it must sit between --upgrade and --localfile. Without -y (a human at a real +# terminal) no token is added and the what's-new screen opens as intended after the upgrade. +YES_TOKEN="" +if [ "${ASSUME_YES}" -eq 1 ]; then + YES_TOKEN="y" +fi + echo "[+] Finalizing: ${TARGET_BIN} --upgrade --localfile" # The beta binary is already swapped in and verified to run. If the local finalize # fails (daemon migrate/restart, backup.env merge, permission fixes -- the parts # that touch the live system), surface the rollback path explicitly: set -e would # otherwise abort here and never print the footer that documents .prev. -if ! "${TARGET_BIN}" --upgrade --localfile; then +if ! "${TARGET_BIN}" --upgrade ${YES_TOKEN} --localfile; then echo "--------------------------------------------" echo "❌ Finalize failed. The beta binary IS installed but the local upgrade did" echo " not complete (backup.env / daemon / permissions may be half-applied)." @@ -391,5 +401,6 @@ echo " Binary: ${TARGET_BIN}" echo " Rollback: mv -f ${TARGET_BIN}.prev ${TARGET_BIN}" echo "" echo " You are now on a PRERELEASE. When a stable release of the same or newer" -echo " version ships, 'proxsave --upgrade' will move you back onto stable." +echo " version ships, open the dashboard and choose Upgrade (under Maintenance) to" +echo " move back onto stable." echo "--------------------------------------------"