feat(agent-vault): session logs

packages/agentvault/cache.go

@@ -65,11 +65,12 @@ type resolvedService struct {
 }
 
 type sessionEntry struct {
-	sessionID string
-	expiresAt *time.Time
-	services  []*resolvedService
-	lastSeen  time.Time
-	fetchedAt time.Time
+	sessionID  string
+	expiresAt  *time.Time
+	services   []*resolvedService
+	sessionLog *sessionLogGrant
+	lastSeen   time.Time
+	fetchedAt  time.Time
 }
 
 // The map key is the sha256 of the token, never the token itself, so a heap dump yields no live credential.
@@ -79,7 +80,7 @@ func sessionKey(token string) string {
 }
 
 type sessionResolver interface {
-	resolve(sessionToken string) (*resolveResult, error)
+	resolve(sessionToken string, held *sessionLogGrant) (*resolveResult, error)
 }
 
 type sessionCache struct {
@@ -137,22 +138,41 @@ func isProxyTokenRejected(err error) bool {
 	return errors.As(err, &apiErr) && apiErr.Name == proxyTokenRejectedName
 }
 
+// The names on Infisical's own 404s and 401s. A route miss, a middlebox or an auth proxy in front of Infisical
+// answers under another name or none.
+const (
+	infisicalNotFoundName     = "NotFound"
+	infisicalUnauthorizedName = "UnauthorizedError"
+)
+
 // Resolve answers 200, 401 or 404 by contract, and 401 with a name when the proxy's own token is the
-// problem. Only those two statuses are a verdict on the session; anything else from a 4xx is a proxy-side
-// fault or a middlebox, and the heartbeat classifier reads a 4xx the same way, so the two agree. A
-// rejected proxy token is not a verdict on the session and is reported separately.
+// problem. Only Infisical's own 401 (UnauthorizedError) or 404 (NotFound) is a verdict on the session; any
+// other 4xx, an unnamed one included, is a proxy-side fault or a middlebox, and the heartbeat classifier reads a
+// 4xx the same way, so the two agree. A rejected proxy token is not a verdict on the session and is reported
+// separately.
 func isSessionGone(err error) bool {
 	var apiErr *api.APIError
 	if errors.As(err, &apiErr) {
 		if isProxyTokenRejected(err) {
 			return false
 		}
-		return apiErr.StatusCode == http.StatusUnauthorized || apiErr.StatusCode == http.StatusNotFound
+		return (apiErr.StatusCode == http.StatusUnauthorized && apiErr.Name == infisicalUnauthorizedName) ||
+			(apiErr.StatusCode == http.StatusNotFound && apiErr.Name == infisicalNotFoundName)
 	}
 	return errors.Is(err, errSessionGone)
 }
 
 func (c *sessionCache) get(sessionToken string) ([]*resolvedService, error) {
+	services, _, err := c.lookup(sessionToken)
+	return services, err
+}
+
+type cacheLookup struct {
+	services   []*resolvedService
+	sessionLog *sessionLogGrant
+}
+
+func (c *sessionCache) lookup(sessionToken string) ([]*resolvedService, *sessionLogGrant, error) {
 	key := sessionKey(sessionToken)
 
 	c.mu.Lock()
@@ -162,30 +182,30 @@ func (c *sessionCache) get(sessionToken string) ([]*resolvedService, error) {
 			delete(c.entries, key)
 			delete(c.tokens, key)
 			c.mu.Unlock()
-			return nil, errSessionGone
+			return nil, nil, errSessionGone
 		}
 		// Past the grace window the entry is a miss, so a stalled refresh loop cannot keep an old credential alive.
 		if time.Since(entry.fetchedAt) > c.grace() {
 			delete(c.entries, key)
 			delete(c.tokens, key)
 		} else {
 			entry.lastSeen = time.Now()
-			svcs := entry.services
+			svcs, grant := entry.services, entry.sessionLog
 			c.mu.Unlock()
-			return svcs, nil
+			return svcs, grant, nil
 		}
 	}
 	if refused, ok := c.refused[key]; ok {
 		if time.Now().Before(refused.until) {
 			c.mu.Unlock()
-			return nil, refused.err
+			return nil, nil, refused.err
 		}
 		delete(c.refused, key)
 	}
 	c.mu.Unlock()
 
 	resolved, err, _ := c.inflight.Do(key, func() (any, error) {
-		result, err := c.resolver.resolve(sessionToken)
+		result, err := c.resolver.resolve(sessionToken, nil)
 		if err != nil {
 			// A rejected proxy token is remembered too: the poll loop exits after two such heartbeats, but
 			// until then every agent request would otherwise cost a resolve.
@@ -201,19 +221,21 @@ func (c *sessionCache) get(sessionToken string) ([]*resolvedService, error) {
 		defer c.mu.Unlock()
 		c.evictIfFullLocked()
 		c.entries[key] = &sessionEntry{
-			sessionID: result.SessionID,
-			expiresAt: result.ExpiresAt,
-			services:  result.Services,
-			lastSeen:  time.Now(),
-			fetchedAt: time.Now(),
+			sessionID:  result.SessionID,
+			expiresAt:  result.ExpiresAt,
+			services:   result.Services,
+			sessionLog: result.SessionLog,
+			lastSeen:   time.Now(),
+			fetchedAt:  time.Now(),
 		}
 		c.tokens[key] = sessionToken
-		return result.Services, nil
+		return cacheLookup{services: result.Services, sessionLog: result.SessionLog}, nil
 	})
 	if err != nil {
-		return nil, err
+		return nil, nil, err
 	}
-	return resolved.([]*resolvedService), nil
+	out := resolved.(cacheLookup)
+	return out.services, out.sessionLog, nil
 }
 
 func (c *sessionCache) evictIfFullLocked() {
@@ -289,7 +311,14 @@ func (c *sessionCache) refresh() {
 }
 
 func (c *sessionCache) refreshOne(key, token string) {
-	result, err := c.resolver.resolve(token)
+	c.mu.Lock()
+	var held *sessionLogGrant
+	if entry, ok := c.entries[key]; ok {
+		held = entry.sessionLog
+	}
+	c.mu.Unlock()
+
+	result, err := c.resolver.resolve(token, held)
 	if err != nil {
 		c.handleRefreshFailure(key, err)
 		return
@@ -301,6 +330,7 @@ func (c *sessionCache) refreshOne(key, token string) {
 		entry.sessionID = result.SessionID
 		entry.expiresAt = result.ExpiresAt
 		entry.services = result.Services
+		entry.sessionLog = result.SessionLog
 		entry.fetchedAt = time.Now()
 	}
 }

packages/agentvault/cache_test.go

@@ -11,16 +11,18 @@ import (
 )
 
 type stubResolver struct {
-	mu     sync.Mutex
-	calls  int
-	result *resolveResult
-	err    error
-	delay  time.Duration
+	mu       sync.Mutex
+	calls    int
+	result   *resolveResult
+	err      error
+	delay    time.Duration
+	lastHeld *sessionLogGrant
 }
 
-func (s *stubResolver) resolve(string) (*resolveResult, error) {
+func (s *stubResolver) resolve(_ string, held *sessionLogGrant) (*resolveResult, error) {
 	s.mu.Lock()
 	s.calls++
+	s.lastHeld = held
 	result, err, delay := s.result, s.err, s.delay
 	s.mu.Unlock()
 	time.Sleep(delay)
@@ -95,7 +97,7 @@ func TestRefreshDropsAGoneSessionImmediately(t *testing.T) {
 				t.Fatalf("get: %v", err)
 			}
 
-			resolver.err = &api.APIError{StatusCode: status}
+			resolver.err = &api.APIError{StatusCode: status, Name: map[int]string{401: infisicalUnauthorizedName, 404: infisicalNotFoundName}[status]}
 			cache.refresh()
 
 			if len(cache.entries) != 0 {
@@ -196,27 +198,31 @@ func TestStaleEntryIsNotServedFromTheCache(t *testing.T) {
 	}
 }
 
-// Only the statuses resolve answers by contract end a session. A 400, 403 or 422 cannot come from resolve
-// itself, so it is a proxy-side fault or a middlebox and rides the grace window like an outage.
+// Only the refusals resolve answers by contract end a session. A 400, 403 or 422, or a 404 that is not
+// Infisical's NotFound, cannot come from resolve itself, so it is a proxy-side fault or a middlebox and rides
+// the grace window like an outage.
 func TestRefreshTreatsOnlyTheContractRefusalsAsTerminal(t *testing.T) {
 	for _, tc := range []struct {
 		status int
+		name   string
 		kept   bool
 	}{
-		{401, false}, {404, false},
-		{400, true}, {403, true}, {405, true}, {407, true}, {422, true},
-		{408, true}, {429, true}, {500, true}, {502, true},
+		{401, infisicalUnauthorizedName, false}, {404, infisicalNotFoundName, false},
+		{401, "", true}, {401, "Unauthorized", true},
+		{404, "", true}, {404, "Not Found", true},
+		{400, "", true}, {403, "", true}, {405, "", true}, {407, "", true}, {422, "", true},
+		{408, "", true}, {429, "", true}, {500, "", true}, {502, "", true},
 	} {
 		resolver := &stubResolver{result: &resolveResult{SessionID: "s1", Services: []*resolvedService{serviceWithSecret("v")}}}
 		cache := newTestCache(resolver)
 		if _, err := cache.get("tok"); err != nil {
 			t.Fatal(err)
 		}
-		resolver.err = &api.APIError{StatusCode: tc.status}
+		resolver.err = &api.APIError{StatusCode: tc.status, Name: tc.name}
 		cache.refresh()
 		_, kept := cache.get("tok")
 		if (kept == nil) != tc.kept {
-			t.Fatalf("status %d: credential still served = %v, want %v", tc.status, kept == nil, tc.kept)
+			t.Fatalf("status %d %q: credential still served = %v, want %v", tc.status, tc.name, kept == nil, tc.kept)
 		}
 	}
 }
@@ -305,7 +311,7 @@ func TestOnlyOneRefreshRunsAtATime(t *testing.T) {
 }
 
 func TestADefinitiveRefusalIsNotReResolvedEveryRequest(t *testing.T) {
-	resolver := &stubResolver{err: &api.APIError{StatusCode: 404, Name: "NotFound"}}
+	resolver := &stubResolver{err: &api.APIError{StatusCode: 404, Name: infisicalNotFoundName}}
 	cache := newTestCache(resolver)
 
 	for i := 0; i < 20; i++ {
@@ -343,7 +349,7 @@ func TestAnOutageIsNotRememberedAsARefusal(t *testing.T) {
 }
 
 func TestARefusalExpires(t *testing.T) {
-	resolver := &stubResolver{err: &api.APIError{StatusCode: 404}}
+	resolver := &stubResolver{err: &api.APIError{StatusCode: 404, Name: infisicalNotFoundName}}
 	cache := newTestCache(resolver)
 	_, _ = cache.get("agv_dead")
 	cache.mu.Lock()

packages/agentvault/policy.go

@@ -17,7 +17,7 @@ var errBodyUnreadable = errors.New("could not read the request body")
 
 func checkServicePolicy(svc *resolvedService, req *http.Request) error {
 	if !svc.allowsMethod(req.Method) {
-		return fmt.Errorf("service %q does not allow %s: %w", svc.name, req.Method, errPolicyBlocked)
+		return fmt.Errorf("service %q does not allow %s: %w", svc.name, truncateLogged(req.Method, maxLoggedMethodLen), errPolicyBlocked)
 	}
 	if len(svc.allowedPathPrefixes) > 0 {
 		path := requestPath(req)
@@ -103,8 +103,8 @@ func escapeInvalidPathBytes(raw string) string {
 func requestPath(req *http.Request) string {
 	path := req.URL.EscapedPath()
 	if path == "" {
-		// forwardHTTP refuses an opaque target before this runs, so the branch is a floor under that check
-		// rather than a shape expected here. A genuinely empty path is the root.
+		// forward refuses an opaque target before any policy reads the path, so this branch is what the log
+		// line and the session log record show for one. A genuinely empty path is the root.
 		if req.URL.Opaque != "" {
 			return req.URL.Opaque
 		}
@@ -114,10 +114,14 @@ func requestPath(req *http.Request) string {
 }
 
 func truncatePath(path string) string {
-	if len(path) > maxLoggedPathLen {
-		return path[:maxLoggedPathLen] + "...[truncated]"
+	return truncateLogged(path, maxLoggedPathLen)
+}
+
+func truncateLogged(value string, limit int) string {
+	if len(value) > limit {
+		return value[:limit] + "...[truncated]"
 	}
-	return path
+	return value
 }
 
 // Never decodes: anything whose meaning depends on the upstream's normalisation is refused outright, so the

packages/agentvault/policy_test.go

@@ -49,6 +49,17 @@ func TestMethodPolicy(t *testing.T) {
 		}
 	})
 
+	t.Run("a refused method is capped before it reaches the log", func(t *testing.T) {
+		svc := serviceWithPolicy([]string{"GET"}, nil)
+		err := checkServicePolicy(svc, requestTo(t, strings.Repeat("A", 1<<20), "/x"))
+		if !errors.Is(err, errPolicyBlocked) {
+			t.Fatalf("an unlisted method should be blocked, got %v", err)
+		}
+		if len(err.Error()) > 200 {
+			t.Fatalf("the refusal carries %d bytes; the agent's method would fill the proxy log", len(err.Error()))
+		}
+	})
+
 	t.Run("a lower-case method is folded rather than blocked", func(t *testing.T) {
 		svc := serviceWithPolicy([]string{"GET"}, nil)
 		req := requestTo(t, "GET", "/x")