diff --git a/CHANGELOG.md b/CHANGELOG.md index f590a7c..cb424fb 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,36 @@ +## v0.83.0 — observability pass: always-DEBUG capture ring + GET /debug/logs + heartbeat log-pull + gap-fill sweep (2026-07-11) + +Agent half of the cross-repo observability task (controller v0.116.0 + hub v0.46.0). Motivating +incident: a refused NAS verify on an `info`-level box left NOTHING readable remotely — the agent +logged only to host journald and the new features emitted few lines. + +- **Capture layer** (`internal/log`): `applog.New` now returns `(logger, *Ring)` — a slog fan-out + where stderr keeps the configured level (journald unchanged) and a ~1000-entry ring handler is + FIXED at `LevelDebug`, so flow detail exists for remote pulls without a config flip. The ring is + an io.Writer fed by a stdlib TextHandler; entries are parsed (time/level/message-verbatim). + Red-proof: ring gated at the emit level → capture-at-info test FAILS ("ring holds 1, want 2"). +- **`GET /debug/logs`** (local API, same token-auth/self-scoping wrap as siblings): the ring as + JSON `{entries, total}`; `?raw=1` plain text; 503 when unwired. Plus a request-level DEBUG + middleware (method/path/status/duration — never bodies) wrapping the whole mux. +- **Heartbeat log-pull** (the report-channel logtail.go pattern mirrored): the control envelope + gains `log_tail_requested: bool` (additive); when set, the NEXT heartbeat carries + `log_tail: {collected_at, lines[]}` (newest-kept, 128 KB cap). Consume-once both ends: local + pending drains onto the carrying push; a FAILED push leaves the hub request pending → the next + envelope re-arms (retry proven in tests; red-proof: drain removed → tail ships every cycle → + FAIL). Serving a pull logs `operator log pull served` (INFO — customer-visible transparency). +- **Gap-fill sweep** (entry, decisions, outcome+duration, errors): netverify (job start, trigger + outcome, /proc/mounts verdict, journal byte-count, classification code, rollback outcome, + duration), netstorage add (pre-probe pass verdict, creds staged/removed — path only), netmount + Ensure/Remove (per-unit install/enable/remove-step results), signedjobs (jobs fetched ids+ + duration, op received class/host/expiry — never signatures), selfupdate executor (invariants + passed, download sha-match+duration), disks (assign/eject/decommission outcome INFO), + ReassertGuestBinds (pass summary), controller-swap (pre-pull verify, negative health verdict), + desired syncer + hub loop (per-exchange DEBUG with durations). +- **S7 log-sequence smoke**: a full fake NAS add at emit level info must leave the ordered phase + markers in the ring (red-proof: dropping the /proc/mounts verdict line → FAIL naming the phase). +- No new sudoers grants, no journald scraping, no streaming — pull-only. Demo-deploy only — NOT + published (Peti stays 0.81.0; this reaches him with the next publish train). + ## v0.82.0 — local-API version channel: X-Felhom-Agent-Version on every response (2026-07-11) The controller's capability detection upgrades from route-probing to version comparison: the diff --git a/REUSE.md b/REUSE.md index 770414f..ee53b6c 100644 --- a/REUSE.md +++ b/REUSE.md @@ -138,7 +138,8 @@ | `localapi.GuestExecutor` | internal/localapi/controllerswap.go | `*GuestBinder` (pct exec) | `fakeGuestExec` internal/localapi/controllerswap_test.go | | `reconcile.OpVerifier` | internal/reconcile/gate.go | `*authz.Verifier` | fake verifier in internal/reconcile gate tests | | `signedjobs.WipeOps` / `Executor` (`ExecutorChain`) | internal/signedjobs/wipe.go + runner.go | `*storage.SudoHostOps`; `WipeExecutor`+`DecommissionExecutor` | internal/signedjobs wipe/runner/decommission tests | -| `hub.reporter` / `collectorIface` / `EnvelopeObserver` | internal/hub/loop.go | `*hub.Client`, `*hub.Collector`; `desired.Syncer` + `signedjobs.Runner` | `fakeReporter`/`fakeCollector` internal/hub/loop_test.go | +| `hub.reporter` / `collectorIface` / `EnvelopeObserver` | internal/hub/loop.go | `*hub.Client`, `*hub.Collector`; `desired.Syncer` + `signedjobs.Runner` | `fakeReporter`/`fakeCollector` internal/hub/loop_test.go; `recordingReporter` loop_logtail_test.go | +| `applog.Ring` (always-DEBUG capture ring) + fan-out `applog.New → (logger, ring)` | internal/log/log.go | wired in cmd/felhom-agent/main.go → `localapi.Options.LogRing` + `Loop.SetLogTailSource(ring.Lines)` | internal/log/log_test.go; localapi/debuglogs_test.go — v0.83.0; the byte-capped `Lines` is the heartbeat tail source | | `pbsdr.StorageReader` / `SecretConsumer` / `Manager.probeFP` (func seam) | internal/pbsdr/manager.go | `*proxmox.Client`; `*hub.Client`; `pbs.ProbeFingerprint` | `fakeStorage`/`fakeConsumer`/`fakeRunner` internal/pbsdr/manager_test.go (argv+stdin recorder) | | `capability.Runner` | internal/capability/probe.go | `*proxmox.ExecRunner` (RunnerDirect) | `fakeRunner` internal/capability/probe_test.go | | Cross-repo: local API ↔ controller | internal/localapi/server.go routes; contract seeded by internal/provision/doc.go (`bootstrap.json`: endpoint + leaf fingerprint + token) | felhom-controller's agentapi client | pin = served leaf cert (memory gotcha) | diff --git a/cmd/felhom-agent/main.go b/cmd/felhom-agent/main.go index caaa741..20696c2 100644 --- a/cmd/felhom-agent/main.go +++ b/cmd/felhom-agent/main.go @@ -167,11 +167,13 @@ func main() { } cfg = config.Default() } - logger := applog.New(cfg.LogLevel) + // logRing is the always-DEBUG capture ring (v0.83.0 observability): served by the + // local API's GET /debug/logs and the heartbeat log-pull. Selftests ignore it. + logger, logRing := applog.New(cfg.LogLevel) switch selftest.mode { case "": - os.Exit(runDaemon(cfg, logger)) + os.Exit(runDaemon(cfg, logger, logRing)) case "read": os.Exit(runSelftestRead(context.Background(), cfg, logger)) case "task": @@ -369,7 +371,7 @@ func logCapabilities(statuses []capability.Status, logger *slog.Logger) { // runDaemon is the default mode: collect a host-report and POST it to the hub on a // loop. Requires both proxmox (to collect) and hub config. -func runDaemon(cfg config.Config, logger *slog.Logger) int { +func runDaemon(cfg config.Config, logger *slog.Logger, logRing *applog.Ring) int { if err := cfg.Validate(); err != nil { fmt.Fprintln(os.Stderr, "daemon: proxmox not configured:", err) return 2 @@ -427,6 +429,11 @@ func runDaemon(cfg config.Config, logger *slog.Logger) int { collector.SetCapabilityProber(probeAll) loop := hub.NewLoop(collector, client, time.Duration(hcfg.PollSeconds)*time.Second, logger) interval := time.Duration(hcfg.PollSeconds) * time.Second + // Heartbeat log-pull (v0.83.0): when the control envelope requests it, the NEXT + // heartbeat carries the debug ring's tail (newest-kept, byte-capped in the loop). + if logRing != nil { + loop.SetLogTailSource(logRing.Lines) + } // Desired-state provider (slice 10A): the hub-served target the reconcile engine converges // toward. Starts EMPTY (generation 0) — reconcile is a live no-op until the hub serves intent, @@ -659,7 +666,7 @@ func runDaemon(cfg config.Config, logger *slog.Logger) int { jobsRunner := signedjobs.NewRunner(client, gate, signedjobs.ExecutorChain{wipeExec, decommExec, updateExec}, cfg.Hub.HostID, logger) loop.SetEnvelopeObserver(hub.MultiObserver(desiredSyncer, jobsRunner)) - localSrv := buildLocalAPIServer(cfg, px, backupStore, observer, driveKnown, hostOps, gate, collector, intentRec, guestBindStore, formatJobStore, logger, &localTokens) + localSrv := buildLocalAPIServer(cfg, px, backupStore, observer, driveKnown, hostOps, gate, collector, intentRec, guestBindStore, formatJobStore, logRing, logger, &localTokens) if localTokens != nil { defer localTokens.Close() } @@ -948,7 +955,7 @@ func buildRestoreTestScheduler(cfg config.Config, px *proxmox.Client, engine *re // leaf (stable fingerprint). Any failure DISABLES the server (returns nil) WITHOUT crashing the // daemon — the host still reports/reconciles; only the controller channel is unavailable until // fixed. The opened token store is returned via outTokens so the caller can Close it. -func buildLocalAPIServer(cfg config.Config, px *proxmox.Client, store *backup.Store, observer *storage.Observer, driveTargets storage.KnownTargets, hostOps *storage.SudoHostOps, gate *reconcile.Gate, collector *hub.Collector, intent localapi.IntentRecorder, guestBinds *localapi.GuestBindStore, formatJobs *localapi.FormatJobStore, logger *slog.Logger, outTokens **localapi.TokenStore) *localapi.Server { +func buildLocalAPIServer(cfg config.Config, px *proxmox.Client, store *backup.Store, observer *storage.Observer, driveTargets storage.KnownTargets, hostOps *storage.SudoHostOps, gate *reconcile.Gate, collector *hub.Collector, intent localapi.IntentRecorder, guestBinds *localapi.GuestBindStore, formatJobs *localapi.FormatJobStore, logRing *applog.Ring, logger *slog.Logger, outTokens **localapi.TokenStore) *localapi.Server { if !cfg.LocalAPI.Enabled() { return nil } @@ -1019,6 +1026,7 @@ func buildLocalAPIServer(cfg config.Config, px *proxmox.Client, store *backup.St // per-storage view to the customer's monitoring page (reuses the slice-4 collector). HostMetrics: collector, HostID: cfg.Hub.HostID, // slice 10B: anti-retarget host in the data-bearing-format pending-op + LogRing: logRing, // v0.83.0: GET /debug/logs — the always-DEBUG capture ring Logger: logger, }) if err != nil { diff --git a/internal/desired/syncer.go b/internal/desired/syncer.go index ad93ab2..0e98c55 100644 --- a/internal/desired/syncer.go +++ b/internal/desired/syncer.go @@ -12,6 +12,7 @@ package desired import ( "context" "log/slog" + "time" "gitea.dooplex.hu/admin/felhom-agent/internal/hub" "gitea.dooplex.hu/admin/felhom-agent/internal/reconcile" @@ -66,12 +67,17 @@ func (s *Syncer) OnEnvelope(ctx context.Context, env *hub.ControlEnvelope) { if env.DesiredGeneration <= have { return // cached: the heavy desired-state moves only on a generation advance } + s.logger.Debug("desired: generation advanced — fetching desired-state", + "have_generation", have, "envelope_generation", env.DesiredGeneration) + start := time.Now() resp, err := s.fetcher.FetchDesiredState(ctx) if err != nil { s.logger.Warn("desired: fetch failed; keeping cached desired-state", "have_generation", have, "envelope_generation", env.DesiredGeneration, "err", err) return } + s.logger.Debug("desired: fetched", "generation", resp.Generation, + "duration_ms", time.Since(start).Milliseconds()) state := mapWire(resp.DesiredState, s.logger) // Cache against the FETCHED generation (not the envelope's) — robust to a generation that // advanced again between the heartbeat and this fetch (we won't re-fetch the same state). diff --git a/internal/hub/loop.go b/internal/hub/loop.go index a3a0034..7d553b7 100644 --- a/internal/hub/loop.go +++ b/internal/hub/loop.go @@ -57,8 +57,20 @@ type Loop struct { logger *slog.Logger trigger <-chan struct{} // optional: an out-of-band report request (storage watchdog) observer EnvelopeObserver // optional: the slice-10A desired-state sync hook + + // Heartbeat log-pull (v0.83.0): logTailSource yields the debug ring's formatted + // lines newest-kept within a byte budget (applog.Ring.Lines). logTailPending is + // armed by an envelope's log_tail_requested and drained onto the NEXT report — + // the report-channel logtail.go consume-once shape: a failed push leaves the + // hub's request pending, so the next successful envelope re-arms it (fail-safe + // retry, no duplicate shipping). Loop state is single-goroutine (cycle only). + logTailSource func(maxBytes int) []string + logTailPending bool } +// logTailMaxBytes caps the heartbeat log tail (newest lines kept). +const logTailMaxBytes = 128 * 1024 + // NewLoop builds the loop. interval is the starting cadence (the hub may override it // per-cycle via the control envelope). func NewLoop(collector collectorIface, client reporter, interval time.Duration, logger *slog.Logger) *Loop { @@ -79,6 +91,10 @@ func (l *Loop) SetTrigger(ch <-chan struct{}) { l.trigger = ch } // desired-state when the generation advances. Optional — unset is a clean no-op. func (l *Loop) SetEnvelopeObserver(o EnvelopeObserver) { l.observer = o } +// SetLogTailSource wires the debug ring for the heartbeat log-pull (v0.83.0). +// Optional — unset means an envelope's log_tail_requested is ignored. +func (l *Loop) SetLogTailSource(src func(maxBytes int) []string) { l.logTailSource = src } + // Run reports immediately, then on each tick, until ctx is cancelled (then nil). func (l *Loop) Run(ctx context.Context) error { interval := l.interval @@ -116,19 +132,40 @@ func (l *Loop) Run(ctx context.Context) error { // cycle runs one collect→report→adopt. It never returns an error: failures are // logged and the current interval is kept, so the loop keeps running. func (l *Loop) cycle(ctx context.Context, current time.Duration) time.Duration { + start := time.Now() report, err := l.collector.Collect(ctx) if err != nil { l.logger.Warn("hub: collect failed; skipping this cycle's report", "err", err) return current } + // Fulfill a pending log-pull: attach the ring tail to THIS report and clear the + // local pending flag (consume-once). On a failed push the hub's request is still + // pending and the next envelope re-arms it — logtail.go's fail-safe retry shape. + // The explicit nil first makes this robust to a collector reusing its report struct. + report.LogTail = nil + if l.logTailPending && l.logTailSource != nil { + report.LogTail = &LogTail{ + CollectedAt: time.Now().UTC().Format(time.RFC3339), + Lines: l.logTailSource(logTailMaxBytes), + } + } + l.logTailPending = false env, err := l.client.Report(ctx, report) if err != nil { l.logger.Warn("hub: report failed; keeping current interval", "err", err) return current } + if report.LogTail != nil { + // Transparency: the pull is visible in the box's own log (and thus in the ring). + l.logger.Info("operator log pull served", "component", "agent", "lines", len(report.LogTail.Lines)) + } l.logger.Debug("hub: report sent", - "guests", len(report.Guests), + "guests", len(report.Guests), "duration_ms", time.Since(start).Milliseconds(), "blocked", env.Blocked, "desired_generation", env.DesiredGeneration, "has_signed_ops", env.HasSignedOps) + if env.LogTailRequested { + l.logger.Debug("hub: log tail requested — shipping on the next heartbeat") + l.logTailPending = true + } // Slice 10A: hand the envelope to the desired-state sync hook (fetch desired-state on a // generation advance). Done off the report's critical path semantics — a sync/fetch failure diff --git a/internal/hub/loop_logtail_test.go b/internal/hub/loop_logtail_test.go new file mode 100644 index 0000000..8b03a90 --- /dev/null +++ b/internal/hub/loop_logtail_test.go @@ -0,0 +1,121 @@ +package hub + +import ( + "context" + "errors" + "testing" + "time" +) + +// recordingReporter records each pushed report and serves a scripted per-call +// (envelope, error) sequence — the S2 heartbeat log-pull harness. +type recordingReporter struct { + reports []*HostReport + script []struct { + env *ControlEnvelope + err error + } +} + +func (r *recordingReporter) Report(_ context.Context, rep *HostReport) (*ControlEnvelope, error) { + // Copy the LogTail pointer state at push time (the loop reuses collector reports). + cp := *rep + r.reports = append(r.reports, &cp) + i := len(r.reports) - 1 + if i < len(r.script) { + return r.script[i].env, r.script[i].err + } + return &ControlEnvelope{}, nil +} + +func tailLoop(rep *recordingReporter) *Loop { + var cn int32 + l := NewLoop(&fakeCollector{report: &HostReport{}, n: &cn}, rep, time.Hour, quietLogger()) + l.SetLogTailSource(func(maxBytes int) []string { return []string{"line-a", "line-b"} }) + return l +} + +// S2 (agent half): an envelope's log_tail_requested arms the pull; the NEXT report +// carries log_tail; the one after (request cleared hub-side) carries nothing — +// consume-once. Companion red-proof: drop the `l.logTailPending = false` drain → +// report 3 also carries a tail → the last assertion fails. +func TestLoop_LogTailRequestedShipsOnNextReportOnce(t *testing.T) { + rep := &recordingReporter{script: []struct { + env *ControlEnvelope + err error + }{ + {env: &ControlEnvelope{LogTailRequested: true}}, + {env: &ControlEnvelope{}}, // the tail arrived — hub cleared the request + {env: &ControlEnvelope{}}, + }} + l := tailLoop(rep) + ctx := context.Background() + l.cycle(ctx, time.Hour) + l.cycle(ctx, time.Hour) + l.cycle(ctx, time.Hour) + + if len(rep.reports) != 3 { + t.Fatalf("reports = %d, want 3", len(rep.reports)) + } + if rep.reports[0].LogTail != nil { + t.Errorf("report 1 must not carry a tail (the request only arrived in its envelope)") + } + got := rep.reports[1].LogTail + if got == nil || len(got.Lines) != 2 || got.Lines[0] != "line-a" || got.CollectedAt == "" { + t.Fatalf("report 2 log_tail = %+v, want the 2 ring lines + collected_at", got) + } + if rep.reports[2].LogTail != nil { + t.Errorf("report 3 carries a tail again — consume-once broken: %+v", rep.reports[2].LogTail) + } +} + +// S2 companion (fail-safe retry): the push CARRYING the tail fails → the local pending +// is spent, but the hub's request is still pending, so the next envelope re-arms it and +// the following report fulfills. Asserts the retry ships the tail exactly once more. +func TestLoop_FailedTailPushIsReArmedByNextEnvelope(t *testing.T) { + rep := &recordingReporter{script: []struct { + env *ControlEnvelope + err error + }{ + {env: &ControlEnvelope{LogTailRequested: true}}, // arm + {err: errors.New("hub 5xx")}, // the carrying push FAILS + {env: &ControlEnvelope{LogTailRequested: true}}, // hub still pending → re-arm + {env: &ControlEnvelope{}}, // fulfilled + }} + l := tailLoop(rep) + ctx := context.Background() + for i := 0; i < 4; i++ { + l.cycle(ctx, time.Hour) + } + if len(rep.reports) != 4 { + t.Fatalf("reports = %d, want 4", len(rep.reports)) + } + if rep.reports[1].LogTail == nil { + t.Errorf("report 2 (the failed push) should have carried the tail") + } + if rep.reports[2].LogTail != nil { + t.Errorf("report 3 must not carry a tail (pending was spent; envelope re-arms only after it)") + } + if rep.reports[3].LogTail == nil { + t.Errorf("report 4 must fulfill the re-armed request — retry lost") + } +} + +// No source wired → the request is ignored (clean no-op, no panic). +func TestLoop_LogTailRequestIgnoredWithoutSource(t *testing.T) { + rep := &recordingReporter{script: []struct { + env *ControlEnvelope + err error + }{ + {env: &ControlEnvelope{LogTailRequested: true}}, + {env: &ControlEnvelope{}}, + }} + var cn int32 + l := NewLoop(&fakeCollector{report: &HostReport{}, n: &cn}, rep, time.Hour, quietLogger()) + ctx := context.Background() + l.cycle(ctx, time.Hour) + l.cycle(ctx, time.Hour) + if rep.reports[1].LogTail != nil { + t.Errorf("tail shipped with no source wired: %+v", rep.reports[1].LogTail) + } +} diff --git a/internal/hub/report.go b/internal/hub/report.go index 3278c97..f9d4de3 100644 --- a/internal/hub/report.go +++ b/internal/hub/report.go @@ -85,6 +85,15 @@ type HostReport struct { // Carries NO secret. PBSDR *PBSDRStatus `json:"pbs_dr,omitempty"` + // LogTail is the agent's on-demand debug-ring tail (v0.83.0 observability) — the agent + // mirror of the controller's report log_tails channel. Present ONLY on the heartbeat + // right after the control envelope requested it (log_tail_requested); consume-once on + // both ends (the hub clears its pending request on arrival). Newest lines kept, byte- + // capped loop-side. Carries log lines only — the logging conventions forbid secrets in + // any log line, and the hub's bundle gate re-checks before storing. `omitempty`: absent + // in the steady state, so the cross-repo host-report golden stays byte-stable. + LogTail *LogTail `json:"log_tail,omitempty"` + // OOB is the operator-access health stanza (TASK H1). It answers the operator's question — "can I // get into this box right now, and if not, why" — from the hub: felhom-sshd up + on which port, // locally reachable, the tunnel handshake age (the OOB path rides wg-felhom), whether the operator @@ -368,6 +377,16 @@ type ControlEnvelope struct { Blocked bool `json:"blocked"` // reserved — ignored DesiredGeneration int64 `json:"desired_generation"` // slice 10A: the cached-vs-current change signal HasSignedOps bool `json:"has_signed_ops"` // slice 10A: signed-jobs queue non-empty (exec 10B) + // LogTailRequested (v0.83.0) — the operator wants this agent's debug-ring tail; the + // NEXT heartbeat carries it in log_tail (the report-channel log_tail_requests mirror). + // Absent/false on an old hub → nothing happens. + LogTailRequested bool `json:"log_tail_requested"` +} + +// LogTail is the heartbeat's on-demand agent log tail (see HostReport.LogTail). +type LogTail struct { + CollectedAt string `json:"collected_at"` // RFC3339 + Lines []string `json:"lines"` } // DesiredStateResponse is GET /hosts/{host_id}/desired-state (slice 10A — the "Down" channel's diff --git a/internal/localapi/controllerswap.go b/internal/localapi/controllerswap.go index b801b79..7797011 100644 --- a/internal/localapi/controllerswap.go +++ b/internal/localapi/controllerswap.go @@ -241,6 +241,7 @@ func (c *ControllerSwapper) Swap(ctx context.Context, vmid int, target string) * c.saveState(st) // crash-safety: previous recorded BEFORE any mutation // The controller pre-pulled the image; refuse to swap to an absent image (would brick the guest). + c.logger.Debug("controller-swap: pre-pull verify", "vmid", vmid, "target", target, "previous", prev) if !c.imagePresent(ctx, vmid, target) { st.State = "failed" st.Error = "target image not present in guest (controller did not pre-pull it)" @@ -270,6 +271,7 @@ func (c *ControllerSwapper) Swap(ctx context.Context, vmid int, target string) * c.logger.Info("controller-swap: new controller healthy", "vmid", vmid, "target", target) return st } + c.logger.Warn("controller-swap: health verdict negative — rolling back", "vmid", vmid, "target", target) return c.rollback(ctx, st, "new controller did not become healthy within timeout") } diff --git a/internal/localapi/debuglogs.go b/internal/localapi/debuglogs.go new file mode 100644 index 0000000..f198ae7 --- /dev/null +++ b/internal/localapi/debuglogs.go @@ -0,0 +1,64 @@ +package localapi + +import ( + "net/http" + "strconv" + "time" + + applog "gitea.dooplex.hu/admin/felhom-agent/internal/log" +) + +// GET /debug/logs (v0.83.0 observability) — the agent's always-DEBUG capture ring, +// served over the same token-authed, self-scoped local API as every sibling route. +// This is what makes the agent's side of a flow (e.g. a NAS verify) visible from the +// controller's Debug page without journald access or a config flip. ?raw=1 mirrors +// the controller viewer's plain-text variant. Log lines carry keys never values +// (logging conventions), so the ring is safe to serve to the guest's operator view. + +// handleDebugLogs serves the ring as JSON entries ({entries, total}) or plain text. +func (s *Server) handleDebugLogs(w http.ResponseWriter, r *http.Request, vmid int) { + if s.logRing == nil { + writeErr(w, http.StatusServiceUnavailable, "debug log ring not configured on this agent") + return + } + limit := 0 // 0 = everything held (ring-bounded) + if v := r.URL.Query().Get("limit"); v != "" { + if n, err := strconv.Atoi(v); err == nil && n > 0 && n <= applog.DefaultRingSize { + limit = n + } + } + if r.URL.Query().Get("raw") == "1" { + w.Header().Set("Content-Type", "text/plain; charset=utf-8") + for _, line := range s.logRing.Lines(0) { + w.Write([]byte(line)) + w.Write([]byte("\n")) + } + return + } + entries, total := s.logRing.Entries(limit) + writeOK(w, map[string]any{"vmid": vmid, "entries": entries, "total": total}) +} + +// statusRecorder captures the wrapped handler's status for the request log line. +type statusRecorder struct { + http.ResponseWriter + status int +} + +func (sr *statusRecorder) WriteHeader(code int) { + sr.status = code + sr.ResponseWriter.WriteHeader(code) +} + +// logRequests is the request-level DEBUG middleware: method, path, status, duration +// — never bodies (bodies can carry secrets; the ring must not). +func (s *Server) logRequests(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + start := time.Now() + rec := &statusRecorder{ResponseWriter: w, status: http.StatusOK} + next.ServeHTTP(rec, r) + s.logger.Debug("local-api: request", + "method", r.Method, "path", r.URL.Path, + "status", rec.status, "duration_ms", time.Since(start).Milliseconds()) + }) +} diff --git a/internal/localapi/debuglogs_test.go b/internal/localapi/debuglogs_test.go new file mode 100644 index 0000000..8da8d24 --- /dev/null +++ b/internal/localapi/debuglogs_test.go @@ -0,0 +1,130 @@ +package localapi + +import ( + "bytes" + "encoding/json" + "io" + "log/slog" + "strings" + "testing" + + applog "gitea.dooplex.hu/admin/felhom-agent/internal/log" +) + +// newDebugLogServer builds a minimal server with the debug ring wired and one line +// of each level captured (emit level info — the capture-at-info posture). +func newDebugLogServer(t *testing.T) (*Server, *applog.Ring) { + t.Helper() + logger, ring := applog.NewWithWriter(&bytes.Buffer{}, "info", 50) + logger.Debug("netverify: flow detail", "step", "probe") + logger.Info("netmount: ensured network mount", "name", "nas") + srv, err := NewServer(Options{ + ListenAddr: "127.0.0.1:0", + Guests: &fakeGuests{}, + Backups: &fakeBackups{}, + Store: &fakeStore{}, + Storage: fakeStorage{}, + Tokens: staticTokens{"A": 8200}, + LogRing: ring, + Logger: slog.New(slog.NewTextHandler(io.Discard, nil)), + }) + if err != nil { + t.Fatalf("new server: %v", err) + } + return srv, ring +} + +// GET /debug/logs serves the ring's entries — INCLUDING the DEBUG line captured at +// emit level info (the endpoint exists so the controller's agent tab can show flow +// detail without a config flip). Companion red-proof: unwire LogRing → 503. +func TestDebugLogs_ServesRingEntriesIncludingDebug(t *testing.T) { + srv, _ := newDebugLogServer(t) + w := do(t, srv.Handler(), "GET", "/debug/logs", "A", "") + if w.Code != 200 { + t.Fatalf("status = %d body=%s", w.Code, w.Body.String()) + } + var resp struct { + OK bool `json:"ok"` + Data struct { + Entries []applog.Entry `json:"entries"` + Total int `json:"total"` + } `json:"data"` + } + if err := json.Unmarshal(w.Body.Bytes(), &resp); err != nil { + t.Fatalf("decode: %v", err) + } + if !resp.OK || resp.Data.Total != 2 || len(resp.Data.Entries) != 2 { + t.Fatalf("resp = %+v, want ok with 2 entries", resp) + } + if resp.Data.Entries[0].Level != "DEBUG" || !strings.Contains(resp.Data.Entries[0].Message, "flow detail") { + t.Errorf("entry 0 = %+v, want the captured DEBUG line", resp.Data.Entries[0]) + } +} + +// ?raw=1 serves plain text lines (the controller viewer's raw variant). +func TestDebugLogs_RawVariant(t *testing.T) { + srv, _ := newDebugLogServer(t) + w := do(t, srv.Handler(), "GET", "/debug/logs?raw=1", "A", "") + if w.Code != 200 || !strings.HasPrefix(w.Header().Get("Content-Type"), "text/plain") { + t.Fatalf("status=%d content-type=%q", w.Code, w.Header().Get("Content-Type")) + } + body := w.Body.String() + if !strings.Contains(body, "[DEBUG]") || !strings.Contains(body, "ensured network mount") { + t.Errorf("raw body missing lines:\n%s", body) + } +} + +// The route is auth-gated like every sibling (no token → 401), and reports "not +// configured" (503) when the ring is not wired — never a panic, never an empty 200. +func TestDebugLogs_AuthAndUnconfigured(t *testing.T) { + srv, _ := newDebugLogServer(t) + if w := do(t, srv.Handler(), "GET", "/debug/logs", "", ""); w.Code != 401 { + t.Errorf("unauthed status = %d, want 401", w.Code) + } + bare, err := NewServer(Options{ + ListenAddr: "127.0.0.1:0", + Guests: &fakeGuests{}, + Backups: &fakeBackups{}, + Store: &fakeStore{}, + Storage: fakeStorage{}, + Tokens: staticTokens{"A": 8200}, + Logger: slog.New(slog.NewTextHandler(io.Discard, nil)), + }) + if err != nil { + t.Fatalf("new server: %v", err) + } + if w := do(t, bare.Handler(), "GET", "/debug/logs", "A", ""); w.Code != 503 { + t.Errorf("unconfigured status = %d, want 503", w.Code) + } +} + +// The request middleware logs method/path/status/duration at DEBUG into the wired +// logger — proven through a ring-backed server logger (the line must land in the ring). +func TestRequestLogging_DebugLineInRing(t *testing.T) { + logger, ring := applog.NewWithWriter(&bytes.Buffer{}, "info", 50) + srv, err := NewServer(Options{ + ListenAddr: "127.0.0.1:0", + Guests: &fakeGuests{}, + Backups: &fakeBackups{}, + Store: &fakeStore{}, + Storage: fakeStorage{}, + Tokens: staticTokens{"A": 8200}, + LogRing: ring, + Logger: logger, + }) + if err != nil { + t.Fatalf("new server: %v", err) + } + do(t, srv.Handler(), "GET", "/storage", "A", "") + entries, _ := ring.Entries(0) + found := false + for _, e := range entries { + if e.Level == "DEBUG" && strings.Contains(e.Message, "local-api: request") && + strings.Contains(e.Message, "path=/storage") { + found = true + } + } + if !found { + t.Errorf("no request DEBUG line in the ring; entries=%+v", entries) + } +} diff --git a/internal/localapi/disks.go b/internal/localapi/disks.go index fc0e785..e2043d1 100644 --- a/internal/localapi/disks.go +++ b/internal/localapi/disks.go @@ -319,6 +319,7 @@ func (s *Server) handleDiskAssign(w http.ResponseWriter, r *http.Request, vmid i writeErr(w, http.StatusBadRequest, "assign failed: "+err.Error()) return } + s.logger.Info("local-api: disk assigned (host mount ensured)", "vmid", vmid, "where", req.Where) writeOK(w, map[string]any{"vmid": vmid, "assigned": req.Where}) } @@ -372,6 +373,8 @@ func (s *Server) handleDiskEject(w http.ResponseWriter, r *http.Request, vmid in return } } + s.logger.Info("local-api: drive ejected (bind detached, raw mount kept)", + "vmid", vmid, "where", req.Where, "dependent_guests", len(dependents)) writeOK(w, map[string]any{"vmid": vmid, "ejected": req.Where, "dependent_guests": dependents}) } @@ -440,6 +443,8 @@ func (s *Server) handleDiskDecommission(w http.ResponseWriter, r *http.Request, // the RAW /mnt/ host mount — that would orphan the drive (a non-removable SATA drive doesn't get // re-plugged), so a one-click re-enroll (H3) could not re-bind it. The soft decommission marker blocks // scheduling; physical removal is the separate "remove from system" action. NEVER format/mkfs here. + s.logger.Info("local-api: drive decommissioned (logical retire, data untouched)", + "vmid", vmid, "where", req.Where, "durable_id", id, "dependent_guests", len(dependents)) writeOK(w, map[string]any{"vmid": vmid, "decommissioned": req.Where, "dependent_guests": dependents}) } @@ -920,7 +925,10 @@ func (s *Server) ReassertGuestBinds(ctx context.Context) { } } } - for vmid, ids := range s.guestBinds.Guests() { + guests := s.guestBinds.Guests() + s.logger.Debug("reconcile: guest-bind re-assert pass", + "guests", len(guests), "resolved_mounts", len(mountByDurable)) + for vmid, ids := range guests { for _, id := range ids { // Intent-aware (B2, load-bearing): NEVER bind a drive that is not currently `enrolled` — an // ejected or decommissioned drive must not auto-rebind, even if still host-mounted. A nil diff --git a/internal/localapi/netstorage.go b/internal/localapi/netstorage.go index d717ae7..ca84a1d 100644 --- a/internal/localapi/netstorage.go +++ b/internal/localapi/netstorage.go @@ -127,12 +127,15 @@ func (s *Server) handleNetStorageAdd(w http.ResponseWriter, r *http.Request, vmi if !s.netReachable(spec.Protocol, spec.Server) { s.releaseNetVerify(job) s.logger.Warn("local-api: network mount refused — endpoint not reachable", - "name", spec.Name, "server", spec.Server, "proto", spec.Protocol) + "name", spec.Name, "server", spec.Server, "proto", spec.Protocol, + "code", storage.NetVerifyUnreachable) writeStatus(w, http.StatusBadGateway, false, map[string]any{"code": storage.NetVerifyUnreachable}, "NAS endpoint not reachable") return } + s.logger.Debug("local-api: NAS endpoint pre-probe passed", + "name", spec.Name, "server", spec.Server, "proto", spec.Protocol) // SMB: stage the credentials out-of-band (0600). NFS needs none (server squash). if spec.Protocol == storage.ProtocolSMB { @@ -144,6 +147,7 @@ func (s *Server) handleNetStorageAdd(w http.ResponseWriter, r *http.Request, vmi return } spec.CredsRef = credsPath + s.logger.Debug("local-api: SMB credentials staged", "name", spec.Name, "path", credsPath) // path only, never content } if err := s.netStorage.EnsureNetworkMount(r.Context(), spec); err != nil { @@ -251,7 +255,9 @@ func (s *Server) writeSMBCreds(name, username, password string) (string, error) // removeSMBCreds deletes a share's creds file (best-effort; absent is fine). func (s *Server) removeSMBCreds(name string) { - _ = os.Remove(s.smbCredsPath(name)) + if err := os.Remove(s.smbCredsPath(name)); err == nil { + s.logger.Debug("local-api: SMB credentials file removed", "name", name, "path", s.smbCredsPath(name)) + } } // smbCredsPath computes a share's creds file path (pure — used by validation BEFORE the file exists). diff --git a/internal/localapi/netverify_logseq_test.go b/internal/localapi/netverify_logseq_test.go new file mode 100644 index 0000000..0c65599 --- /dev/null +++ b/internal/localapi/netverify_logseq_test.go @@ -0,0 +1,67 @@ +package localapi + +import ( + "bytes" + "net/http" + "strings" + "testing" + + applog "gitea.dooplex.hu/admin/felhom-agent/internal/log" +) + +// S7 sweep smoke (agent half): a full fake NAS add at emit level INFO must leave the +// EXPECTED LOG SEQUENCE in the debug ring — this is the test that encodes "an operator +// can reconstruct the NAS flow from the debug view". Companion red-proof: remove any +// one of the asserted phase lines (e.g. the /proc/mounts verdict Debug) → its marker +// is absent → FAIL naming the missing phase. +func TestNetAdd_LogSequenceReconstructsFlow(t *testing.T) { + logger, ring := applog.NewWithWriter(&bytes.Buffer{}, "info", 200) + n := &fakeNetOps{} + srv := newVerifyServer(t, n, t.TempDir(), verifySeams{ + mounted: func(string) bool { return true }, // §8: in /proc/mounts ⇒ verified + }) + srv.logger = logger // ring-backed capture layer under the whole flow + + body := `{"name":"vids","protocol":"smb","server":"nas","export":"vids","mapped_uid":1000,"mapped_gid":1000,"username":"u","password":"p"}` + if w := do(t, srv.Handler(), "POST", "/netstorage/add", "A", body); w.Code != http.StatusOK { + t.Fatalf("add: got %d (%s)", w.Code, w.Body.String()) + } + final := pollVerify(t, srv.Handler()) + if final["phase"] != netVerifyPhaseDone { + t.Fatalf("phase = %v, want done", final["phase"]) + } + + lines := ring.Lines(0) + joined := strings.Join(lines, "\n") + // The phase markers, in order (each must exist; each must come after the previous). + sequence := []string{ + "NAS endpoint pre-probe passed", + "SMB credentials staged", + "network mount installed", + "netverify: job started", + "netverify: /proc/mounts verdict", + "netverify: mount verified", + } + pos := -1 + for _, marker := range sequence { + idx := indexOfLine(lines, marker, pos+1) + if idx < 0 { + t.Fatalf("phase line %q missing (or out of order) — flow not reconstructable.\nring:\n%s", marker, joined) + } + pos = idx + } + // The secret never appears in any line (creds are path-only). + if strings.Contains(joined, "password") || strings.Contains(joined, `"p"`) { + t.Errorf("a credential-looking token leaked into the log ring:\n%s", joined) + } +} + +// indexOfLine finds the first line at or after `from` containing marker; -1 if none. +func indexOfLine(lines []string, marker string, from int) int { + for i := from; i < len(lines); i++ { + if strings.Contains(lines[i], marker) { + return i + } + } + return -1 +} diff --git a/internal/localapi/netverifyjob.go b/internal/localapi/netverifyjob.go index 3113afe..4905d0a 100644 --- a/internal/localapi/netverifyjob.go +++ b/internal/localapi/netverifyjob.go @@ -112,8 +112,12 @@ func (s *Server) runNetVerify(spec storage.NetworkMountSpec, job *netVerifyJob) done := make(chan struct{}) go func() { defer close(done) + start := time.Now() ctx, cancel := context.WithTimeout(base, netVerifyDeadline) defer cancel() + s.logger.Debug("netverify: job started", + "job_id", job.JobID, "name", spec.Name, "where", spec.Where(), + "proto", spec.Protocol, "deadline_s", int(netVerifyDeadline.Seconds())) // Trigger a real mount: a directory read through the enabled automount mounts the share // (spike Q1, ~1 s on a healthy LAN). The read may block until systemd resolves the mount @@ -123,16 +127,24 @@ func (s *Server) runNetVerify(spec storage.NetworkMountSpec, job *netVerifyJob) go func() { trigger <- s.netTrigger(spec.Where()) }() timedOut := false select { - case <-trigger: + case terr := <-trigger: + // The read error is NOT the verdict (§8) — logged for the flow trace only. + s.logger.Debug("netverify: automount trigger returned", + "name", spec.Name, "read_err", fmt.Sprint(terr)) case <-ctx.Done(): timedOut = true + s.logger.Debug("netverify: deadline fired before the trigger resolved", "name", spec.Name) } // §8 truth table: /proc/mounts is the ONLY success judge. A trigger read error on a mounted // share (EACCES on a 0700 export) is a GOOD mount — the controller's uid-1000 probe decides // writability, not the agent user's readability. - if s.netMounted(spec.Where()) { - s.logger.Info("netverify: mount verified", "name", spec.Name, "where", spec.Where()) + mounted := s.netMounted(spec.Where()) + s.logger.Debug("netverify: /proc/mounts verdict", + "name", spec.Name, "where", spec.Where(), "mounted", mounted, "timed_out", timedOut) + if mounted { + s.logger.Info("netverify: mount verified", "name", spec.Name, "where", spec.Where(), + "duration_ms", time.Since(start).Milliseconds()) s.finishNetVerify(job, netVerifyPhaseDone, "", "") return } @@ -142,7 +154,8 @@ func (s *Server) runNetVerify(spec storage.NetworkMountSpec, job *netVerifyJob) code, detail := s.classifyNetFailure(base, spec, timedOut) s.rollbackNetMount(base, spec) s.logger.Warn("netverify: verify failed — install rolled back", - "name", spec.Name, "code", code, "timed_out", timedOut) + "name", spec.Name, "code", code, "timed_out", timedOut, + "duration_ms", time.Since(start).Milliseconds()) s.finishNetVerify(job, netVerifyPhaseFailed, code, detail) }() return done @@ -168,7 +181,9 @@ func (s *Server) classifyNetFailure(base context.Context, spec storage.NetworkMo "unit", unit, "err", jerr) return fallback, "journal unavailable — add the felhom-agent user to the systemd-journal group (usermod -aG systemd-journal felhom-agent)" } + s.logger.Debug("netverify: journal tail read for classification", "unit", unit, "bytes", len(tail)) code, hint := storage.ClassifyNetVerifyFailure(tail, s.netReachable(spec.Protocol, spec.Server)) + s.logger.Debug("netverify: failure classified", "name", spec.Name, "code", code, "timed_out", timedOut) if code == storage.NetVerifyMountFailed && timedOut { code = storage.NetVerifyTimeout } @@ -189,6 +204,8 @@ func (s *Server) rollbackNetMount(base context.Context, spec storage.NetworkMoun if err := s.netStorage.RemoveNetworkMount(ctx, spec.Name); err != nil { s.logger.Error("netverify: rollback RemoveNetworkMount failed (manual cleanup may be needed)", "name", spec.Name, "err", err) + } else { + s.logger.Info("netverify: failed install rolled back (unit pair removed)", "name", spec.Name) } if spec.Protocol == storage.ProtocolSMB { s.removeSMBCreds(spec.Name) diff --git a/internal/localapi/server.go b/internal/localapi/server.go index 754d043..92951e7 100644 --- a/internal/localapi/server.go +++ b/internal/localapi/server.go @@ -16,6 +16,7 @@ import ( "gitea.dooplex.hu/admin/felhom-agent/internal/escrow" "gitea.dooplex.hu/admin/felhom-agent/internal/hub" + applog "gitea.dooplex.hu/admin/felhom-agent/internal/log" "gitea.dooplex.hu/admin/felhom-agent/internal/proxmox" "gitea.dooplex.hu/admin/felhom-agent/internal/storage" ) @@ -133,7 +134,10 @@ type Options struct { // Supports() compares this against a per-feature MinAgent table instead of route-probing // (v0.82.0; the probe stays as the fallback for header-less agents). Optional. AgentVersion string - Logger *slog.Logger + // LogRing is the agent's always-DEBUG capture ring (v0.83.0 observability), served by + // GET /debug/logs. OPTIONAL — when nil the endpoint reports "not configured". + LogRing *applog.Ring + Logger *slog.Logger } // defaultBackupCadence is the fallback /backup/due window when none is configured. @@ -191,6 +195,7 @@ type Server struct { hostMetrics HostMetricsProvider // slice 9 (optional) hostID string // slice 10B: for the data-bearing-format pending-op hint agentVersion string // v0.82.0: the X-Felhom-Agent-Version response header value + logRing *applog.Ring // v0.83.0: GET /debug/logs source (optional) // reresolveWipe performs the [AGENT-001] anti-retarget re-resolution before an // inline customer-confirmed wipe (durable id → current device, re-derive+match, @@ -281,6 +286,7 @@ func NewServer(o Options) (*Server, error) { hostMetrics: o.HostMetrics, hostID: o.HostID, agentVersion: o.AgentVersion, + logRing: o.LogRing, jobs: map[int]*backupJob{}, swapInFlight: map[int]bool{}, } @@ -344,16 +350,21 @@ func (s *Server) Handler() http.Handler { // fork-4 hygiene: wipe the staged secret once escrowed (controller calls this on confirm). Idempotent. mux.HandleFunc("DELETE /escrow/stage-secret", s.withGuest(s.handleWipeStagedEscrowSecret)) + // v0.83.0 observability: the agent's always-DEBUG capture ring, for the controller's + // Debug page agent tab (same auth/self-scoping wrap as every sibling route). + mux.HandleFunc("GET /debug/logs", s.withGuest(s.handleDebugLogs)) + // v0.82.0 version channel: EVERY response (any route, any status — including auth failures) // carries X-Felhom-Agent-Version, so the controller learns the agent version passively from its // ordinary traffic and can capability-gate by comparison instead of route-probing. Header-less // (pre-0.82) agents keep working — the controller falls back to the probe. - return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + // v0.83.0: wrapped in the request-level DEBUG log middleware (method/path/status/duration). + return s.logRequests(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { if s.agentVersion != "" { w.Header().Set("X-Felhom-Agent-Version", s.agentVersion) } mux.ServeHTTP(w, r) - }) + })) } // Run binds the bridge socket, serves TLS, and shuts down gracefully on ctx cancellation. It diff --git a/internal/log/log.go b/internal/log/log.go index 2ed70a4..bd3e521 100644 --- a/internal/log/log.go +++ b/internal/log/log.go @@ -1,28 +1,223 @@ // Package log builds the agent's slog logger. Kept tiny on purpose; the agent is // a host service, so logs go to stderr (journald-friendly). Secrets must never be // passed to the logger — config is logged only via Config.Redacted (see config). +// +// Observability pass (v0.83.0): New now fans out to TWO handlers — stderr at the +// configured level (journald behavior unchanged) and an in-memory debug Ring fixed +// at LevelDebug. The ring is the remote-diagnostics capture layer: DEBUG detail +// exists for GET /debug/logs and the heartbeat log-pull WITHOUT a config flip. package log import ( + "context" + "io" "log/slog" "os" "strings" + "sync" + "time" ) +// DefaultRingSize is the debug ring's entry capacity (~1000 lines ≈ a few hours of +// normal operation; the heartbeat tail is additionally byte-capped by its caller). +const DefaultRingSize = 1000 + // New returns a text slog.Logger at the given level ("debug"|"info"|"warn"| -// "error"; unknown falls back to info), writing to stderr. -func New(level string) *slog.Logger { - var lvl slog.Level +// "error"; unknown falls back to info) writing to stderr, plus the debug Ring +// that captures EVERY record at LevelDebug regardless of the stderr level. +func New(level string) (*slog.Logger, *Ring) { + return NewWithWriter(os.Stderr, level, DefaultRingSize) +} + +// NewWithWriter is the injectable constructor (tests capture the stderr stream). +func NewWithWriter(w io.Writer, level string, ringSize int) (*slog.Logger, *Ring) { + lvl := ParseLevel(level) + ring := NewRing(ringSize) + stderrH := slog.NewTextHandler(w, &slog.HandlerOptions{Level: lvl}) + // The ring handler is FIXED at LevelDebug — the capture layer must hold flow + // detail even when the emit level is info (the motivating incident: an info box + // showed nothing about a refused NAS verify because the detail never existed). + ringH := slog.NewTextHandler(ring, &slog.HandlerOptions{Level: slog.LevelDebug}) + return slog.New(fanout{stderrH, ringH}), ring +} + +// ParseLevel maps a config level string to a slog.Level (unknown → info). +func ParseLevel(level string) slog.Level { switch strings.ToLower(level) { case "debug": - lvl = slog.LevelDebug + return slog.LevelDebug case "warn", "warning": - lvl = slog.LevelWarn + return slog.LevelWarn case "error": - lvl = slog.LevelError + return slog.LevelError default: - lvl = slog.LevelInfo + return slog.LevelInfo } - h := slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{Level: lvl}) - return slog.New(h) +} + +// fanout dispatches one record to every handler whose level admits it. Each +// handler keeps its own level, so the ring can capture DEBUG while stderr stays +// at the configured emit level. +type fanout []slog.Handler + +func (f fanout) Enabled(ctx context.Context, lvl slog.Level) bool { + for _, h := range f { + if h.Enabled(ctx, lvl) { + return true + } + } + return false +} + +func (f fanout) Handle(ctx context.Context, r slog.Record) error { + var firstErr error + for _, h := range f { + if !h.Enabled(ctx, r.Level) { + continue + } + if err := h.Handle(ctx, r.Clone()); err != nil && firstErr == nil { + firstErr = err + } + } + return firstErr +} + +func (f fanout) WithAttrs(attrs []slog.Attr) slog.Handler { + out := make(fanout, len(f)) + for i, h := range f { + out[i] = h.WithAttrs(attrs) + } + return out +} + +func (f fanout) WithGroup(name string) slog.Handler { + out := make(fanout, len(f)) + for i, h := range f { + out[i] = h.WithGroup(name) + } + return out +} + +// Entry is one captured log record, parsed from the slog text line (the port of +// the controller's web.LogBuffer entry, adapted to slog's text format). +type Entry struct { + Time time.Time `json:"timestamp"` + Level string `json:"level"` // DEBUG | INFO | WARN | ERROR + Message string `json:"message"` // msg=… plus attrs, verbatim from the text handler +} + +// Ring is a thread-safe fixed-size ring of Entries. It implements io.Writer so a +// slog.TextHandler can feed it (one Write per record — TextHandler writes each +// record as a single line). +type Ring struct { + mu sync.RWMutex + entries []Entry + pos int + full bool +} + +// NewRing creates a ring keeping the last size entries (size ≤ 0 → DefaultRingSize). +func NewRing(size int) *Ring { + if size <= 0 { + size = DefaultRingSize + } + return &Ring{entries: make([]Entry, size)} +} + +// Write parses one slog text line ("time=… level=… msg=… k=v …") into an Entry. +func (r *Ring) Write(p []byte) (int, error) { + line := strings.TrimRight(string(p), "\r\n") + if line == "" { + return len(p), nil + } + e := parseSlogLine(line) + r.mu.Lock() + r.entries[r.pos] = e + r.pos = (r.pos + 1) % len(r.entries) + if r.pos == 0 && !r.full { + r.full = true + } + r.mu.Unlock() + return len(p), nil +} + +// Entries returns up to limit entries in chronological order (newest kept when +// truncating; limit ≤ 0 or > cap → everything held) plus the total held count. +func (r *Ring) Entries(limit int) ([]Entry, int) { + r.mu.RLock() + defer r.mu.RUnlock() + total := r.pos + start := 0 + if r.full { + total = len(r.entries) + start = r.pos + } + out := make([]Entry, 0, total) + for i := 0; i < total; i++ { + out = append(out, r.entries[(start+i)%len(r.entries)]) + } + if limit > 0 && len(out) > limit { + out = out[len(out)-limit:] + } + return out, total +} + +// Lines renders the held entries as plain text lines (chronological), dropping +// from the HEAD (oldest) to honor maxBytes so the newest lines survive — the +// heartbeat log-tail budget (maxBytes ≤ 0 → no byte cap). +func (r *Ring) Lines(maxBytes int) []string { + entries, _ := r.Entries(0) + lines := make([]string, len(entries)) + for i, e := range entries { + lines[i] = e.Time.Format(time.RFC3339) + " [" + e.Level + "] " + e.Message + } + if maxBytes <= 0 { + return lines + } + total := 0 + start := len(lines) + for i := len(lines) - 1; i >= 0; i-- { + total += len(lines[i]) + 1 // +1 for the newline it represents + if total > maxBytes { + break + } + start = i + } + return lines[start:] +} + +// parseSlogLine splits a TextHandler line into time / level / the rest. Attrs and +// the quoted msg stay verbatim in Message — honest, and immune to quoting edge +// cases the viewer doesn't need parsed. +func parseSlogLine(line string) Entry { + e := Entry{Level: "INFO", Message: line, Time: time.Now()} + rest := line + if v, r2, ok := cutField(rest, "time="); ok { + if t, err := time.Parse(time.RFC3339Nano, v); err == nil { + e.Time = t + } + rest = r2 + } + if v, r2, ok := cutField(rest, "level="); ok { + switch v { + case "DEBUG", "INFO", "WARN", "ERROR": + e.Level = v + } + rest = r2 + } + e.Message = rest + return e +} + +// cutField extracts a leading `key=value ` field (unquoted — slog never quotes +// its own time/level values) and returns the value + the remainder. +func cutField(s, key string) (val, rest string, ok bool) { + if !strings.HasPrefix(s, key) { + return "", s, false + } + s = s[len(key):] + if i := strings.IndexByte(s, ' '); i >= 0 { + return s[:i], s[i+1:], true + } + return s, "", true } diff --git a/internal/log/log_test.go b/internal/log/log_test.go new file mode 100644 index 0000000..eb9a39b --- /dev/null +++ b/internal/log/log_test.go @@ -0,0 +1,121 @@ +package log + +import ( + "bytes" + "fmt" + "strings" + "testing" +) + +// S1 capture-at-info (the observability pass's load-bearing property): at emit level +// "info" a DEBUG line reaches the ring AND is absent from the stderr stream. Companion +// red-proof: revert the fan-out (New returning a single stderr handler) → the ring +// misses the DEBUG entry → the first assertion fails. +func TestCaptureAtInfo_RingHoldsDebugStderrDoesNot(t *testing.T) { + var stderr bytes.Buffer + logger, ring := NewWithWriter(&stderr, "info", 50) + + logger.Debug("netverify: /proc/mounts verdict", "mounted", false) + logger.Info("netmount: ensured network mount", "name", "nas-media") + + entries, total := ring.Entries(0) + if total != 2 { + t.Fatalf("ring holds %d entries, want 2 (DEBUG must be captured at emit level info)", total) + } + if entries[0].Level != "DEBUG" || !strings.Contains(entries[0].Message, "proc/mounts verdict") { + t.Errorf("ring entry 0 = %+v, want the DEBUG verdict line", entries[0]) + } + if entries[1].Level != "INFO" { + t.Errorf("ring entry 1 level = %q, want INFO", entries[1].Level) + } + if strings.Contains(stderr.String(), "proc/mounts verdict") { + t.Errorf("stderr contains the DEBUG line at emit level info:\n%s", stderr.String()) + } + if !strings.Contains(stderr.String(), "ensured network mount") { + t.Errorf("stderr missing the INFO line:\n%s", stderr.String()) + } +} + +// At emit level "debug" both sinks carry the line (journald behavior unchanged). +func TestCaptureAtDebug_BothSinks(t *testing.T) { + var stderr bytes.Buffer + logger, ring := NewWithWriter(&stderr, "debug", 50) + logger.Debug("flow detail", "k", "v") + if _, total := ring.Entries(0); total != 1 { + t.Fatalf("ring total = %d, want 1", total) + } + if !strings.Contains(stderr.String(), "flow detail") { + t.Errorf("stderr missing the DEBUG line at emit level debug:\n%s", stderr.String()) + } +} + +// The ring wraps: with capacity 5 and 8 writes, the NEWEST 5 survive in order. +func TestRing_WrapKeepsNewest(t *testing.T) { + var stderr bytes.Buffer + logger, ring := NewWithWriter(&stderr, "error", 5) + for i := 0; i < 8; i++ { + logger.Info(fmt.Sprintf("line-%d", i)) + } + entries, total := ring.Entries(0) + if total != 5 || len(entries) != 5 { + t.Fatalf("total=%d len=%d, want 5", total, len(entries)) + } + for i, e := range entries { + want := fmt.Sprintf("line-%d", i+3) + if !strings.Contains(e.Message, want) { + t.Errorf("entry %d = %q, want it to contain %q (chronological, newest kept)", i, e.Message, want) + } + } +} + +// Entries(limit) keeps the most recent `limit` entries. +func TestRing_LimitKeepsNewest(t *testing.T) { + logger, ring := NewWithWriter(&bytes.Buffer{}, "error", 10) + for i := 0; i < 6; i++ { + logger.Info(fmt.Sprintf("line-%d", i)) + } + entries, _ := ring.Entries(2) + if len(entries) != 2 || !strings.Contains(entries[1].Message, "line-5") || !strings.Contains(entries[0].Message, "line-4") { + t.Errorf("Entries(2) = %+v, want the two newest lines", entries) + } +} + +// Lines honors the byte budget by dropping the OLDEST lines (the heartbeat 128 KB cap). +func TestRing_LinesByteBudgetKeepsNewest(t *testing.T) { + logger, ring := NewWithWriter(&bytes.Buffer{}, "error", 10) + for i := 0; i < 5; i++ { + logger.Info(fmt.Sprintf("line-%d %s", i, strings.Repeat("x", 100))) + } + all := ring.Lines(0) + if len(all) != 5 { + t.Fatalf("uncapped lines = %d, want 5", len(all)) + } + // Budget for roughly two lines. + budget := len(all[3]) + len(all[4]) + 2 + capped := ring.Lines(budget) + if len(capped) >= 5 { + t.Fatalf("byte budget did not truncate: %d lines", len(capped)) + } + if !strings.Contains(capped[len(capped)-1], "line-4") { + t.Errorf("newest line missing after byte cap: %q", capped[len(capped)-1]) + } +} + +// The slog text line parser extracts time + level and preserves the remainder verbatim. +func TestParseSlogLine(t *testing.T) { + e := parseSlogLine(`time=2026-07-11T10:30:00.123+02:00 level=WARN msg="verify failed" code=auth_failed`) + if e.Level != "WARN" { + t.Errorf("level = %q, want WARN", e.Level) + } + if e.Time.Year() != 2026 || e.Time.Minute() != 30 { + t.Errorf("time not parsed: %v", e.Time) + } + if !strings.Contains(e.Message, `msg="verify failed"`) || !strings.Contains(e.Message, "code=auth_failed") { + t.Errorf("message lost content: %q", e.Message) + } + // A non-slog line degrades to INFO with the line verbatim (never dropped). + raw := parseSlogLine("plain text line") + if raw.Level != "INFO" || raw.Message != "plain text line" { + t.Errorf("raw line entry = %+v", raw) + } +} diff --git a/internal/selfupdate/executor.go b/internal/selfupdate/executor.go index 0066ac6..a3bc2fb 100644 --- a/internal/selfupdate/executor.go +++ b/internal/selfupdate/executor.go @@ -98,6 +98,7 @@ func (e *Executor) Execute(ctx context.Context, op string, params json.RawMessag if e.runner == nil { return fmt.Errorf("agent_update: no wrapper runner configured") } + e.logger.Debug("agent_update: op invariants passed (semver + sha format)", "version", p.Version) dir := stagingDir(e.stateDir) if err := os.MkdirAll(dir, 0o750); err != nil { @@ -107,11 +108,14 @@ func (e *Executor) Execute(ctx context.Context, op string, params json.RawMessag url := interpolateURL(e.urlTemplate, p.Version) e.logger.Warn("agent_update: downloading operator-signed binary", "version", p.Version, "url", url, "sha256", p.SHA256) + dlStart := time.Now() got, err := e.download(ctx, url, staged) if err != nil { _ = os.Remove(staged) return fmt.Errorf("agent_update: download %s: %w", url, err) } + e.logger.Debug("agent_update: download complete", "version", p.Version, + "sha_match", got == p.SHA256, "duration_ms", time.Since(dlStart).Milliseconds()) // The signed sha is the ONLY integrity root — verify BEFORE anything touches the live binary. if got != p.SHA256 { _ = os.Remove(staged) diff --git a/internal/signedjobs/runner.go b/internal/signedjobs/runner.go index 05c7cad..83764c3 100644 --- a/internal/signedjobs/runner.go +++ b/internal/signedjobs/runner.go @@ -14,6 +14,7 @@ import ( "fmt" "log/slog" "sync" + "time" "gitea.dooplex.hu/admin/felhom-agent/internal/authz" "gitea.dooplex.hu/admin/felhom-agent/internal/hub" @@ -98,10 +99,17 @@ func (r *Runner) RunOnce(ctx context.Context) (int, error) { r.mu.Unlock() defer func() { r.mu.Lock(); r.running = false; r.mu.Unlock() }() + start := time.Now() jobs, err := r.source.Jobs(ctx) if err != nil { return 0, fmt.Errorf("signedjobs: fetch jobs: %w", err) } + ids := make([]string, len(jobs)) + for i, j := range jobs { + ids[i] = j.JobID + } + r.logger.Debug("signedjobs: jobs fetched", "count", len(jobs), "ids", ids, + "duration_ms", time.Since(start).Milliseconds()) processed := 0 for _, j := range jobs { if r.processJob(ctx, j) { @@ -122,6 +130,11 @@ func (r *Runner) processJob(ctx context.Context, j hub.JobWire) bool { return true } + // Op received — class/target/expiry only, NEVER the signature or nonce material. + r.logger.Debug("signedjobs: op received", + "job", j.JobID, "op", ob.Op, "target_host", ob.Target.HostID, + "issued_at", ob.IssuedAt.Format(time.RFC3339), "expires_at", ob.ExpiresAt.Format(time.RFC3339)) + intent := reconcile.Intent{ Class: reconcile.OpClass(ob.Op), HostID: ob.Target.HostID, diff --git a/internal/storage/netmount.go b/internal/storage/netmount.go index 3d0d93e..7b4c7b2 100644 --- a/internal/storage/netmount.go +++ b/internal/storage/netmount.go @@ -366,9 +366,12 @@ func (h *SudoHostOps) EnsureNetworkMount(ctx context.Context, spec NetworkMountS if err := h.installUnit(ctx, mountUnit, renderNetworkMountUnit(spec)); err != nil { return err } + h.logger.Debug("netmount: mount unit installed", "unit", mountUnit) if err := h.installUnit(ctx, automountUnit, renderNetworkAutomountUnit(spec)); err != nil { return err } + h.logger.Debug("netmount: automount unit installed", "unit", automountUnit, + "idle_timeout_s", spec.idleTimeout()) if err := h.run(ctx, h.bins.Systemctl, "daemon-reload"); err != nil { return fmt.Errorf("netmount: daemon-reload: %w", err) } @@ -376,6 +379,7 @@ func (h *SudoHostOps) EnsureNetworkMount(ctx context.Context, spec NetworkMountS if err := h.run(ctx, h.bins.Systemctl, "enable", "--now", "--", automountUnit); err != nil { return fmt.Errorf("netmount: enabling automount %s: %w", automountUnit, err) } + h.logger.Debug("netmount: automount enabled + started", "unit", automountUnit) h.logger.Info("netmount: ensured network mount", "name", spec.Name, "proto", spec.Protocol, "server", spec.Server, "export", spec.Export, "where", spec.Where(), "host_uid", spec.HostUID()) return nil @@ -414,9 +418,15 @@ func (h *SudoHostOps) RemoveNetworkMount(ctx context.Context, name string) error automountUnit := strings.TrimSuffix(mountUnit, ".mount") + ".automount" // Stop the automount first (so it can't re-trigger the mount), then the mount. Tolerate "not loaded". - _ = h.run(ctx, h.bins.Systemctl, "stop", "--", automountUnit) - _ = h.run(ctx, h.bins.Systemctl, "disable", "--", automountUnit) - _ = h.run(ctx, h.bins.Systemctl, "stop", "--", mountUnit) + for _, step := range [][]string{ + {"stop", "--", automountUnit}, + {"disable", "--", automountUnit}, + {"stop", "--", mountUnit}, + } { + err := h.run(ctx, h.bins.Systemctl, step...) + h.logger.Debug("netmount: remove step", "verb", step[0], "unit", step[len(step)-1], + "ok", err == nil) // a "not loaded" failure here is expected + tolerated + } destAuto := filepath.Join(h.unitDir, automountUnit) destMount := filepath.Join(h.unitDir, mountUnit)