Audit authorization denials on the proxy runner path

docs/arch/03-transport-architecture.md

@@ -213,8 +213,8 @@ All proxy types integrate with the middleware chain:
 graph LR
     Client[Client Request] --> MW1[Middleware 1<br/>Auth]
     MW1 --> MW2[Middleware 2<br/>Parser]
-    MW2 --> MW3[Middleware 3<br/>Authz]
-    MW3 --> MW4[Middleware 4<br/>Audit]
+    MW2 --> MW3[Middleware 3<br/>Audit]
+    MW3 --> MW4[Middleware 4<br/>Authz]
     MW4 --> Proxy[Proxy Handler]
     Proxy --> Container[MCP Server]
 
@@ -227,7 +227,7 @@ graph LR
 
 **Implementation:**
 - `pkg/transport/types/transport.go` - `MiddlewareFunction` and `NamedMiddleware` types
-- Middleware applied in reverse order (last registered = outermost)
+- Middleware wraps the handler in reverse registration order, so the first registered entry is the outermost wrapper and runs first at request time
 - Each transport type accepts `[]NamedMiddleware` in constructor (each wraps a `MiddlewareFunction` with its name for logging)
 
 ## Remote MCP Server Proxying

docs/middleware.md

@@ -17,8 +17,8 @@ The middleware chain consists of the following components:
 5. **Tool Mapping Middleware**: Enables tool filtering and override capabilities through two complementary middleware components that process outgoing `tools/list` responses and incoming `tools/call` requests (optional)
 6. **Usage Metrics Middleware**: Collects anonymous usage metrics for ToolHive development (optional)
 7. **Telemetry Middleware**: Instruments requests with OpenTelemetry (optional)
-8. **Authorization Middleware**: Evaluates Cedar policies to authorize requests (optional)
-9. **Audit Middleware**: Logs request events for compliance and monitoring (optional)
+8. **Audit Middleware**: Logs request events for compliance and monitoring (optional)
+9. **Authorization Middleware**: Evaluates Cedar policies to authorize requests (optional)
 10. **Header Forward Middleware**: Injects custom headers into requests to remote MCP servers (optional)
 11. **Recovery Middleware**: Catches panics and returns HTTP 500 errors (always present)
 
@@ -38,7 +38,7 @@ When configured together, the effective order is:
 3. MCP parsing
 4. Mutating webhooks
 5. Validating webhooks
-6. Telemetry, authorization, and audit middleware
+6. Telemetry, audit, and authorization middleware
 
 Multiple webhook definitions of the same type run in configuration order. When multiple `--webhook-config` files are provided, later files override earlier webhook definitions with the same `name`.
 
@@ -59,12 +59,12 @@ Example config files:
 
 ```mermaid
 graph TD
-    A[Incoming MCP Request] --> R[Recovery Middleware]
-    R --> B[Authentication Middleware]
+    A[Incoming MCP Request] --> B[Authentication Middleware]
     B --> C[MCP Parsing Middleware]
-    C --> D[Authorization Middleware]
-    D --> E[Audit Middleware]
-    E --> F[MCP Server Handler]
+    C --> E[Audit Middleware]
+    E --> D[Authorization Middleware]
+    D --> R[Recovery Middleware]
+    R --> F[MCP Server Handler]
 
     R --> R1[Catch Panics]
     R1 --> R2[Log Stack Trace]
@@ -101,17 +101,15 @@ graph TD
 ```mermaid
 sequenceDiagram
     participant Client
-    participant Recovery as Recovery
     participant Auth as Authentication
     participant Parser as MCP Parser
-    participant Authz as Authorization
     participant Audit as Audit
+    participant Authz as Authorization
+    participant Recovery as Recovery
     participant Server as MCP Server
 
-    Client->>Recovery: HTTP Request
-    Note over Recovery: Wraps entire chain to catch panics
-
-    Recovery->>Auth: HTTP Request with JWT
+    Client->>Auth: HTTP Request with JWT
+    Note over Recovery: Innermost wrapper: catches panics<br/>from the handler and inner middleware
     Auth->>Auth: Validate JWT Token
     Auth->>Auth: Extract Claims
     Note over Auth: Add claims to context
@@ -122,19 +120,23 @@ sequenceDiagram
     Parser->>Parser: Extract Resource ID & Arguments
     Note over Parser: Add parsed data to context
 
-    Parser->>Authz: Request + Parsed MCP Data
+    Parser->>Audit: Request + Parsed MCP Data
+    Note over Audit: Wraps authorization so every<br/>request is logged, including denials
+
+    Audit->>Authz: Request
     Authz->>Authz: Get Parsed Data from Context
     Authz->>Authz: Create Cedar Entities
     Authz->>Authz: Evaluate Policies
 
     alt Authorized
-        Authz->>Audit: Authorized Request
-        Audit->>Audit: Extract Event Data
-        Audit->>Audit: Log Audit Event
-        Audit->>Server: Process Request
-        Server->>Client: Response
+        Authz->>Server: Process Request
+        Server->>Audit: Response
+        Audit->>Audit: Log Audit Event (outcome success)
+        Audit->>Client: Response
     else Unauthorized
-        Authz->>Client: 403 Forbidden
+        Authz->>Audit: 403 Forbidden
+        Audit->>Audit: Log Audit Event (outcome denied)
+        Audit->>Client: 403 Forbidden
     else Panic Occurs
         Recovery->>Recovery: Log stack trace
         Recovery->>Client: 500 Internal Server Error
@@ -389,6 +391,7 @@ thv config usage-metrics enable
 - Log structured audit events as JSON
 - Track request duration and outcome
 - Support file-based and stdout log destinations
+- Wrap the authorization middleware so denied requests are still recorded (outcome `denied`)
 
 **Event Types**:
 - `mcp_initialize` - Client initialization events
