From 53138b733c63dad05f06cb5807fb8830c7806e52 Mon Sep 17 00:00:00 2001
From: James Telfer <792299+jamestelfer@users.noreply.github.com>
Date: Thu, 3 Oct 2024 23:13:08 +1000
Subject: [PATCH 1/8] feat: beginning of audit functionality

Middleware for setup, writing of log, context handling.
---
 codecov.yml                |   2 +
 internal/audit/log.go      | 157 +++++++++++++++++++++++++++++++++++++
 internal/audit/log_test.go | 142 +++++++++++++++++++++++++++++++++
 internal/audit/response.go |  48 ++++++++++++
 4 files changed, 349 insertions(+)
 create mode 100644 internal/audit/log.go
 create mode 100644 internal/audit/log_test.go
 create mode 100644 internal/audit/response.go

diff --git a/codecov.yml b/codecov.yml
index d31b2b6..a134b0d 100644
--- a/codecov.yml
+++ b/codecov.yml
@@ -1,6 +1,8 @@
 ignore:
   # testing utility
   - "cmd/create"
+  # has sufficient secondary coverage
+  - "internal/audit/response.go"
   # telemetry configuration
   - "internal/observe/telemetry.go"
   # bootstrap only
diff --git a/internal/audit/log.go b/internal/audit/log.go
new file mode 100644
index 0000000..4d7ec3b
--- /dev/null
+++ b/internal/audit/log.go
@@ -0,0 +1,157 @@
+package audit
+
+import (
+	"context"
+	"fmt"
+	"net/http"
+
+	"github.com/rs/zerolog"
+)
+
+// marker for interface implementation
+var _ zerolog.LogObjectMarshaler = (*Entry)(nil)
+
+// marker for context key
+type key struct{}
+
+const (
+	// Level is the log level at which audit logs are written.
+	Level = zerolog.Level(20)
+)
+
+var (
+	// logKey is the key used to store the audit log entry in the context.
+	logKey = key{}
+)
+
+// Entry is an audit log entry for the current request.
+type Entry struct {
+	Method           string
+	Path             string
+	Status           int
+	SourceIP         string
+	UserAgent        string
+	RequestedProfile string
+	Identity         string
+	Authorized       bool
+	Error            string
+	Repositories     []string
+	Permissions      []string
+}
+
+// MarshalZerologObject implements zerolog.LogObjectMarshaler. This avoids the
+// need for reflection when logging, at the cost of requiring maintenance when
+// the Entry struct changes.
+func (e *Entry) MarshalZerologObject(event *zerolog.Event) {
+	event.Str("method", e.Method).
+		Str("path", e.Path).
+		Int("status", e.Status).
+		Str("sourceIP", e.SourceIP).
+		Str("userAgent", e.UserAgent).
+		Str("requestedProfile", e.RequestedProfile).
+		Str("identity", e.Identity).
+		Bool("authorized", e.Authorized).
+		Str("error", e.Error).
+		Strs("repositories", e.Repositories).
+		Strs("permissions", e.Permissions)
+}
+
+// Begin sets up the audit log entry for the current request with details from the request.
+func (e *Entry) Begin(r *http.Request) {
+	e.Path = r.URL.Path
+	e.Method = r.Method
+	e.UserAgent = r.UserAgent()
+	e.SourceIP = r.RemoteAddr
+}
+
+// End writes the audit log entry. If the returned func is deferred, any panic
+// will be recovered so the log entry can be written before the panic is
+// re-raised.
+func (e *Entry) End(ctx context.Context) func() {
+	return func() {
+		// recover from panic if necessary
+		r := recover()
+		if r != nil {
+			// record the details of the panic, attempting to avoid overwriting an
+			// earlier error
+			e.Status = http.StatusInternalServerError
+			err := fmt.Sprintf("panic: %v", r)
+			if e.Error != "" {
+				e.Error += "; "
+			}
+			e.Error += err
+		}
+
+		// OK is the default if the status is not set when the response is written.
+		if e.Status == 0 {
+			e.Status = http.StatusOK
+		}
+
+		zerolog.Ctx(ctx).WithLevel(Level).EmbedObject(e).Str("type", "audit").Msg("audit_event")
+
+		if r != nil {
+			// repanic the panic
+			panic(r)
+		}
+	}
+}
+
+// Middleware is an HTTP middleware that creates a new audit log entry for the
+// current request and enriches it with information about the request. The log
+// entry is written to the log when the request is complete.
+//
+// A panic during the request will be recovered and logged as an error in the
+// audit entry. The HTTP status code of the response is also logged in the audit
+// entry; further details may be added by the application.
+func Middleware() func(next http.Handler) http.Handler {
+	zerologConfiguration()
+
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			ctx, entry := Context(r.Context())
+
+			// wrap the response writer to capture the status code
+			response := wrapResponseWriter(w, Log(ctx))
+
+			entry.Begin(r)
+			defer entry.End(ctx)()
+
+			next.ServeHTTP(response, r.WithContext(ctx))
+		})
+	}
+}
+
+// Get the log entry for the current request. This is safe to use even if the
+// context does not create an entry.
+func Log(ctx context.Context) *Entry {
+	_, e := Context(ctx)
+	return e
+}
+
+// Context returns the Entry for the current request, creating one if it
+// does not exist. If the returned context is kept, the returned entry can be
+// further enriched. If not, information written to the entry will be lost.
+func Context(ctx context.Context) (context.Context, *Entry) {
+	e, ok := ctx.Value(logKey).(*Entry)
+	if !ok {
+		e = &Entry{}
+
+		ctx = context.WithValue(ctx, logKey, e)
+	}
+
+	return ctx, e
+}
+
+func zerologConfiguration() {
+	// configure the console writer
+	zerolog.FormattedLevels[Level] = "AUD"
+
+	// format the audit level as "audit", falling back to the default
+	marshal := zerolog.LevelFieldMarshalFunc
+	zerolog.LevelFieldMarshalFunc = func(l zerolog.Level) string {
+		if l == Level {
+			return "audit"
+		}
+		return marshal(l)
+	}
+}
diff --git a/internal/audit/log_test.go b/internal/audit/log_test.go
new file mode 100644
index 0000000..7282adc
--- /dev/null
+++ b/internal/audit/log_test.go
@@ -0,0 +1,142 @@
+package audit_test
+
+import (
+	"context"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	"github.com/jamestelfer/chinmina-bridge/internal/audit"
+	"github.com/rs/zerolog"
+	"github.com/rs/zerolog/log"
+	"github.com/stretchr/testify/assert"
+)
+
+func TestMiddleware(t *testing.T) {
+
+	t.Run("captures request info and configures context", func(t *testing.T) {
+		testAgent := "kettle/1.0"
+		handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			ctx := r.Context()
+
+			entry := audit.Log(ctx)
+			assert.Equal(t, testAgent, entry.UserAgent)
+
+			w.WriteHeader(http.StatusTeapot)
+		})
+
+		middleware := audit.Middleware()(handler)
+
+		req, w := requestSetup()
+		req.Header.Set("User-Agent", testAgent)
+
+		middleware.ServeHTTP(w, req)
+
+		assert.Equal(t, http.StatusTeapot, w.Result().StatusCode)
+	})
+
+	t.Run("captures status code", func(t *testing.T) {
+		var capturedContext context.Context
+		handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			capturedContext = r.Context()
+			w.WriteHeader(http.StatusTeapot)
+		})
+
+		req, w := requestSetup()
+
+		middleware := audit.Middleware()(handler)
+
+		middleware.ServeHTTP(w, req)
+
+		entry := audit.Log(capturedContext)
+
+		assert.Equal(t, http.StatusTeapot, w.Result().StatusCode)
+		assert.Equal(t, http.StatusTeapot, entry.Status)
+	})
+
+	t.Run("log written", func(t *testing.T) {
+		auditWritten := false
+
+		ctx := withLogHook(
+			context.Background(),
+			zerolog.HookFunc(func(e *zerolog.Event, level zerolog.Level, msg string) {
+				if level == audit.Level {
+					auditWritten = true
+				}
+			}),
+		)
+
+		handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			w.WriteHeader(http.StatusTeapot)
+		})
+
+		middleware := audit.Middleware()(handler)
+
+		req, w := requestSetup()
+
+		middleware.ServeHTTP(w, req.WithContext(ctx))
+
+		assert.True(t, auditWritten, "audit log entry should be written")
+	})
+
+	t.Run("log written on panic", func(t *testing.T) {
+		auditWritten := false
+
+		ctx := withLogHook(
+			context.Background(),
+			zerolog.HookFunc(func(e *zerolog.Event, level zerolog.Level, msg string) {
+				if level == audit.Level {
+					auditWritten = true
+				}
+			}),
+		)
+
+		var entry *audit.Entry
+
+		handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			_, entry = audit.Context(r.Context())
+			entry.Error = "failure pre-panic"
+			panic("not a teapot")
+		})
+
+		middleware := audit.Middleware()(handler)
+
+		req, w := requestSetup()
+
+		assert.PanicsWithValue(t, "not a teapot", func() {
+			middleware.ServeHTTP(w, req.WithContext(ctx))
+			// this will panic as it's expected that the middleware will re-panic
+		})
+
+		assert.Equal(t, "failure pre-panic; panic: not a teapot", entry.Error)
+		assert.True(t, auditWritten, "audit log entry should be written")
+	})
+}
+
+func TestAuditing(t *testing.T) {
+	ctx := context.Background()
+	r, _ := requestSetup()
+
+	_, e := audit.Context(ctx)
+	e.Begin(r)
+	e.End(ctx)()
+
+	assert.NotEmpty(t, e.SourceIP)
+	e.SourceIP = "" // clear IP as it will change between tests
+
+	assert.Equal(t, &audit.Entry{Method: "GET", Path: "/foo", UserAgent: "kettle/1.0", Status: 200}, e)
+}
+
+func requestSetup() (*http.Request, *httptest.ResponseRecorder) {
+	req := httptest.NewRequest(http.MethodGet, "http://example.com/foo", nil)
+	req.Header.Set("User-Agent", "kettle/1.0")
+
+	w := httptest.NewRecorder()
+
+	return req, w
+}
+
+func withLogHook(ctx context.Context, hook zerolog.HookFunc) context.Context {
+	testLog := log.Logger.With().Logger().Hook(hook)
+	return testLog.WithContext(ctx)
+}
diff --git a/internal/audit/response.go b/internal/audit/response.go
new file mode 100644
index 0000000..227bd80
--- /dev/null
+++ b/internal/audit/response.go
@@ -0,0 +1,48 @@
+package audit
+
+import (
+	"bufio"
+	"net"
+	"net/http"
+)
+
+func wrapResponseWriter(w http.ResponseWriter, e *Entry) http.ResponseWriter {
+	wrapped := &responseWrapper{responseWriter: w, entry: e}
+	if _, ok := w.(http.Hijacker); ok {
+		return &hijackWrapper{*wrapped}
+	}
+	return wrapped
+}
+
+type responseWrapper struct {
+	responseWriter http.ResponseWriter
+	entry          *Entry
+}
+
+func (w *responseWrapper) Header() http.Header {
+	return w.responseWriter.Header()
+}
+
+func (w *responseWrapper) Write(buf []byte) (int, error) {
+	return w.responseWriter.Write(buf)
+}
+
+func (w *responseWrapper) WriteHeader(code int) {
+	w.entry.Status = code
+	w.responseWriter.WriteHeader(code)
+}
+
+func (w *responseWrapper) Flush() {
+	if flusher, ok := w.responseWriter.(http.Flusher); ok {
+		flusher.Flush()
+	}
+}
+
+// hijackWrapper wraps a response writer that supports hijacking.
+type hijackWrapper struct {
+	responseWrapper
+}
+
+func (h *hijackWrapper) Hijack() (net.Conn, *bufio.ReadWriter, error) {
+	return h.responseWriter.(http.Hijacker).Hijack()
+}

