From 26a43708b776ab9790cba2a674bd8e99a6026d93 Mon Sep 17 00:00:00 2001 From: kisfenyo Date: Sat, 11 Jul 2026 16:45:57 +0200 Subject: [PATCH] =?UTF-8?q?v0.116.0:=20observability=20pass=20=E2=80=94=20?= =?UTF-8?q?always-on=20debug=20ring=20+=20leveled=20sweep=20+=20agent=20ta?= =?UTF-8?q?b=20+=20self-log=20pull=20=E2=80=94=20MinAgent:=200.81.0?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Capture layer: LogBuffer always exists; logger = MultiWriter(LevelFilterWriter (stdout, logging.level), ring) so DEBUG detail exists remotely without a config flip while docker logs keep respecting the level. New internal/logx leveled helpers. Report ACK gains controller_log_requested (additive); next report ships controller_log_tail (128KB, consume-once, app-tail wire byte-compatible). Debug page: Vezérlő|Ügynök tabs; agent tab proxies agent /debug/logs with the pre-0.83 notice on typed 404. Sweep: netstorage_job phases, netprobe, handler validation refusals + orphan WARN, SupportsWithSource gate line, agentapi per-call DEBUG, migrate phase lines, tier2/offbox unswallowed persists. Red-proofs: filter-disabled, drain-removed, dropped-phase-line all FAIL. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01PSK5g6qYLknKj8u3QAFEr6 --- CHANGELOG.md | 35 +++++ REUSE.md | 8 +- controller/README.md | 5 +- controller/cmd/controller/main.go | 17 ++- controller/internal/agentapi/client.go | 54 ++++++++ controller/internal/agentapi/features.go | 22 +++- controller/internal/backup/offbox.go | 11 +- controller/internal/backup/tier2.go | 18 ++- controller/internal/logx/logx.go | 37 ++++++ controller/internal/report/builder.go | 4 + controller/internal/report/pusher.go | 4 + controller/internal/report/selftail.go | 74 +++++++++++ controller/internal/report/selftail_test.go | 107 ++++++++++++++++ controller/internal/report/types.go | 5 + controller/internal/stacks/migrate.go | 6 +- .../internal/web/agent_disk_handlers.go | 4 + controller/internal/web/capture_layer_test.go | 82 ++++++++++++ controller/internal/web/handler_debug.go | 39 ++++++ controller/internal/web/levelfilter.go | 34 +++++ controller/internal/web/logbuffer.go | 41 ++++++ .../internal/web/netstorage_handlers.go | 12 +- controller/internal/web/netstorage_job.go | 38 +++++- controller/internal/web/observability_test.go | 121 ++++++++++++++++++ controller/internal/web/server.go | 3 + controller/internal/web/templates/debug.html | 47 ++++++- 25 files changed, 797 insertions(+), 31 deletions(-) create mode 100644 controller/internal/logx/logx.go create mode 100644 controller/internal/report/selftail.go create mode 100644 controller/internal/report/selftail_test.go create mode 100644 controller/internal/web/capture_layer_test.go create mode 100644 controller/internal/web/levelfilter.go create mode 100644 controller/internal/web/observability_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index 02ec479..8530635 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,40 @@ ## Changelog +### v0.116.0 — observability pass: always-on debug ring + leveled sweep + agent tab + self-log pull (2026-07-11) — MinAgent: 0.81.0 + +Controller half of the cross-repo observability task (agent v0.83.0 + hub v0.46.0). Motivating +incident: a live NAS-verify refusal on an `info` box showed NOTHING in the debug view — the ring +only existed at `logging.level=debug`, so the detail never existed. + +- **Capture layer**: `setupLogger` now ALWAYS builds the 1000-entry `LogBuffer`; the logger is + `MultiWriter(LevelFilterWriter(stdout, logging.level), ring)` — DEBUG always reaches the ring, + stdout/docker-logs keep respecting `logging.level` exactly as before (red-proof: filter disabled → + the capture test fails on the stdout assertion). New `internal/logx` leveled helpers + (`Debugf/Infof/Warnf/Errorf`, caller-attributed via `Output(3,…)`); legacy `isDebug()` sites + untouched (observation, not refactor). +- **Report self-log pull** (`report/selftail.go`): ACK gains `controller_log_requested` (additive); + the NEXT report carries `controller_log_tail` (ring newest-kept, 128 KB, consume-once — the + v0.111.0 logtail.go shape copied exactly; red-proof: drain removed → ships every cycle → FAIL). + The app-tail wire is byte-compatible (schema test asserts steady-state omission + unchanged keys). + Serving a pull logs the customer-visible `operator log pull served` INFO (rides IN the tail). +- **Debug page agent tab**: Naplóviewer gains `Vezérlő | Ügynök` tabs; the agent tab proxies + `GET /api/debug/agent-logs` → agent `GET /debug/logs` (client `DebugLogs`, 10 s budget). A + pre-0.83 agent (typed 404 StatusError) renders "Az ügynök naplónézete az ügynök következő + frissítése után érhető el." — ok-response, no error spam, nothing else gated (S6 tested both + polarities). Template gates green. +- **Gap-fill sweep** (all new lines via logx; entry/decisions/outcome+duration/errors): + netstorage_job (start, per-phase transitions with elapsed, agent add/verify/probe verdicts, + rollback start+outcome, terminal WARN/INFO with duration), netprobe (exec start + result), + netstorage_handlers (per-check validation refusals, orphan-share WARN, capability-gate line now + carries the decision SOURCE via new `SupportsWithSource` — version vs probe vs cache), agentapi + client (per-call DEBUG method/path/status/duration + agent-version-change line; `SetLogger` wired + on the memoized client), migrate engine (run start, per-phase DEBUG, complete line with duration), + tier2/offbox (run-start INFO + previously SWALLOWED status-persist errors now WARN). +- **S7 log-sequence smoke**: a full fake NAS add at level info must leave the 8 ordered phase + markers in the ring (red-proof: dropped probe-verdict line → FAIL naming the marker). +- MinAgent: **0.81.0 unchanged** — the agent tab degrades to the notice on older agents; nothing + else is coupled. Demo-deploy only; Peti untouched (his visibility arrives with the next train). + ### v0.115.0 — version-aware Supports (agent version channel) + DSM-validated guidance (2026-07-11) — MinAgent: 0.81.0 Capability detection upgrades from route-probing to explicit version comparison, riding agent diff --git a/REUSE.md b/REUSE.md index 02860f8..b63510f 100644 --- a/REUSE.md +++ b/REUSE.md @@ -137,7 +137,9 @@ | `timeAgoStr` | controller/internal/web/funcmap.go | `(s RFC3339 string) string` | Ago-format for STRING timestamps | Exists because `timeAgo(time.Time)` 500'd on strings (v0.93 bug) | | `Server.baseData` / `executeTemplate` | controller/internal/web/handlers.go + server.go | page-data plumbing | New pages | baseData injects nav/alerts/version; templates must pass `controller/scripts/template_id_gate.py` + `controller/scripts/emoji_gate.py` | | `Server.RequireAuth` / `CsrfProtect` / `csrfField` | controller/internal/web/auth.go + csrf.go | middleware | Any new authed route/form | csrfField emits the hidden input; setup wizard has its OWN csrf (§6) | -| `LogBuffer` | controller/internal/web/logbuffer.go | ring buffer io.Writer | In-memory log capture for debug UI | — | +| `LogBuffer` + `Lines(maxBytes)` | controller/internal/web/logbuffer.go | ring buffer io.Writer | In-memory log capture for the debug UI + the report `controller_log_tail` source | v0.116.0: ALWAYS constructed (any logging.level) — the logger is `MultiWriter(LevelFilterWriter(stdout, level), ring)`; `Lines` drops OLDEST to honor the byte budget | +| `logx.Debugf/Infof/Warnf/Errorf` | controller/internal/logx/logx.go | `(l *log.Logger, format, args…)` | ALL NEW leveled log lines (the v0.116.0 sweep standard) | routing is the WRITER's job — Debugf always reaches the ring, stdout filters; nil logger = no-op; caller-attributed (Output calldepth 3) | +| `web.LevelFilterWriter` | controller/internal/web/levelfilter.go | `NewLevelFilterWriter(w, minLevel)` | stdout leveling under the always-on ring | untagged lines parse INFO; always reports full length written | | `monitor.RunHealthCheck` / `EffectiveProtected` | controller/internal/monitor/healthcheck.go | system health report | Health + protected-container list | — | | `util.TruncateStr` | controller/internal/util/strings.go | `(s, maxLen) string` | Rune-safe truncation | The intended shared helper; stacks still uses its byte-based twin (§6) | @@ -175,8 +177,10 @@ |---|---|---|---| | `diskAgent` | controller/internal/web/storage_handlers.go | `*agentapi.Client` | `mockAgent` in controller/internal/web/storage_handlers_test.go | | `netAgent` + `Server.netAgentFn/netProbeFn/netListFn` | controller/internal/web/netstorage_job.go (+ server.go fields) | `*agentapi.Client` / `runNetProbe` (linux re-exec) / `agent.ListNetStorage` | `fakeNetAgent` + fn injections in controller/internal/web/netstorage_job_test.go — the NAS add orchestration never shells/TLS-dials in tests | +| `Server.agentLogsFn` (func seam) | controller/internal/web/server.go | nil → `agentClient().DebugLogs` (agent GET /debug/logs) | injected in controller/internal/web/observability_test.go (incl. the pre-0.83 typed-404 notice path) | +| `report.SetPendingControllerLog` / `SetControllerLogSource` | controller/internal/report/selftail.go | ACK-armed consume-once self-log pull (the logtail.go shape) | selftail_test.go; source = `logBuffer.Lines`, wired once in main.go | | `util.ParseVersion` / `util.Version.Compare` | controller/internal/util/version.go | THE one semver comparator (house rule: never a second) — selfupdate aliases it; agentapi's MinAgent comparison uses it | rejects pre-release/dev/latest (callers fall back, never trust); numeric compare (0.100 > 0.81) | -| `agentapi.AgentVersionReporter` + `featureMinAgent` | controller/internal/agentapi/features.go | version-first Supports (v0.82.0 header channel); probe = fallback for header-less agents | a coupled feature adds BOTH a featureProbes row AND a featureMinAgent row | +| `agentapi.AgentVersionReporter` + `featureMinAgent` | controller/internal/agentapi/features.go | version-first Supports (v0.82.0 header channel); probe = fallback for header-less agents | a coupled feature adds BOTH a featureProbes row AND a featureMinAgent row; v0.116.0: `SupportsWithSource` also reports HOW the verdict was reached (version/probe-cache/probe) for the gate log line | | `netProbeReadBack` (package var) | controller/internal/web/netprobe.go | `os.ReadFile` | overridden in TestNetProbeChild (nonce-tamper + cleanup-fail rows); package var because the child is a RE-EXEC'd process in production | | `quiesce.Backend` / `quiesce.Stacks` | controller/internal/quiesce/quiesce.go | adapter over `*agentapi.Client` / `*stacks.Manager` | `fakeBackend`/`fakeStacks` in controller/internal/quiesce/quiesce_test.go | | `channelhealth.Probe` (func) + `Sink` | controller/internal/channelhealth/checker.go | `Server.ProbeAgentChannel` / notifier adapter | `fakeSink` in controller/internal/channelhealth/checker_test.go | diff --git a/controller/README.md b/controller/README.md index 549c8f3..a4596f6 100644 --- a/controller/README.md +++ b/controller/README.md @@ -1817,11 +1817,12 @@ When `logging.level: "debug"` is set in `controller.yaml`, the controller expose | — | Telemetria teszt | `GET /api/debug/telemetry` | Run the full telemetry collection pipeline on-demand (metrics query + log scan). Returns per-app table: container list, memory current/avg/peak, CPU avg, catalog limit, log error/warning counts, and top issues. Useful for verifying container→stack mapping and testing log scanner patterns without waiting for the 15-minute report cycle. | | 6 | Önfrissítés teszt | `POST /api/debug/selfupdate/dry-run` | Dry-run update check: current vs new image lines, compose writability, backup state. | | 7 | DR / Telepítő varázsló | `POST /api/debug/dr/trigger-setup`, `GET /api/debug/dr/infra-status` | Infra backup status per drive. Trigger setup mode via marker file (requires "RESET" + infra backup pre-check). | -| 8 | Naplóviewer | `GET /api/debug/logs?level=&limit=&after=` | In-memory log viewer (last 1000 entries), level filter, 2s auto-refresh, color-coded entries. | +| 8 | Naplóviewer | `GET /api/debug/logs?level=&limit=&after=`, `GET /api/debug/agent-logs` | In-memory log viewer (last 1000 entries), level filter, 2s auto-refresh, color-coded entries. Two tabs (v0.116.0): **Vezérlő** (own ring) and **Ügynök** (the agent's always-DEBUG ring proxied over the local API; a pre-0.83 agent renders the "available after the agent's next update" notice). | #### Key Implementation Details -- **Log buffer** (`internal/web/logbuffer.go`): Ring buffer implementing `io.Writer`, created before all modules via `io.MultiWriter(os.Stdout, logBuffer)`. Parses `[DEBUG]`/`[INFO]`/`[WARN]`/`[ERROR]` tags from standard log format. +- **Log buffer** (`internal/web/logbuffer.go`): Ring buffer implementing `io.Writer`. Since v0.116.0 it ALWAYS exists (any `logging.level`) and captures every line INCLUDING `[DEBUG]`: the logger is `io.MultiWriter(LevelFilterWriter(os.Stdout, logging.level), logBuffer)` — stdout/docker-logs keep respecting `logging.level`, the ring holds the full detail for remote diagnostics. `logBuffer.Lines(maxBytes)` renders the newest-kept plain-text tail (the report `controller_log_tail` source). New leveled lines use `internal/logx` (`Debugf/Infof/Warnf/Errorf`); legacy `isDebug()` call sites are unchanged. +- **Controller self-log pull** (`internal/report/selftail.go`): the hub's report ACK may carry `controller_log_requested` — the NEXT report ships `controller_log_tail` (ring, 128 KB cap, consume-once, the v0.111.0 app-tail pattern; additive fields, app-tail wire unchanged). Serving a pull logs the customer-visible `operator log pull served` INFO line. - **Storage simulation**: `simulatedPaths` map in watchdog prevents the watchdog from re-probing simulated-disconnected paths. Disconnect runs all real steps except `lazyUnmount` (drive stays physically mounted). - **DR trigger safety**: Uses marker file (`data/.needs-setup`) instead of modifying controller.yaml. Pre-checks that infra backup exists on at least one drive. - **Routing**: `/api/debug/` carved out in HTTP mux (same pattern as `/api/storage/`), routed to web server with auth + CSRF. diff --git a/controller/cmd/controller/main.go b/controller/cmd/controller/main.go index 2cc47f4..33579a2 100644 --- a/controller/cmd/controller/main.go +++ b/controller/cmd/controller/main.go @@ -86,6 +86,8 @@ func main() { } logger, logBuffer := setupLogger(cfg) + // v0.116.0: the debug ring is the controller_log_tail source (report self-tail channel). + report.SetControllerLogSource(logBuffer.Lines) // --- Bootstrap ingestion (slice 8A → v0.40.0 onboarding, doc 03 §6) --- // On first run, if this controller is not yet configured AND the host agent's provisioning @@ -455,6 +457,8 @@ func main() { // never reaches in). The NEXT report cycle collects + ships the tails; the hub // clears its pending request on receipt. An empty list clears any stale local set. report.SetPendingLogTails(resp.LogTailRequests) + // v0.116.0: the controller's OWN ring, same pattern (selftail.go). + report.SetPendingControllerLog(resp.ControllerLogRequested) } // Wire hub push status into alert manager for dashboard alerts alertMgr.SetHubPushStatus(func() web.HubPushStatusData { @@ -969,13 +973,18 @@ func selfUpdateAuthMiddleware(cfg *config.Config, webServer *web.Server, next ht }) } +// setupLogger builds the v0.116.0 capture layer: the LogBuffer ring ALWAYS exists +// and captures every line (DEBUG included — remote diagnostics need the detail to +// exist without a config flip), while stdout (docker logs) keeps respecting +// logging.level via the level filter. Lshortfile stays debug-only (unchanged). func setupLogger(cfg *config.Config) (*log.Logger, *web.LogBuffer) { + logBuffer := web.NewLogBuffer(1000) + flags := log.LstdFlags if cfg.Logging.Level == "debug" { - logBuffer := web.NewLogBuffer(1000) - logger := log.New(io.MultiWriter(os.Stdout, logBuffer), "", log.LstdFlags|log.Lshortfile) - return logger, logBuffer + flags |= log.Lshortfile } - return log.New(os.Stdout, "", log.LstdFlags), nil + stdout := web.NewLevelFilterWriter(os.Stdout, cfg.Logging.Level) + return log.New(io.MultiWriter(stdout, logBuffer), "", flags), logBuffer } // stackAdapter implements backup.StackDataProvider using stacks.Manager. diff --git a/controller/internal/agentapi/client.go b/controller/internal/agentapi/client.go index bddd2da..52fe422 100644 --- a/controller/internal/agentapi/client.go +++ b/controller/internal/agentapi/client.go @@ -16,11 +16,14 @@ import ( "encoding/json" "fmt" "io" + "log" "net/http" "regexp" "strings" "sync" "time" + + "gitea.dooplex.hu/admin/felhom-controller/internal/logx" ) // Client talks to one agent local-API endpoint with a pinned leaf + bearer token. @@ -35,8 +38,15 @@ type Client struct { // Supports falls back to the route probe. verMu sync.Mutex lastAgentVersion string + // logger is the optional per-call DEBUG trace sink (v0.116.0 observability — the + // capture ring holds these even at logging.level=info). nil = silent (unchanged). + logger *log.Logger } +// SetLogger wires the optional per-call DEBUG trace logger (method, path, status, +// duration + agent-version changes — never bodies or tokens). +func (c *Client) SetLogger(l *log.Logger) { c.logger = l } + // reAgentVersion is the bare-semver shape the publish pipeline enforces (publish-agent.sh) — the // ONLY header values trusted for capability comparison. Anything else (garbage, "dev", suffixes) // is ignored and the probe fallback stays in charge. @@ -50,8 +60,12 @@ func (c *Client) noteAgentVersion(resp *http.Response) { return } c.verMu.Lock() + prev := c.lastAgentVersion c.lastAgentVersion = v c.verMu.Unlock() + if prev != v { + logx.Debugf(c.logger, "[agentapi] agent version seen: %s (was %q)", v, prev) + } } // AgentVersion returns the last strictly-validated agent version seen on this client's traffic @@ -799,12 +813,15 @@ func (c *Client) postWithStatus(ctx context.Context, path string, body any) (api } req.Header.Set("Authorization", "Bearer "+c.token) req.Header.Set("Content-Type", "application/json") + start := time.Now() resp, err := c.hc.Do(req) if err != nil { + logx.Debugf(c.logger, "[agentapi] POST %s failed after %dms: %v", path, time.Since(start).Milliseconds(), err) return env, 0, fmt.Errorf("agentapi: POST %s: %w", path, err) } defer resp.Body.Close() c.noteAgentVersion(resp) // v0.82.0 version channel: passive capture on EVERY response + logx.Debugf(c.logger, "[agentapi] POST %s -> %d (%dms)", path, resp.StatusCode, time.Since(start).Milliseconds()) raw, _ := io.ReadAll(io.LimitReader(resp.Body, 1<<20)) if err := json.Unmarshal(raw, &env); err != nil { return env, resp.StatusCode, fmt.Errorf("agentapi: POST %s: HTTP %d, bad envelope: %w", path, resp.StatusCode, err) @@ -812,6 +829,37 @@ func (c *Client) postWithStatus(ctx context.Context, path string, body any) (api return env, resp.StatusCode, nil } +// ---- v0.116.0: agent debug-log ring (the Debug page agent tab) ---------------------------- + +// AgentLogEntry mirrors the agent's GET /debug/logs entry (agent ≥ 0.83.0). +type AgentLogEntry struct { + Timestamp time.Time `json:"timestamp"` + Level string `json:"level"` + Message string `json:"message"` +} + +// AgentLogsResponse mirrors the agent's GET /debug/logs data payload. +type AgentLogsResponse struct { + VMID int `json:"vmid"` + Entries []AgentLogEntry `json:"entries"` + Total int `json:"total"` +} + +// DebugLogs fetches the agent's always-DEBUG capture ring. Against a pre-0.83 +// agent the route is absent → a typed *StatusError with Code 404 (the caller +// renders the "available after the agent's next update" notice — S6). +func (c *Client) DebugLogs(ctx context.Context) (AgentLogsResponse, error) { + var out AgentLogsResponse + data, err := c.get(ctx, "/debug/logs") + if err != nil { + return out, err + } + if err := json.Unmarshal(data, &out); err != nil { + return out, fmt.Errorf("agentapi: parsing debug logs: %w", err) + } + return out, nil +} + // ---- slice 9: host metrics (the customer host-health view) ------------------------------- // HostMetrics mirrors the agent's GET /host/metrics `host` block (shared HostMetrics wire shape). @@ -908,12 +956,15 @@ func (c *Client) get(ctx context.Context, path string) (json.RawMessage, error) return nil, err } req.Header.Set("Authorization", "Bearer "+c.token) + start := time.Now() resp, err := c.hc.Do(req) if err != nil { + logx.Debugf(c.logger, "[agentapi] GET %s failed after %dms: %v", path, time.Since(start).Milliseconds(), err) return nil, fmt.Errorf("agentapi: GET %s: %w", path, err) } defer resp.Body.Close() c.noteAgentVersion(resp) // v0.82.0 version channel: passive capture on EVERY response + logx.Debugf(c.logger, "[agentapi] GET %s -> %d (%dms)", path, resp.StatusCode, time.Since(start).Milliseconds()) raw, _ := io.ReadAll(io.LimitReader(resp.Body, 1<<20)) if resp.StatusCode != http.StatusOK { return nil, &StatusError{Path: path, Code: resp.StatusCode} @@ -941,12 +992,15 @@ func (c *Client) post(ctx context.Context, path string, body any) (json.RawMessa } req.Header.Set("Authorization", "Bearer "+c.token) req.Header.Set("Content-Type", "application/json") + start := time.Now() resp, err := c.hc.Do(req) if err != nil { + logx.Debugf(c.logger, "[agentapi] POST %s failed after %dms: %v", path, time.Since(start).Milliseconds(), err) return nil, fmt.Errorf("agentapi: POST %s: %w", path, err) } defer resp.Body.Close() c.noteAgentVersion(resp) // v0.82.0 version channel: passive capture on EVERY response + logx.Debugf(c.logger, "[agentapi] POST %s -> %d (%dms)", path, resp.StatusCode, time.Since(start).Milliseconds()) raw, _ := io.ReadAll(io.LimitReader(resp.Body, 1<<20)) if resp.StatusCode != http.StatusOK && resp.StatusCode != http.StatusAccepted { return nil, fmt.Errorf("agentapi: POST %s: HTTP %d", path, resp.StatusCode) diff --git a/controller/internal/agentapi/features.go b/controller/internal/agentapi/features.go index a4bb15d..de289a5 100644 --- a/controller/internal/agentapi/features.go +++ b/controller/internal/agentapi/features.go @@ -7,6 +7,7 @@ import ( "sync" "time" + "gitea.dooplex.hu/admin/felhom-controller/internal/logx" "gitea.dooplex.hu/admin/felhom-controller/internal/util" ) @@ -109,13 +110,21 @@ type SupportCache struct { // window, probe on miss). The probe runs OUTSIDE the lock — concurrent misses may double-probe // (harmless: the probe is one cheap GET). func (sc *SupportCache) Supports(ctx context.Context, p SupportProber, f Feature) SupportState { + state, _ := sc.SupportsWithSource(ctx, p, f) + return state +} + +// SupportsWithSource is Supports plus the DECISION SOURCE ("version" | "probe-cache" | +// "probe" | "unregistered") — the v0.116.0 observability extension so the gate line can +// say HOW the verdict was reached. Behavior is byte-identical to v0.115.0 Supports. +func (sc *SupportCache) SupportsWithSource(ctx context.Context, p SupportProber, f Feature) (SupportState, string) { probe, ok := featureProbes[f] if !ok { - return SupportUnknown // unregistered feature — never refuse on a table gap + return SupportUnknown, "unregistered" // unregistered feature — never refuse on a table gap } if vr, hasVer := p.(AgentVersionReporter); hasVer { if state, decided := supportsByVersion(vr.AgentVersion(), f); decided { - return state + return state, "version" } } sc.mu.Lock() @@ -125,7 +134,7 @@ func (sc *SupportCache) Supports(ctx context.Context, p SupportProber, f Feature } if e, hit := sc.entries[f]; hit && nowFn().Sub(e.at) < supportTTL { sc.mu.Unlock() - return e.state + return e.state, "probe-cache" } sc.mu.Unlock() @@ -138,14 +147,17 @@ func (sc *SupportCache) Supports(ctx context.Context, p SupportProber, f Feature sc.entries[f] = supportEntry{state: state, at: nowFn()} sc.mu.Unlock() } - return state + return state, "probe" } // Supports probes (cached, TTL 5m, both polarities) whether the connected agent provides the // feature. 2xx ⇒ Yes. 404 ⇒ No. Anything else ⇒ Unknown (never "too old"). The web layer drives // the same machinery through its netAgent seam (Server.netFeatures) so tests can fake the probe. func (c *Client) Supports(ctx context.Context, f Feature) SupportState { - return c.features.Supports(ctx, c, f) + state, source := c.features.SupportsWithSource(ctx, c, f) + logx.Debugf(c.logger, "[agentapi] Supports(%s) = %s (source=%s agent_version=%q)", + f, state, source, c.AgentVersion()) + return state } // supportsByVersion decides a feature by version comparison alone. decided=false (unknown/garbage diff --git a/controller/internal/backup/offbox.go b/controller/internal/backup/offbox.go index 5821eb8..a277359 100644 --- a/controller/internal/backup/offbox.go +++ b/controller/internal/backup/offbox.go @@ -394,7 +394,10 @@ func (m *Manager) RunOffboxBackup(ctx context.Context) error { t := m.settings.GetOffboxTarget() base, env := m.offboxBaseArgs(t) start := time.Now() - _ = m.settings.UpdateOffboxStatus(func(o *settings.OffboxTarget) { o.LastStatus = "running"; o.LastError = "" }) + m.logger.Printf("[INFO] [offbox] backup run started (%d app(s) toggled)", len(apps)) + if err := m.settings.UpdateOffboxStatus(func(o *settings.OffboxTarget) { o.LastStatus = "running"; o.LastError = "" }); err != nil { + m.logger.Printf("[WARN] [offbox] status persist (running) failed: %v", err) + } var backedUp int var missing []string @@ -424,7 +427,7 @@ func (m *Manager) RunOffboxBackup(ctx context.Context) error { if runErr == nil { snapshots = m.offboxRecordStats(ctx, base, env) } - _ = m.settings.UpdateOffboxStatus(func(o *settings.OffboxTarget) { + if perr := m.settings.UpdateOffboxStatus(func(o *settings.OffboxTarget) { o.LastRun = time.Now().UTC().Format(time.RFC3339) o.LastDuration = dur.Round(time.Second).String() if runErr != nil { @@ -446,7 +449,9 @@ func (m *Manager) RunOffboxBackup(ctx context.Context) error { } o.LastWarning = strings.Join(warns, " ") } - }) + }); perr != nil { + m.logger.Printf("[WARN] [offbox] status persist (final) failed: %v", perr) + } if m.offboxNotify != nil { m.offboxNotify(dur, snapshots, runErr) } diff --git a/controller/internal/backup/tier2.go b/controller/internal/backup/tier2.go index fe6482a..941150c 100644 --- a/controller/internal/backup/tier2.go +++ b/controller/internal/backup/tier2.go @@ -305,7 +305,7 @@ func (m *Manager) recordTier2Success(stackName string, target *Tier2Target, size if m.settings == nil { return } - _ = m.settings.SetCrossDriveConfig(stackName, m.withTier2Prefs(stackName, &settings.CrossDriveBackup{ + if err := m.settings.SetCrossDriveConfig(stackName, m.withTier2Prefs(stackName, &settings.CrossDriveBackup{ Enabled: true, Method: "rsync", DestinationPath: target.NamespaceRoot, @@ -314,14 +314,16 @@ func (m *Manager) recordTier2Success(stackName string, target *Tier2Target, size LastStatus: "ok", LastDuration: dur.Round(time.Second).String(), LastSizeHuman: humanizeBytes(sizeBytes), - })) + })); err != nil { + m.logger.Printf("[WARN] [backup] Tier 2 status persist (ok) for %s failed: %v", stackName, err) + } } func (m *Manager) recordTier2Failure(stackName string, target *Tier2Target, cause error) { if m.settings == nil { return } - _ = m.settings.SetCrossDriveConfig(stackName, m.withTier2Prefs(stackName, &settings.CrossDriveBackup{ + if err := m.settings.SetCrossDriveConfig(stackName, m.withTier2Prefs(stackName, &settings.CrossDriveBackup{ Enabled: true, Method: "rsync", DestinationPath: target.NamespaceRoot, @@ -329,20 +331,24 @@ func (m *Manager) recordTier2Failure(stackName string, target *Tier2Target, caus LastRun: time.Now().Format(time.RFC3339), LastStatus: "error", LastError: cause.Error(), - })) + })); err != nil { + m.logger.Printf("[WARN] [backup] Tier 2 status persist (error) for %s failed: %v", stackName, err) + } } func (m *Manager) recordTier2NoTarget(stackName, reason string) { if m.settings == nil { return } - _ = m.settings.SetCrossDriveConfig(stackName, m.withTier2Prefs(stackName, &settings.CrossDriveBackup{ + if err := m.settings.SetCrossDriveConfig(stackName, m.withTier2Prefs(stackName, &settings.CrossDriveBackup{ Enabled: false, Method: "rsync", Schedule: "daily", LastStatus: "no_target", LastError: reason, - })) + })); err != nil { + m.logger.Printf("[WARN] [backup] Tier 2 status persist (no_target) for %s failed: %v", stackName, err) + } } func tier2NoTargetReason(err error) string { diff --git a/controller/internal/logx/logx.go b/controller/internal/logx/logx.go new file mode 100644 index 0000000..bdfd6d6 --- /dev/null +++ b/controller/internal/logx/logx.go @@ -0,0 +1,37 @@ +// Package logx is the leveled log helper of the v0.116.0 observability pass. It +// prefixes the standard [LEVEL] tag and writes through log.Logger.Output so the +// Lshortfile source (debug mode) attributes to the CALLER, not this file. +// +// Routing is the WRITER's job, not this package's: main.go builds the logger as +// MultiWriter(LevelFilterWriter(stdout, logging.level), LogBuffer) — so a +// logx.Debugf line ALWAYS reaches the debug ring (remote diagnostics) while +// stdout keeps respecting logging.level. Legacy `isDebug()`-gated Printf call +// sites are left as-is (they gate emission entirely); ALL NEW leveled lines use +// these helpers. Conventions (levels, English, no secrets): +// felhom.eu/documentation/runbooks/logging-conventions.md. +package logx + +import ( + "fmt" + "log" +) + +// Debugf logs flow detail (phase steps, per-call traces, parsed values). +func Debugf(l *log.Logger, format string, args ...any) { output(l, "DEBUG", format, args...) } + +// Infof logs state changes and operations with durations ("X done in Yms"). +func Infof(l *log.Logger, format string, args ...any) { output(l, "INFO", format, args...) } + +// Warnf logs degraded-but-continuing conditions. +func Warnf(l *log.Logger, format string, args ...any) { output(l, "WARN", format, args...) } + +// Errorf logs a failed operation — always include the underlying error. +func Errorf(l *log.Logger, format string, args ...any) { output(l, "ERROR", format, args...) } + +func output(l *log.Logger, tag, format string, args ...any) { + if l == nil { + return + } + // calldepth 3: Output ← output ← Debugf/… ← the caller we want attributed. + _ = l.Output(3, "["+tag+"] "+fmt.Sprintf(format, args...)) +} diff --git a/controller/internal/report/builder.go b/controller/internal/report/builder.go index fc36596..32f7cca 100644 --- a/controller/internal/report/builder.go +++ b/controller/internal/report/builder.go @@ -168,6 +168,10 @@ func BuildReport( }, logger) } + // Controller self-log tail (v0.116.0): the controller's OWN debug ring, same + // consume-once ACK-flag pattern (selftail.go). nil in the steady state. + r.ControllerLogTail = buildControllerLogTail(logger) + // Geo-restriction status — ALWAYS present (even when never configured) so the hub // always renders the section. A nil pointer (omitempty) made the hub hide the whole // section for a never-configured controller; a present-but-disabled report renders diff --git a/controller/internal/report/pusher.go b/controller/internal/report/pusher.go index 08050c6..3ce3a5c 100644 --- a/controller/internal/report/pusher.go +++ b/controller/internal/report/pusher.go @@ -44,6 +44,10 @@ type PushResponse struct { // pull-based ACK-flag pattern as escrow: the NEXT report ships the tails; the hub // clears the pending request on receipt (consume-once). Absent/empty = nothing pending. LogTailRequests []string `json:"log_tail_requests"` + // ControllerLogRequested (v0.116.0) — the operator wants THIS controller's own debug + // ring; the NEXT report ships controller_log_tail (selftail.go). Absent/false on an + // old hub = nothing pending. + ControllerLogRequested bool `json:"controller_log_requested"` } // Pusher sends reports to the central hub. diff --git a/controller/internal/report/selftail.go b/controller/internal/report/selftail.go new file mode 100644 index 0000000..8a71242 --- /dev/null +++ b/controller/internal/report/selftail.go @@ -0,0 +1,74 @@ +package report + +import ( + "log" + "sync" + "time" +) + +// Controller self-log tail (v0.116.0 observability) — the CONTROLLER's own debug +// ring riding the report channel, the exact consume-once ACK-flag shape of +// logtail.go (which stays byte-compatible; these are ADDITIVE fields): the hub +// stores a pending per-customer request; the report ACK advertises it as +// controller_log_requested; the NEXT report carries controller_log_tail; the hub +// clears the pending request on arrival. A failed push leaves the hub request +// pending — the next ACK re-arms it (fail-safe retry, no duplicate shipping). + +// controllerLogMaxBytes caps the shipped tail (newest lines kept — the ring's +// Lines budget, mirrored agent-side at the same 128 KB). +const controllerLogMaxBytes = 128 * 1024 + +// ControllerLogTail is the report's on-demand controller ring tail. +type ControllerLogTail struct { + CollectedAt time.Time `json:"collected_at"` + Lines []string `json:"lines"` +} + +var ( + selfTailMu sync.Mutex + selfTailPending bool + selfTailSource func(maxBytes int) []string +) + +// SetPendingControllerLog records the ACK's controller_log_requested flag. The +// hub is the source of truth: an ACK without the flag clears any stale pending. +func SetPendingControllerLog(requested bool) { + selfTailMu.Lock() + defer selfTailMu.Unlock() + selfTailPending = requested +} + +// SetControllerLogSource wires the debug ring (web.LogBuffer.Lines) — set once by +// main.go at startup. Unset means a pending request is silently unfulfillable +// (drained but nothing shipped; the hub re-arms on the next ACK). +func SetControllerLogSource(src func(maxBytes int) []string) { + selfTailMu.Lock() + defer selfTailMu.Unlock() + selfTailSource = src +} + +// drainPendingControllerLog takes + CLEARS the pending flag and returns the +// source (consume-once controller-side, the drainPendingLogTails shape). +func drainPendingControllerLog() (func(maxBytes int) []string, bool) { + selfTailMu.Lock() + defer selfTailMu.Unlock() + pending := selfTailPending + selfTailPending = false + return selfTailSource, pending +} + +// buildControllerLogTail attaches the ring tail when a pull is pending. The INFO +// line is the CUSTOMER-VISIBLE transparency record (it lands in the ring/viewer): +// an operator pull of this box's controller log is never silent. +func buildControllerLogTail(logger *log.Logger) *ControllerLogTail { + src, pending := drainPendingControllerLog() + if !pending || src == nil { + return nil + } + // Logged BEFORE collecting, so the transparency line rides in the tail it announces. + if logger != nil { + logger.Printf("[INFO] [report] operator log pull served (controller ring)") + } + lines := src(controllerLogMaxBytes) + return &ControllerLogTail{CollectedAt: time.Now().UTC(), Lines: lines} +} diff --git a/controller/internal/report/selftail_test.go b/controller/internal/report/selftail_test.go new file mode 100644 index 0000000..0bd8df5 --- /dev/null +++ b/controller/internal/report/selftail_test.go @@ -0,0 +1,107 @@ +package report + +import ( + "bytes" + "encoding/json" + "log" + "strings" + "testing" + "time" +) + +func resetSelfTail() { + SetPendingControllerLog(false) + SetControllerLogSource(nil) +} + +// S2 (controller half): the ACK's controller_log_requested arms the pull; the next +// build attaches the ring tail; the build after that attaches nothing (consume-once). +// Companion red-proof: remove the `selfTailPending = false` drain → the second build +// ships again → the nil assertion fails. +func TestControllerLogTail_ConsumeOnce(t *testing.T) { + t.Cleanup(resetSelfTail) + SetControllerLogSource(func(maxBytes int) []string { return []string{"l1", "l2", "l3"} }) + SetPendingControllerLog(true) + + var logbuf bytes.Buffer + logger := log.New(&logbuf, "", 0) + first := buildControllerLogTail(logger) + if first == nil || len(first.Lines) != 3 || first.CollectedAt.IsZero() { + t.Fatalf("first build tail = %+v, want the 3 ring lines + collected_at", first) + } + // Customer transparency: the pull is announced in the box's own log. + if !strings.Contains(logbuf.String(), "operator log pull served") { + t.Errorf("transparency INFO line missing: %q", logbuf.String()) + } + if second := buildControllerLogTail(logger); second != nil { + t.Errorf("second build shipped again — consume-once broken: %+v", second) + } +} + +// The hub is the source of truth: an ACK without the flag clears a stale pending. +func TestControllerLogTail_AckClears(t *testing.T) { + t.Cleanup(resetSelfTail) + SetControllerLogSource(func(int) []string { return []string{"x"} }) + SetPendingControllerLog(true) + SetPendingControllerLog(false) + if tail := buildControllerLogTail(nil); tail != nil { + t.Errorf("cleared pending still shipped: %+v", tail) + } +} + +// No source wired (defensive) → pending is drained, nothing shipped, no panic. +func TestControllerLogTail_NoSource(t *testing.T) { + t.Cleanup(resetSelfTail) + SetPendingControllerLog(true) + if tail := buildControllerLogTail(nil); tail != nil { + t.Errorf("tail shipped with no source: %+v", tail) + } +} + +// S3 app-tail byte-compatibility: the v0.111.0 log_tails wire shape is unchanged by +// the additive controller_log_tail — absent in the steady state (omitempty), and the +// existing keys marshal identically. Companion red-proof: drop `omitempty` from +// ControllerLogTail → the steady-state JSON gains a null key → FAIL. +func TestReportSchema_AppTailUnchangedAndSelfTailAdditive(t *testing.T) { + r := &Report{ + Version: 1, + CustomerID: "c1", + LogTails: []LogTail{{ + App: "gokapi", CollectedAt: time.Date(2026, 7, 11, 10, 0, 0, 0, time.UTC), + Lines: []string{"a", "b"}, + }}, + } + raw, err := json.Marshal(r) + if err != nil { + t.Fatal(err) + } + var m map[string]json.RawMessage + if err := json.Unmarshal(raw, &m); err != nil { + t.Fatal(err) + } + if _, present := m["controller_log_tail"]; present { + t.Errorf("controller_log_tail present in the steady state — must be omitted (additive)") + } + var tails []map[string]json.RawMessage + if err := json.Unmarshal(m["log_tails"], &tails); err != nil || len(tails) != 1 { + t.Fatalf("log_tails shape changed: %s", m["log_tails"]) + } + for _, key := range []string{"app", "collected_at", "lines"} { + if _, ok := tails[0][key]; !ok { + t.Errorf("log_tails entry lost key %q — app-tail flow must stay byte-compatible", key) + } + } + + // The ACK parse: old fields + the new flag coexist; absent flag = false. + var pr PushResponse + if err := json.Unmarshal([]byte(`{"status":"ok","log_tail_requests":["gokapi"],"controller_log_requested":true}`), &pr); err != nil { + t.Fatal(err) + } + if len(pr.LogTailRequests) != 1 || !pr.ControllerLogRequested { + t.Errorf("ACK parse = %+v", pr) + } + var old PushResponse + if err := json.Unmarshal([]byte(`{"status":"ok"}`), &old); err != nil || old.ControllerLogRequested { + t.Errorf("old ACK must parse with the flag false: %+v err=%v", old, err) + } +} diff --git a/controller/internal/report/types.go b/controller/internal/report/types.go index 198aefb..a0d3b97 100644 --- a/controller/internal/report/types.go +++ b/controller/internal/report/types.go @@ -38,6 +38,11 @@ type Report struct { // LogTails (v0.111.0) — on-demand ordered log tails, present only on the report cycle // right after the ACK requested them (log_tail_requests). Redacted + capped (logtail.go). LogTails []LogTail `json:"log_tails,omitempty"` + + // ControllerLogTail (v0.116.0) — the controller's OWN debug-ring tail, present only on + // the cycle right after the ACK's controller_log_requested (selftail.go; additive — the + // app-tail flow above is untouched). + ControllerLogTail *ControllerLogTail `json:"controller_log_tail,omitempty"` } // SystemReport holds host-level system info. diff --git a/controller/internal/stacks/migrate.go b/controller/internal/stacks/migrate.go index d7535b7..0617a40 100644 --- a/controller/internal/stacks/migrate.go +++ b/controller/internal/stacks/migrate.go @@ -361,7 +361,10 @@ func (m *Manager) migSourceSize(j *MigrationJob) int64 { // idempotent and skips already-completed units, so re-entry never re-copies or re-removes. func (m *Manager) runMigration(ctx context.Context, j *MigrationJob) { defer m.releaseMigrating() + m.logger.Printf("[INFO] [migrate] %s running: %s → %s scope=%s apps=%d phase=%s", + j.ID, j.Source, j.Target, j.Scope, len(j.Apps), j.Phase) for { + m.logger.Printf("[DEBUG] [migrate] %s phase %s", j.ID, j.Phase) var err error switch j.Phase { case PhaseStop: @@ -404,7 +407,8 @@ func (m *Manager) runMigration(ctx context.Context, j *MigrationJob) { m.logger.Printf("[ERROR] [migrate] journal write failed: %v", perr) } if j.Phase == PhaseDone { - m.logger.Printf("[INFO] [migrate] %s complete: %s → %s (%d app(s))", j.ID, j.Source, j.Target, len(j.Apps)) + m.logger.Printf("[INFO] [migrate] %s complete: %s → %s (%d app(s), %s)", + j.ID, j.Source, j.Target, len(j.Apps), j.FinishedAt.Sub(j.StartedAt).Round(time.Second)) if m.migDoneHook != nil { m.migDoneHook(j.clone()) // decommission policy (soft-mark + agent) lives in the hook } diff --git a/controller/internal/web/agent_disk_handlers.go b/controller/internal/web/agent_disk_handlers.go index a64d975..0fe488f 100644 --- a/controller/internal/web/agent_disk_handlers.go +++ b/controller/internal/web/agent_disk_handlers.go @@ -58,6 +58,10 @@ func (s *Server) agentClient() (*agentapi.Client, error) { s.agentCliOnce.Do(func() { s.agentCli, s.agentCliErr = agentapi.New( s.cfg.LocalAPI.Endpoint, s.cfg.LocalAPI.Token, s.cfg.LocalAPI.Fingerprint) + if s.agentCliErr == nil { + // v0.116.0: per-call DEBUG traces into the capture ring (method/path/status/duration). + s.agentCli.SetLogger(s.logger) + } }) return s.agentCli, s.agentCliErr } diff --git a/controller/internal/web/capture_layer_test.go b/controller/internal/web/capture_layer_test.go new file mode 100644 index 0000000..6640353 --- /dev/null +++ b/controller/internal/web/capture_layer_test.go @@ -0,0 +1,82 @@ +package web + +import ( + "bytes" + "io" + "log" + "strings" + "testing" + "time" +) + +// S1 capture-at-info (controller half): with the v0.116.0 writer layout — +// MultiWriter(LevelFilterWriter(stdout, "info"), LogBuffer) — a [DEBUG] line +// reaches the RING and is ABSENT from stdout, while [INFO] reaches both. +// Companion red-proof: gate the ring behind the same filter (the pre-fix shape, +// where the ring only existed at logging.level=debug) → the ring assertion fails. +func TestCaptureAtInfo_RingHoldsDebugStdoutDoesNot(t *testing.T) { + var stdout bytes.Buffer + lb := NewLogBuffer(50) + logger := log.New(io.MultiWriter(NewLevelFilterWriter(&stdout, "info"), lb), "", log.LstdFlags) + + logger.Printf("[DEBUG] [web] netstorage add \"vids\" phase agent_add -> verifying") + logger.Printf("[INFO] [web] network storage added + verified: vids") + + entries, total := lb.Entries("DEBUG", 0, time.Time{}) + if total != 2 || len(entries) != 2 { + t.Fatalf("ring holds %d entries (returned %d), want 2 — DEBUG must be captured at logging.level=info", total, len(entries)) + } + if entries[0].Level != "DEBUG" || !strings.Contains(entries[0].Message, "phase agent_add") { + t.Errorf("ring entry 0 = %+v, want the DEBUG phase line", entries[0]) + } + if strings.Contains(stdout.String(), "phase agent_add") { + t.Errorf("stdout carries the DEBUG line at level info:\n%s", stdout.String()) + } + if !strings.Contains(stdout.String(), "added + verified") { + t.Errorf("stdout missing the INFO line:\n%s", stdout.String()) + } +} + +// The filter respects higher minimums too (warn drops INFO) and passes untagged lines at info. +func TestLevelFilterWriter_Thresholds(t *testing.T) { + cases := []struct { + min string + line string + wants bool + }{ + {"info", "[DEBUG] x", false}, + {"info", "[INFO] x", true}, + {"info", "untagged line", true}, // parses as INFO + {"warn", "[INFO] x", false}, + {"warn", "[ERROR] x", true}, + {"debug", "[DEBUG] x", true}, + } + for _, c := range cases { + var out bytes.Buffer + logger := log.New(NewLevelFilterWriter(&out, c.min), "", log.LstdFlags) + logger.Printf("%s", c.line) + got := strings.Contains(out.String(), c.line) + if got != c.wants { + t.Errorf("min=%s line=%q passed=%v want %v", c.min, c.line, got, c.wants) + } + } +} + +// Lines renders chronological plain-text lines and honors the byte budget by +// keeping the NEWEST lines (the controller_log_tail 128 KB cap). +func TestLogBufferLines_ByteBudgetKeepsNewest(t *testing.T) { + lb := NewLogBuffer(10) + logger := log.New(lb, "", log.LstdFlags) + for i := 0; i < 5; i++ { + logger.Printf("[INFO] line-%d %s", i, strings.Repeat("x", 80)) + } + all := lb.Lines(0) + if len(all) != 5 || !strings.Contains(all[4], "line-4") { + t.Fatalf("uncapped lines wrong: %d %v", len(all), all) + } + budget := len(all[3]) + len(all[4]) + 2 + capped := lb.Lines(budget) + if len(capped) >= 5 || !strings.Contains(capped[len(capped)-1], "line-4") { + t.Errorf("byte cap kept %d lines, newest=%q — must drop oldest first", len(capped), capped[len(capped)-1]) + } +} diff --git a/controller/internal/web/handler_debug.go b/controller/internal/web/handler_debug.go index d101fea..c73ecc2 100644 --- a/controller/internal/web/handler_debug.go +++ b/controller/internal/web/handler_debug.go @@ -5,6 +5,7 @@ import ( "crypto/sha256" "encoding/hex" "encoding/json" + "errors" "fmt" "net/http" "os" @@ -13,6 +14,7 @@ import ( "strings" "time" + "gitea.dooplex.hu/admin/felhom-controller/internal/agentapi" "gitea.dooplex.hu/admin/felhom-controller/internal/appexport" "gitea.dooplex.hu/admin/felhom-controller/internal/monitor" "gitea.dooplex.hu/admin/felhom-controller/internal/report" @@ -79,6 +81,8 @@ func (s *Server) handleDebugAPI(w http.ResponseWriter, r *http.Request) { // Section 8: Log viewer case subpath == "logs" && r.Method == http.MethodGet: s.debugLogBuffer(w, r) + case subpath == "agent-logs" && r.Method == http.MethodGet: + s.debugAgentLogs(w, r) // Section 9: App Export/Import case subpath == "appexport/status" && r.Method == http.MethodGet: @@ -528,6 +532,41 @@ func (s *Server) debugLogBuffer(w http.ResponseWriter, r *http.Request) { }) } +// debugAgentLogs proxies the host agent's always-DEBUG capture ring (agent ≥ 0.83.0) +// for the Debug page's "Ügynök" tab. A pre-0.83 agent has no such route — the typed +// 404 (StatusError, the features.go precedent) renders the "available after the +// agent's next update" notice instead of an error; nothing else is gated on it. +func (s *Server) debugAgentLogs(w http.ResponseWriter, r *http.Request) { + fetch := s.agentLogsFn + if fetch == nil { + client, err := s.agentClient() + if err != nil { + writeDebugJSON(w, http.StatusOK, false, "Az ügynök nincs konfigurálva ezen a rendszeren.", nil) + return + } + fetch = client.DebugLogs + } + ctx, cancel := context.WithTimeout(r.Context(), 10*time.Second) + defer cancel() + resp, err := fetch(ctx) + if err != nil { + var se *agentapi.StatusError + if errors.As(err, &se) && se.Code == http.StatusNotFound { + writeDebugJSON(w, http.StatusOK, true, "", map[string]interface{}{ + "unsupported": true, + "notice": "Az ügynök naplónézete az ügynök következő frissítése után érhető el.", + }) + return + } + writeDebugJSON(w, http.StatusOK, false, err.Error(), nil) + return + } + writeDebugJSON(w, http.StatusOK, true, "", map[string]interface{}{ + "entries": resp.Entries, + "total": resp.Total, + }) +} + // ── Section 9: App Export/Import ───────────────────────────────────── func (s *Server) debugAppExportStatus(w http.ResponseWriter, r *http.Request) { diff --git a/controller/internal/web/levelfilter.go b/controller/internal/web/levelfilter.go new file mode 100644 index 0000000..b7d293b --- /dev/null +++ b/controller/internal/web/levelfilter.go @@ -0,0 +1,34 @@ +package web + +import "io" + +// LevelFilterWriter drops log lines BELOW a minimum level from the wrapped writer. +// It is the stdout half of the v0.116.0 capture layer: the logger now always fans +// out to (stdout-filter, LogBuffer ring) — the ring captures EVERYTHING (DEBUG +// included) for remote diagnostics, while docker logs keep respecting +// logging.level exactly as before. Lines with no recognizable [LEVEL] tag parse +// as INFO (parseLine), so untagged output keeps flowing at the info level. +type LevelFilterWriter struct { + w io.Writer + min int +} + +// NewLevelFilterWriter wraps w so only lines at/above minLevel pass ("debug" +// passes everything; unknown falls back to debug = pass-through). +func NewLevelFilterWriter(w io.Writer, minLevel string) *LevelFilterWriter { + return &LevelFilterWriter{w: w, min: levelPriority(minLevel)} +} + +// Write parses the line's level tag and forwards it only when it clears the +// minimum. It always reports the full length as written (a dropped line is a +// success, not an error — log.Logger must never see a short write). +func (f *LevelFilterWriter) Write(p []byte) (int, error) { + entry := parseLine(string(p)) + if levelPriority(entry.Level) < f.min { + return len(p), nil + } + if _, err := f.w.Write(p); err != nil { + return 0, err + } + return len(p), nil +} diff --git a/controller/internal/web/logbuffer.go b/controller/internal/web/logbuffer.go index a656383..b0b7ef1 100644 --- a/controller/internal/web/logbuffer.go +++ b/controller/internal/web/logbuffer.go @@ -103,6 +103,47 @@ func (lb *LogBuffer) Entries(minLevel string, limit int, after time.Time) ([]Log return result, 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 +// report-channel controller_log_tail budget (maxBytes ≤ 0 → no byte cap). +// Format mirrors the agent ring's: " [] ". +func (lb *LogBuffer) Lines(maxBytes int) []string { + lb.mu.RLock() + total := lb.size + start := 0 + if !lb.full { + total = lb.pos + } else { + start = lb.pos + } + entries := make([]LogEntry, 0, total) + for i := 0; i < total; i++ { + entries = append(entries, lb.entries[(start+i)%lb.size]) + } + lb.mu.RUnlock() + lines := make([]string, len(entries)) + for i, e := range entries { + src := "" + if e.Source != "" { + src = e.Source + ": " + } + lines[i] = e.Timestamp.Format(time.RFC3339) + " [" + e.Level + "] " + src + e.Message + } + if maxBytes <= 0 { + return lines + } + budget := 0 + keepFrom := len(lines) + for i := len(lines) - 1; i >= 0; i-- { + budget += len(lines[i]) + 1 // +1 for the newline it represents + if budget > maxBytes { + break + } + keepFrom = i + } + return lines[keepFrom:] +} + // parseLine parses a single log line into a LogEntry. func parseLine(line string) LogEntry { entry := LogEntry{ diff --git a/controller/internal/web/netstorage_handlers.go b/controller/internal/web/netstorage_handlers.go index 3a8c1bc..e72b0bf 100644 --- a/controller/internal/web/netstorage_handlers.go +++ b/controller/internal/web/netstorage_handlers.go @@ -9,6 +9,7 @@ import ( "time" "gitea.dooplex.hu/admin/felhom-controller/internal/agentapi" + "gitea.dooplex.hu/admin/felhom-controller/internal/logx" "gitea.dooplex.hu/admin/felhom-controller/internal/settings" ) @@ -79,20 +80,24 @@ func (s *Server) handleNetStorageAdd(w http.ResponseWriter, r *http.Request) { } name := strings.TrimSpace(req.Name) if !mountNameRe.MatchString(name) { + logx.Debugf(s.logger, "[web] netstorage add refused by validation: name %q", name) writeDiskJSON(w, http.StatusBadRequest, false, "érvénytelen név (csak betűk, számok, _ és -)", nil) return } proto := strings.ToLower(strings.TrimSpace(req.Protocol)) if proto != "nfs" && proto != "smb" { + logx.Debugf(s.logger, "[web] netstorage add %q refused by validation: protocol %q", name, proto) writeDiskJSON(w, http.StatusBadRequest, false, "protokoll: nfs vagy smb", nil) return } server, export := strings.TrimSpace(req.Server), strings.TrimSpace(req.Export) if server == "" || export == "" { + logx.Debugf(s.logger, "[web] netstorage add %q refused by validation: empty server/export", name) writeDiskJSON(w, http.StatusBadRequest, false, "a szerver és a megosztás kötelező", nil) return } if proto == "smb" && (req.Username == "" || req.Password == "") { + logx.Debugf(s.logger, "[web] netstorage add %q refused by validation: smb credentials missing", name) writeDiskJSON(w, http.StatusBadRequest, false, "SMB-hez felhasználónév és jelszó szükséges", nil) return } @@ -114,8 +119,8 @@ func (s *Server) handleNetStorageAdd(w http.ResponseWriter, r *http.Request) { // instead of failing mid-pipeline in `verifying` with a misleading rollback. Runs BEFORE the // single-flight claim (a refused add must not consume the slot). SupportUnknown passes: a down // agent speaks through the existing agent-error paths, never as "too old". - support := s.netFeatures.Supports(r.Context(), agent, agentapi.FeatureNetstorageVerify) - s.logger.Printf("[DEBUG] [web] netstorage add %q capability gate: %s=%s", name, agentapi.FeatureNetstorageVerify, support) + support, supSource := s.netFeatures.SupportsWithSource(r.Context(), agent, agentapi.FeatureNetstorageVerify) + s.logger.Printf("[DEBUG] [web] netstorage add %q capability gate: %s=%s (source=%s)", name, agentapi.FeatureNetstorageVerify, support, supSource) if support == agentapi.SupportNo { s.logger.Printf("[WARN] [web] netstorage add %q refused: agent predates %s (probe 404)", name, agentapi.FeatureNetstorageVerify) writeDiskJSON(w, http.StatusPreconditionFailed, false, netAddOutdatedMsg, map[string]any{"code": "agent_outdated"}) @@ -199,6 +204,9 @@ func (s *Server) networkStorageItems(ctx context.Context) []networkStorageItem { } } sort.Strings(orphans) + if len(orphans) > 0 { + logx.Warnf(s.logger, "[web] netstorage: %d orphan agent-side share(s) with no registry entry: %v", len(orphans), orphans) + } for _, name := range orphans { m := live[name] items = append(items, networkStorageItem{ diff --git a/controller/internal/web/netstorage_job.go b/controller/internal/web/netstorage_job.go index 216de35..96fce93 100644 --- a/controller/internal/web/netstorage_job.go +++ b/controller/internal/web/netstorage_job.go @@ -9,6 +9,7 @@ import ( "time" "gitea.dooplex.hu/admin/felhom-controller/internal/agentapi" + "gitea.dooplex.hu/admin/felhom-controller/internal/logx" "gitea.dooplex.hu/admin/felhom-controller/internal/settings" ) @@ -129,7 +130,19 @@ func (s *Server) netProbe(ctx context.Context, dir string) probeOutcome { if s.netProbeFn != nil { return s.netProbeFn(ctx, dir) } - return runNetProbe(ctx, dir) + logx.Debugf(s.logger, "[web] netprobe exec start (uid-1000 re-exec) dir=%s", dir) + o := runNetProbe(ctx, dir) + logx.Debugf(s.logger, "[web] netprobe result: ok=%v category=%s detail=%s", + o.OK, o.Category, firstLine(o.Detail)) + return o +} + +// firstLine bounds a raw detail to its first line for a log field. +func firstLine(s string) string { + if i := strings.IndexByte(s, '\n'); i >= 0 { + return s[:i] + } + return s } // startNetAdd claims the single-flight slot and launches the detached orchestration. false = an add @@ -153,8 +166,13 @@ func (s *Server) runNetAdd(agent netAgent, req agentapi.AddNetStorageRequest, la defer s.netAdd.release() ctx, cancel := context.WithTimeout(context.Background(), netAddDeadline) defer cancel() + start := time.Now() + logx.Infof(s.logger, "[web] netstorage add %q started (%s %s:%s, mapped_uid=%d)", + req.Name, req.Protocol, req.Server, req.Export, req.MappedUID) setPhase := func(p string) { + logx.Debugf(s.logger, "[web] netstorage add %q phase %s -> %s (%dms elapsed)", + req.Name, job.Phase, p, time.Since(start).Milliseconds()) job.Phase = p job.UpdatedAt = time.Now().UTC() s.netAdd.set(job) @@ -166,15 +184,19 @@ func (s *Server) runNetAdd(agent netAgent, req agentapi.AddNetStorageRequest, la job.Detail = detail job.UpdatedAt = time.Now().UTC() s.netAdd.set(job) - s.logger.Printf("[WARN] [web] netstorage add %q failed: category=%s detail=%s", req.Name, category, detail) + logx.Warnf(s.logger, "[web] netstorage add %q failed: category=%s detail=%s (%dms)", + req.Name, category, detail, time.Since(start).Milliseconds()) } rollback := func(why string) { + logx.Debugf(s.logger, "[web] netstorage add %q rollback started (%s)", req.Name, why) rctx, rcancel := context.WithTimeout(context.Background(), netRollbackBudget) defer rcancel() if err := agent.RemoveNetStorage(rctx, req.Name); err != nil { // Best-effort by design: the agent may have auto-rolled-back already (double-remove is // harmless) — but log it, a REAL leftover shows up as an orphan row in the list. - s.logger.Printf("[WARN] [web] netstorage add %q rollback (%s): remove: %v", req.Name, why, err) + logx.Warnf(s.logger, "[web] netstorage add %q rollback (%s): remove: %v", req.Name, why, err) + } else { + logx.Infof(s.logger, "[web] netstorage add %q rolled back (%s)", req.Name, why) } } @@ -192,9 +214,13 @@ func (s *Server) runNetAdd(agent netAgent, req agentapi.AddNetStorageRequest, la // Phase 2 — poll the agent's verify slot. On a pre-verify agent (no job started) skip straight // to the probe: the mount-trigger check then happens implicitly through the probe's write. + logx.Debugf(s.logger, "[web] netstorage add %q agent add accepted (verify=%s job_id=%s guest_path=%s)", + req.Name, res.Verify, res.JobID, res.GuestPath) if res.Verify == "started" { setPhase(netAddPhaseVerifying) verdict, verr := s.pollAgentVerify(ctx, agent, res.JobID) + logx.Debugf(s.logger, "[web] netstorage add %q agent verify verdict: phase=%s code=%s (err=%v)", + req.Name, verdict.Phase, verdict.Code, verr) switch { case verr != nil: rollback("verify poll failed") @@ -218,6 +244,8 @@ func (s *Server) runNetAdd(agent netAgent, req agentapi.AddNetStorageRequest, la // Phase 3 — the in-guest uid-1000 write probe (the squash trap). setPhase(netAddPhaseProbing) outcome := s.netProbe(ctx, res.GuestPath) + logx.Debugf(s.logger, "[web] netstorage add %q probe verdict: ok=%v category=%s warn=%q", + req.Name, outcome.OK, outcome.Category, outcome.Warn) if !outcome.OK { rollback("probe failed") fail(outcome.Category, outcome.Detail) @@ -250,8 +278,8 @@ func (s *Server) runNetAdd(agent netAgent, req agentapi.AddNetStorageRequest, la job.Warn = outcome.Warn job.UpdatedAt = time.Now().UTC() s.netAdd.set(job) - s.logger.Printf("[INFO] [web] network storage added + verified: %s (%s %s:%s) → %s (warn=%q)", - req.Name, req.Protocol, req.Server, req.Export, res.GuestPath, outcome.Warn) + logx.Infof(s.logger, "[web] network storage added + verified: %s (%s %s:%s) → %s (warn=%q) in %dms", + req.Name, req.Protocol, req.Server, req.Export, res.GuestPath, outcome.Warn, time.Since(start).Milliseconds()) } // pollAgentVerify polls the agent's verify slot until it leaves `running` (or ctx expires). diff --git a/controller/internal/web/observability_test.go b/controller/internal/web/observability_test.go new file mode 100644 index 0000000..a7cc8d6 --- /dev/null +++ b/controller/internal/web/observability_test.go @@ -0,0 +1,121 @@ +package web + +import ( + "context" + "encoding/json" + "log" + "net/http" + "net/http/httptest" + "strings" + "testing" + + "gitea.dooplex.hu/admin/felhom-controller/internal/agentapi" +) + +// S6 old-agent degradation: the Debug page agent tab against a pre-0.83 agent (typed +// 404 — the StatusError precedent) renders the Hungarian notice, ok:true, no error +// spam. Companion red-proof: match the error by string instead of errors.As → +// unsupported turns into an error payload → the notice assertion fails. +func TestDebugAgentLogs_Pre083AgentRendersNotice(t *testing.T) { + s := testServer(t) + s.agentLogsFn = func(context.Context) (agentapi.AgentLogsResponse, error) { + return agentapi.AgentLogsResponse{}, &agentapi.StatusError{Path: "/debug/logs", Code: http.StatusNotFound} + } + w := httptest.NewRecorder() + s.debugAgentLogs(w, httptest.NewRequest("GET", "/api/debug/agent-logs", nil)) + var resp struct { + OK bool `json:"ok"` + Data struct { + Unsupported bool `json:"unsupported"` + Notice string `json:"notice"` + } `json:"data"` + } + if err := json.Unmarshal(w.Body.Bytes(), &resp); err != nil { + t.Fatalf("decode: %v (%s)", err, w.Body.String()) + } + if !resp.OK || !resp.Data.Unsupported { + t.Fatalf("resp = %+v, want ok+unsupported (not an error)", resp) + } + if !strings.Contains(resp.Data.Notice, "az ügynök következő frissítése után") { + t.Errorf("notice = %q, want the next-update text", resp.Data.Notice) + } +} + +// A working ≥0.83 agent's entries are proxied through verbatim. +func TestDebugAgentLogs_ProxiesEntries(t *testing.T) { + s := testServer(t) + s.agentLogsFn = func(context.Context) (agentapi.AgentLogsResponse, error) { + return agentapi.AgentLogsResponse{ + Entries: []agentapi.AgentLogEntry{{Level: "DEBUG", Message: "netverify: job started"}}, + Total: 1, + }, nil + } + w := httptest.NewRecorder() + s.debugAgentLogs(w, httptest.NewRequest("GET", "/api/debug/agent-logs", nil)) + body := w.Body.String() + if !strings.Contains(body, "netverify: job started") || !strings.Contains(body, `"total":1`) { + t.Errorf("proxy body missing agent entries: %s", body) + } +} + +// A non-404 agent error (down, 5xx) is an honest error payload — never the notice. +func TestDebugAgentLogs_OtherErrorIsError(t *testing.T) { + s := testServer(t) + s.agentLogsFn = func(context.Context) (agentapi.AgentLogsResponse, error) { + return agentapi.AgentLogsResponse{}, &agentapi.StatusError{Path: "/debug/logs", Code: 502} + } + w := httptest.NewRecorder() + s.debugAgentLogs(w, httptest.NewRequest("GET", "/api/debug/agent-logs", nil)) + if strings.Contains(w.Body.String(), "unsupported") || !strings.Contains(w.Body.String(), `"ok":false`) { + t.Errorf("non-404 must be an error, not the notice: %s", w.Body.String()) + } +} + +// S7 sweep smoke (controller half): a full fake NAS add at logging.level=info must +// leave the EXPECTED ORDERED phase lines in the debug ring — the test that encodes +// "an operator can reconstruct the NAS flow from the debug view". Companion +// red-proof: drop one asserted phase line (e.g. the probe verdict Debug) → FAIL +// naming the missing marker. +func TestNetAdd_LogSequenceReconstructsFlow(t *testing.T) { + s := testServer(t) + lb := NewLogBuffer(200) + // The production writer layout at logging.level=info: ring captures everything. + s.logger = log.New(lb, "", log.LstdFlags) + + agent := &fakeNetAgent{addRes: okAddRes("media"), verify: agentapi.NetVerifyStatus{Phase: "done", JobID: "job-1"}} + s.netProbeFn = func(context.Context, string) probeOutcome { return probeOutcome{OK: true} } + if !s.startNetAdd(agent, netAddReq("media"), "NAS media") { + t.Fatal("startNetAdd refused") + } + job := waitNetAdd(t, s) + if job.Phase != netAddPhaseDone { + t.Fatalf("phase = %s, want done", job.Phase) + } + + lines := lb.Lines(0) + sequence := []string{ + `netstorage add "media" started`, + "agent add accepted", + "phase agent_add -> verifying", + "agent verify verdict: phase=done", + "phase verifying -> probing", + "probe verdict: ok=true", + "phase probing -> registering", + "network storage added + verified", + } + pos := -1 + for _, marker := range sequence { + idx := -1 + for i := pos + 1; i < len(lines); i++ { + if strings.Contains(lines[i], marker) { + idx = i + break + } + } + if idx < 0 { + t.Fatalf("phase line %q missing (or out of order) — flow not reconstructable.\nring:\n%s", + marker, strings.Join(lines, "\n")) + } + pos = idx + } +} diff --git a/controller/internal/web/server.go b/controller/internal/web/server.go index 5785bb8..1b56bcb 100644 --- a/controller/internal/web/server.go +++ b/controller/internal/web/server.go @@ -74,6 +74,9 @@ type Server struct { netAgentFn func() (netAgent, error) netProbeFn func(ctx context.Context, dir string) probeOutcome netListFn func(ctx context.Context) ([]agentapi.NetworkMountStatus, error) + // agentLogsFn is the Debug-page agent-tab seam (v0.116.0). nil → the shared + // agentClient().DebugLogs; tests inject (incl. the pre-0.83 typed-404 path). + agentLogsFn func(ctx context.Context) (agentapi.AgentLogsResponse, error) // netFeatures caches the agent-capability probe (agentapi features.go) for the coupled NAS add // semantics — the add gate + the settings-page banner read it. Zero value ready. netFeatures agentapi.SupportCache diff --git a/controller/internal/web/templates/debug.html b/controller/internal/web/templates/debug.html index 986a493..5873f86 100644 --- a/controller/internal/web/templates/debug.html +++ b/controller/internal/web/templates/debug.html @@ -212,6 +212,10 @@ ▶