diff --git a/src/WidgetWorks.WebApi/Diagnostics/CorrelationId.cs b/src/WidgetWorks.WebApi/Diagnostics/CorrelationId.cs new file mode 100644 index 0000000..90d709c --- /dev/null +++ b/src/WidgetWorks.WebApi/Diagnostics/CorrelationId.cs @@ -0,0 +1,65 @@ +namespace WidgetWorks.WebApi.Diagnostics; + +/// +/// Gives every request an identifier the caller can quote back. +/// +/// Without one, a customer saying "checkout failed around three" is the entire incident report: +/// the response carried nothing, and the log line for their exception sits among every other line +/// from that minute with no way to tell them apart. With one, six characters turn diagnosis into +/// a lookup. +/// +public static class CorrelationId +{ + /// Header the id is read from and echoed on, matching the de-facto convention. + public const string HeaderName = "X-Correlation-Id"; + + /// Longest inbound id accepted, so a caller cannot push arbitrary text into the logs. + private const int MaxLength = 64; + + /// + /// Resolves the id for a request: an inbound one when the caller supplied something sane, so a + /// trace already begun upstream keeps its thread, otherwise the id ASP.NET already assigns. + /// + /// Inbound values are sanitised rather than trusted. This string ends up in log messages, and + /// text carrying newlines could otherwise forge whole log entries (CWE-117) — the same class of + /// defect already fixed once in this codebase, on the order-status path. + /// + public static string Resolve(HttpContext context) + { + ArgumentNullException.ThrowIfNull(context); + + var supplied = context.Request.Headers[HeaderName].ToString(); + if (!string.IsNullOrWhiteSpace(supplied)) + { + var cleaned = Sanitize(supplied); + if (cleaned.Length > 0) + { + return cleaned; + } + } + + return context.TraceIdentifier; + } + + /// Keeps letters, digits and a few separators; drops everything else and truncates. + private static string Sanitize(string value) + { + var kept = new char[Math.Min(value.Length, MaxLength)]; + var length = 0; + + foreach (var c in value) + { + if (length == kept.Length) + { + break; + } + + if (char.IsAsciiLetterOrDigit(c) || c is '-' or '_' or ':' or '.') + { + kept[length++] = c; + } + } + + return new string(kept, 0, length); + } +} diff --git a/src/WidgetWorks.WebApi/Diagnostics/ExceptionHandling.cs b/src/WidgetWorks.WebApi/Diagnostics/ExceptionHandling.cs new file mode 100644 index 0000000..5dffdbc --- /dev/null +++ b/src/WidgetWorks.WebApi/Diagnostics/ExceptionHandling.cs @@ -0,0 +1,61 @@ +using Microsoft.AspNetCore.Diagnostics; + +namespace WidgetWorks.WebApi.Diagnostics; + +public static class ExceptionHandling +{ + /// + /// Turns an unhandled exception into a supportable answer. + /// + /// The previous behaviour was safe but opaque: no handler meant a bare 500 with an empty body, + /// and while that leaks nothing — the developer exception page is Development-only — it left + /// nothing connecting what the customer saw to what the logs recorded. + /// + /// The response now carries a correlation id and the same id is on the log line, so a report + /// becomes a lookup. The body still says nothing about the failure itself: an exception message + /// can name a host, a column, or a connection string, and this reaches anonymous callers. + /// + public static void UseWidgetWorksExceptionHandler(this WebApplication app) + { + app.UseExceptionHandler(builder => builder.Run(async context => + { + var correlationId = CorrelationId.Resolve(context); + var feature = context.Features.Get(); + + // The path is sanitised because Request.Path.Value is the *decoded* path: a URL + // containing %0A arrives here as a real newline, which would end this log entry and + // begin one the caller wrote (CWE-117). The correlation id is already clean by + // construction; the method comes from the server's own parser. + app.Logger.LogError( + feature?.Error, + "Unhandled exception for {Method} {Path} (correlation {CorrelationId}).", + LogSafe.Text(context.Request.Method, maxLength: 16), + LogSafe.Text(context.Request.Path.Value), + correlationId); + + context.Response.StatusCode = StatusCodes.Status500InternalServerError; + context.Response.Headers[CorrelationId.HeaderName] = correlationId; + + await context.Response.WriteAsJsonAsync(new + { + error = "Something went wrong on our side. Quote the reference below if you contact us.", + correlationId, + }); + })); + + // Echoed on every response, not only failures, so a caller can correlate a slow or wrong + // answer as readily as a failed one — and so a support conversation can start before anyone + // has looked at a log. + app.Use(async (context, next) => + { + var correlationId = CorrelationId.Resolve(context); + context.Response.OnStarting(() => + { + context.Response.Headers[CorrelationId.HeaderName] = correlationId; + return Task.CompletedTask; + }); + + await next(context); + }); + } +} diff --git a/src/WidgetWorks.WebApi/Diagnostics/HealthEndpoints.cs b/src/WidgetWorks.WebApi/Diagnostics/HealthEndpoints.cs new file mode 100644 index 0000000..17bf2d7 --- /dev/null +++ b/src/WidgetWorks.WebApi/Diagnostics/HealthEndpoints.cs @@ -0,0 +1,87 @@ +using System.Data; +using Dapper; +using WidgetWorks.Infrastructure.Persistence; + +namespace WidgetWorks.WebApi.Diagnostics; + +/// +/// Two probes answering two different questions, because conflating them is how a monitoring signal +/// ends up unable to report bad news. +/// +public static class HealthEndpoints +{ + /// Outcome of the startup migration — a fact about this boot. + /// Why it failed, when it did. + public static void MapHealthEndpoints(this IEndpointRouteBuilder routes, bool migrationSucceeded, string? migrationError) + { + // Liveness. Answers "did this process start correctly", which is a fact settled at boot and + // needs no database. Deliberately unchanged in contract: the provisioning script watches it + // on first boot and stops the app when it reports unhealthy, and the keep-warm schedule + // pings it every few minutes to hold a free-tier instance loaded. + // + // That ping is why this must not touch the database. Waking a serverless database on every + // warm-up would hold a metered resource awake around the clock — roughly 180 CU-hrs against + // a 100 CU-hr monthly budget. Warm the app, let the database sleep. + routes.MapGet("/health", (TimeProvider clock) => migrationSucceeded + ? Results.Ok(new { status = "ok", utcNow = clock.GetUtcNow() }) + : Results.Json( + new { status = "unhealthy", reason = "database migration failed", detail = migrationError, utcNow = clock.GetUtcNow() }, + statusCode: StatusCodes.Status503ServiceUnavailable)); + + // Readiness. Answers "can this instance serve a request right now", which liveness cannot: + // a process that started perfectly is still useless once its database goes away, and the + // startup answer never changes to say so. + // + // Point platform probes and alerting here, not at /health — and keep scheduled warm-up + // pings off it, or the cost the shallow probe exists to avoid comes straight back. + routes.MapGet("/health/ready", async ( + IDbConnectionFactory connections, + TimeProvider clock, + ILoggerFactory loggerFactory, + CancellationToken ct) => + { + var startedAt = clock.GetUtcNow(); + try + { + using var db = await connections.OpenAsync(ct); + await db.ExecuteScalarAsync(new CommandDefinition("select 1", cancellationToken: ct)); + + return Results.Ok(new + { + status = "ready", + database = "ok", + migrationSucceeded, + checkedAt = startedAt, + }); + } + catch (OperationCanceledException) when (ct.IsCancellationRequested) + { + // The caller gave up or the host is shutting down. Not a verdict about the database, + // so it is reported as unavailable without being logged as a fault. + return Results.Json( + new { status = "unavailable", reason = "the readiness check was cancelled", checkedAt = startedAt }, + statusCode: StatusCodes.Status503ServiceUnavailable); + } + catch (Exception ex) + { + // Logged rather than swallowed: the probe's 503 tells the platform to stop sending + // traffic here, and this line is the only place the reason survives. + loggerFactory + .CreateLogger(typeof(HealthEndpoints)) + .LogError(ex, "Readiness check failed: the database did not answer."); + + return Results.Json( + new + { + status = "not ready", + database = "unreachable", + // The exception type, never its message: a connection failure can carry a + // host name or a user, and this endpoint is unauthenticated. + reason = ex.GetType().Name, + checkedAt = startedAt, + }, + statusCode: StatusCodes.Status503ServiceUnavailable); + } + }); + } +} diff --git a/src/WidgetWorks.WebApi/Diagnostics/LogSafe.cs b/src/WidgetWorks.WebApi/Diagnostics/LogSafe.cs new file mode 100644 index 0000000..713dab7 --- /dev/null +++ b/src/WidgetWorks.WebApi/Diagnostics/LogSafe.cs @@ -0,0 +1,48 @@ +namespace WidgetWorks.WebApi.Diagnostics; + +/// +/// Makes caller-controlled text safe to put in a log message. +/// +/// A log file is a flat stream of lines, so any value carrying a newline can end one entry and +/// begin another that reads exactly like a genuine record — an attacker choosing what the log +/// appears to say about them (CWE-117). Request paths are the easy example: Path.Value is +/// the *decoded* path, so %0A in a URL arrives as a real line break. +/// +public static class LogSafe +{ + /// Shown in place of a value that sanitised away to nothing, so the field is never blank. + public const string Empty = "(empty)"; + + /// + /// Strips control characters and truncates. Everything printable is kept, because the point is + /// to preserve what was actually requested — a path full of odd characters is exactly what an + /// operator needs to see — while removing the ones that can restructure the log itself. + /// + public static string Text(string? value, int maxLength = 256) + { + if (string.IsNullOrEmpty(value)) + { + return Empty; + } + + var kept = new char[Math.Min(value.Length, maxLength)]; + var length = 0; + + foreach (var c in value) + { + if (length == kept.Length) + { + break; + } + + // char.IsControl covers CR, LF, tab and the rest of the C0/C1 ranges — the characters + // that can break a line or confuse a log viewer. + if (!char.IsControl(c)) + { + kept[length++] = c; + } + } + + return length == 0 ? Empty : new string(kept, 0, length); + } +} diff --git a/src/WidgetWorks.WebApi/Program.cs b/src/WidgetWorks.WebApi/Program.cs index bd6c6fb..292d61b 100644 --- a/src/WidgetWorks.WebApi/Program.cs +++ b/src/WidgetWorks.WebApi/Program.cs @@ -18,6 +18,7 @@ using WidgetWorks.WebApi.Payments; using WidgetWorks.WebApi.Security; using WidgetWorks.Application.Checkout.ReleaseStale; +using WidgetWorks.WebApi.Diagnostics; using WidgetWorks.WebApi.Hosting; using WidgetWorks.WebApi.RateLimiting; using WidgetWorks.WebApi.TwoFactor; @@ -28,6 +29,7 @@ builder.Services.AddInfrastructure(builder.Configuration); builder.Services.AddOpenApi(); builder.Services.AddWidgetWorksRateLimiting(builder.Configuration); +builder.Services.AddSingleton(); // Stock held by an order whose payment never settles is returned to sale on a timer. Options are // bound here so the sweep can be retuned, or turned off for a host that should not run background @@ -136,21 +138,29 @@ await users.GetSecurityStampAsync(userId, context.HttpContext.RequestAborted) is app.MapScalarApiReference(); // interactive API UI at /scalar/v1 } +// First, so it wraps every other piece of middleware: anything that throws below this point +// becomes a correlated 500 rather than an empty one. +app.UseWidgetWorksExceptionHandler(); + app.UseCors(SpaCorsPolicy); +// Watches real traffic for the proxy misconfiguration that would otherwise turn per-caller +// throttling into a global cap without anything saying so. +app.Use(async (context, next) => +{ + context.RequestServices.GetRequiredService().Inspect(context); + await next(context); +}); + // Ahead of authentication on purpose: a throttled request is rejected before the app spends // work validating credentials, which is what keeps a guessing flood cheap to absorb. app.UseRateLimiter(); app.UseAuthentication(); app.UseAuthorization(); -// 200 only when the database is actually usable. A 503 naming the failure is what turns a silent -// restart loop into a one-line diagnosis. -app.MapGet("/health", (TimeProvider clock) => migration.Successful - ? Results.Ok(new { status = "ok", utcNow = clock.GetUtcNow() }) - : Results.Json( - new { status = "unhealthy", reason = "database migration failed", detail = migration.Error, utcNow = clock.GetUtcNow() }, - statusCode: StatusCodes.Status503ServiceUnavailable)); +// Liveness at /health (cheap, no database — the keep-warm schedule pings it) and readiness at +// /health/ready (queries the database, for platform probes and alerting). +app.MapHealthEndpoints(migration.Successful, migration.Error); app.MapAuthEndpoints(); app.MapSecurityEndpoints(); app.MapTwoFactorEndpoints(); diff --git a/src/WidgetWorks.WebApi/RateLimiting/ProxyConfigurationCheck.cs b/src/WidgetWorks.WebApi/RateLimiting/ProxyConfigurationCheck.cs new file mode 100644 index 0000000..872ee85 --- /dev/null +++ b/src/WidgetWorks.WebApi/RateLimiting/ProxyConfigurationCheck.cs @@ -0,0 +1,57 @@ +namespace WidgetWorks.WebApi.RateLimiting; + +/// +/// Notices the one configuration mistake that turns throttling into an outage, and says so. +/// +/// Rate limiting partitions by caller. Behind a reverse proxy every request arrives carrying the +/// proxy's address, so unless X-Forwarded-For is trusted, every caller in the world collapses +/// into a single partition and the limiter becomes a global cap that the first busy minute trips for +/// everybody. Nothing about that is visible in a log: requests simply start returning 429. +/// +/// The inverse mistake is the security one — trusting the header with no proxy in front lets a +/// caller forge it and mint a fresh partition per request, opting out of throttling entirely. +/// +/// Both are silent, so this watches real traffic and warns once for whichever it sees. +/// +public sealed class ProxyConfigurationCheck(RateLimitOptions options, ILogger logger) +{ + private int _warned; + + /// Inspects one request. Cheap after the first warning, and warns at most once. + public void Inspect(HttpContext context) + { + ArgumentNullException.ThrowIfNull(context); + + if (Volatile.Read(ref _warned) != 0) + { + return; + } + + var forwarded = context.Request.Headers.ContainsKey("X-Forwarded-For"); + + if (forwarded && !options.TrustForwardedFor) + { + WarnOnce( + "Requests carry X-Forwarded-For but RateLimiting:TrustForwardedFor is false, so every " + + "caller shares one throttling partition and the limits apply to all traffic combined. " + + "Set it true if a trusted proxy sits in front of this app."); + } + else if (!forwarded && options.TrustForwardedFor) + { + WarnOnce( + "RateLimiting:TrustForwardedFor is true but requests arrive without X-Forwarded-For. " + + "If no proxy is in front, a caller can forge that header and give itself an " + + "unlimited number of throttling partitions. Set it false unless a proxy is guaranteed."); + } + } + + private void WarnOnce(string message) + { + // Interlocked so a burst of concurrent requests produces one warning rather than a page of + // identical ones, which is how a real signal gets scrolled past. + if (Interlocked.Exchange(ref _warned, 1) == 0) + { + logger.LogWarning("{Message}", message); + } + } +} diff --git a/tests/WidgetWorks.ApiTests/DiagnosticsApiTests.cs b/tests/WidgetWorks.ApiTests/DiagnosticsApiTests.cs new file mode 100644 index 0000000..d748ad9 --- /dev/null +++ b/tests/WidgetWorks.ApiTests/DiagnosticsApiTests.cs @@ -0,0 +1,180 @@ +using System.Net; +using System.Net.Http.Json; +using Microsoft.AspNetCore.Http; +using WidgetWorks.WebApi.Diagnostics; +using Xunit; + +namespace WidgetWorks.ApiTests; + +/// +/// The two probes and the correlation id. These exist because the previous behaviour was safe but +/// unobservable: a health endpoint that could never report bad news, and a 500 with nothing tying it +/// to a log line. +/// +[Collection(ApiCollection.Name)] +public sealed class DiagnosticsApiTests(ApiFixture fixture) +{ + private sealed record Liveness(string Status); + private sealed record Readiness(string Status, string Database, bool MigrationSucceeded); + + [Fact] + public async Task Liveness_answers_without_touching_the_database() + { + using var client = fixture.Factory.CreateClient(); + + var response = await client.GetAsync("/health"); + + Assert.Equal(HttpStatusCode.OK, response.StatusCode); + var body = await response.Content.ReadFromJsonAsync(); + Assert.Equal("ok", body!.Status); + } + + [Fact] + public async Task Readiness_reports_the_database_actually_answering() + { + using var client = fixture.Factory.CreateClient(); + + var response = await client.GetAsync("/health/ready"); + + Assert.Equal(HttpStatusCode.OK, response.StatusCode); + var body = await response.Content.ReadFromJsonAsync(); + Assert.Equal("ready", body!.Status); + Assert.Equal("ok", body.Database); + Assert.True(body.MigrationSucceeded); + } + + [Fact] + public async Task Readiness_is_a_separate_endpoint_so_the_cheap_probe_stays_cheap() + { + using var client = fixture.Factory.CreateClient(); + + // Both exist and both answer. The distinction is the point: /health is what the keep-warm + // schedule pings, and waking a serverless database on that cadence is what would blow the + // monthly compute budget. Merging them is the mistake this pins against. + Assert.Equal(HttpStatusCode.OK, (await client.GetAsync("/health")).StatusCode); + Assert.Equal(HttpStatusCode.OK, (await client.GetAsync("/health/ready")).StatusCode); + } + + [Fact] + public async Task Every_response_carries_a_correlation_id() + { + using var client = fixture.Factory.CreateClient(); + + var response = await client.GetAsync("/health"); + + Assert.True(response.Headers.TryGetValues(CorrelationId.HeaderName, out var values)); + Assert.False(string.IsNullOrWhiteSpace(values!.First())); + } + + [Fact] + public async Task A_caller_supplied_correlation_id_is_kept_so_a_trace_survives() + { + using var client = fixture.Factory.CreateClient(); + using var request = new HttpRequestMessage(HttpMethod.Get, "/health"); + request.Headers.Add(CorrelationId.HeaderName, "trace-from-upstream-1"); + + var response = await client.SendAsync(request); + + // A request that already carries an id keeps it, so one trace spans several services rather + // than restarting at each hop. + Assert.Equal("trace-from-upstream-1", response.Headers.GetValues(CorrelationId.HeaderName).First()); + } +} + +/// +/// The id itself. Worth unit tests because it reaches log messages, and text that reaches a log +/// message is an injection surface. +/// +public class CorrelationIdTests +{ + private static HttpContext RequestWith(string? supplied) + { + var context = new DefaultHttpContext { TraceIdentifier = "trace-assigned-by-the-host" }; + if (supplied is not null) + { + context.Request.Headers[CorrelationId.HeaderName] = supplied; + } + + return context; + } + + [Fact] + public void Falls_back_to_the_id_the_host_already_assigned() + => Assert.Equal("trace-assigned-by-the-host", CorrelationId.Resolve(RequestWith(null))); + + [Theory] + [InlineData("")] + [InlineData(" ")] + public void An_empty_header_is_ignored(string supplied) + => Assert.Equal("trace-assigned-by-the-host", CorrelationId.Resolve(RequestWith(supplied))); + + [Fact] + public void A_sane_inbound_id_is_kept() + => Assert.Equal("abc-123_x.y:z", CorrelationId.Resolve(RequestWith("abc-123_x.y:z"))); + + [Fact] + public void Newlines_are_stripped_so_a_caller_cannot_forge_log_entries() + { + // Left intact this would put an attacker-authored line into the log stream that reads like + // a genuine record (CWE-117) - the same class of defect already fixed once here, on the + // order-status path. + var forged = CorrelationId.Resolve(RequestWith("ok\r\nfatal: database deleted by admin")); + + Assert.DoesNotContain('\n', forged); + Assert.DoesNotContain('\r', forged); + Assert.StartsWith("ok", forged, StringComparison.Ordinal); + } + + [Fact] + public void An_absurdly_long_id_is_truncated_rather_than_logged_whole() + { + var resolved = CorrelationId.Resolve(RequestWith(new string('a', 500))); + + Assert.True(resolved.Length <= 64); + } + + [Fact] + public void A_header_of_only_junk_falls_back_instead_of_yielding_an_empty_id() + => Assert.Equal("trace-assigned-by-the-host", CorrelationId.Resolve(RequestWith("<<<>>>"))); +} +/// +/// Making caller-controlled text safe for a log line. CodeQL flagged the original version of the +/// exception handler for exactly this: Request.Path.Value is the decoded path, so %0A in a URL +/// arrives as a real newline and the caller gets to write a log entry. +/// +public class LogSafeTests +{ + [Fact] + public void Ordinary_text_survives_untouched() + => Assert.Equal("/catalog/widgets", LogSafe.Text("/catalog/widgets")); + + [Fact] + public void Newlines_are_removed_so_a_caller_cannot_forge_an_entry() + { + var forged = LogSafe.Text("/orders\r\nfatal: database deleted by admin"); + + Assert.DoesNotContain('\n', forged); + Assert.DoesNotContain('\r', forged); + // The text still reads, so an operator can see what was actually requested. + Assert.StartsWith("/orders", forged, StringComparison.Ordinal); + } + + [Fact] + public void Tabs_and_other_control_characters_go_too() + => Assert.Equal("ab", LogSafe.Text("a\tb\u0000")); + + [Fact] + public void Odd_but_printable_characters_are_kept_because_that_is_the_evidence() + => Assert.Equal("/search?q=