Make a failure and the build that produced it visible in the logs

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.</para>
 ///
-/// <para>Nothing is logged here. <c>RequestFailureObserver</c> 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.</para>
+/// <para>It also records anything nobody else did. <c>RequestFailureObserver</c> 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 <c>Send</c>, 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.</para>
 /// </summary>
 public sealed class GlobalExceptionFilter : IExceptionFilter
 {
+    private readonly ILogger<GlobalExceptionFilter> _logger;
+
+    public GlobalExceptionFilter(ILogger<GlobalExceptionFilter> logger) { _logger = logger; }
+
     public void OnException(ExceptionContext context)
     {
         var failure = FailureClassifier.Classify(context.Exception);
 
+        LogIfNobodyElseDid(context, failure);
+
         var body = new Dictionary<string, object?> { ["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;
     }
 
+    /// <summary>
+    /// 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.
+    /// </summary>
+    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);
+    }
+
     /// <summary>
     /// 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

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;

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

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": ""
     }
   },

backend/src/CodeSpace.Core/CodeSpace.Core.csproj

@@ -48,6 +48,12 @@
       <CopyToPublishDirectory>PreserveNewest</CopyToPublishDirectory>
       <CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
     </Content>
+    <!-- Deliberately NOT also <EmbeddedResource>. DbUp journals a script by NAME, and the two
+         providers name the same file differently — "0001_initial.sql" from the file system,
+         "CodeSpace.Core.Persistence.DbUpFiles.0001_initial.sql" embedded. Adding the second source
+         makes every already-applied migration look unapplied under its new name, so the next deploy
+         re-runs the entire history against a live database. MigrationDiscoveryTests fails if anyone
+         adds it. -->
   </ItemGroup>
 
   <ItemGroup>

backend/src/CodeSpace.Core/Failures/FailureLogging.cs

@@ -0,0 +1,40 @@
+using CodeSpace.Messages.Failures;
+using Microsoft.Extensions.Logging;
+
+namespace CodeSpace.Core.Failures;
+
+/// <summary>
+/// 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.
+///
+/// <para>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.</para>
+/// </summary>
+public static class FailureLogging
+{
+    /// <summary>
+    /// Key stamped on <see cref="Exception.Data"/> 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".
+    ///
+    /// <para>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.</para>
+    /// </summary>
+    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);
+
+    /// <summary>The severity a failure of this kind is worth. See the class remarks.</summary>
+    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,
+    };
+}

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;
     }
-
-    /// <summary>
-    /// 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.
-    /// </summary>
-    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,
-    };
 }

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();
     }
 
+    /// <summary>
+    /// The script names DbUp would journal, without connecting to anything. Exists for
+    /// <c>MigrationDiscoveryTests</c>, which guards the two silent packaging failures: finding no
+    /// scripts at all, and finding each one twice under two provider-specific names.
+    /// </summary>
+    public static IReadOnlyList<string> 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();
     }
 
+    /// <summary>
+    /// Refuse to "succeed" having found nothing to run.
+    ///
+    /// <para>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, <c>PerformUpgrade</c> returns
+    /// <c>Successful = true</c> 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.</para>
+    ///
+    /// <para>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.</para>
+    /// </summary>
+    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;

backend/src/CodeSpace.Core/Settings/Logging/BuildIdentity.cs

@@ -0,0 +1,36 @@
+using System.Reflection;
+
+namespace CodeSpace.Core.Settings.Logging;
+
+/// <summary>
+/// Which build this process is. Stamped on every log event and printed at startup, because the
+/// alternative is having to infer it.
+///
+/// <para>Written after an incident that cost three rounds of diagnosis. A pod answered
+/// <c>/api/auth/sign-in</c> 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".</para>
+///
+/// <para>The value comes from <see cref="AssemblyInformationalVersionAttribute"/>, which the SDK
+/// stamps with the commit sha appended as <c>1.2.3+abcdef…</c> 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.</para>
+/// </summary>
+public static class BuildIdentity
+{
+    /// <summary>Version plus commit sha when the SDK stamped one; the bare version otherwise.</summary>
+    public static string Value { get; } = Resolve();
+
+    private static string Resolve()
+    {
+        var assembly = Assembly.GetEntryAssembly() ?? typeof(BuildIdentity).Assembly;
+
+        var informational = assembly.GetCustomAttribute<AssemblyInformationalVersionAttribute>()?.InformationalVersion;
+
+        if (!string.IsNullOrWhiteSpace(informational)) return informational;
+
+        return assembly.GetName().Version?.ToString() ?? "unknown";
+    }
+}