From 068718fe069463e5ec5b7ce9dddc2c78e879a266 Mon Sep 17 00:00:00 2001 From: Juan Agudelo Date: Mon, 3 Aug 2026 09:36:15 -0500 Subject: [PATCH] fix: Enhance audit logging middleware to capture tenant information and response status codes - Updated AuditActionLoggingMiddleware to read tenant from HttpContext.Items for accurate logging. - Modified IAuditEventRecorder and AuditEventRecorder to accept tenant configuration. - Adjusted middleware registration order in Program.cs to ensure correct status code logging. - Improved documentation to clarify middleware behavior and tenant resolution. --- .../Audit/AuditActionLoggingMiddleware.cs | 27 +++++- .../Audit/AuditEventRecorder.cs | 9 +- .../Audit/IAuditEventRecorder.cs | 5 +- .../TenantIdentificationMiddleware.cs | 10 +++ Application/EdFi.Ods.AdminApi/Program.cs | 8 +- docs/audit-logging.md | 88 +++++++++++++++++-- docs/design/2026-07-28-audit-trail-logging.md | 40 +++++++-- 7 files changed, 165 insertions(+), 22 deletions(-) diff --git a/Application/EdFi.Ods.AdminApi.Common/Infrastructure/Audit/AuditActionLoggingMiddleware.cs b/Application/EdFi.Ods.AdminApi.Common/Infrastructure/Audit/AuditActionLoggingMiddleware.cs index 0c441c294..a54100dd0 100644 --- a/Application/EdFi.Ods.AdminApi.Common/Infrastructure/Audit/AuditActionLoggingMiddleware.cs +++ b/Application/EdFi.Ods.AdminApi.Common/Infrastructure/Audit/AuditActionLoggingMiddleware.cs @@ -3,6 +3,7 @@ // The Ed-Fi Alliance licenses this file to you under the Apache License, Version 2.0. // See the LICENSE and NOTICES files in the project root for more information. +using EdFi.Ods.AdminApi.Common.Infrastructure.MultiTenancy; using Microsoft.AspNetCore.Http; namespace EdFi.Ods.AdminApi.Common.Infrastructure.Audit; @@ -22,7 +23,6 @@ public async Task InvokeAsync(HttpContext context) return; } - var clientId = context.User.FindFirst("client_id")?.Value; var sourceIpAddress = context.Connection.RemoteIpAddress?.ToString(); var httpVerb = context.Request.Method; var httpUrl = context.Request.Path.Value; @@ -33,16 +33,35 @@ public async Task InvokeAsync(HttpContext context) } catch { + // Authentication and tenant resolution both run downstream of this middleware, + // so context.User/context.Items are only populated by the time next() has run + // (or thrown) - never before. The tenant must be read from context.Items rather + // than the AsyncLocal-backed tenant context provider, since that provider's + // value reverts once TenantResolverMiddleware's own frame returns (see + // TenantResolverMiddleware.TenantConfigurationItemsKey). recorder.Record( AuditEventType.Action, - clientId, + context.User.FindFirst("client_id")?.Value, sourceIpAddress, httpVerb, httpUrl, - StatusCodes.Status500InternalServerError); + StatusCodes.Status500InternalServerError, + GetTenant(context)); throw; } - recorder.Record(AuditEventType.Action, clientId, sourceIpAddress, httpVerb, httpUrl, context.Response.StatusCode); + recorder.Record( + AuditEventType.Action, + context.User.FindFirst("client_id")?.Value, + sourceIpAddress, + httpVerb, + httpUrl, + context.Response.StatusCode, + GetTenant(context)); } + + private static TenantConfiguration? GetTenant(HttpContext context) => + context.Items.TryGetValue(TenantResolverMiddleware.TenantConfigurationItemsKey, out var tenant) + ? tenant as TenantConfiguration + : null; } diff --git a/Application/EdFi.Ods.AdminApi.Common/Infrastructure/Audit/AuditEventRecorder.cs b/Application/EdFi.Ods.AdminApi.Common/Infrastructure/Audit/AuditEventRecorder.cs index c09187aed..81a67c2ec 100644 --- a/Application/EdFi.Ods.AdminApi.Common/Infrastructure/Audit/AuditEventRecorder.cs +++ b/Application/EdFi.Ods.AdminApi.Common/Infrastructure/Audit/AuditEventRecorder.cs @@ -29,7 +29,8 @@ public void Record( string? sourceIpAddress, string? httpVerb, string? httpUrl, - int? statusCode) + int? statusCode, + TenantConfiguration? tenant = null) { if (!settings.Value.Enabled) { @@ -38,7 +39,11 @@ public void Record( try { - var tenant = tenantContextProvider.Get(); + // The AsyncLocal-backed tenantContextProvider reverts for a caller once the + // middleware that called Set() (TenantResolverMiddleware) has returned, so a + // caller positioned outside it (AuditActionLoggingMiddleware, recording after + // next() completes) must resolve the tenant itself and pass it in explicitly. + tenant ??= tenantContextProvider.Get(); var adminConnectionString = !string.IsNullOrEmpty(tenant?.AdminConnectionString) ? tenant.AdminConnectionString : configuration.GetConnectionStringByName("EdFi_Admin"); diff --git a/Application/EdFi.Ods.AdminApi.Common/Infrastructure/Audit/IAuditEventRecorder.cs b/Application/EdFi.Ods.AdminApi.Common/Infrastructure/Audit/IAuditEventRecorder.cs index 5f8aac2d4..e7b7360cd 100644 --- a/Application/EdFi.Ods.AdminApi.Common/Infrastructure/Audit/IAuditEventRecorder.cs +++ b/Application/EdFi.Ods.AdminApi.Common/Infrastructure/Audit/IAuditEventRecorder.cs @@ -3,6 +3,8 @@ // The Ed-Fi Alliance licenses this file to you under the Apache License, Version 2.0. // See the LICENSE and NOTICES files in the project root for more information. +using EdFi.Ods.AdminApi.Common.Infrastructure.MultiTenancy; + namespace EdFi.Ods.AdminApi.Common.Infrastructure.Audit; public interface IAuditEventRecorder @@ -13,5 +15,6 @@ void Record( string? sourceIpAddress, string? httpVerb, string? httpUrl, - int? statusCode); + int? statusCode, + TenantConfiguration? tenant = null); } diff --git a/Application/EdFi.Ods.AdminApi.Common/Infrastructure/MultiTenancy/TenantIdentificationMiddleware.cs b/Application/EdFi.Ods.AdminApi.Common/Infrastructure/MultiTenancy/TenantIdentificationMiddleware.cs index ee4845648..c4f9e70c8 100644 --- a/Application/EdFi.Ods.AdminApi.Common/Infrastructure/MultiTenancy/TenantIdentificationMiddleware.cs +++ b/Application/EdFi.Ods.AdminApi.Common/Infrastructure/MultiTenancy/TenantIdentificationMiddleware.cs @@ -20,6 +20,14 @@ public partial class TenantResolverMiddleware( IOptions options, IOptions swaggerOptions) : IMiddleware { + // AsyncLocal-backed context (tenantConfigurationContextProvider) reverts for a caller + // once this middleware's own InvokeAsync frame returns, so callers positioned outside + // it (e.g. AuditActionLoggingMiddleware, which must run outermost to see the final + // response status) cannot read it after calling next(). HttpContext.Items instead + // lives on the HttpContext instance itself, unaffected by that unwind, so it's mirrored + // here for any such caller. + public const string TenantConfigurationItemsKey = "TenantConfiguration"; + private readonly ITenantConfigurationProvider _tenantConfigurationProvider = tenantConfigurationProvider; private readonly IContextProvider _tenantConfigurationContextProvider = tenantConfigurationContextProvider; private readonly IOptions _options = options; @@ -47,6 +55,7 @@ public async Task InvokeAsync(HttpContext context, RequestDelegate next) if (_tenantConfigurationProvider.Get().TryGetValue(tenantIdentifier!, out var tenantConfiguration)) { _tenantConfigurationContextProvider.Set(tenantConfiguration); + context.Items[TenantConfigurationItemsKey] = tenantConfiguration; } else { @@ -67,6 +76,7 @@ public async Task InvokeAsync(HttpContext context, RequestDelegate next) _tenantConfigurationProvider.Get().TryGetValue(defaultTenant, out var tenantConfiguration)) { _tenantConfigurationContextProvider.Set(tenantConfiguration); + context.Items[TenantConfigurationItemsKey] = tenantConfiguration; } else { diff --git a/Application/EdFi.Ods.AdminApi/Program.cs b/Application/EdFi.Ods.AdminApi/Program.cs index cdbba3ea4..3e14e8fc8 100644 --- a/Application/EdFi.Ods.AdminApi/Program.cs +++ b/Application/EdFi.Ods.AdminApi/Program.cs @@ -52,7 +52,12 @@ AdminApiVersions.Initialize(app); -//The ordering here is meaningful: Logging -> Routing -> Auth -> Endpoints +//The ordering here is meaningful: Audit -> Logging -> Routing -> Auth -> Endpoints +//AuditActionLoggingMiddleware must be outermost so it observes the final response status +//code after RequestLoggingMiddleware/V3RequestErrorMiddleware has translated any exception +//into its real HTTP status (they catch and never rethrow), rather than guessing 500 itself. +app.UseMiddleware(); + if (adminApiMode == AdminApiMode.V3) { app.UseMiddleware(); @@ -71,7 +76,6 @@ app.UseAuthentication(); app.UseRateLimiter(); app.UseAuthorization(); -app.UseMiddleware(); app.MapFeatureEndpoints(); app.MapControllers(); diff --git a/docs/audit-logging.md b/docs/audit-logging.md index eb06dd3a7..fbe6da169 100644 --- a/docs/audit-logging.md +++ b/docs/audit-logging.md @@ -42,7 +42,7 @@ Three event types are recorded, corresponding to the `AuditEventType` enum |---|---| | `AuthenticationSuccess` | A client successfully obtains a token at `/connect/token` (OpenIddict's `ApplyTokenResponseContext`, handled by `SecurityExtensions.DefaultTokenResponseHandler` — recorded when the token response has no `Error`). | | `AuthenticationFailure` | (a) A token request at `/connect/token` fails (invalid client, invalid grant, invalid scope, etc. — same handler as above, recorded when the token response has an `Error`); or (b) any other request anywhere in the API is rejected with a 401 because the bearer token is missing, malformed, or expired (`JwtBearerEvents.OnChallenge` in `SecurityExtensions.cs`). | -| `Action` | Every request whose HTTP method is `POST`, `PUT`, `PATCH`, or `DELETE`, regardless of outcome. `GET` requests are never logged as action events. Captured by `AuditActionLoggingMiddleware` (`Application/EdFi.Ods.AdminApi.Common/Infrastructure/Audit/AuditActionLoggingMiddleware.cs`), registered in the request pipeline in `Program.cs` (`app.UseMiddleware();`). | +| `Action` | Every request whose HTTP method is `POST`, `PUT`, `PATCH`, or `DELETE`, regardless of outcome (2xx, 4xx — including 401/403 rejections — or 5xx). `GET` requests are never logged as action events. Captured by `AuditActionLoggingMiddleware` (`Application/EdFi.Ods.AdminApi.Common/Infrastructure/Audit/AuditActionLoggingMiddleware.cs`), registered as the **outermost** middleware in the request pipeline in `Program.cs` (`app.UseMiddleware();`, before `RequestLoggingMiddleware`/`V3RequestErrorMiddleware`, `UseAuthentication`, and `UseAuthorization`). | Note: `JwtBearerEvents.OnAuthenticationFailed` and `OnTokenValidated` also exist in `SecurityExtensions.cs` for logging/diagnostics, but only @@ -66,7 +66,7 @@ entity in `Application/EdFi.Ods.AdminApi.Common/Infrastructure/Audit/AuditLog.cs | `SourceIpAddress` | `NVARCHAR(45)` | Yes | Populated for all three event types from `HttpContext.Connection.RemoteIpAddress`. | | `HttpVerb` | `NVARCHAR(10)` | Yes | Populated only for `Action` events (e.g. `POST`, `PUT`, `PATCH`, `DELETE`). Always `null` for both authentication event paths (`/connect/token` and the `OnChallenge` 401 path). | | `HttpUrl` | `NVARCHAR(2048)` | Yes | Populated only for `Action` events (the request path). Always `null` for authentication events. | -| `StatusCode` | `INT` | Yes | Populated for `Action` events (the actual response status code, or `500` if the request pipeline threw an exception before a status code was set) and for the `OnChallenge` 401 path (always `401`). Always `null` for the `/connect/token` `ApplyTokenResponseContext` handler, since that handler runs before the final HTTP status is finalized. | +| `StatusCode` | `INT` | Yes | Populated for `Action` events (the actual response status code — including 401/403/404/etc. produced by downstream error-handling middleware, or `500` as a last-resort fallback if an exception escapes the entire pipeline unhandled) and for the `OnChallenge` 401 path (always `401`). Always `null` for the `/connect/token` `ApplyTokenResponseContext` handler, since that handler runs before the final HTTP status is finalized. | Indexes exist on `Timestamp` and `ClientId` to support the most common lookups (recent events, and events for a given client). @@ -130,6 +130,12 @@ the same per-tenant DbUp migration process used for the rest of the schema. current tenant context before enqueueing an event, so events are always written to the requesting tenant's own database. +For `Action` events specifically, the tenant is *not* read from the +`AsyncLocal`-backed tenant context provider that everything else in the app +uses — see "Why `Action` events resolve tenant from `HttpContext.Items`, +not the ambient tenant context" below for why, and how it's actually +resolved. + ## No HTTP exposure There is no controller, minimal API route, or other HTTP endpoint that @@ -149,9 +155,75 @@ addressed in a future iteration: * Any admin UI, reporting dashboard, export tooling, or query API for browsing audit data. * Logging of read-only (`GET`) requests as action events. -* Authorization-denied (403) mutation attempts. `AuditActionLoggingMiddleware` - is registered after `app.UseAuthorization()`, so requests that ASP.NET - Core's authorization middleware short-circuits with a 403 never reach it - and are not audited. Only 401 (authentication) rejections and mutation - attempts that complete the pipeline (2xx, 4xx other than 401/403, 5xx) are - currently captured. Capturing 403s is deferred to a future iteration. + +## Middleware ordering: why `AuditActionLoggingMiddleware` runs first + +`AuditActionLoggingMiddleware` is registered before `RequestLoggingMiddleware` +(V2) / `V3RequestErrorMiddleware` (V3), and before `UseAuthentication` / +`UseAuthorization`, so that it wraps the entire rest of the pipeline. This +matters for two reasons: + +1. **Exception-driven status codes.** `RequestLoggingMiddleware` and + `V3RequestErrorMiddleware` catch exceptions (`ValidationException` → 400, + `INotFoundException` → 404, etc.) and translate them into the real HTTP + status without rethrowing. If the audit middleware sat *inside* that + translation layer (as it originally did, registered after + `UseAuthorization`), its own exception handler would run first and + hardcode `StatusCode = 500` for every exception — before the real status + was ever known — producing an audit row that didn't match what the client + actually received. Running outermost means `next()` only returns to the + audit middleware after the real status has been finalized, so the + recorded `StatusCode` always matches the response the client saw. +2. **Authorization-denied (401/403) requests.** ASP.NET Core's authorization + middleware short-circuits a denied request (sets 401/403 and returns + without calling further into the pipeline) rather than throwing. With the + audit middleware outermost, that short-circuit still unwinds back through + it normally, so these denials are now captured as `Action` rows too — + previously they never reached the audit middleware at all. + +One consequence: `AuditActionLoggingMiddleware` reads the `client_id` claim +from `context.User` *after* `next()` returns/throws, not before — since +authentication now runs downstream of it (inside `next()`), `context.User` +isn't populated yet at the point the middleware is entered. + +## Why `Action` events resolve tenant from `HttpContext.Items`, not the ambient tenant context + +The rest of the app resolves the current tenant via +`IContextProvider` +(`Application/EdFi.Ods.AdminApi.Common/Infrastructure/Context/ContextProvider.cs`), +backed by `AsyncLocalContextStorage` +(`Application/EdFi.Ods.AdminApi.Common/Infrastructure/Context/ContextStorage.cs`). +`TenantResolverMiddleware` calls `Set()` on it, and every scoped service +resolved further down the pipeline (as a descendant call) sees that value +correctly — this is how `IUsersContext`/`ISecurityContext` pick the right +per-tenant connection string today. + +`AuditActionLoggingMiddleware` cannot use the same mechanism for `Action` +events, because of how it's positioned (see the "Middleware ordering" +section above): it reads state only *after* `next()` has fully returned — +i.e. after `TenantResolverMiddleware.InvokeAsync` itself has already +returned. `AsyncLocal` values only flow *forward* into methods called from +where they're set; once the setting method's own call frame returns, the +value reverts for its caller. So by the time `AuditActionLoggingMiddleware` +calls `recorder.Record(...)`, `tenantContextProvider.Get()` is back to +whatever it was *before* `TenantResolverMiddleware` ran — `null` for a normal +request — and `AuditEventRecorder` would silently fall back to the +non-tenant-specific `EdFi_Admin` connection string. In multitenant mode that +fallback isn't a valid connection string for the active tenant's DB engine, +so every `Action` event write failed, retried twice, and fell back to the +rate-limited text log — meaning **no `Action` rows were ever persisted**, +while `AuthenticationSuccess`/`AuthenticationFailure` rows (recorded from +inside the OpenIddict/JWT pipeline, still nested within +`TenantResolverMiddleware`'s call frame) were unaffected. + +The fix: `TenantResolverMiddleware` also stores the resolved tenant in +`context.Items[TenantResolverMiddleware.TenantConfigurationItemsKey]`. +Unlike the `AsyncLocal` context, `HttpContext.Items` lives on the +`HttpContext` instance itself — the same instance passed explicitly to every +middleware in the chain — so it survives regardless of which call frames +have returned. `AuditActionLoggingMiddleware` reads it from there and passes +it explicitly into `IAuditEventRecorder.Record(..., tenant)`, which prefers +the explicit value over the `AsyncLocal` lookup when one is supplied. The +authentication-event call sites in `SecurityExtensions.cs` are unaffected — +they still resolve tenant via the `AsyncLocal` provider, correctly, since +they run as descendants of `TenantResolverMiddleware`, not after it returns. diff --git a/docs/design/2026-07-28-audit-trail-logging.md b/docs/design/2026-07-28-audit-trail-logging.md index f5f8d2c80..3438e52bb 100644 --- a/docs/design/2026-07-28-audit-trail-logging.md +++ b/docs/design/2026-07-28-audit-trail-logging.md @@ -64,11 +64,41 @@ each project, following the existing 5-digit-sequence naming convention. ## Capture Points **Action events** (POST/PUT/PATCH/DELETE only — GETs excluded per scope): -new lightweight middleware, registered alongside the existing -`RequestLoggingMiddleware` (V2) / `V3RequestErrorMiddleware` (V3). It -captures client_id (from the authenticated principal), timestamp, verb, URL, -and source IP up front, then after `next()` completes, adds the response -status code and enqueues the event. +new lightweight middleware, registered as the **outermost** middleware in the +pipeline — before `RequestLoggingMiddleware` (V2) / `V3RequestErrorMiddleware` +(V3), and before `UseAuthentication`/`UseAuthorization`. It captures timestamp, +verb, URL, and source IP up front; `client_id` and the response status code +are both read only after `next()` returns or throws, since authentication and +status-code finalization both happen downstream of this middleware. + +This ordering is deliberate, not incidental: `RequestLoggingMiddleware`/ +`V3RequestErrorMiddleware` catch exceptions and translate them into the real +HTTP status (e.g. `ValidationException` → 400, `INotFoundException` → 404) +without rethrowing. If the audit middleware sat inside that translation layer, +its own exception handler would fire first and have to guess a status code +before the real one was known. Sitting outermost means it always observes the +final, already-translated status — including 401/403 authorization denials, +which ASP.NET Core's authorization middleware short-circuits (sets the status +and returns without calling further into the pipeline, rather than throwing). + +**Tenant resolution caveat from the same ordering change:** the rest of the +app resolves the current tenant via an `AsyncLocal`-backed +`IContextProvider`, set by `TenantResolverMiddleware`. +`AsyncLocal` values only flow forward into methods called from where they're +set — once `TenantResolverMiddleware.InvokeAsync` itself returns, the value +reverts for its caller. Because the audit middleware now reads state only +*after* `next()` has fully returned (i.e. after `TenantResolverMiddleware` +has already returned), it cannot use that same lookup — doing so silently +resolved to the non-tenant-specific default connection string in multitenant +mode, which isn't a valid connection string for the active tenant's DB +engine, and every `Action` write failed. Fix: `TenantResolverMiddleware` also +stores the resolved tenant in `context.Items[...TenantConfigurationItemsKey]` +— `HttpContext.Items` lives on the `HttpContext` instance itself, unaffected +by which call frames have returned — and the audit middleware reads it from +there instead, passing it explicitly into `IAuditEventRecorder.Record(..., +tenant)`. The authentication-event hooks in `SecurityExtensions.cs` are +unaffected, since they run as descendants of `TenantResolverMiddleware` +(before it returns) and keep using the `AsyncLocal` lookup unchanged. **Authentication events**, hooked in the shared `Application/EdFi.Ods.AdminApi/Infrastructure/Security/SecurityExtensions.cs`: