6ae0fea558
Async cancellation hygiene, fire-and-forget observability, retry/shutdown semantics, and audit-row coverage across 9 modules. Highlights: Cancellation & lifecycle: - AuditLog-006: SqliteAuditWriter.Dispose hops to thread pool, escaping the captured SyncContext that risked sync-over-async deadlock. - AuditLog-010: SiteAuditTelemetryActor owns a private lifecycle CTS, threaded through drain paths instead of CancellationToken.None. - Comm-019: CentralCommunicationActor adds lifecycle CTS for repo calls. - Host-019: Migration StartupRetry forwards ApplicationStopping so SIGTERM during the bounded-retry window aborts cleanly. Cursor / retry / counter correctness: - AuditLog-004: SiteAuditReconciliationActor's cursor now holds at `since` when any row's idempotent insert is still being retried (per-EventId retry counter, MaxPermanentInsertAttempts=5 escape valve with LogCritical abandon). No more silent abandonment of permanently-failing rows. - ConfigDB-019: Dropped the catch-and-continue on EnsureLookaheadAsync's SPLIT loop — by class-doc construction the catch could only mask real failures and let the next iteration create permanent partition holes. - HM-017/018: HealthReportSender + CentralHealthReportLoop snapshot per-interval counters before sending, restore via new ISiteHealthCollector.AddIntervalCounters on transport failure so counts aren't silently lost. Fire-and-forget / shutdown waits: - InboundAPI-018: AuditWriteMiddleware observes faulted audit-write tasks via OnlyOnFaulted continuation (Warning log; response unchanged). - SnF-024: StoreAndForwardService.StopAsync awaits in-flight retry sweep with a bounded SweepShutdownWaitTimeout (10s). Leak / refactor: - Comm-021: SiteStreamGrpcServer.SubscribeInstance wraps Subscribe in its own try/catch so a throw doesn't leak the relay actor or _activeStreams entry. - Comm-022: VERIFIED already-closed by Comm-016's dead-code purge. - CLI-017: BundleCommands' three subcommands delegate to ExecuteCommandAsync (auth-failure exit-code contract unified). Defensive / validation: - CLI-021: CliConfig.Load wraps file-read/JSON parse so malformed config prints a warning and returns defaults instead of crashing the CLI. - Host-022: ParseLevel emits stderr one-shot warning for unrecognised MinimumLevel instead of silently coercing to Information. - ESG-019: ExternalSystemClient sets HttpClient.Timeout=Infinite so the per-call CTS is the sole timeout source (was clipped to 100s by .NET). - Security-020: New SecurityOptionsValidator (IValidateOptions) rejects empty LdapServer/LdapSearchBase with ValidateOnStart. - DM-019: Lifecycle command timeouts now emit DisableTimedOut/EnableTimedOut/ DeleteTimedOut audit entries (mirrors DeployFailed pattern). Plus reconciled stale per-module Open-findings counters that had drifted from prior sessions. 20+ new regression tests across 11 test projects; build clean; affected suites all green. README regenerated: 75 open (was 93).
804 lines
30 KiB
C#
804 lines
30 KiB
C#
using System.Net;
|
|
using System.Text;
|
|
using System.Text.Json;
|
|
using Microsoft.AspNetCore.Http;
|
|
using Microsoft.AspNetCore.Routing;
|
|
using Microsoft.Extensions.Logging.Abstractions;
|
|
using Microsoft.Extensions.Options;
|
|
using ScadaLink.AuditLog.Configuration;
|
|
using ScadaLink.Commons.Entities.Audit;
|
|
using ScadaLink.Commons.Interfaces.Services;
|
|
using ScadaLink.Commons.Types.Enums;
|
|
using ScadaLink.InboundAPI.Middleware;
|
|
|
|
namespace ScadaLink.InboundAPI.Tests.Middleware;
|
|
|
|
/// <summary>
|
|
/// M4 Bundle D (D1) — verifies <see cref="AuditWriteMiddleware"/> emits exactly one
|
|
/// <see cref="AuditChannel.ApiInbound"/> row per request via
|
|
/// <see cref="ICentralAuditWriter"/> covering all outcome shapes:
|
|
/// success (InboundRequest/Delivered), client/server error (InboundRequest/Failed),
|
|
/// and unauthenticated (InboundAuthFailure/Failed). Audit-write failures must NEVER
|
|
/// alter the HTTP response (alog.md §13).
|
|
/// </summary>
|
|
public class AuditWriteMiddlewareTests
|
|
{
|
|
/// <summary>
|
|
/// Test-only recording <see cref="ICentralAuditWriter"/>. Captures every
|
|
/// <see cref="AuditEvent"/> the middleware emits so each test can assert on
|
|
/// the shape of the row produced for one request.
|
|
/// </summary>
|
|
private sealed class RecordingAuditWriter : ICentralAuditWriter
|
|
{
|
|
public List<AuditEvent> Events { get; } = new();
|
|
public Func<AuditEvent, Task>? OnWrite { get; set; }
|
|
|
|
public Task WriteAsync(AuditEvent evt, CancellationToken ct = default)
|
|
{
|
|
lock (Events)
|
|
{
|
|
Events.Add(evt);
|
|
}
|
|
|
|
return OnWrite?.Invoke(evt) ?? Task.CompletedTask;
|
|
}
|
|
}
|
|
|
|
/// <summary>
|
|
/// Builds an <see cref="HttpContext"/> primed for the inbound API route shape:
|
|
/// POST /api/{methodName}, optional JSON body, RemoteIpAddress + User-Agent.
|
|
/// The route value resolver mirrors the production endpoint mapping so the
|
|
/// middleware can pull the method name without owning routing itself.
|
|
/// </summary>
|
|
private static DefaultHttpContext BuildContext(
|
|
string methodName = "echo",
|
|
string? body = null,
|
|
string? userAgent = "test-agent/1.0",
|
|
IPAddress? remoteIp = null)
|
|
{
|
|
var ctx = new DefaultHttpContext();
|
|
ctx.Request.Method = "POST";
|
|
ctx.Request.Path = $"/api/{methodName}";
|
|
ctx.Request.RouteValues["methodName"] = methodName;
|
|
|
|
if (body is not null)
|
|
{
|
|
var bytes = Encoding.UTF8.GetBytes(body);
|
|
ctx.Request.Body = new MemoryStream(bytes);
|
|
ctx.Request.ContentLength = bytes.Length;
|
|
ctx.Request.ContentType = "application/json";
|
|
}
|
|
|
|
if (userAgent is not null)
|
|
{
|
|
ctx.Request.Headers["User-Agent"] = userAgent;
|
|
}
|
|
|
|
ctx.Connection.RemoteIpAddress = remoteIp ?? IPAddress.Parse("10.0.0.5");
|
|
|
|
return ctx;
|
|
}
|
|
|
|
private static AuditWriteMiddleware CreateMiddleware(
|
|
RequestDelegate next,
|
|
ICentralAuditWriter writer,
|
|
AuditLogOptions? options = null) =>
|
|
new(
|
|
next,
|
|
writer,
|
|
NullLogger<AuditWriteMiddleware>.Instance,
|
|
new StaticAuditLogOptionsMonitor(options ?? new AuditLogOptions()));
|
|
|
|
/// <summary>
|
|
/// File-local <see cref="IOptionsMonitor{TOptions}"/> test double — returns the
|
|
/// same snapshot on every read, no change-token plumbing required. Mirrors the
|
|
/// <c>StaticMonitor</c> pattern in
|
|
/// <c>tests/ScadaLink.AuditLog.Tests/Payload/InboundChannelCapTests.cs</c>.
|
|
/// </summary>
|
|
private sealed class StaticAuditLogOptionsMonitor : IOptionsMonitor<AuditLogOptions>
|
|
{
|
|
private readonly AuditLogOptions _value;
|
|
|
|
public StaticAuditLogOptionsMonitor(AuditLogOptions value) => _value = value;
|
|
|
|
public AuditLogOptions CurrentValue => _value;
|
|
|
|
public AuditLogOptions Get(string? name) => _value;
|
|
|
|
public IDisposable? OnChange(Action<AuditLogOptions, string?> listener) => null;
|
|
}
|
|
|
|
// ---------------------------------------------------------------------
|
|
// 1. Happy path — InboundRequest/Delivered/HttpStatus 200
|
|
// ---------------------------------------------------------------------
|
|
|
|
[Fact]
|
|
public async Task Pipeline_Success_EmitsOneEvent_KindInboundRequest_StatusDelivered_HttpStatus200()
|
|
{
|
|
var writer = new RecordingAuditWriter();
|
|
var ctx = BuildContext();
|
|
var mw = CreateMiddleware(_ =>
|
|
{
|
|
ctx.Response.StatusCode = 200;
|
|
return Task.CompletedTask;
|
|
}, writer);
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
var evt = Assert.Single(writer.Events);
|
|
Assert.Equal(AuditChannel.ApiInbound, evt.Channel);
|
|
Assert.Equal(AuditKind.InboundRequest, evt.Kind);
|
|
Assert.Equal(AuditStatus.Delivered, evt.Status);
|
|
Assert.Equal(200, evt.HttpStatus);
|
|
// Central direct-write — no ForwardState (alog.md §6).
|
|
Assert.Null(evt.ForwardState);
|
|
Assert.NotEqual(Guid.Empty, evt.EventId);
|
|
Assert.Equal("echo", evt.Target);
|
|
}
|
|
|
|
// ---------------------------------------------------------------------
|
|
// 2. 400 — script/validation failure path
|
|
// ---------------------------------------------------------------------
|
|
|
|
[Fact]
|
|
public async Task Pipeline_400_EmitsEvent_Status_Failed_HttpStatus400()
|
|
{
|
|
var writer = new RecordingAuditWriter();
|
|
var ctx = BuildContext();
|
|
var mw = CreateMiddleware(_ =>
|
|
{
|
|
ctx.Response.StatusCode = 400;
|
|
return Task.CompletedTask;
|
|
}, writer);
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
var evt = Assert.Single(writer.Events);
|
|
// A 400 is a request the auth succeeded for — still InboundRequest, not
|
|
// InboundAuthFailure. Only 401/403 maps to the auth-failure kind.
|
|
Assert.Equal(AuditKind.InboundRequest, evt.Kind);
|
|
Assert.Equal(AuditStatus.Failed, evt.Status);
|
|
Assert.Equal(400, evt.HttpStatus);
|
|
}
|
|
|
|
// ---------------------------------------------------------------------
|
|
// 3. 401 — auth failure path
|
|
// ---------------------------------------------------------------------
|
|
|
|
[Fact]
|
|
public async Task Pipeline_401_EmitsEvent_KindInboundAuthFailure_StatusFailed()
|
|
{
|
|
var writer = new RecordingAuditWriter();
|
|
var ctx = BuildContext();
|
|
var mw = CreateMiddleware(_ =>
|
|
{
|
|
ctx.Response.StatusCode = 401;
|
|
return Task.CompletedTask;
|
|
}, writer);
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
var evt = Assert.Single(writer.Events);
|
|
Assert.Equal(AuditKind.InboundAuthFailure, evt.Kind);
|
|
Assert.Equal(AuditStatus.Failed, evt.Status);
|
|
Assert.Equal(401, evt.HttpStatus);
|
|
// The candidate API key never resolved to a name, so Actor stays null —
|
|
// never echo back an unauthenticated principal.
|
|
Assert.Null(evt.Actor);
|
|
}
|
|
|
|
[Fact]
|
|
public async Task Pipeline_403_EmitsEvent_KindInboundAuthFailure_StatusFailed()
|
|
{
|
|
var writer = new RecordingAuditWriter();
|
|
var ctx = BuildContext();
|
|
var mw = CreateMiddleware(_ =>
|
|
{
|
|
ctx.Response.StatusCode = 403;
|
|
return Task.CompletedTask;
|
|
}, writer);
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
var evt = Assert.Single(writer.Events);
|
|
Assert.Equal(AuditKind.InboundAuthFailure, evt.Kind);
|
|
Assert.Equal(AuditStatus.Failed, evt.Status);
|
|
Assert.Equal(403, evt.HttpStatus);
|
|
}
|
|
|
|
// ---------------------------------------------------------------------
|
|
// 4. 500 — handler threw OR returned 500
|
|
// ---------------------------------------------------------------------
|
|
|
|
[Fact]
|
|
public async Task Pipeline_500_EmitsEvent_Status_Failed()
|
|
{
|
|
var writer = new RecordingAuditWriter();
|
|
var ctx = BuildContext();
|
|
var mw = CreateMiddleware(_ =>
|
|
{
|
|
ctx.Response.StatusCode = 500;
|
|
return Task.CompletedTask;
|
|
}, writer);
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
var evt = Assert.Single(writer.Events);
|
|
Assert.Equal(AuditKind.InboundRequest, evt.Kind);
|
|
Assert.Equal(AuditStatus.Failed, evt.Status);
|
|
Assert.Equal(500, evt.HttpStatus);
|
|
}
|
|
|
|
[Fact]
|
|
public async Task Pipeline_Throws_EmitsEvent_Status_Failed_And_Rethrows()
|
|
{
|
|
var writer = new RecordingAuditWriter();
|
|
var ctx = BuildContext();
|
|
var boom = new InvalidOperationException("kaboom");
|
|
var mw = CreateMiddleware(_ => throw boom, writer);
|
|
|
|
// The middleware MUST re-throw so the request's own error path is
|
|
// authoritative — audit emission is best-effort only.
|
|
var thrown = await Assert.ThrowsAsync<InvalidOperationException>(
|
|
() => mw.InvokeAsync(ctx));
|
|
Assert.Same(boom, thrown);
|
|
|
|
var evt = Assert.Single(writer.Events);
|
|
Assert.Equal(AuditStatus.Failed, evt.Status);
|
|
Assert.Equal("kaboom", evt.ErrorMessage);
|
|
}
|
|
|
|
// ---------------------------------------------------------------------
|
|
// 5. Actor resolution — the endpoint handler stashes the API key name
|
|
// AFTER successful auth so the middleware can pick it up from
|
|
// HttpContext.Items.
|
|
// ---------------------------------------------------------------------
|
|
|
|
[Fact]
|
|
public async Task ApiKeyName_Resolved_From_HttpContext_AsActor()
|
|
{
|
|
var writer = new RecordingAuditWriter();
|
|
var ctx = BuildContext();
|
|
var mw = CreateMiddleware(_ =>
|
|
{
|
|
// The endpoint handler is expected to stash the resolved API key
|
|
// name here once ApiKeyValidator.ValidateAsync has succeeded.
|
|
ctx.Items[AuditWriteMiddleware.AuditActorItemKey] = "integration-svc";
|
|
ctx.Response.StatusCode = 200;
|
|
return Task.CompletedTask;
|
|
}, writer);
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
var evt = Assert.Single(writer.Events);
|
|
Assert.Equal("integration-svc", evt.Actor);
|
|
}
|
|
|
|
// ---------------------------------------------------------------------
|
|
// 6. Writer failure must NEVER alter the HTTP response
|
|
// ---------------------------------------------------------------------
|
|
|
|
[Fact]
|
|
public async Task AuditWriter_Throws_HttpResponse_Unchanged_Success_Stays_Success()
|
|
{
|
|
var writer = new RecordingAuditWriter
|
|
{
|
|
OnWrite = _ => throw new InvalidOperationException("writer offline"),
|
|
};
|
|
var ctx = BuildContext();
|
|
var mw = CreateMiddleware(_ =>
|
|
{
|
|
ctx.Response.StatusCode = 200;
|
|
return Task.CompletedTask;
|
|
}, writer);
|
|
|
|
// Audit emission is best-effort; even a thrown writer must NOT bubble
|
|
// up and contaminate the user-facing response status.
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
Assert.Equal(200, ctx.Response.StatusCode);
|
|
}
|
|
|
|
[Fact]
|
|
public async Task AuditWriter_Throws_OnFailedRequest_HttpResponse_Unchanged()
|
|
{
|
|
var writer = new RecordingAuditWriter
|
|
{
|
|
OnWrite = _ => throw new InvalidOperationException("writer offline"),
|
|
};
|
|
var ctx = BuildContext();
|
|
var mw = CreateMiddleware(_ =>
|
|
{
|
|
ctx.Response.StatusCode = 500;
|
|
return Task.CompletedTask;
|
|
}, writer);
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
Assert.Equal(500, ctx.Response.StatusCode);
|
|
}
|
|
|
|
// ---------------------------------------------------------------------
|
|
// 7. Provenance — RemoteIp + User-Agent surface in Extra JSON
|
|
// ---------------------------------------------------------------------
|
|
|
|
[Fact]
|
|
public async Task RemoteIp_And_UserAgent_AppearInExtra()
|
|
{
|
|
var writer = new RecordingAuditWriter();
|
|
var ctx = BuildContext(
|
|
userAgent: "curl/8.4.0",
|
|
remoteIp: IPAddress.Parse("192.168.50.50"));
|
|
var mw = CreateMiddleware(_ =>
|
|
{
|
|
ctx.Response.StatusCode = 200;
|
|
return Task.CompletedTask;
|
|
}, writer);
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
var evt = Assert.Single(writer.Events);
|
|
Assert.NotNull(evt.Extra);
|
|
using var doc = JsonDocument.Parse(evt.Extra!);
|
|
var root = doc.RootElement;
|
|
Assert.Equal("192.168.50.50", root.GetProperty("remoteIp").GetString());
|
|
Assert.Equal("curl/8.4.0", root.GetProperty("userAgent").GetString());
|
|
}
|
|
|
|
// ---------------------------------------------------------------------
|
|
// Body capture — the small JSON body is buffered and stashed on
|
|
// RequestSummary so subsequent reads (the endpoint handler's
|
|
// JsonDocument.Parse) still see the full payload.
|
|
// ---------------------------------------------------------------------
|
|
|
|
[Fact]
|
|
public async Task RequestBody_IsBuffered_AndStashed_OnRequestSummary()
|
|
{
|
|
var writer = new RecordingAuditWriter();
|
|
var requestJson = "{\"x\":1}";
|
|
var ctx = BuildContext(body: requestJson);
|
|
|
|
string? observedAfterMiddleware = null;
|
|
var mw = CreateMiddleware(async hc =>
|
|
{
|
|
// Downstream code must still be able to read the body — the
|
|
// middleware enables buffering and rewinds so the handler sees the
|
|
// unconsumed stream.
|
|
using var reader = new StreamReader(hc.Request.Body);
|
|
observedAfterMiddleware = await reader.ReadToEndAsync();
|
|
hc.Response.StatusCode = 200;
|
|
}, writer);
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
Assert.Equal(requestJson, observedAfterMiddleware);
|
|
var evt = Assert.Single(writer.Events);
|
|
Assert.Equal(requestJson, evt.RequestSummary);
|
|
}
|
|
|
|
// ---------------------------------------------------------------------
|
|
// Execution id — Audit Log #23: each inbound row carries a fresh
|
|
// per-request execution id so inbound rows are correlatable. The inbound
|
|
// row's CorrelationId stays null — CorrelationId is purely the
|
|
// per-operation-lifecycle id and an inbound request is a one-shot.
|
|
// ---------------------------------------------------------------------
|
|
|
|
[Fact]
|
|
public async Task InboundRow_CarriesNonNull_ExecutionId_And_NullCorrelationId()
|
|
{
|
|
var writer = new RecordingAuditWriter();
|
|
var ctx = BuildContext();
|
|
var mw = CreateMiddleware(_ =>
|
|
{
|
|
ctx.Response.StatusCode = 200;
|
|
return Task.CompletedTask;
|
|
}, writer);
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
var evt = Assert.Single(writer.Events);
|
|
Assert.NotNull(evt.ExecutionId);
|
|
Assert.NotEqual(Guid.Empty, evt.ExecutionId!.Value);
|
|
// CorrelationId is the per-operation-lifecycle id; an inbound request
|
|
// is a one-shot with no multi-row operation to correlate.
|
|
Assert.Null(evt.CorrelationId);
|
|
}
|
|
|
|
[Fact]
|
|
public async Task SeparateRequests_GetDistinct_ExecutionIds()
|
|
{
|
|
var writer = new RecordingAuditWriter();
|
|
var mw = CreateMiddleware(hc =>
|
|
{
|
|
hc.Response.StatusCode = 200;
|
|
return Task.CompletedTask;
|
|
}, writer);
|
|
|
|
await mw.InvokeAsync(BuildContext());
|
|
await mw.InvokeAsync(BuildContext());
|
|
|
|
Assert.Equal(2, writer.Events.Count);
|
|
Assert.NotEqual(writer.Events[0].ExecutionId, writer.Events[1].ExecutionId);
|
|
}
|
|
|
|
// ---------------------------------------------------------------------
|
|
// ParentExecutionId — Audit Log #23 (ParentExecutionId feature, T3): the
|
|
// inbound request's ExecutionId is minted ONCE, early, and stashed on
|
|
// HttpContext.Items so the endpoint handler can carry it onto the routed
|
|
// RouteToCallRequest as ParentExecutionId. The inbound row that the
|
|
// middleware itself emits stays top-level — its own ParentExecutionId is
|
|
// NEVER set.
|
|
// ---------------------------------------------------------------------
|
|
|
|
[Fact]
|
|
public async Task InboundExecutionId_IsStashedOnHttpItems_BeforeEndpointRuns()
|
|
{
|
|
var writer = new RecordingAuditWriter();
|
|
var ctx = BuildContext();
|
|
object? observedDuringHandler = null;
|
|
var mw = CreateMiddleware(hc =>
|
|
{
|
|
// The endpoint handler must be able to read the early-minted id —
|
|
// it is stashed before _next so a downstream reader sees it.
|
|
hc.Items.TryGetValue(AuditWriteMiddleware.InboundExecutionIdItemKey, out observedDuringHandler);
|
|
hc.Response.StatusCode = 200;
|
|
return Task.CompletedTask;
|
|
}, writer);
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
var stashed = Assert.IsType<Guid>(observedDuringHandler);
|
|
Assert.NotEqual(Guid.Empty, stashed);
|
|
}
|
|
|
|
[Fact]
|
|
public async Task InboundRow_ExecutionId_Equals_TheEarlyMintedStashedId()
|
|
{
|
|
var writer = new RecordingAuditWriter();
|
|
var ctx = BuildContext();
|
|
Guid stashedDuringHandler = Guid.Empty;
|
|
var mw = CreateMiddleware(hc =>
|
|
{
|
|
stashedDuringHandler =
|
|
(Guid)hc.Items[AuditWriteMiddleware.InboundExecutionIdItemKey]!;
|
|
hc.Response.StatusCode = 200;
|
|
return Task.CompletedTask;
|
|
}, writer);
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
// The inbound audit row's ExecutionId must be the SAME id minted early
|
|
// and shared with the endpoint handler — not a second, late mint.
|
|
var evt = Assert.Single(writer.Events);
|
|
Assert.Equal(stashedDuringHandler, evt.ExecutionId);
|
|
}
|
|
|
|
[Fact]
|
|
public async Task InboundRow_OwnParentExecutionId_StaysNull()
|
|
{
|
|
var writer = new RecordingAuditWriter();
|
|
var ctx = BuildContext();
|
|
var mw = CreateMiddleware(_ =>
|
|
{
|
|
ctx.Response.StatusCode = 200;
|
|
return Task.CompletedTask;
|
|
}, writer);
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
// The inbound request is itself top-level — only the spawn id flows
|
|
// OUT on RouteToCallRequest. The inbound row's own ParentExecutionId
|
|
// is never set.
|
|
var evt = Assert.Single(writer.Events);
|
|
Assert.Null(evt.ParentExecutionId);
|
|
}
|
|
|
|
[Fact]
|
|
public async Task DurationMs_IsRecorded()
|
|
{
|
|
var writer = new RecordingAuditWriter();
|
|
var ctx = BuildContext();
|
|
var mw = CreateMiddleware(async _ =>
|
|
{
|
|
// The middleware records elapsed milliseconds — a small delay
|
|
// ensures DurationMs is non-negative and roughly tracks reality
|
|
// without being flake-sensitive in CI.
|
|
await Task.Delay(5);
|
|
ctx.Response.StatusCode = 200;
|
|
}, writer);
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
var evt = Assert.Single(writer.Events);
|
|
Assert.NotNull(evt.DurationMs);
|
|
Assert.True(evt.DurationMs >= 0);
|
|
}
|
|
|
|
// ---------------------------------------------------------------------
|
|
// Response body capture — Audit Log #23 (inbound full-response feature).
|
|
// Until the M5-deferred work landed, ResponseSummary was always null.
|
|
// These tests pin the new contract: the middleware wraps Response.Body,
|
|
// runs the pipeline, copies the buffered bytes back to the real stream,
|
|
// and stashes a UTF-8 string copy on ResponseSummary.
|
|
// ---------------------------------------------------------------------
|
|
|
|
[Fact]
|
|
public async Task ResponseBody_IsCaptured_OnResponseSummary()
|
|
{
|
|
var writer = new RecordingAuditWriter();
|
|
var ctx = BuildContext();
|
|
var responseJson = "{\"result\":42}";
|
|
var mw = CreateMiddleware(async hc =>
|
|
{
|
|
hc.Response.StatusCode = 200;
|
|
hc.Response.ContentType = "application/json";
|
|
await hc.Response.WriteAsync(responseJson);
|
|
}, writer);
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
var evt = Assert.Single(writer.Events);
|
|
Assert.Equal(responseJson, evt.ResponseSummary);
|
|
}
|
|
|
|
[Fact]
|
|
public async Task ResponseBody_IsForwardedToOriginalStream_DownstreamReadersSeeIt()
|
|
{
|
|
// Wrapping the response body must be TRANSPARENT — the real client
|
|
// stream still receives every byte the pipeline wrote.
|
|
var writer = new RecordingAuditWriter();
|
|
var ctx = BuildContext();
|
|
var captured = new MemoryStream();
|
|
ctx.Response.Body = captured; // simulate the client/test sink
|
|
|
|
var responseJson = "{\"ok\":true}";
|
|
var mw = CreateMiddleware(async hc =>
|
|
{
|
|
hc.Response.StatusCode = 200;
|
|
await hc.Response.WriteAsync(responseJson);
|
|
}, writer);
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
Assert.Equal(responseJson, Encoding.UTF8.GetString(captured.ToArray()));
|
|
}
|
|
|
|
[Fact]
|
|
public async Task ResponseBody_Empty_LeavesResponseSummaryNull()
|
|
{
|
|
// No bytes written => null, not empty-string. Mirrors the request-body
|
|
// contract in ReadBufferedRequestBodyAsync.
|
|
var writer = new RecordingAuditWriter();
|
|
var ctx = BuildContext();
|
|
var mw = CreateMiddleware(hc =>
|
|
{
|
|
hc.Response.StatusCode = 204;
|
|
return Task.CompletedTask;
|
|
}, writer);
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
var evt = Assert.Single(writer.Events);
|
|
Assert.Null(evt.ResponseSummary);
|
|
Assert.Equal(204, evt.HttpStatus);
|
|
}
|
|
|
|
[Fact]
|
|
public async Task ResponseBody_OnHandlerThrow_BodyCapturedUpToTheThrow()
|
|
{
|
|
// If the handler writes some bytes then throws, the audit row still
|
|
// surfaces whatever the framework had flushed. The middleware re-throws
|
|
// (audit is best-effort, the request's error path stays authoritative).
|
|
var writer = new RecordingAuditWriter();
|
|
var ctx = BuildContext();
|
|
var boom = new InvalidOperationException("kaboom");
|
|
var mw = CreateMiddleware(async hc =>
|
|
{
|
|
hc.Response.StatusCode = 500;
|
|
await hc.Response.WriteAsync("partial");
|
|
throw boom;
|
|
}, writer);
|
|
|
|
var thrown = await Assert.ThrowsAsync<InvalidOperationException>(
|
|
() => mw.InvokeAsync(ctx));
|
|
Assert.Same(boom, thrown);
|
|
|
|
var evt = Assert.Single(writer.Events);
|
|
Assert.Equal(AuditStatus.Failed, evt.Status);
|
|
Assert.Equal("partial", evt.ResponseSummary);
|
|
}
|
|
|
|
// ---------------------------------------------------------------------
|
|
// Bounded audit capture — memory safety follow-up. The capture site now
|
|
// honours AuditLogOptions.InboundMaxBytes at READ time (not just at
|
|
// filter-time), so a 500 MiB body cannot transiently allocate 500 MiB of
|
|
// string. The cap is local to the AUDIT copy; downstream readers and the
|
|
// real client still see every byte.
|
|
// ---------------------------------------------------------------------
|
|
|
|
[Fact]
|
|
public async Task RequestBody_AboveInboundMaxBytes_TruncatedToCap_PayloadTruncatedTrue()
|
|
{
|
|
// 4 KiB cap, 20 KB body — the audit copy must be UTF-8 byte-safe
|
|
// capped at 4 KiB AND PayloadTruncated must flip, while the
|
|
// downstream handler still sees the full 20 KB payload.
|
|
const int cap = 4096;
|
|
var bigBody = new string('a', 20_000);
|
|
var writer = new RecordingAuditWriter();
|
|
var ctx = BuildContext(body: bigBody);
|
|
|
|
string? observedAfterMiddleware = null;
|
|
var mw = CreateMiddleware(
|
|
async hc =>
|
|
{
|
|
using var reader = new StreamReader(hc.Request.Body);
|
|
observedAfterMiddleware = await reader.ReadToEndAsync();
|
|
hc.Response.StatusCode = 200;
|
|
},
|
|
writer,
|
|
options: new AuditLogOptions { InboundMaxBytes = cap });
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
// (iii) Downstream handler still sees the FULL body — the cap applied
|
|
// only to the audit copy.
|
|
Assert.Equal(bigBody, observedAfterMiddleware);
|
|
|
|
var evt = Assert.Single(writer.Events);
|
|
// (i) Audit copy bounded at cap bytes (UTF-8 byte count).
|
|
Assert.NotNull(evt.RequestSummary);
|
|
Assert.True(
|
|
Encoding.UTF8.GetByteCount(evt.RequestSummary!) <= cap,
|
|
$"RequestSummary byte count {Encoding.UTF8.GetByteCount(evt.RequestSummary!)} exceeded cap {cap}");
|
|
// (ii) Truncation flag set by the middleware (the filter will OR its
|
|
// own determination on top, but the middleware MUST set it itself).
|
|
Assert.True(evt.PayloadTruncated);
|
|
}
|
|
|
|
[Fact]
|
|
public async Task ResponseBody_AboveInboundMaxBytes_TruncatedToCap_ClientStillReceivesAllBytes_PayloadTruncatedTrue()
|
|
{
|
|
// 4 KiB cap, 20 KB response — the test sink (acts as the real client)
|
|
// MUST receive all 20 KB while the audit copy is bounded at 4 KiB.
|
|
const int cap = 4096;
|
|
var bigResponse = new string('b', 20_000);
|
|
var writer = new RecordingAuditWriter();
|
|
var ctx = BuildContext();
|
|
var captured = new MemoryStream();
|
|
ctx.Response.Body = captured; // stand-in for the client sink
|
|
|
|
var mw = CreateMiddleware(
|
|
async hc =>
|
|
{
|
|
hc.Response.StatusCode = 200;
|
|
await hc.Response.WriteAsync(bigResponse);
|
|
},
|
|
writer,
|
|
options: new AuditLogOptions { InboundMaxBytes = cap });
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
// Client sink received every byte — the forwarding wrap is transparent.
|
|
Assert.Equal(bigResponse, Encoding.UTF8.GetString(captured.ToArray()));
|
|
|
|
var evt = Assert.Single(writer.Events);
|
|
// Audit copy bounded at cap bytes.
|
|
Assert.NotNull(evt.ResponseSummary);
|
|
Assert.True(
|
|
Encoding.UTF8.GetByteCount(evt.ResponseSummary!) <= cap,
|
|
$"ResponseSummary byte count {Encoding.UTF8.GetByteCount(evt.ResponseSummary!)} exceeded cap {cap}");
|
|
Assert.True(evt.PayloadTruncated);
|
|
}
|
|
|
|
// ---------------------------------------------------------------------
|
|
// InboundAPI-018: asynchronously faulted audit-write tasks must be
|
|
// observed (logged) rather than silently dropped — but must still NOT
|
|
// alter the user-facing HTTP response (alog.md §13).
|
|
// ---------------------------------------------------------------------
|
|
|
|
/// <summary>
|
|
/// Test-only writer whose <see cref="WriteAsync"/> returns a Task that
|
|
/// faults AFTER an asynchronous boundary, so the throw happens after
|
|
/// <see cref="AuditWriteMiddleware"/>'s synchronous try/catch can see it —
|
|
/// exactly the fire-and-forget bug InboundAPI-018 closes.
|
|
/// </summary>
|
|
private sealed class AsyncFaultingAuditWriter : ICentralAuditWriter
|
|
{
|
|
public Task WriteAsync(AuditEvent evt, CancellationToken ct = default)
|
|
{
|
|
return FaultAsync();
|
|
|
|
static async Task FaultAsync()
|
|
{
|
|
// Yield off-thread so the fault surfaces ASYNCHRONOUSLY (not
|
|
// captured by a synchronous try/catch around the WriteAsync
|
|
// call site).
|
|
await Task.Yield();
|
|
throw new InvalidOperationException("async audit write failed");
|
|
}
|
|
}
|
|
}
|
|
|
|
/// <summary>
|
|
/// Captures log entries written through a <see cref="ILogger{TCategoryName}"/>
|
|
/// so the test can assert on the Warning that
|
|
/// <see cref="AuditWriteMiddleware.ObserveAuditWriteFault"/> emits.
|
|
/// </summary>
|
|
private sealed class RecordingLogger : Microsoft.Extensions.Logging.ILogger<AuditWriteMiddleware>
|
|
{
|
|
public List<(Microsoft.Extensions.Logging.LogLevel Level, string Message, Exception? Exception)> Entries { get; } = new();
|
|
|
|
public IDisposable BeginScope<TState>(TState state) where TState : notnull => NullScope.Instance;
|
|
|
|
public bool IsEnabled(Microsoft.Extensions.Logging.LogLevel logLevel) => true;
|
|
|
|
public void Log<TState>(
|
|
Microsoft.Extensions.Logging.LogLevel logLevel,
|
|
Microsoft.Extensions.Logging.EventId eventId,
|
|
TState state,
|
|
Exception? exception,
|
|
Func<TState, Exception?, string> formatter)
|
|
{
|
|
lock (Entries)
|
|
{
|
|
Entries.Add((logLevel, formatter(state, exception), exception));
|
|
}
|
|
}
|
|
|
|
private sealed class NullScope : IDisposable
|
|
{
|
|
public static readonly NullScope Instance = new();
|
|
public void Dispose() { }
|
|
}
|
|
}
|
|
|
|
[Fact]
|
|
public async Task AuditWriter_AsyncFault_IsObserved_AsWarning_AndDoesNotAlterResponse()
|
|
{
|
|
var writer = new AsyncFaultingAuditWriter();
|
|
var logger = new RecordingLogger();
|
|
var ctx = BuildContext();
|
|
|
|
var mw = new AuditWriteMiddleware(
|
|
next: _ =>
|
|
{
|
|
ctx.Response.StatusCode = 200;
|
|
return Task.CompletedTask;
|
|
},
|
|
auditWriter: writer,
|
|
logger: logger,
|
|
options: new StaticAuditLogOptionsMonitor(new AuditLogOptions()));
|
|
|
|
await mw.InvokeAsync(ctx);
|
|
|
|
// The user-facing response is untouched — audit emission is best-effort.
|
|
Assert.Equal(200, ctx.Response.StatusCode);
|
|
|
|
// Give the off-thread continuation a moment to fire and log. Spin
|
|
// briefly rather than sleep-then-assert so the test is resilient to
|
|
// scheduler jitter without inflating runtime on success.
|
|
var deadline = DateTime.UtcNow.AddSeconds(2);
|
|
while (DateTime.UtcNow < deadline)
|
|
{
|
|
lock (logger.Entries)
|
|
{
|
|
if (logger.Entries.Any(e =>
|
|
e.Level == Microsoft.Extensions.Logging.LogLevel.Warning
|
|
&& e.Exception is not null
|
|
&& e.Message.Contains("async audit write faulted")))
|
|
{
|
|
return;
|
|
}
|
|
}
|
|
await Task.Delay(20);
|
|
}
|
|
|
|
// If we reach this point, the continuation did not fire — pre-fix the
|
|
// fault would have been swallowed entirely and no log line emitted.
|
|
var snapshot = logger.Entries.Select(e => $"{e.Level}: {e.Message}").ToList();
|
|
Assert.Fail(
|
|
"Expected a Warning log entry observing the async audit-write fault — none found. " +
|
|
$"Entries: [{string.Join(", ", snapshot)}]");
|
|
}
|
|
}
|