fix: record token details to audit log

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

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
+	}
+}

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)
+}

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