hub 0.177.0: Reboot guest on the host page (D65 = A, reboot_guest in the agent's closed list, 30-minute expiry); R-1346: the slow-request line and the vouch save's per-leg timing

hub/internal/accesslog/accesslog.go

@@ -53,6 +53,8 @@ type Log struct {
 	keep time.Duration
 	now  func() time.Time
 	logf func(format string, a ...any)
+	// slowAfter: R-1346's slow-request line.
+	slowAfter time.Duration
 
 	ch   chan string
 	done chan struct{}
@@ -75,13 +77,25 @@ type Options struct {
 	Keep time.Duration
 	Now  func() time.Time
 	Logf func(format string, a ...any)
+	// SlowAfter (R-1346): a request slower than this gets one operator log line (method, path, status, duration);
+	// zero → DefaultSlowAfter.
+	SlowAfter time.Duration
 }
 
+// DefaultSlowAfter is when a request counts as slow (R-1346).
+const DefaultSlowAfter = 5 * time.Second
+
+// slowExempt are the paths slow BY DESIGN: the box's long-poll waits up to 4 minutes for a change.
+var slowExempt = map[string]bool{"/api/v1/wait": true}
+
 // New starts the writer and prunes once. The directory is created on first write, never at construction, so a
 // missing volume costs a logged error and nothing else.
 func New(o Options) *Log {
-	l := &Log{dir: o.Dir, keep: o.Keep, now: o.Now, logf: o.Logf,
+	l := &Log{dir: o.Dir, keep: o.Keep, now: o.Now, logf: o.Logf, slowAfter: o.SlowAfter,
 		ch: make(chan string, bufferLines), done: make(chan struct{})}
+	if l.slowAfter <= 0 {
+		l.slowAfter = DefaultSlowAfter
+	}
 	if l.keep <= 0 {
 		l.keep = DefaultKeep
 	}
@@ -282,7 +296,14 @@ func (l *Log) Middleware(next http.Handler) http.Handler {
 			e.mu.Lock()
 			auth := e.auth
 			e.mu.Unlock()
-			l.enqueue(FormatLine(start, r, status, l.now().Sub(start), auth))
+			dur := l.now().Sub(start)
+			l.enqueue(FormatLine(start, r, status, dur, auth))
+			if dur > l.slowAfter && !slowExempt[r.URL.Path] {
+				// R-1346: the slow page names itself in the operator log — the path only (SafePath: no query, no
+				// capability), never a value.
+				l.logf("[WARN] slow request: %s %s %s %dms (over %s)", safeToken(r.Method, 10), SafePath(r), status,
+					dur.Milliseconds(), l.slowAfter)
+			}
 		}()
 		next.ServeHTTP(rec, r.WithContext(context.WithValue(r.Context(), ctxKey{}, e)))
 		finished = true

hub/internal/accesslog/accesslog_test.go

@@ -1,6 +1,7 @@
 package accesslog
 
 import (
+	"fmt"
 	"net/http"
 	"net/http/httptest"
 	"os"
@@ -233,3 +234,46 @@ func TestAccessLog_SkipsOnlyTheKubeletProbe(t *testing.T) {
 		t.Fatalf("want exactly the ingress /healthz logged, got:\n%s", got)
 	}
 }
+
+// R-1346: a request slower than 5 s gets one operator log line — method, path (no query value), status, duration — so a
+// slow page names itself in the hub's log. The box long-poll (/api/v1/wait) is slow by design and is not named.
+// RED-PROOF: drop the slow check → no line → FAILS; drop the wait exception → the 240 s poll is named → FAILS.
+func TestAccessLog_ASlowRequestIsNamed(t *testing.T) {
+	c := &clock{t: time.Date(2026, 10, 29, 13, 3, 19, 0, time.UTC)}
+	var mu sync.Mutex
+	var lines []string
+	l := New(Options{Dir: t.TempDir(), Now: c.now, Logf: func(f string, a ...any) {
+		mu.Lock()
+		defer mu.Unlock()
+		lines = append(lines, fmt.Sprintf(f, a...))
+	}})
+	defer l.Close()
+	took := 0 * time.Second
+	h := l.Middleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		c.set(c.now().Add(took))
+		w.WriteHeader(http.StatusSeeOther)
+	}))
+	took = 170 * time.Second
+	serve(h, httptest.NewRequest(http.MethodPost, "/configuration/artifacts?agent_version=0.169.0", nil))
+	took = 4 * time.Second
+	serve(h, httptest.NewRequest(http.MethodGet, "/customers/tester-1", nil))
+	took = 240 * time.Second
+	serve(h, httptest.NewRequest(http.MethodGet, "/api/v1/wait?gen=7", nil))
+	mu.Lock()
+	defer mu.Unlock()
+	var slow []string
+	for _, ln := range lines {
+		if strings.Contains(ln, "slow request") {
+			slow = append(slow, ln)
+		}
+	}
+	if len(slow) != 1 {
+		t.Fatalf("slow lines = %q, want exactly the 170 s save", slow)
+	}
+	if want := "[WARN] slow request: POST /configuration/artifacts 303 170000ms"; !strings.HasPrefix(slow[0], want) {
+		t.Fatalf("line %q, want prefix %q", slow[0], want)
+	}
+	if strings.Contains(slow[0], "0.169.0") {
+		t.Fatalf("a query value reached the log: %q", slow[0])
+	}
+}