From fa225423e352c008fa7ea178f8f1b7f6d670c7cb Mon Sep 17 00:00:00 2001 From: Philippe Matray Date: Mon, 10 Aug 2026 14:14:52 +0200 Subject: [PATCH] Put an ILogger seam over the Serilog pipeline Framework code reaches logging through Serilog's static Log, which pins the project to one logger implementation and leaks Serilog types outward. Introduce Microsoft.Extensions.Logging.ILogger as the abstraction in front of it, keeping Serilog as the provider and the pipeline itself untouched. AddFalloutLogging configures the pipeline and registers the abstraction over it. It deliberately avoids services.AddLogging, which would install MEL's own filter pipeline with an Information default -- a second level authority that would drop trace and debug records before Serilog saw them, displacing Logging.LevelSwitch. BuildManager.Execute now owns a per-run composition root and feeds the resolved factory to a static facade on Logging, so the ~85 Log.* call sites and the static build engine are unchanged. The provider is declared outside the try so it survives into Finish(), but built inside it so a configuration failure still returns the same exit code as before. The seam is internal: it is framework foundation, not public surface yet. Nothing in the public API changes and no output changes. First of the additive PRs in #428. --- Directory.Packages.props | 2 + src/Fallout.Build/Execution/BuildManager.cs | 13 +- src/Fallout.Build/Fallout.Build.csproj | 3 + .../Logging.DependencyInjection.cs | 44 +++ src/Fallout.Build/Logging.cs | 63 ++++ .../Fallout.Build.Specs/LoggerBridgeSpecs.cs | 281 ++++++++++++++++++ 6 files changed, 405 insertions(+), 1 deletion(-) create mode 100644 src/Fallout.Build/Logging.DependencyInjection.cs create mode 100644 tests/Fallout.Build.Specs/LoggerBridgeSpecs.cs diff --git a/Directory.Packages.props b/Directory.Packages.props index 6f67c023b..73ad10e56 100644 --- a/Directory.Packages.props +++ b/Directory.Packages.props @@ -16,11 +16,13 @@ + + diff --git a/src/Fallout.Build/Execution/BuildManager.cs b/src/Fallout.Build/Execution/BuildManager.cs index 33fe49dc3..c3fff90d4 100644 --- a/src/Fallout.Build/Execution/BuildManager.cs +++ b/src/Fallout.Build/Execution/BuildManager.cs @@ -4,7 +4,9 @@ using System.Linq.Expressions; using System.Runtime.CompilerServices; using System.Text; +using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.DependencyModel; +using Microsoft.Extensions.Logging; using Fallout.Common.Tooling; using Fallout.Common.Utilities; using Fallout.Common.Utilities.Collections; @@ -44,9 +46,16 @@ public static int Execute(Expression>[] defaultTargetExpressi using var context = BuildContext.Activate(); var build = new T(); + // The composition root for the run. Declared out here so it survives into `finally` — + // Finish() still writes the outcome summary — but built inside the `try`, so a failure while + // configuring logging is reported the same way it was before there was a container. + ServiceProvider services = null; + IDisposable loggerFactoryScope = null; + try { - Logging.Configure(build); + services = new ServiceCollection().AddFalloutLogging(build).BuildServiceProvider(); + loggerFactoryScope = Logging.UseLoggerFactory(services.GetRequiredService()); build.ExecutableTargets = ExecutableTargetFactory.CreateAll(build, defaultTargetExpressions); build.ExecuteExtension(x => x.OnBuildCreated(build.ExecutableTargets)); @@ -89,6 +98,8 @@ public static int Execute(Expression>[] defaultTargetExpressi { Finish(); Log.CloseAndFlush(); + loggerFactoryScope?.Dispose(); + services?.Dispose(); // Per-run teardown (handler unsubscription + state reset) is owned by the BuildContext, // run when `context` is disposed at method exit. } diff --git a/src/Fallout.Build/Fallout.Build.csproj b/src/Fallout.Build/Fallout.Build.csproj index ea2b968c3..3a5f87428 100644 --- a/src/Fallout.Build/Fallout.Build.csproj +++ b/src/Fallout.Build/Fallout.Build.csproj @@ -18,7 +18,10 @@ + + + diff --git a/src/Fallout.Build/Logging.DependencyInjection.cs b/src/Fallout.Build/Logging.DependencyInjection.cs new file mode 100644 index 000000000..c03871c69 --- /dev/null +++ b/src/Fallout.Build/Logging.DependencyInjection.cs @@ -0,0 +1,44 @@ +using System; +using System.Linq; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.DependencyInjection.Extensions; +using Microsoft.Extensions.Logging; + +namespace Fallout.Common.Execution; + +/// +/// Composition root for the logging seam. Serilog stays the provider — this only puts +/// in front of it so framework code can stop referencing Serilog directly. +/// +/// +/// Internal on purpose: the abstraction is the framework's own foundation, not public surface yet. +/// The root AssemblyInfo.cs grants InternalsVisibleTo to Fallout.Cli and the +/// spec assemblies, which is everything that needs to wire a container today. +/// +internal static class LoggingServiceCollectionExtensions +{ + /// + /// Configures the Serilog pipeline for and registers the + /// abstraction over it. + /// + /// + /// Deliberately not services.AddLogging(...). That installs Microsoft.Extensions.Logging's + /// own filter pipeline, whose default minimum is — a second + /// level authority that would silently drop trace and debug records before Serilog ever saw + /// them. Registering the Serilog factory directly leaves as the + /// only thing deciding what gets logged. + /// + public static IServiceCollection AddFalloutLogging(this IServiceCollection services, IFalloutBuild build = null) + { + Logging.Configure(build); + + services.TryAddSingleton(_ => Logging.CreateSerilogLoggerFactory()); + + // Logger is a thin wrapper that defers to ILoggerFactory, so it inherits the factory + // above rather than introducing a filter pipeline of its own. + services.TryAddSingleton(typeof(ILogger<>), typeof(Logger<>)); + services.TryAddSingleton(sp => sp.GetRequiredService().CreateLogger(Logging.DefaultCategoryName)); + + return services; + } +} diff --git a/src/Fallout.Build/Logging.cs b/src/Fallout.Build/Logging.cs index 978674058..fc2bf8774 100644 --- a/src/Fallout.Build/Logging.cs +++ b/src/Fallout.Build/Logging.cs @@ -10,15 +10,27 @@ using Serilog; using Serilog.Core; using Serilog.Events; +using Serilog.Extensions.Logging; using Serilog.Formatting.Compact; using Serilog.Sinks.SystemConsole.Themes; +// Both Serilog and Microsoft.Extensions.Logging declare an ILogger. This file is the seam between +// them, so the unqualified name is bound to the abstraction the framework codes against; Serilog's +// own pipeline is reached through the static Log class below. +using ILogger = Microsoft.Extensions.Logging.ILogger; +using ILoggerFactory = Microsoft.Extensions.Logging.ILoggerFactory; + namespace Fallout.Common.Execution; public static class Logging { public static readonly LoggingLevelSwitch LevelSwitch = new(); + /// Category for framework log records written without a category of their own. + internal const string DefaultCategoryName = "Fallout"; + + private static ILoggerFactory loggerFactory; + internal static bool SupportsAnsiOutput => Environment.GetEnvironmentVariable("TERM") is { } term && term.StartsWithOrdinalIgnoreCase("xterm"); internal static IHostTheme DefaultTheme { get; } = SupportsAnsiOutput ? AnsiConsoleHostTheme.Default256AnsiColorTheme @@ -36,6 +48,57 @@ public static LogLevel Level set => LevelSwitch.MinimumLevel = value.ToLogEventLevel(); } + /// + /// Logger factory for the current build run, backed by the Serilog pipeline that + /// installs. BuildManager feeds this from its composition root + /// (see AddFalloutLogging). Outside a run there is no container — the CLI commands call + /// directly — so this falls back to a factory over the ambient Serilog + /// pipeline, and the seam is usable either way. + /// + internal static ILoggerFactory Factory => loggerFactory ??= CreateSerilogLoggerFactory(); + + /// + /// Logger for framework code that has no category of its own. Deliberately not cached — each + /// access creates a logger against the pipeline that is current right now, which is what keeps + /// the façade correct across the reassignments described on + /// . + /// + internal static ILogger Logger => Factory.CreateLogger(DefaultCategoryName); + + /// + /// Points at until the returned bracket is + /// disposed. Ownership stays with the caller: disposing the bracket restores the previous + /// factory, it does not dispose . + /// + internal static IDisposable UseLoggerFactory(ILoggerFactory factory) + { + return DelegateDisposable.SetAndRestore(() => loggerFactory, factory.NotNull()); + } + + /// + /// Bridges onto Serilog. + /// + /// + /// Passing no logger leaves the factory itself unbound, so each logger it hands out reads the + /// ambient as it is created. That matters because the pipeline is not + /// stable for the lifetime of the process: installs it late and + /// replaces it on re-entry, and Host.WriteErrorsAndWarnings swaps it again to render the + /// end-of-build summary. Pinning a logger into the factory would strand every consumer on + /// whichever pipeline happened to exist first. + /// + /// Binding still happens per logger rather than per write, because the category name is + /// attached as Serilog's SourceContext at construction. Two consequences the callers + /// depend on: AddFalloutLogging configures the pipeline before it registers the + /// factory, so a container-resolved logger can never bind a stale one; and + /// is not cached. + /// + /// Serilog owns the pipeline's lifetime (Log.CloseAndFlush), hence dispose: false. + /// + internal static ILoggerFactory CreateSerilogLoggerFactory() + { + return new SerilogLoggerFactory(logger: null, dispose: false); + } + public static void Configure(IFalloutBuild build = null) { if (build != null) diff --git a/tests/Fallout.Build.Specs/LoggerBridgeSpecs.cs b/tests/Fallout.Build.Specs/LoggerBridgeSpecs.cs new file mode 100644 index 000000000..ef65d4239 --- /dev/null +++ b/tests/Fallout.Build.Specs/LoggerBridgeSpecs.cs @@ -0,0 +1,281 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using Fallout.Common.Execution; +using Fallout.Common.Utilities; +using FluentAssertions; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Serilog; +using Serilog.Core; +using Serilog.Events; +using Xunit; +using ILogger = Microsoft.Extensions.Logging.ILogger; +using MsLogLevel = Microsoft.Extensions.Logging.LogLevel; + +namespace Fallout.Common.Specs; + +/// +/// Covers the seam over Serilog added for #428. Serilog stays the provider; +/// the bridge only has to be faithful — same severities, same message templates, same exceptions, +/// and no second level authority of its own. +/// +/// +/// Exercising the seam means writing through the ambient , which is +/// process-wide: spec classes outside this collection run in parallel and log as they go, so every +/// message here carries and the collected events are filtered down to it. +/// Without that, a stray warning from another class lands in the sink and fails an assertion. +/// +[Collection(ProcessGlobalStateCollection.Name)] +public class LoggerBridgeSpecs +{ + /// Distinguishes this class's log records from those of concurrently running specs. + private const string Marker = "loggerbridgespec"; + + [Theory] + [InlineData(MsLogLevel.Trace, LogEventLevel.Verbose)] + [InlineData(MsLogLevel.Debug, LogEventLevel.Debug)] + [InlineData(MsLogLevel.Information, LogEventLevel.Information)] + [InlineData(MsLogLevel.Warning, LogEventLevel.Warning)] + [InlineData(MsLogLevel.Error, LogEventLevel.Error)] + [InlineData(MsLogLevel.Critical, LogEventLevel.Fatal)] + public void Each_logger_level_maps_to_its_serilog_level(MsLogLevel level, LogEventLevel expected) + { + var events = Capture(logger => logger.Log(level, Marker + " a line")); + + events.Should().ContainSingle().Which.Level.Should().Be(expected); + } + + [Fact] + public void The_bridge_does_not_filter_below_information() + { + // Regression guard for the AddFalloutLogging registration. Wiring the seam through + // services.AddLogging(...) would install Microsoft.Extensions.Logging's own filter pipeline, + // whose default minimum is Information — trace and debug records would vanish before Serilog + // ever saw them, and the level switch would no longer be the only thing that decides. + using var pipeline = PreserveAmbientPipeline(); + using var services = new ServiceCollection().AddFalloutLogging().BuildServiceProvider(); + + var events = CaptureAmbient(() => + { + var logger = services.GetRequiredService>(); + logger.LogTrace(Marker + " trace line"); + logger.LogDebug(Marker + " debug line"); + }); + + events.Select(x => x.Level).Should().Equal(LogEventLevel.Verbose, LogEventLevel.Debug); + } + + [Fact] + public void The_level_switch_still_gates_the_bridge() + { + var original = FalloutBuild.Verbosity; + try + { + FalloutBuild.Verbosity = Verbosity.Minimal; + + var events = Capture( + logger => + { + logger.LogInformation(Marker + " below the gate"); + logger.LogWarning(Marker + " above the gate"); + }, + configuration => configuration.MinimumLevel.ControlledBy(Logging.LevelSwitch)); + + events.Should().ContainSingle().Which.Level.Should().Be(LogEventLevel.Warning); + } + finally + { + FalloutBuild.Verbosity = original; + } + } + + [Fact] + public void Message_templates_survive_the_bridge() + { + const string Template = Marker + " restored {PackageCount} packages"; + + var events = Capture(logger => logger.LogInformation(Template, 12)); + + var logEvent = events.Should().ContainSingle().Subject; + // The template must stay a template — a pre-rendered string would defeat the structured + // sinks (the compact-JSON interceptor formatter, the file sinks) downstream. + logEvent.MessageTemplate.Text.Should().Be(Template); + logEvent.Properties.Should().ContainKey("PackageCount") + .WhoseValue.Should().BeOfType() + .Which.Value.Should().Be(12); + } + + [Fact] + public void Exceptions_reach_the_log_event() + { + var exception = new InvalidOperationException("boom"); + + var events = Capture(logger => logger.LogError(exception, Marker + " the target failed")); + + events.Should().ContainSingle().Which.Exception.Should().BeSameAs(exception); + } + + [Fact] + public void The_factory_is_not_pinned_to_one_pipeline() + { + // Log.Logger is reassigned during a run — Configure installs it late, and + // Host.WriteErrorsAndWarnings swaps it again for the end-of-build summary. The factory + // itself must stay unbound so a logger it creates afterwards lands in the current pipeline. + var factory = Logging.CreateSerilogLoggerFactory(); + var first = new CollectingSink(); + var second = new CollectingSink(); + + using (PreserveAmbientPipeline()) + { + Log.Logger = CreateLogger(first); + factory.CreateLogger(Logging.DefaultCategoryName).LogWarning(Marker + " before the swap"); + + Log.Logger = CreateLogger(second); + factory.CreateLogger(Logging.DefaultCategoryName).LogWarning(Marker + " after the swap"); + } + + first.Marked.Should().ContainSingle(); + second.Marked.Should().ContainSingle(); + } + + [Fact] + public void The_facade_logger_tracks_the_current_pipeline() + { + // Binding happens once per logger, not once per write, because the category is attached as + // SourceContext at construction. Logging.Logger is therefore deliberately uncached — that is + // what keeps the façade pointed at whichever pipeline is installed right now. + var sink = new CollectingSink(); + + using (PreserveAmbientPipeline()) + { + var before = Logging.Logger; + + Log.Logger = CreateLogger(sink); + Logging.Logger.LogWarning(Marker + " after the swap"); + + Logging.Logger.Should().NotBeSameAs(before); + } + + sink.Marked.Should().ContainSingle(); + } + + [Fact] + public void The_facade_works_without_a_composition_root() + { + // The CLI commands call Logging.Configure() directly, with no container in sight, so the + // façade has to fall back to the ambient pipeline rather than throw. + var events = CaptureAmbient(() => Logging.Logger.LogInformation(Marker + " no container here")); + + events.Should().ContainSingle().Which.Level.Should().Be(LogEventLevel.Information); + } + + [Fact] + public void The_container_resolves_the_logging_abstractions() + { + using var pipeline = PreserveAmbientPipeline(); + using var services = new ServiceCollection().AddFalloutLogging().BuildServiceProvider(); + + services.GetRequiredService().Should().NotBeNull(); + services.GetRequiredService>().Should().NotBeNull(); + services.GetRequiredService().Should().NotBeNull(); + } + + [Fact] + public void Using_a_logger_factory_restores_the_previous_one() + { + var previous = Logging.Factory; + var replacement = new StubLoggerFactory(); + + using (Logging.UseLoggerFactory(replacement)) + { + Logging.Factory.Should().BeSameAs(replacement); + } + + Logging.Factory.Should().BeSameAs(previous); + } + + [Fact] + public void Using_a_null_logger_factory_is_rejected() + { + var act = () => Logging.UseLoggerFactory(factory: null); + + act.Should().Throw(); + } + + /// + /// Writes through a bridged logger against a pipeline that collects this class's records, and + /// returns them. overrides the minimum-level rule. + /// + private static LogEvent[] Capture( + Action write, + Func configure = null) + { + return CaptureAmbient( + () => write.Invoke(Logging.CreateSerilogLoggerFactory().CreateLogger(Logging.DefaultCategoryName)), + configure); + } + + /// Runs against a collecting . + private static LogEvent[] CaptureAmbient( + Action write, + Func configure = null) + { + var sink = new CollectingSink(); + using (PreserveAmbientPipeline()) + { + Log.Logger = CreateLogger(sink, configure); + write.Invoke(); + } + + return sink.Marked.ToArray(); + } + + /// Restores the ambient Serilog pipeline when the returned bracket is disposed. + private static IDisposable PreserveAmbientPipeline() + { + var original = Log.Logger; + return DelegateDisposable.CreateBracket(cleanup: () => Log.Logger = original); + } + + private static Serilog.Core.Logger CreateLogger( + ILogEventSink sink, + Func configure = null) + { + var configuration = new LoggerConfiguration(); + configuration = configure?.Invoke(configuration) ?? configuration.MinimumLevel.Verbose(); + return configuration.WriteTo.Sink(sink).CreateLogger(); + } + + private class CollectingSink : ILogEventSink + { + private readonly List events = new(); + + /// The records this class wrote, with concurrent specs' traffic filtered out. + public IReadOnlyList Marked + { + get + { + lock (events) + return events.Where(x => x.MessageTemplate.Text.Contains(Marker)).ToList(); + } + } + + public void Emit(LogEvent logEvent) + { + lock (events) + events.Add(logEvent); + } + } + + private class StubLoggerFactory : ILoggerFactory + { + public ILogger CreateLogger(string categoryName) => throw new NotSupportedException(); + + public void AddProvider(ILoggerProvider provider) => throw new NotSupportedException(); + + public void Dispose() + { + } + } +}