@@ -560,8 +563,7 @@ thv run --transport sse --name my-server --audit-config <(echo '{"component":"my
 - Prevent server crashes from unhandled panics
 
 **Behavior**:
-- Always added as the outermost middleware wrapper (added last in chain, executes first)
-- Catches any panic from the entire middleware chain and MCP handlers
+- On the `vmcp` path it is applied explicitly as the outermost wrapper and catches panics from the entire chain. On the `thv`/`thv-proxyrunner` path it is appended last to the config slice, which makes it the innermost wrapper: it catches panics from the proxy handler, but not from middleware that wrap it
 - Logs error with stack trace using `logger.Errorf`
 - Returns generic "Internal Server Error" message (no sensitive details exposed)
 
@@ -618,8 +620,8 @@ The middleware chain uses Go's `context.Context` to pass data between components
 graph LR
     A[Request Context] --> B[+ JWT Claims]
     B --> C[+ Parsed MCP Data]
-    C --> D[+ Authorization Result]
-    D --> E[+ Audit Metadata]
+    C --> E[+ Audit Metadata]
+    E --> D[+ Authorization Result]
 
     subgraph "Authentication"
         B
@@ -629,13 +631,13 @@ graph LR
         C
     end
 
-    subgraph "Authorization"
-        D
-    end
-
     subgraph "Audit"
         E
     end
+
+    subgraph "Authorization"
+        D
+    end
 ```
 
 ## Configuration
@@ -661,8 +663,8 @@ The middleware order is critical and enforced by the system:
 
 1. **Authentication** - Must be first to establish client identity
 2. **MCP Parsing** - Must come after authentication to access JWT context
-3. **Authorization** - Must come after parsing to access structured MCP data
-4. **Audit** - Must be last to capture the complete request lifecycle
+3. **Audit** - Must wrap authorization so every request is logged, including policy denials (outcome `denied`)
+4. **Authorization** - Must come after parsing to access structured MCP data
 
 ## Error Handling
 
@@ -1001,19 +1003,20 @@ The middleware chain execution order is critical and controlled by the order in
 6. **MCP Parser Middleware** (always present) - Parses JSON-RPC MCP requests
 7. **Usage Metrics Middleware** (if enabled) - Tracks tool call counts
 8. **Telemetry Middleware** (if enabled) - OpenTelemetry instrumentation
-9. **Authorization Middleware** (if enabled) - Cedar policy evaluation
-10. **Audit Middleware** (if enabled) - Request logging
+9. **Audit Middleware** (if enabled) - Request logging
+10. **Authorization Middleware** (if enabled) - Cedar policy evaluation
 11. **Header Forward Middleware** (if configured for remote servers) - Injects custom headers
-12. **Recovery Middleware** (always present) - Catches panics (outermost wrapper)
+12. **Recovery Middleware** (always present) - Catches panics
 
 **Important Ordering Rules**:
 - Authentication must come first to establish client identity
 - Upstream Token Swap must come after Authentication (requires `tsid` claim) and before Token Exchange (so it can read the original JWT)
 - Token Exchange must come after Upstream Swap if both are used (can further transform the upstream IdP token)
 - Tool filters should come before MCP Parser to operate on raw requests
 - MCP Parser must come before Authorization (provides structured MCP data)
+- Audit must come before Authorization so it wraps it: policy denials (403) must still produce an audit event with outcome `denied`
 - Header Forward executes close to the backend handler (innermost position)
-- Recovery is always last in config (so it executes first as outermost wrapper)
+- Recovery is always last in config, making it the innermost wrapper (the chain wraps in reverse config order, so the first entry is the outermost and runs first)
 
 ### Custom Authorization Policies
 

pkg/runner/authz_audit_integration_test.go

@@ -0,0 +1,171 @@
+// SPDX-FileCopyrightText: Copyright 2025 Stacklok, Inc.
+// SPDX-License-Identifier: Apache-2.0
+
+package runner
+
+import (
+	"bytes"
+	"encoding/json"
+	"net/http"
+	"net/http/httptest"
+	"os"
+	"path/filepath"
+	"strings"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"go.uber.org/mock/gomock"
+
+	"github.com/stacklok/toolhive/pkg/audit"
+	"github.com/stacklok/toolhive/pkg/authz/authorizers"
+	"github.com/stacklok/toolhive/pkg/authz/authorizers/cedar"
+	statusesmocks "github.com/stacklok/toolhive/pkg/workloads/statuses/mocks"
+)
+
+// buildRunnerMiddlewareChain populates the middleware configs for runConfig,
+// instantiates the middlewares through the runner factories (the same path the
+// proxyrunner takes), and wraps final with them in the order the proxies apply
+// them (reverse slice order, so index 0 is the outermost wrapper).
+func buildRunnerMiddlewareChain(t *testing.T, runConfig *RunConfig, final http.Handler) http.Handler {
+	t.Helper()
+
+	require.NoError(t, PopulateMiddlewareConfigs(runConfig))
+
+	ctrl := gomock.NewController(t)
+	t.Cleanup(ctrl.Finish)
+	mockStatusManager := statusesmocks.NewMockStatusManager(ctrl)
+
+	runner := NewRunner(runConfig, mockStatusManager)
+	for _, mwConfig := range runConfig.MiddlewareConfigs {
+		factory, ok := runner.supportedMiddleware[mwConfig.Type]
+		require.True(t, ok, "no factory for middleware type %q", mwConfig.Type)
+		require.NoError(t, factory(&mwConfig, runner))
+	}
+	require.NotEmpty(t, runner.middlewares)
+	// The factories acquire resources (the auditor's log file, the usage-metrics
+	// flush goroutine); release them when the test finishes.
+	t.Cleanup(func() {
+		for _, mw := range runner.middlewares {
+			_ = mw.Close()
+		}
+	})
+
+	handler := final
+	for i := len(runner.middlewares) - 1; i >= 0; i-- {
+		handler = runner.middlewares[i].Handler()(handler)
+	}
+	return handler
+}
+
+// readAuditEvents parses the newline-delimited JSON audit log at path.
+func readAuditEvents(t *testing.T, path string) []map[string]any {
+	t.Helper()
+
+	data, err := os.ReadFile(path)
+	require.NoError(t, err)
+
+	var events []map[string]any
+	for _, line := range strings.Split(strings.TrimSpace(string(data)), "\n") {
+		if line == "" {
+			continue
+		}
+		var event map[string]any
+		require.NoError(t, json.Unmarshal([]byte(line), &event), "audit log line is not JSON: %s", line)
+		events = append(events, event)
+	}
+	return events
+}
+
+// TestAuthzDecisionIsAudited proves, through the full middleware chain the
+// proxyrunner builds via PopulateMiddlewareConfigs, that authorization
+// decisions produce audit events: a Cedar-denied tools/call must return HTTP
+// 403 AND still emit an audit event with outcome "denied", and an authorized
+// call must emit one with outcome "success". This is the regression guard for
+// the ordering bug where audit was wired inside authz and denials were never
+// audited.
+func TestAuthzDecisionIsAudited(t *testing.T) {
+	t.Parallel()
+
+	tests := []struct {
+		name            string
+		policy          string
+		wantStatus      int
+		wantOutcome     string
+		wantHandlerHit  bool
+		wantDeniedError bool
+	}{
+		{
+			name: "denied tool call returns 403 and is audited with outcome denied",
+			// Permit only an unrelated tool: "target_tool" is default-denied.
+			policy:          `permit(principal, action == Action::"call_tool", resource == Tool::"some_other_tool");`,
+			wantStatus:      http.StatusForbidden,
+			wantOutcome:     "denied",
+			wantHandlerHit:  false,
+			wantDeniedError: true,
+		},
+		{
+			name:           "allowed tool call returns 200 and is audited with outcome success",
+			policy:         `permit(principal, action, resource);`,
+			wantStatus:     http.StatusOK,
+			wantOutcome:    "success",
+			wantHandlerHit: true,
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			t.Parallel()
+
+			authzConfig, err := authorizers.NewConfig(cedar.Config{
+				Version: "1.0",
+				Type:    cedar.ConfigType,
+				Options: &cedar.ConfigOptions{
+					Policies:     []string{tt.policy},
+					EntitiesJSON: "[]",
+				},
+			})
+			require.NoError(t, err)
+
+			auditLogPath := filepath.Join(t.TempDir(), "audit.log")
+
+			runConfig := NewRunConfig()
+			runConfig.Name = "test-server"
+			runConfig.AuthzConfig = authzConfig
+			runConfig.AuditConfig = &audit.Config{
+				Component: "test-component",
+				LogFile:   auditLogPath,
+			}
+
+			handlerHit := false
+			backend := http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
+				handlerHit = true
+				w.WriteHeader(http.StatusOK)
+				_, _ = w.Write([]byte(`{"jsonrpc":"2.0","id":1,"result":{}}`))
+			})
+
+			handler := buildRunnerMiddlewareChain(t, runConfig, backend)
+
+			reqBody := `{"jsonrpc":"2.0","method":"tools/call","id":1,"params":{"name":"target_tool","arguments":{}}}`
+			req := httptest.NewRequest(http.MethodPost, "/", bytes.NewBufferString(reqBody))
+			req.Header.Set("Content-Type", "application/json")
+
+			rr := httptest.NewRecorder()
+			handler.ServeHTTP(rr, req)
+
+			require.Equal(t, tt.wantStatus, rr.Code, "response body: %s", rr.Body.String())
+			assert.Equal(t, tt.wantHandlerHit, handlerHit)
+			if tt.wantDeniedError {
+				assert.Contains(t, rr.Body.String(), "Unauthorized",
+					"denied response must carry the authorization-denied error")
+			}
+
+			events := readAuditEvents(t, auditLogPath)
+			require.Len(t, events, 1, "exactly one audit event must be emitted")
+			event := events[0]
+			assert.Equal(t, "mcp_tool_call", event["type"],
+				"the parsed MCP method must drive the audit event type")
+			assert.Equal(t, tt.wantOutcome, event["outcome"])
+		})
+	}
+}