From 651a718eb6406ed829e92e5cfbdff2c3e37dbc11 Mon Sep 17 00:00:00 2001 From: "Mars.P" Date: Fri, 14 Aug 2026 16:29:35 +0800 Subject: [PATCH] Make a failure and the build that produced it visible in the logs A pod answered sign-in with a Postgres 42703 for a column a migration had already renamed -- which only the code from before that migration asks for -- while the operator had built and pushed the version after it. Three things had to be true for that to take three rounds to diagnose. Nothing recorded the build. Every log event now carries Build, and the first line of every boot names it alongside the environment and where searchable logs are going, so "is this pod running the code I think it is" is answerable from one line. The searchable copy went nowhere. Serilog:Seq:ServerUrl shipped as http://localhost:5341, which every deployment inherits and which in a container resolves to itself. The batched sink retries against nothing and the operator reads an empty Seq as silence. The base file now ships blank -- console-only, and it says so -- and the local convenience moves to appsettings.Development.json. Failures thrown outside the MediatR pipeline reached no sink at all. GlobalExceptionFilter logged nothing on the grounds that RequestFailureObserver had, but that only sees exceptions escaping a handler; anything from a controller, model binding or an auth filter was a masked 500 with no line anywhere. The filter now records what the observer marked as unrecorded, at the same severity. Also refuses to start when DbUp discovers no migration scripts. They travel as content files beside the assembly, and if that copy is ever missing PerformUpgrade reports success having applied nothing, which presents exactly as this incident did. --- .../Filters/GlobalExceptionFilter.cs | 36 ++++- backend/src/CodeSpace.Api/Program.cs | 17 +++ .../appsettings.Development.json | 5 + backend/src/CodeSpace.Api/appsettings.json | 13 +- .../src/CodeSpace.Core/CodeSpace.Core.csproj | 6 + .../CodeSpace.Core/Failures/FailureLogging.cs | 40 +++++ .../Failures/RequestFailureObserver.cs | 21 +-- .../Persistence/Db/DbUpRunner.cs | 44 +++++- .../Settings/Logging/BuildIdentity.cs | 36 +++++ .../Filters/FailuresAreAlwaysLoggedTests.cs | 141 ++++++++++++++++++ .../Filters/GlobalExceptionFilterTests.cs | 3 +- .../Persistence/MigrationDiscoveryTests.cs | 60 ++++++++ .../Settings/SeqSinkSettingsTests.cs | 33 +++- 13 files changed, 426 insertions(+), 29 deletions(-) create mode 100644 backend/src/CodeSpace.Core/Failures/FailureLogging.cs create mode 100644 backend/src/CodeSpace.Core/Settings/Logging/BuildIdentity.cs create mode 100644 backend/tests/CodeSpace.IntegrationTests/Filters/FailuresAreAlwaysLoggedTests.cs create mode 100644 backend/tests/CodeSpace.UnitTests/Persistence/MigrationDiscoveryTests.cs diff --git a/backend/src/CodeSpace.Api/Filters/GlobalExceptionFilter.cs b/backend/src/CodeSpace.Api/Filters/GlobalExceptionFilter.cs index 5fd9e3d27..200c9e4f0 100644 --- a/backend/src/CodeSpace.Api/Filters/GlobalExceptionFilter.cs +++ b/backend/src/CodeSpace.Api/Filters/GlobalExceptionFilter.cs @@ -15,16 +15,25 @@ namespace CodeSpace.Api.Filters; /// surface consults. What is left here is the one thing that is genuinely HTTP's business: which /// status number to write, and what a caller is allowed to be told. /// -/// Nothing is logged here. RequestFailureObserver already recorded it at the severity -/// the failure's kind implies, for every request on every transport; logging again would double every -/// line and disagree about severity on half of them. +/// It also records anything nobody else did. RequestFailureObserver covers every +/// exception that escapes a MediatR HANDLER and marks it, so this stays quiet for those rather than +/// doubling the line. What it does not cover is everything thrown OUTSIDE the pipeline — a controller +/// around its Send, model binding, an auth filter, a middleware — and that gap was silent: the +/// caller got a masked 500 and no log line existed anywhere, on any sink, so the failure was +/// indistinguishable from one that never happened. /// public sealed class GlobalExceptionFilter : IExceptionFilter { + private readonly ILogger _logger; + + public GlobalExceptionFilter(ILogger logger) { _logger = logger; } + public void OnException(ExceptionContext context) { var failure = FailureClassifier.Classify(context.Exception); + LogIfNobodyElseDid(context, failure); + var body = new Dictionary { ["code"] = failure.Code, ["message"] = failure.ClientMessage }; // Details are what the caller must act on — the provider to link, the scopes to grant. They @@ -44,6 +53,27 @@ public void OnException(ExceptionContext context) context.ExceptionHandled = true; } + /// + /// Record the failure unless the MediatR observer already did. Same severity table, so a failure + /// does not change how loud it is depending on which layer happened to catch it. + /// + private void LogIfNobodyElseDid(ExceptionContext context, FailureClassification failure) + { + // The caller leaving is not a failure, and the observer skips it for the same reason. + if (context.Exception is OperationCanceledException) return; + + if (FailureLogging.WasLogged(context.Exception)) return; + + _logger.Log( + FailureLogging.SeverityFor(failure.Kind), + context.Exception, + "{Method} {Path} failed outside the request pipeline: {FailureKind}/{FailureCode}", + context.HttpContext.Request.Method, + context.HttpContext.Request.Path.Value, + failure.Kind, + failure.Code); + } + /// /// One kind, one status. The single conditional is upstream mirroring: what a dependency actually /// answered is more useful to the caller than a blanket 502 — a provider's 404 means the repository diff --git a/backend/src/CodeSpace.Api/Program.cs b/backend/src/CodeSpace.Api/Program.cs index 7ded574de..1ca52137d 100644 --- a/backend/src/CodeSpace.Api/Program.cs +++ b/backend/src/CodeSpace.Api/Program.cs @@ -42,6 +42,16 @@ public static void Main(string[] args) try { + // First line of every boot, on the console, which is the one sink that is always attached. + // It is what makes an empty Seq answerable: either this line names the server, and a missing + // event is a real gap worth chasing, or it says console-only and the search was never going + // to find anything. + var seqDestination = new SerilogServerUrlSetting(configuration).Value; + Log.Information("Running build {Build} in {Environment}; logging to console, searchable copy: {SeqDestination}", + BuildIdentity.Value, + environment, + string.IsNullOrWhiteSpace(seqDestination) ? "none — Seq is off, set " + SerilogServerUrlSetting.ConfigurationKey + " to enable it" : seqDestination); + Log.Information("Configuring {Application} host...", application); new DbUpRunner(new CodeSpaceConnectionString(configuration).Value).Run(); @@ -84,8 +94,15 @@ public static void Main(string[] args) private static Serilog.ILogger BuildLogger(IConfiguration configuration, string application) { var logger = new LoggerConfiguration() + // Levels come from Serilog:MinimumLevel in settings, so a deployment can turn a subsystem + // up to Debug without a rebuild. Read FIRST: the sinks below are added on top of whatever + // it configures rather than replaced by it. + .ReadFrom.Configuration(configuration) .Enrich.FromLogContext() .Enrich.WithProperty("Application", application) + // Which build produced this line. Without it, a log cannot answer the first question of + // any deployment incident -- is this pod even running the code I think it is. + .Enrich.WithProperty("Build", BuildIdentity.Value) .WriteTo.Console(); var seqServerUrl = new SerilogServerUrlSetting(configuration).Value; diff --git a/backend/src/CodeSpace.Api/appsettings.Development.json b/backend/src/CodeSpace.Api/appsettings.Development.json index a4f03e096..d2fd35122 100644 --- a/backend/src/CodeSpace.Api/appsettings.Development.json +++ b/backend/src/CodeSpace.Api/appsettings.Development.json @@ -20,5 +20,10 @@ "Microsoft.AspNetCore": "Warning", "Microsoft.EntityFrameworkCore.Database.Command": "Information" } + }, + "Serilog": { + "Seq": { + "ServerUrl": "http://localhost:5341" + } } } diff --git a/backend/src/CodeSpace.Api/appsettings.json b/backend/src/CodeSpace.Api/appsettings.json index ee4f820e5..c1a1b5f29 100644 --- a/backend/src/CodeSpace.Api/appsettings.json +++ b/backend/src/CodeSpace.Api/appsettings.json @@ -1,9 +1,18 @@ { "Serilog": { "Application": "CodeSpace.Api", + "MinimumLevel": { + "Default": "Information", + "Override": { + "Microsoft": "Warning", + "Microsoft.Hosting.Lifetime": "Information", + "Microsoft.EntityFrameworkCore.Database.Command": "Warning", + "System": "Warning" + } + }, "Seq": { - "_doc": "Where structured logs go to be searched later; the console keeps printing either way. ServerUrl defaults to a Seq on the developer's own machine and is never checked — the sink batches in the background, so no Seq running means no Seq, not a slower or failing boot. Blank it to turn Seq off outright rather than aim it at a host that will refuse every batch. ApiKey is empty because a local Seq ingests anonymously; only a locked-down deployment needs to set it.", - "ServerUrl": "http://localhost:5341", + "_doc": "Where structured logs go to be searched later; the console keeps printing either way. ServerUrl is BLANK here on purpose: a deployment that has not named its Seq gets honest console-only logging, and says so at startup. Shipping a default of localhost:5341 instead would aim every deployed pod at itself, where nothing is listening -- and an empty Seq is indistinguishable from an application that had nothing to report. appsettings.Development.json keeps localhost:5341 so a developer still needs no configuration. ApiKey is only needed by a Seq that refuses anonymous ingestion.", + "ServerUrl": "", "ApiKey": "" } }, diff --git a/backend/src/CodeSpace.Core/CodeSpace.Core.csproj b/backend/src/CodeSpace.Core/CodeSpace.Core.csproj index be42f28a2..bb3c51faa 100644 --- a/backend/src/CodeSpace.Core/CodeSpace.Core.csproj +++ b/backend/src/CodeSpace.Core/CodeSpace.Core.csproj @@ -48,6 +48,12 @@ PreserveNewest PreserveNewest + diff --git a/backend/src/CodeSpace.Core/Failures/FailureLogging.cs b/backend/src/CodeSpace.Core/Failures/FailureLogging.cs new file mode 100644 index 000000000..77c1d082e --- /dev/null +++ b/backend/src/CodeSpace.Core/Failures/FailureLogging.cs @@ -0,0 +1,40 @@ +using CodeSpace.Messages.Failures; +using Microsoft.Extensions.Logging; + +namespace CodeSpace.Core.Failures; + +/// +/// How a failure is recorded, kept in one place so every surface that might record one agrees on the +/// severity and so exactly one of them does. +/// +/// Severity follows what the failure MEANS, not where it happened. A refusal is the system +/// working and belongs at Information; only a broken invariant or a dependency outage is worth waking +/// someone for, and burying those under a stream of expected 403s is how that stops working. +/// +public static class FailureLogging +{ + /// + /// Key stamped on once a failure has been recorded, so a later + /// surface can tell "already logged, don't repeat it" apart from "nobody logged this at all". + /// + /// Carried on the exception rather than in a scope or an ambient flag because the two + /// recorders are in different layers with no shared lifetime — a MediatR exception action in + /// Core and an MVC filter in Api — and the exception is the only thing that provably travels + /// from one to the other. + /// + private const string LoggedKey = "CodeSpace.FailureLogged"; + + public static void MarkLogged(Exception exception) => exception.Data[LoggedKey] = true; + + public static bool WasLogged(Exception exception) => exception.Data.Contains(LoggedKey); + + /// The severity a failure of this kind is worth. See the class remarks. + public static LogLevel SeverityFor(FailureKind kind) => kind switch + { + FailureKind.Internal => LogLevel.Error, + FailureKind.Unavailable => LogLevel.Error, + FailureKind.Conflict => LogLevel.Warning, + FailureKind.Exhausted => LogLevel.Warning, + _ => LogLevel.Information, + }; +} diff --git a/backend/src/CodeSpace.Core/Middlewares/Failures/RequestFailureObserver.cs b/backend/src/CodeSpace.Core/Middlewares/Failures/RequestFailureObserver.cs index 8e5d1d9d5..0bdfc6b5c 100644 --- a/backend/src/CodeSpace.Core/Middlewares/Failures/RequestFailureObserver.cs +++ b/backend/src/CodeSpace.Core/Middlewares/Failures/RequestFailureObserver.cs @@ -44,7 +44,7 @@ public Task Execute(TRequest request, TException exception, CancellationToken ca var failure = FailureClassifier.Classify(exception); _logger.Log( - SeverityFor(failure.Kind), + FailureLogging.SeverityFor(failure.Kind), exception, "{RequestName} failed: {FailureKind}/{FailureCode} user={UserId} team={TeamId}", typeof(TRequest).Name, @@ -53,20 +53,11 @@ public Task Execute(TRequest request, TException exception, CancellationToken ca _currentUser.Id, _currentTeam.Id); + // Tells the MVC filter this one is already accounted for. Without the mark it cannot tell + // "recorded here" from "thrown somewhere the pipeline never saw", and it has to assume the + // latter or those failures reach nobody. + FailureLogging.MarkLogged(exception); + return Task.CompletedTask; } - - /// - /// Severity follows what the failure MEANS, not where it happened. A refusal is the system working - /// and belongs at Information; only a broken invariant or a dependency outage is worth waking - /// someone for, and burying those under a stream of expected 403s is how that stops working. - /// - private static LogLevel SeverityFor(FailureKind kind) => kind switch - { - FailureKind.Internal => LogLevel.Error, - FailureKind.Unavailable => LogLevel.Error, - FailureKind.Conflict => LogLevel.Warning, - FailureKind.Exhausted => LogLevel.Warning, - _ => LogLevel.Information, - }; } diff --git a/backend/src/CodeSpace.Core/Persistence/Db/DbUpRunner.cs b/backend/src/CodeSpace.Core/Persistence/Db/DbUpRunner.cs index 2a650b5a5..04aadd552 100644 --- a/backend/src/CodeSpace.Core/Persistence/Db/DbUpRunner.cs +++ b/backend/src/CodeSpace.Core/Persistence/Db/DbUpRunner.cs @@ -47,7 +47,11 @@ public void Run() try { - Apply(BuildEngine().PerformUpgrade()); + var engine = BuildEngine(); + + EnsureScriptsWereFound(engine); + + Apply(engine.PerformUpgrade()); } finally { @@ -79,18 +83,22 @@ private static void Execute(NpgsqlConnection gate, string sql) command.ExecuteNonQuery(); } + /// + /// The script names DbUp would journal, without connecting to anything. Exists for + /// MigrationDiscoveryTests, which guards the two silent packaging failures: finding no + /// scripts at all, and finding each one twice under two provider-specific names. + /// + public static IReadOnlyList DiscoverScriptNames() => + new DbUpRunner(string.Empty).BuildEngine().GetDiscoveredScripts().Select(script => script.Name).ToList(); + private UpgradeEngine BuildEngine() { var assemblyLocation = Path.GetDirectoryName(Assembly.GetExecutingAssembly().Location) ?? string.Empty; - var embeddedResourcePrefix = ScriptFolder.Replace(Path.DirectorySeparatorChar, '.'); return DeployChanges.To.PostgresqlDatabase(_connectionString) .WithScriptsFromFileSystem( Path.Combine(assemblyLocation, ScriptFolder), new FileSystemScriptOptions { IncludeSubDirectories = true }) - .WithScriptsAndCodeEmbeddedInAssembly( - typeof(DbUpRunner).Assembly, - s => s.StartsWith($"{typeof(DbUpRunner).Assembly.GetName().Name}.{embeddedResourcePrefix}")) // Disable $variable$ substitution — our PBKDF2 hash format uses '$' as a // section separator (pbkdf2$sha256$iter$salt$digest) and DbUp would otherwise // try to expand "$sha256$" as a variable lookup and abort. @@ -100,6 +108,32 @@ private UpgradeEngine BuildEngine() .Build(); } + /// + /// Refuse to "succeed" having found nothing to run. + /// + /// The scripts reach the published image as content files copied next to the assembly. If + /// that copy is ever missing — a Dockerfile that publishes only the DLL, a trimmed layer, a + /// changed output path — DbUp discovers zero scripts, PerformUpgrade returns + /// Successful = true because nothing failed, and the process starts happily against a + /// database that was never migrated. Every failure after that is a confusing one about a missing + /// column, arriving from whichever request happens to touch it first, with nothing anywhere + /// naming the real cause. + /// + /// Zero is never legitimate: this repository has shipped migrations since 0001, so an + /// engine that can see the scripts always finds some, applied or not. + /// + private static void EnsureScriptsWereFound(UpgradeEngine engine) + { + var discovered = engine.GetDiscoveredScripts().Count; + + if (discovered > 0) return; + + throw new InvalidOperationException( + $"DbUp found no migration scripts. Expected them beside the assembly in '{ScriptFolder}' or embedded in " + + $"{typeof(DbUpRunner).Assembly.GetName().Name}. Refusing to start rather than serve requests against a " + + "database nothing has migrated."); + } + private static void Apply(DatabaseUpgradeResult result) { if (result.Successful) return; diff --git a/backend/src/CodeSpace.Core/Settings/Logging/BuildIdentity.cs b/backend/src/CodeSpace.Core/Settings/Logging/BuildIdentity.cs new file mode 100644 index 000000000..c13ee3a2a --- /dev/null +++ b/backend/src/CodeSpace.Core/Settings/Logging/BuildIdentity.cs @@ -0,0 +1,36 @@ +using System.Reflection; + +namespace CodeSpace.Core.Settings.Logging; + +/// +/// Which build this process is. Stamped on every log event and printed at startup, because the +/// alternative is having to infer it. +/// +/// Written after an incident that cost three rounds of diagnosis. A pod answered +/// /api/auth/sign-in with a Postgres 42703 for a column a migration had already renamed, which +/// only the code from BEFORE that migration would ask for — while the operator had built and pushed +/// the version after it. Tags had been reused, so nothing in the logs could say which build was +/// actually running, and the same staleness silently explained the second symptom: that image also +/// predated the Seq sink, so a correctly configured Seq stayed empty and looked like "no errors". +/// +/// The value comes from , which the SDK +/// stamps with the commit sha appended as 1.2.3+abcdef… when building from a git checkout. It +/// therefore identifies the SOURCE, not the tag someone chose to push it under — which is the only +/// form of the answer worth having. +/// +public static class BuildIdentity +{ + /// Version plus commit sha when the SDK stamped one; the bare version otherwise. + public static string Value { get; } = Resolve(); + + private static string Resolve() + { + var assembly = Assembly.GetEntryAssembly() ?? typeof(BuildIdentity).Assembly; + + var informational = assembly.GetCustomAttribute()?.InformationalVersion; + + if (!string.IsNullOrWhiteSpace(informational)) return informational; + + return assembly.GetName().Version?.ToString() ?? "unknown"; + } +} diff --git a/backend/tests/CodeSpace.IntegrationTests/Filters/FailuresAreAlwaysLoggedTests.cs b/backend/tests/CodeSpace.IntegrationTests/Filters/FailuresAreAlwaysLoggedTests.cs new file mode 100644 index 000000000..ef27626fc --- /dev/null +++ b/backend/tests/CodeSpace.IntegrationTests/Filters/FailuresAreAlwaysLoggedTests.cs @@ -0,0 +1,141 @@ +using CodeSpace.Api.Filters; +using CodeSpace.Core.Failures; +using CodeSpace.Core.Middlewares.Failures; +using CodeSpace.Core.Services.Identity; +using CodeSpace.IntegrationTests.Infrastructure; +using CodeSpace.Messages.Exceptions; +using Microsoft.AspNetCore.Http; +using Microsoft.AspNetCore.Mvc; +using Microsoft.AspNetCore.Mvc.Abstractions; +using Microsoft.AspNetCore.Mvc.Filters; +using Microsoft.AspNetCore.Routing; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; +using Shouldly; + +namespace CodeSpace.IntegrationTests.Filters; + +/// +/// Every failure a caller is told about must exist in a log somewhere. Two surfaces can record one — +/// RequestFailureObserver for anything escaping a MediatR handler, and the MVC filter for +/// everything else — and the contract is exactly-once: never zero, never twice. +/// +/// Zero was the real state before this. The filter deliberately logged nothing, on the reasoning +/// that the observer had already done it; but the observer only ever sees exceptions that escape a +/// HANDLER. Anything thrown outside the pipeline — a controller around its Send, model binding, +/// an auth filter — produced a masked 500 and no line on any sink, so an operator searching for the +/// error found an empty result identical to nothing having gone wrong. +/// +[Trait("Category", "Integration")] +public class FailuresAreAlwaysLoggedTests +{ + [Fact] + public void A_failure_the_pipeline_never_saw_is_recorded_by_the_filter() + { + var logger = new CapturingLogger(); + + Run(new InvalidOperationException("thrown in a controller, outside Send"), logger); + + logger.Entries.Count.ShouldBe(1, + customMessage: "An exception thrown outside the MediatR pipeline reaches no other recorder. Without this " + + "line the caller gets a 500 and nothing exists in any sink to explain it."); + } + + /// + /// Drives the REAL observer rather than stamping the mark by hand. Stamping it here would only + /// prove the filter honours a mark, and would stay green if the observer never set one — which is + /// the half that makes exactly-once hold. + /// + [Fact] + public async Task A_failure_the_observer_recorded_is_not_recorded_again_by_the_filter() + { + var exception = new InvalidOperationException("escaped a MediatR handler"); + + var observer = new RequestFailureObserver( + NullLogger>.Instance, + new TestCurrentUser(Guid.NewGuid()), + new StubCurrentTeam(Guid.NewGuid())); + + await observer.Execute("a-request", exception, CancellationToken.None); + + var logger = new CapturingLogger(); + Run(exception, logger); + + logger.Entries.ShouldBeEmpty( + customMessage: "The observer already logged this one; a second line would double every pipeline failure. " + + "If this fails, the observer stopped marking and every pipeline failure is now logged twice."); + } + + /// The other direction: an exception the observer never saw carries no mark, so the filter must record it. + [Fact] + public void An_exception_the_observer_never_saw_carries_no_mark() + { + FailureLogging.WasLogged(new InvalidOperationException("never reached a handler")).ShouldBeFalse(); + } + + /// + /// The severity comes from what the failure MEANS, so an unlogged refusal does not arrive as an + /// error just because it happened to be caught here instead of in the pipeline. + /// + [Theory] + [InlineData(LogLevel.Error)] + public void An_internal_failure_is_recorded_at_error(LogLevel expected) + { + var logger = new CapturingLogger(); + + Run(new Exception("an invariant broke"), logger); + + logger.Entries.Single().Level.ShouldBe(expected); + } + + [Fact] + public void A_refusal_is_recorded_below_error() + { + var logger = new CapturingLogger(); + + Run(new PasswordRotationRequiredException(), logger); + + logger.Entries.Single().Level.ShouldBe(LogLevel.Information, + customMessage: "A refusal is the system working. Recording it as an error is how the real errors get buried."); + } + + /// A caller who left is not a failure, and the observer skips it for the same reason. + [Fact] + public void A_cancelled_request_is_not_recorded() + { + var logger = new CapturingLogger(); + + Run(new OperationCanceledException(), logger); + + logger.Entries.ShouldBeEmpty(); + } + + private static void Run(Exception exception, CapturingLogger logger) + { + var filter = new GlobalExceptionFilter(logger); + var actionContext = new ActionContext(new DefaultHttpContext(), new RouteData(), new ActionDescriptor()); + var context = new ExceptionContext(actionContext, new List()) { Exception = exception }; + + filter.OnException(context); + } + + private sealed class StubCurrentTeam : ICurrentTeam + { + public StubCurrentTeam(Guid? id) { Id = id; } + + public Guid? Id { get; } + public bool IsSet => Id is not null; + } + + private sealed class CapturingLogger : ILogger + { + public List<(LogLevel Level, string Message)> Entries { get; } = new(); + + public IDisposable? BeginScope(TState state) where TState : notnull => null; + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) => + Entries.Add((logLevel, formatter(state, exception))); + } +} diff --git a/backend/tests/CodeSpace.IntegrationTests/Filters/GlobalExceptionFilterTests.cs b/backend/tests/CodeSpace.IntegrationTests/Filters/GlobalExceptionFilterTests.cs index 0eb44eadd..c38fee20c 100644 --- a/backend/tests/CodeSpace.IntegrationTests/Filters/GlobalExceptionFilterTests.cs +++ b/backend/tests/CodeSpace.IntegrationTests/Filters/GlobalExceptionFilterTests.cs @@ -8,6 +8,7 @@ using Microsoft.AspNetCore.Mvc.Abstractions; using Microsoft.AspNetCore.Mvc.Filters; using Microsoft.AspNetCore.Routing; +using Microsoft.Extensions.Logging.Abstractions; using Shouldly; namespace CodeSpace.IntegrationTests.Filters; @@ -149,7 +150,7 @@ public void Password_rotation_required_maps_to_403_with_the_code_the_spa_redirec private static ObjectResult Run(Exception exception) { - var filter = new GlobalExceptionFilter(); + var filter = new GlobalExceptionFilter(NullLogger.Instance); var actionContext = new ActionContext(new DefaultHttpContext(), new RouteData(), new ActionDescriptor()); var context = new ExceptionContext(actionContext, new List()) { Exception = exception }; diff --git a/backend/tests/CodeSpace.UnitTests/Persistence/MigrationDiscoveryTests.cs b/backend/tests/CodeSpace.UnitTests/Persistence/MigrationDiscoveryTests.cs new file mode 100644 index 000000000..888cb8706 --- /dev/null +++ b/backend/tests/CodeSpace.UnitTests/Persistence/MigrationDiscoveryTests.cs @@ -0,0 +1,60 @@ +using CodeSpace.Core.Persistence.Db; +using Shouldly; + +namespace CodeSpace.UnitTests.Persistence; + +/// +/// What DbUp can see before it is allowed to change anything. +/// +/// Two failure modes, opposite to each other, and both silent. Discovering NOTHING makes +/// PerformUpgrade report success having applied nothing, so the process starts against an +/// unmigrated database and the first request to touch a missing column carries the only evidence. +/// Discovering everything TWICE is worse: DbUp journals a script by NAME, and the same file reached +/// through two providers arrives under two different names, so every migration in the repository +/// would be applied a second time to a database that already has them. +/// +[Trait("Category", "Unit")] +public class MigrationDiscoveryTests +{ + [Fact] + public void Every_migration_is_discovered_exactly_once() + { + var names = DbUpRunner.DiscoverScriptNames(); + + var duplicates = names + .GroupBy(FileNameOf, StringComparer.OrdinalIgnoreCase) + .Where(group => group.Count() > 1) + .Select(group => $"{group.Key} discovered as [{string.Join(", ", group)}]") + .ToList(); + + duplicates.ShouldBeEmpty( + customMessage: "The same migration is reachable through more than one script provider, under a different " + + "name each way. DbUp journals by name, so on any existing database the second name is " + + "unapplied and every one of these would run again:\n" + string.Join("\n", duplicates)); + } + + /// + /// Zero is never legitimate — the repository has shipped migrations since 0001 — so this failing + /// means the scripts did not travel with the build, which is the shape a packaging change takes. + /// + [Fact] + public void Migrations_travel_with_the_build() + { + DbUpRunner.DiscoverScriptNames().Count.ShouldBeGreaterThan(100, + customMessage: "DbUp found (almost) no migration scripts. They are copied next to the assembly by the " + + "Content item in CodeSpace.Core.csproj; if that stops happening, a deployed image migrates " + + "nothing and reports success."); + } + + /// The name DbUp journals is the file name, which is what every existing database already records. + [Fact] + public void Scripts_are_journalled_under_their_bare_file_name() + { + DbUpRunner.DiscoverScriptNames().ShouldContain( + name => name.EndsWith("0001_initial.sql", StringComparison.OrdinalIgnoreCase), + customMessage: "0001_initial.sql must be discoverable. If its journalled name ever changes shape, every " + + "deployed database sees the whole history as unapplied."); + } + + private static string FileNameOf(string scriptName) => scriptName.Split('.', '/', '\\')[^2] + ".sql"; +} diff --git a/backend/tests/CodeSpace.UnitTests/Settings/SeqSinkSettingsTests.cs b/backend/tests/CodeSpace.UnitTests/Settings/SeqSinkSettingsTests.cs index 9dda5c278..aeddfc230 100644 --- a/backend/tests/CodeSpace.UnitTests/Settings/SeqSinkSettingsTests.cs +++ b/backend/tests/CodeSpace.UnitTests/Settings/SeqSinkSettingsTests.cs @@ -60,11 +60,31 @@ public void Neither_setting_carries_a_fallback_of_its_own() new SerilogApiKeySetting(empty).Value.ShouldBeNull(); } + /// + /// The base file ships NO server. A deployment that has not named its Seq then gets honest + /// console-only logging and says so at startup. + /// + /// It used to ship http://localhost:5341, which every deployed pod inherited and + /// which resolves inside the container to itself, where nothing listens. The batched sink retries + /// against nothing forever and the operator sees an empty Seq — indistinguishable from an + /// application with nothing to report. That cost a real incident: an error was in the pod's + /// console the whole time while Seq was searched and found clean. + /// [Fact] - public void The_shipped_default_is_a_seq_on_the_developers_own_machine() + public void The_base_file_ships_no_seq_so_an_unconfigured_deployment_is_honest_about_it() { - new SerilogServerUrlSetting(ShippedApiConfiguration()).Value.ShouldBe("http://localhost:5341", - customMessage: "the committed Serilog:Seq:ServerUrl no longer points at the default local Seq port — a developer following the README would log to nowhere"); + new SerilogServerUrlSetting(ShippedApiConfiguration()).Value.ShouldBeNullOrEmpty( + customMessage: "appsettings.json must not name a Seq. Any value here is inherited by every deployment that " + + "does not override it, and a wrong one is worse than none: it makes an empty Seq look like silence."); + } + + /// The developer convenience the base file gives up, kept where it cannot reach a deployment. + [Fact] + public void Development_still_points_at_the_local_seq_so_a_developer_configures_nothing() + { + new SerilogServerUrlSetting(ShippedDevelopmentConfiguration()).Value.ShouldBe("http://localhost:5341", + customMessage: "appsettings.Development.json is what makes a local Seq zero-config; without it a developer " + + "following the README logs to nowhere."); } [Fact] @@ -80,6 +100,13 @@ private static IConfiguration Build(Dictionary values) => private static IConfiguration ShippedApiConfiguration() => new ConfigurationBuilder().AddJsonFile(LocateApiAppSettings(), optional: false).Build(); + /// The configuration a DEVELOPER boots on — base plus the Development overlay, in the order the host layers them. + private static IConfiguration ShippedDevelopmentConfiguration() => + new ConfigurationBuilder() + .AddJsonFile(LocateApiAppSettings(), optional: false) + .AddJsonFile(LocateApiAppSettings().Replace("appsettings.json", "appsettings.Development.json"), optional: false) + .Build(); + private static string LocateApiAppSettings() { for (var dir = new DirectoryInfo(AppContext.BaseDirectory); dir is not null; dir = dir.Parent)