From b1a5ea08e5ed21bce490f2333bbd02c12cfcb78e Mon Sep 17 00:00:00 2001
From: James Telfer <792299+jamestelfer@users.noreply.github.com>
Date: Fri, 4 Oct 2024 14:14:11 +1000
Subject: [PATCH 2/8] fix: add auditor middleware to primary routes

Integrates the functionality, making it available to other components.
---
 main.go | 12 +++++++++---
 1 file changed, 9 insertions(+), 3 deletions(-)

diff --git a/main.go b/main.go
index 3b9e0ec..f427044 100644
--- a/main.go
+++ b/main.go
@@ -10,6 +10,7 @@ import (
 	"time"
 
 	jwtmiddleware "github.com/auth0/go-jwt-middleware/v2"
+	"github.com/jamestelfer/chinmina-bridge/internal/audit"
 	"github.com/jamestelfer/chinmina-bridge/internal/buildkite"
 	"github.com/jamestelfer/chinmina-bridge/internal/config"
 	"github.com/jamestelfer/chinmina-bridge/internal/github"
@@ -28,6 +29,8 @@ func configureServerRoutes(ctx context.Context, cfg config.Config) (http.Handler
 	mux := observe.NewMux(muxWithoutTelemetry)
 
 	// configure middleware
+	auditor := audit.Middleware()
+
 	authorizer, err := jwt.Middleware(cfg.Authorization, jwtmiddleware.WithErrorHandler(jwt.LogErrorHandler()))
 	if err != nil {
 		return nil, fmt.Errorf("authorizer configuration failed: %w", err)
@@ -36,8 +39,9 @@ func configureServerRoutes(ctx context.Context, cfg config.Config) (http.Handler
 	// The request body size is fairly limited to prevent accidental or
 	// deliberate abuse. Given the current API shape, this is not configurable.
 	requestLimitBytes := int64(20 << 10) // 20 KB
+	requestLimiter := maxRequestSize(requestLimitBytes)
 
-	authorized := alice.New(maxRequestSize(requestLimitBytes), authorizer)
+	authorizedRouteMiddleware := alice.New(requestLimiter, auditor, authorizer)
 
 	// setup token handler and dependencies
 	bk, err := buildkite.New(cfg.Buildkite)
@@ -57,8 +61,8 @@ func configureServerRoutes(ctx context.Context, cfg config.Config) (http.Handler
 
 	tokenVendor := vendorCache(vendor.New(bk.RepositoryLookup, gh.CreateAccessToken))
 
-	mux.Handle("POST /token", authorized.Then(handlePostToken(tokenVendor)))
-	mux.Handle("POST /git-credentials", authorized.Then(handlePostGitCredentials(tokenVendor)))
+	mux.Handle("POST /token", authorizedRouteMiddleware.Then(handlePostToken(tokenVendor)))
+	mux.Handle("POST /git-credentials", authorizedRouteMiddleware.Then(handlePostGitCredentials(tokenVendor)))
 
 	// healthchecks are not included in telemetry
 	muxWithoutTelemetry.Handle("GET /healthcheck", handleHealthCheck())
@@ -140,6 +144,8 @@ func configureLogging() {
 			Output(zerolog.ConsoleWriter{Out: os.Stdout}).
 			Level(zerolog.DebugLevel)
 	}
+
+	zerolog.DefaultContextLogger = &log.Logger
 }
 
 func logBuildInfo() {

From 56b140efcea8a5966e51ee5dbdd19d5c08f54ec5 Mon Sep 17 00:00:00 2001
From: James Telfer <792299+jamestelfer@users.noreply.github.com>
Date: Fri, 4 Oct 2024 14:15:11 +1000
Subject: [PATCH 3/8] fix: enable request limiter on healthcheck route

Healthchecks need protection too!
---
 main.go | 5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

diff --git a/main.go b/main.go
index f427044..0e5a741 100644
--- a/main.go
+++ b/main.go
@@ -42,6 +42,7 @@ func configureServerRoutes(ctx context.Context, cfg config.Config) (http.Handler
 	requestLimiter := maxRequestSize(requestLimitBytes)
 
 	authorizedRouteMiddleware := alice.New(requestLimiter, auditor, authorizer)
+	standardRouteMiddleware := alice.New(requestLimiter)
 
 	// setup token handler and dependencies
 	bk, err := buildkite.New(cfg.Buildkite)
@@ -64,8 +65,8 @@ func configureServerRoutes(ctx context.Context, cfg config.Config) (http.Handler
 	mux.Handle("POST /token", authorizedRouteMiddleware.Then(handlePostToken(tokenVendor)))
 	mux.Handle("POST /git-credentials", authorizedRouteMiddleware.Then(handlePostGitCredentials(tokenVendor)))
 
-	// healthchecks are not included in telemetry
-	muxWithoutTelemetry.Handle("GET /healthcheck", handleHealthCheck())
+	// healthchecks are not included in telemetry or authorization
+	muxWithoutTelemetry.Handle("GET /healthcheck", standardRouteMiddleware.Then(handleHealthCheck()))
 
 	return mux, nil
 }

From 0bb9179cc5902a54fdb2ae1a1d8a857a6a719af6 Mon Sep 17 00:00:00 2001
From: James Telfer <792299+jamestelfer@users.noreply.github.com>
Date: Fri, 4 Oct 2024 14:16:37 +1000
Subject: [PATCH 4/8] fix: typo in comment

---
 internal/jwt/jwt.go | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/internal/jwt/jwt.go b/internal/jwt/jwt.go
index 820ec10..7406294 100644
--- a/internal/jwt/jwt.go
+++ b/internal/jwt/jwt.go
@@ -49,7 +49,7 @@ func Middleware(cfg config.AuthorizationConfig, options ...jwtmiddleware.Option)
 		return nil, fmt.Errorf("failed to set up the validator: %v", err)
 	}
 
-	// wrap the standard validator with additional validaton that ensures the
+	// wrap the standard validator with additional validation that ensures the
 	// core claims (including validity periods) are present
 	tokenValidator := registeredClaimsValidator(jwtValidator.ValidateToken)
 

From 26d1c375f5e54488c09a28c748ab94873996e239 Mon Sep 17 00:00:00 2001
From: James Telfer <792299+jamestelfer@users.noreply.github.com>
Date: Sat, 5 Oct 2024 15:09:05 +1000
Subject: [PATCH 5/8] test: add helper for log setup

Sends log output to the test log, and ensures that a context logger is present.
---
 internal/audit/log_test.go  | 11 +++++++++++
 internal/jwt/jwt_test.go    |  3 +++
 internal/testhelpers/log.go | 27 +++++++++++++++++++++++++++
 3 files changed, 41 insertions(+)
 create mode 100644 internal/testhelpers/log.go

diff --git a/internal/audit/log_test.go b/internal/audit/log_test.go
index 7282adc..75d6700 100644
--- a/internal/audit/log_test.go
+++ b/internal/audit/log_test.go
@@ -7,6 +7,7 @@ import (
 	"testing"
 
 	"github.com/jamestelfer/chinmina-bridge/internal/audit"
+	"github.com/jamestelfer/chinmina-bridge/internal/testhelpers"
 	"github.com/rs/zerolog"
 	"github.com/rs/zerolog/log"
 	"github.com/stretchr/testify/assert"
@@ -15,6 +16,8 @@ import (
 func TestMiddleware(t *testing.T) {
 
 	t.Run("captures request info and configures context", func(t *testing.T) {
+		testhelpers.SetupLogger(t)
+
 		testAgent := "kettle/1.0"
 		handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 			ctx := r.Context()
@@ -36,6 +39,8 @@ func TestMiddleware(t *testing.T) {
 	})
 
 	t.Run("captures status code", func(t *testing.T) {
+		testhelpers.SetupLogger(t)
+
 		var capturedContext context.Context
 		handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 			capturedContext = r.Context()
@@ -55,6 +60,8 @@ func TestMiddleware(t *testing.T) {
 	})
 
 	t.Run("log written", func(t *testing.T) {
+		testhelpers.SetupLogger(t)
+
 		auditWritten := false
 
 		ctx := withLogHook(
@@ -80,6 +87,8 @@ func TestMiddleware(t *testing.T) {
 	})
 
 	t.Run("log written on panic", func(t *testing.T) {
+		testhelpers.SetupLogger(t)
+
 		auditWritten := false
 
 		ctx := withLogHook(
@@ -114,6 +123,8 @@ func TestMiddleware(t *testing.T) {
 }
 
 func TestAuditing(t *testing.T) {
+	testhelpers.SetupLogger(t)
+
 	ctx := context.Background()
 	r, _ := requestSetup()
 
diff --git a/internal/jwt/jwt_test.go b/internal/jwt/jwt_test.go
index ec416b7..dcd1eff 100644
--- a/internal/jwt/jwt_test.go
+++ b/internal/jwt/jwt_test.go
@@ -14,6 +14,7 @@ import (
 
 	jwtmiddleware "github.com/auth0/go-jwt-middleware/v2"
 	"github.com/jamestelfer/chinmina-bridge/internal/config"
+	"github.com/jamestelfer/chinmina-bridge/internal/testhelpers"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 )
@@ -118,6 +119,8 @@ func TestMiddleware(t *testing.T) {
 
 	for _, test := range testCases {
 		t.Run(test.name, func(t *testing.T) {
+			testhelpers.SetupLogger(t)
+
 			request, err := http.NewRequest(http.MethodGet, "", nil)
 			require.NoError(t, err)
 
diff --git a/internal/testhelpers/log.go b/internal/testhelpers/log.go
new file mode 100644
index 0000000..0c80adf
--- /dev/null
+++ b/internal/testhelpers/log.go
@@ -0,0 +1,27 @@
+package testhelpers
+
+import (
+	"testing"
+
+	"github.com/rs/zerolog"
+	"github.com/rs/zerolog/log"
+)
+
+func SetupLogger(t *testing.T) {
+	t.Helper()
+
+	// capture the current global logger so it can be restored on test completion.
+	globalLogger := log.Logger
+	t.Cleanup(func() {
+		log.Logger = globalLogger
+		zerolog.DefaultContextLogger = nil
+	})
+
+	// set up a logger that writes to the test output
+	log.Logger = log.
+		Output(zerolog.NewTestWriter(t)).
+		Level(zerolog.DebugLevel)
+
+	// unless set, the context logger will not log anything
+	zerolog.DefaultContextLogger = &log.Logger
+}

From c300bb304105e1a3c6c01756ebb11518ddaed387 Mon Sep 17 00:00:00 2001
From: James Telfer <792299+jamestelfer@users.noreply.github.com>
Date: Sat, 5 Oct 2024 23:21:17 +1000
Subject: [PATCH 6/8] fix: enable audit logging of auth decision

Ensures that the audit log shows the result of the
JWT validation, recording the identity if
successful and the reason if not.
---
 internal/audit/log.go    | 32 +++++++++++++++++----
 internal/jwt/jwt.go      | 57 +++++++++++++++++++++++++++++-------
 internal/jwt/jwt_test.go | 62 +++++++++++++++++++---------------------
 main.go                  |  3 +-
 4 files changed, 105 insertions(+), 49 deletions(-)

diff --git a/internal/audit/log.go b/internal/audit/log.go
index 4d7ec3b..5dd380b 100644
--- a/internal/audit/log.go
+++ b/internal/audit/log.go
@@ -4,6 +4,7 @@ import (
 	"context"
 	"fmt"
 	"net/http"
+	"time"
 
 	"github.com/rs/zerolog"
 )
@@ -32,8 +33,11 @@ type Entry struct {
 	SourceIP         string
 	UserAgent        string
 	RequestedProfile string
-	Identity         string
 	Authorized       bool
+	AuthSubject      string
+	AuthIssuer       string
+	AuthAudience     []string
+	AuthExpirySecs   int64
 	Error            string
 	Repositories     []string
 	Permissions      []string
@@ -49,11 +53,29 @@ func (e *Entry) MarshalZerologObject(event *zerolog.Event) {
 		Str("sourceIP", e.SourceIP).
 		Str("userAgent", e.UserAgent).
 		Str("requestedProfile", e.RequestedProfile).
-		Str("identity", e.Identity).
 		Bool("authorized", e.Authorized).
-		Str("error", e.Error).
-		Strs("repositories", e.Repositories).
-		Strs("permissions", e.Permissions)
+		Str("authSubject", e.AuthSubject).
+		Str("authIssuer", e.AuthIssuer).
+		Str("error", e.Error)
+
+	now := time.Now()
+	if e.AuthExpirySecs > 0 {
+		exp := time.Unix(e.AuthExpirySecs, 0)
+		remaining := exp.Sub(now).Round(time.Millisecond)
+		event.Time("authExpiry", exp)
+		event.Dur("authExpiryRemaining", remaining)
+	}
+	if len(e.AuthAudience) > 0 {
+		event.Strs("authAudience", e.AuthAudience)
+	}
+
+	if len(e.Repositories) > 0 {
+		event.Strs("repositories", e.Repositories)
+	}
+
+	if len(e.Permissions) > 0 {
+		event.Strs("permissions", e.Permissions)
+	}
 }
 
 // Begin sets up the audit log entry for the current request with details from the request.
diff --git a/internal/jwt/jwt.go b/internal/jwt/jwt.go
index 7406294..c5af72b 100644
--- a/internal/jwt/jwt.go
+++ b/internal/jwt/jwt.go
@@ -9,12 +9,13 @@ import (
 	"time"
 
 	"github.com/go-jose/go-jose/v4"
+	"github.com/justinas/alice"
 
 	jwtmiddleware "github.com/auth0/go-jwt-middleware/v2"
 	"github.com/auth0/go-jwt-middleware/v2/jwks"
 	"github.com/auth0/go-jwt-middleware/v2/validator"
-	"github.com/rs/zerolog/log"
 
+	"github.com/jamestelfer/chinmina-bridge/internal/audit"
 	"github.com/jamestelfer/chinmina-bridge/internal/config"
 )
 
@@ -49,21 +50,23 @@ func Middleware(cfg config.AuthorizationConfig, options ...jwtmiddleware.Option)
 		return nil, fmt.Errorf("failed to set up the validator: %v", err)
 	}
 
+	// Auditing of the validation process uses a combination of the error handler
+	// and the audit middleware. The first ensures that validation errors are marked in
+	// the audit log, while the second ensures that the claims are logged when the
+	// token is valid.
+
+	// force the use of the audit error handler
+	options = append(options, jwtmiddleware.WithErrorHandler(auditErrorHandler()))
+
 	// wrap the standard validator with additional validation that ensures the
 	// core claims (including validity periods) are present
 	tokenValidator := registeredClaimsValidator(jwtValidator.ValidateToken)
 
-	return jwtmiddleware.New(tokenValidator, options...).CheckJWT, nil
-}
+	validationMiddleware := jwtmiddleware.New(tokenValidator, options...).CheckJWT
 
-func LogErrorHandler() jwtmiddleware.ErrorHandler {
-	return func(w http.ResponseWriter, r *http.Request, err error) {
-		log.Warn().
-			Err(err).
-			Msg("JWT decode failure")
+	subChain := alice.New(validationMiddleware, auditClaimsMiddleware()).Then
 
-		jwtmiddleware.DefaultErrorHandler(w, r, err)
-	}
+	return subChain, nil
 }
 
 // ContextWithClaims returns a new context.Context with the provided validated claims
@@ -103,6 +106,40 @@ func RequireBuildkiteClaimsFromContext(ctx context.Context) BuildkiteClaims {
 	return *c
 }
 
+func auditClaimsMiddleware() func(next http.Handler) http.Handler {
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			entry := audit.Log(r.Context())
+			claims := ClaimsFromContext(r.Context())
+
+			if claims == nil {
+				entry.Error = "JWT claims missing from context"
+			} else {
+				reg := claims.RegisteredClaims
+				entry.Authorized = true
+				entry.AuthSubject = reg.Subject
+				entry.AuthIssuer = reg.Issuer
+				entry.AuthAudience = reg.Audience
+				entry.AuthExpirySecs = reg.Expiry
+			}
+
+			next.ServeHTTP(w, r)
+		})
+	}
+}
+
+func auditErrorHandler() jwtmiddleware.ErrorHandler {
+	return func(w http.ResponseWriter, r *http.Request, err error) {
+		entry := audit.Log(r.Context())
+		entry.Error = fmt.Sprintf("JWT authorization failure: %s", err.Error())
+
+		// The default error handler will write the appropriate response status
+		// code. The status code is recorded centrally by the central audit
+		// middleware.
+		jwtmiddleware.DefaultErrorHandler(w, r, err)
+	}
+}
+
 type KeyFunc = func(ctx context.Context) (any, error)
 
 func remoteJWKS(cfg config.AuthorizationConfig) (url.URL, KeyFunc, error) {
diff --git a/internal/jwt/jwt_test.go b/internal/jwt/jwt_test.go
index dcd1eff..83f5abc 100644
--- a/internal/jwt/jwt_test.go
+++ b/internal/jwt/jwt_test.go
@@ -1,6 +1,7 @@
 package jwt
 
 import (
+	"context"
 	"crypto/rand"
 	"crypto/rsa"
 	"encoding/json"
@@ -11,8 +12,10 @@ import (
 
 	"github.com/go-jose/go-jose/v4"
 	"github.com/go-jose/go-jose/v4/jwt"
+	"github.com/justinas/alice"
 
 	jwtmiddleware "github.com/auth0/go-jwt-middleware/v2"
+	"github.com/jamestelfer/chinmina-bridge/internal/audit"
 	"github.com/jamestelfer/chinmina-bridge/internal/config"
 	"github.com/jamestelfer/chinmina-bridge/internal/testhelpers"
 	"github.com/stretchr/testify/assert"
@@ -94,18 +97,6 @@ func TestMiddleware(t *testing.T) {
 			wantStatusCode: http.StatusUnauthorized,
 			wantBodyText:   "JWT is invalid",
 		},
-		{
-			name: "error handler",
-			claims: valid(jwt.Claims{
-				Audience: []string{"audience"},
-				Subject:  "subject",
-				Issuer:   "issuer",
-			}),
-			customClaims:   custom("that dog ain't gonna hunt", "test-pipeline"),
-			wantStatusCode: http.StatusUnauthorized,
-			wantBodyText:   "JWT is invalid",
-			options:        []jwtmiddleware.Option{jwtmiddleware.WithErrorHandler(LogErrorHandler())},
-		},
 	}
 
 	jwk := generateJWK(t)
@@ -121,9 +112,13 @@ func TestMiddleware(t *testing.T) {
 		t.Run(test.name, func(t *testing.T) {
 			testhelpers.SetupLogger(t)
 
+			ctx, _ := audit.Context(context.Background())
+
 			request, err := http.NewRequest(http.MethodGet, "", nil)
 			require.NoError(t, err)
 
+			request = request.WithContext(ctx)
+
 			audience := "an-actor-demands-an"
 			if len(test.claims.Audience) > 0 {
 				audience = test.claims.Audience[0]
@@ -139,32 +134,35 @@ func TestMiddleware(t *testing.T) {
 
 			responseRecorder := httptest.NewRecorder()
 
-			options := []jwtmiddleware.Option{
-				jwtmiddleware.WithErrorHandler(errorHandler(t)),
-			}
-
-			if len(test.options) > 0 {
-				options = append(options, test.options...)
-			}
-
-			mw, err := Middleware(cfg, options...)
+			authMiddleware, err := Middleware(cfg, test.options...)
 			require.NoError(t, err)
 
-			handler := mw(successHandler)
+			testMiddleware := alice.New(audit.Middleware(), authMiddleware)
+
+			handler := testMiddleware.Then(successHandler)
 			handler.ServeHTTP(responseRecorder, request)
 
 			assert.Equal(t, test.wantStatusCode, responseRecorder.Code)
 			assert.Contains(t, responseRecorder.Body.String(), test.wantBodyText)
-		})
-	}
-}
-
-func errorHandler(t *testing.T) jwtmiddleware.ErrorHandler {
-	return func(w http.ResponseWriter, r *http.Request, err error) {
-		t.Helper()
-		t.Logf("error handler called: %s, %v", err.Error(), err)
 
-		jwtmiddleware.DefaultErrorHandler(w, r, err)
+			// once the request has been processed, the audit log should have the necessary details
+			auditEntry := audit.Log(ctx)
+			if test.wantStatusCode == http.StatusOK {
+				assert.True(t, auditEntry.Authorized)
+				assert.Empty(t, auditEntry.Error)
+				assert.NotEmpty(t, auditEntry.AuthIssuer)
+				assert.Equal(t, "subject", auditEntry.AuthSubject)
+				assert.ElementsMatch(t, []string{"audience"}, auditEntry.AuthAudience)
+				assert.NotZero(t, auditEntry.AuthExpirySecs)
+			} else {
+				assert.False(t, auditEntry.Authorized)
+				assert.NotEmpty(t, auditEntry.Error)
+				assert.Empty(t, auditEntry.AuthIssuer)
+				assert.Empty(t, auditEntry.AuthSubject)
+				assert.Empty(t, auditEntry.AuthAudience)
+				assert.Zero(t, auditEntry.AuthExpirySecs)
+			}
+		})
 	}
 }
 
@@ -240,7 +238,7 @@ func setupTestServer(t *testing.T, jwk *jose.JSONWebKey) (server *httptest.Serve
 }
 
 func createRequestJWT(t *testing.T, jwk *jose.JSONWebKey, issuer string, claims ...any) string {
-	// t.Helper()
+	t.Helper()
 
 	key := jose.SigningKey{
 		Algorithm: jose.SignatureAlgorithm(jwk.Algorithm),
diff --git a/main.go b/main.go
index 0e5a741..9b1b71d 100644
--- a/main.go
+++ b/main.go
@@ -9,7 +9,6 @@ import (
 	"strings"
 	"time"
 
-	jwtmiddleware "github.com/auth0/go-jwt-middleware/v2"
 	"github.com/jamestelfer/chinmina-bridge/internal/audit"
 	"github.com/jamestelfer/chinmina-bridge/internal/buildkite"
 	"github.com/jamestelfer/chinmina-bridge/internal/config"
@@ -31,7 +30,7 @@ func configureServerRoutes(ctx context.Context, cfg config.Config) (http.Handler
 	// configure middleware
 	auditor := audit.Middleware()
 
-	authorizer, err := jwt.Middleware(cfg.Authorization, jwtmiddleware.WithErrorHandler(jwt.LogErrorHandler()))
+	authorizer, err := jwt.Middleware(cfg.Authorization)
 	if err != nil {
 		return nil, fmt.Errorf("authorizer configuration failed: %w", err)
 	}

From d0a7a7bcb94a3a63ed6bc12a81020465870f5976 Mon Sep 17 00:00:00 2001
From: James Telfer <792299+jamestelfer@users.noreply.github.com>
Date: Sun, 6 Oct 2024 01:14:12 +1000
Subject: [PATCH 7/8] fix: record token details to audit log

---
 internal/audit/log.go               |  9 ++++
 internal/vendor/auditvendor.go      | 30 +++++++++++
 internal/vendor/auditvendor_test.go | 82 +++++++++++++++++++++++++++++
 main.go                             |  2 +-
 4 files changed, 122 insertions(+), 1 deletion(-)
 create mode 100644 internal/vendor/auditvendor.go
 create mode 100644 internal/vendor/auditvendor_test.go

diff --git a/internal/audit/log.go b/internal/audit/log.go
index 5dd380b..b1640a9 100644
--- a/internal/audit/log.go
+++ b/internal/audit/log.go
@@ -41,6 +41,7 @@ type Entry struct {
 	Error            string
 	Repositories     []string
 	Permissions      []string
+	ExpirySecs       int64
 }
 
 // MarshalZerologObject implements zerolog.LogObjectMarshaler. This avoids the
@@ -65,6 +66,14 @@ func (e *Entry) MarshalZerologObject(event *zerolog.Event) {
 		event.Time("authExpiry", exp)
 		event.Dur("authExpiryRemaining", remaining)
 	}
+
+	if e.ExpirySecs > 0 {
+		exp := time.Unix(e.ExpirySecs, 0)
+		remaining := exp.Sub(now).Round(time.Millisecond)
+		event.Time("expiry", exp)
+		event.Dur("expiryRemaining", remaining)
+	}
+
 	if len(e.AuthAudience) > 0 {
 		event.Strs("authAudience", e.AuthAudience)
 	}
diff --git a/internal/vendor/auditvendor.go b/internal/vendor/auditvendor.go
new file mode 100644
index 0000000..9f7a22e
--- /dev/null
+++ b/internal/vendor/auditvendor.go
@@ -0,0 +1,30 @@
+package vendor
+
+import (
+	"context"
+	"fmt"
+
+	"github.com/jamestelfer/chinmina-bridge/internal/audit"
+	"github.com/jamestelfer/chinmina-bridge/internal/jwt"
+)
+
+// Auditor is a function that wraps a PipelineTokenVendor and records the result
+// of vending a token to the audit log.
+func Auditor(vendor PipelineTokenVendor) PipelineTokenVendor {
+	return func(ctx context.Context, claims jwt.BuildkiteClaims, repo string) (*PipelineRepositoryToken, error) {
+		token, err := vendor(ctx, claims, repo)
+
+		entry := audit.Log(ctx)
+		if err != nil {
+			entry.Error = fmt.Sprintf("vendor failure: %v", err)
+		} else if token == nil {
+			entry.Error = "repository mismatch, no token vended"
+		} else {
+			entry.Repositories = []string{token.RepositoryURL}
+			entry.Permissions = []string{"contents:read"}
+			entry.ExpirySecs = token.Expiry.Unix()
+		}
+
+		return token, err
+	}
+}
diff --git a/internal/vendor/auditvendor_test.go b/internal/vendor/auditvendor_test.go
new file mode 100644
index 0000000..e7f67a8
--- /dev/null
+++ b/internal/vendor/auditvendor_test.go
@@ -0,0 +1,82 @@
+package vendor_test
+
+import (
+	"context"
+	"errors"
+	"testing"
+	"time"
+
+	"github.com/jamestelfer/chinmina-bridge/internal/audit"
+	"github.com/jamestelfer/chinmina-bridge/internal/jwt"
+	"github.com/jamestelfer/chinmina-bridge/internal/vendor"
+	"github.com/stretchr/testify/assert"
+)
+
+func TestAuditor_Success(t *testing.T) {
+	successfulVendor := func(ctx context.Context, claims jwt.BuildkiteClaims, repo string) (*vendor.PipelineRepositoryToken, error) {
+		return &vendor.PipelineRepositoryToken{
+			RepositoryURL: "https://example.com/repo",
+			Expiry:        time.Now().Add(1 * time.Hour),
+		}, nil
+	}
+	auditedVendor := vendor.Auditor(successfulVendor)
+
+	ctx, _ := audit.Context(context.Background())
+	claims := jwt.BuildkiteClaims{}
+	repo := "example-repo"
+
+	token, err := auditedVendor(ctx, claims, repo)
+
+	assert.NoError(t, err)
+	assert.NotNil(t, token)
+	assert.Equal(t, "https://example.com/repo", token.RepositoryURL)
+
+	entry := audit.Log(ctx)
+	assert.Empty(t, entry.Error)
+	assert.Equal(t, []string{"https://example.com/repo"}, entry.Repositories)
+	assert.Equal(t, []string{"contents:read"}, entry.Permissions)
+	assert.NotZero(t, entry.ExpirySecs)
+}
+
+func TestAuditor_Mismatch(t *testing.T) {
+	successfulVendor := func(ctx context.Context, claims jwt.BuildkiteClaims, repo string) (*vendor.PipelineRepositoryToken, error) {
+		return nil, nil
+	}
+	auditedVendor := vendor.Auditor(successfulVendor)
+
+	ctx, _ := audit.Context(context.Background())
+	claims := jwt.BuildkiteClaims{}
+	repo := "example-repo"
+
+	token, err := auditedVendor(ctx, claims, repo)
+
+	assert.NoError(t, err)
+	assert.Nil(t, token)
+
+	entry := audit.Log(ctx)
+	assert.Equal(t, "repository mismatch, no token vended", entry.Error)
+	assert.Empty(t, entry.Repositories)
+	assert.Empty(t, entry.Permissions)
+	assert.Zero(t, entry.ExpirySecs)
+}
+
+func TestAuditor_Failure(t *testing.T) {
+	failingVendor := func(ctx context.Context, claims jwt.BuildkiteClaims, repo string) (*vendor.PipelineRepositoryToken, error) {
+		return nil, errors.New("vendor error")
+	}
+	auditedVendor := vendor.Auditor(failingVendor)
+
+	ctx, _ := audit.Context(context.Background())
+	claims := jwt.BuildkiteClaims{}
+	repo := "example-repo"
+
+	token, err := auditedVendor(ctx, claims, repo)
+	assert.Error(t, err)
+	assert.Nil(t, token)
+
+	entry := audit.Log(ctx)
+	assert.Equal(t, "vendor failure: vendor error", entry.Error)
+	assert.Empty(t, entry.Repositories)
+	assert.Empty(t, entry.Permissions)
+	assert.Zero(t, entry.ExpirySecs)
+}
diff --git a/main.go b/main.go
index 9b1b71d..8e71e5c 100644
--- a/main.go
+++ b/main.go
@@ -59,7 +59,7 @@ func configureServerRoutes(ctx context.Context, cfg config.Config) (http.Handler
 		return nil, fmt.Errorf("vendor cache configuration failed: %w", err)
 	}
 
-	tokenVendor := vendorCache(vendor.New(bk.RepositoryLookup, gh.CreateAccessToken))
+	tokenVendor := vendor.Auditor(vendorCache(vendor.New(bk.RepositoryLookup, gh.CreateAccessToken)))
 
 	mux.Handle("POST /token", authorizedRouteMiddleware.Then(handlePostToken(tokenVendor)))
 	mux.Handle("POST /git-credentials", authorizedRouteMiddleware.Then(handlePostGitCredentials(tokenVendor)))

From 36a3fd17a871e54b5686990e89394c8d4162cbb3 Mon Sep 17 00:00:00 2001
From: James Telfer <792299+jamestelfer@users.noreply.github.com>
Date: Sun, 6 Oct 2024 18:59:11 +1100
Subject: [PATCH 8/8] docs: add basic docs for audit functionality.

---
 README.md             |  5 ++++
 docs/observability.md | 58 +++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 63 insertions(+)
 create mode 100644 docs/observability.md

diff --git a/README.md b/README.md
index b26ff9b..e058793 100644
--- a/README.md
+++ b/README.md
@@ -145,6 +145,11 @@ To understand what's right for your organization, consider:
   - it's OK if your organization controls the creation/configuration of
     pipelines: this restricts the opportunity to misconfigure a pipeline.
 
+## Operations
+
+See the [observability documentation](./docs/observability.md) for more details
+on the information provided by the system when running.
+
 ## Configuration
 
 Requirements:
diff --git a/docs/observability.md b/docs/observability.md
new file mode 100644
index 0000000..d9ad466
--- /dev/null
+++ b/docs/observability.md
@@ -0,0 +1,58 @@
+# Observability
+
+The system produces traces and metrics via Open Telemetry, and logs via zerolog.
+There are minimal informational logs, as well as per-request audit logs that are
+written to the process's `stdout`.
+
+## Audit logs
+
+Audit logs provide a level of non-repudiation for the system. These logs are
+written to the container's stdout, and cannot be disabled.
+
+> [!TIP]
+> Requests to non-existent routes do not form part of the audit log. Access logs
+> or firewall logs are better sources for this information.
+
+Each authenticated endpoint (both `/token` and `/git-credentials`) will record
+details about the request, the authorization process, and the GitHub token
+created. If an error occurs, this is also written out.
+
+At a technical level, logs are written to stdout using zerolog at the "audit"
+log level. Initial data is collected by request middleware and the partial entry
+is then accessible via the context. The context entry is further enriched with
+details by other components, including both the JWT middleware and the vendor.
+such that the log is fully completed by the end of the request.
+
+> [!IMPORTANT]
+> A panic in the request chain will still result in the audit log being written,
+> and the panic details will also be included.
+
+### Audit log fields
+
+1. Request data
+    - `Method`: the request method. This will currently be `GET` for all standard requests.
+    - `Path`: the requested path.
+    - `Status` is the HTTP response status of the request
+    - `SourceIP` is the client IP of the requestor
+    - `UserAgent` is the user agent reported by the client
+    - `Error` is the error produced by the request. This may come from internal
+      errors or panics, as well as the JWT validation and token creation
+      components.
+2. Authorization data
+    - `Authorized` is a boolean that is `true` when the request JWT is
+      successfully authorized by the service.
+    - `AuthSubject` is the contents of the `sub` field from the JWT
+    - `AuthIssuer` is the JWT `iss` field
+    - `AuthAudience` is the (possibly multiple) reported `aud` field values from
+      the JWT
+    - `AuthExpirySecs` is the JWT expiry time in seconds after the Unix epoch
+3. Token data
+    - `Repositories` is the set of repositories that the token allows access to
+    - `Permissions` is the set of GitHub token permissions assigned to the token
+    - `ExpirySecs` is the GitHub token expiry time in seconds after the Unix
+      epoch
+
+## Open Telemetry
+
+This section is a stub. For now, refer to the [`.envrc`](../.envrc) file for
+details of all Open Telemetry related configuration that's currently possible.