v0.116.0: observability pass — always-on debug ring + leveled sweep + agent tab + self-log pull — MinAgent: 0.81.0

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 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01PSK5g6qYLknKj8u3QAFEr6

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).