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/docs/dependencies.md b/docs/dependencies.md index 1db8ffdfb..7b0079f15 100644 --- a/docs/dependencies.md +++ b/docs/dependencies.md @@ -15,6 +15,7 @@ Central package versions are pinned in `Directory.Packages.props`; this page lin | `Microsoft.Build` (+ `.Framework`, `.Tasks.Core`, `.Utilities.Core`) | MSBuild engine — read/evaluate `.csproj`/`.props` files | `Fallout.ProjectModel`, `Fallout.MSBuildTasks` | | `Microsoft.Build.Locator` | Locate an installed MSBuild at runtime | `Fallout.ProjectModel` | | `Microsoft.CodeAnalysis.*` (CSharp, Workspaces, MSBuild, Analyzers) | Roslyn — C# parsing/compilation/analysis | `Fallout.SourceGenerators`, `Fallout.Cli` (Cake rewriter) | +| `Microsoft.Extensions.DependencyInjection` | DI container for the per-run composition root that wires the logging seam ([#428](https://github.com/Fallout-build/Fallout/issues/428)) | `Fallout.Build`. Note the footprint: `Fallout.Build` is consumer-facing, so every consumer now pulls the container transitively. Deliberate, not accidental. It currently serves one internal composition root, and the plugin foundation ([milestone #6](https://github.com/Fallout-build/Fallout/milestone/6)) is what will use it more widely. | | `Microsoft.Extensions.DependencyModel` | Parse `.deps.json` runtime metadata | `Fallout.Build` | | `Microsoft.SourceLink.GitHub` | Source-link symbols into published nupkgs so debuggers can step into Fallout | All packable libs | | `Nerdbank.GitVersioning` | Build-time semver derived from git history | All packable libs | @@ -27,6 +28,8 @@ Central package versions are pinned in `Directory.Packages.props`; this page lin |---|---| | `Serilog` + `Sinks.Console` + `Sinks.File` | The logging framework. All `Log.Information/Warning/Error` calls route through this. | | `Serilog.Formatting.Compact` (+ `.Reader`) | Structured JSON log format for machine-readable logs | +| `Serilog.Extensions.Logging` | Serilog provider for `Microsoft.Extensions.Logging`. Backs the `ILogger` seam in `Fallout.Build`, so framework code logs against the abstraction while Serilog stays the provider. | +| `Microsoft.Extensions.Logging.Abstractions` | The `ILogger` / `ILoggerFactory` abstraction itself. Abstractions only, no implementation and no filter pipeline. | ## Azure diff --git a/src/Fallout.Build/Execution/BuildManager.cs b/src/Fallout.Build/Execution/BuildManager.cs index 33fe49dc3..d4eb6a68e 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,20 @@ 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 { + // Configure installs the pipeline; AddFalloutLogging only registers the abstraction over + // it. Order matters here rather than inside the registration: a logger binds the ambient + // pipeline when it is created, so the pipeline has to exist before anything resolves one. Logging.Configure(build); + services = new ServiceCollection().AddFalloutLogging().BuildServiceProvider(); + loggerFactoryScope = Logging.UseLoggerFactory(services.GetRequiredService()); build.ExecutableTargets = ExecutableTargetFactory.CreateAll(build, defaultTargetExpressions); build.ExecuteExtension(x => x.OnBuildCreated(build.ExecutableTargets)); @@ -89,6 +102,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..3cf968bdf --- /dev/null +++ b/src/Fallout.Build/Logging.DependencyInjection.cs @@ -0,0 +1,59 @@ +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 +{ + /// + /// Registers the abstraction over the Serilog pipeline. + /// + /// + /// Registration only. This method never touches the pipeline, so any container can call it, any + /// number of times. Installing the pipeline is , which the caller + /// runs explicitly just before it builds the provider. + /// + /// The two are kept apart because is not idempotent. It + /// reassigns Serilog's Log.Logger on every call. Called with no build, it installs a + /// pipeline with no file sinks, no host sink and no filter. A second container calling this + /// method would then wipe out the pipeline the first one had set up. + /// + /// Deliberately not services.AddLogging(...). That installs Microsoft.Extensions.Logging's + /// own filter pipeline, whose default minimum is . It would be + /// a second authority on levels, dropping trace and debug records before Serilog ever saw them. + /// Registering the Serilog factory directly leaves as the only + /// thing that decides what gets logged. + /// + public static IServiceCollection AddFalloutLogging(this IServiceCollection services) + { + // Safe as a singleton because the factory is left unbound: it reads the ambient pipeline + // every time it creates a logger. See Logging.CreateSerilogLoggerFactory. + services.TryAddSingleton(_ => Logging.CreateSerilogLoggerFactory()); + + // Transient, not singleton. Logger resolves its inner logger in its constructor, and the + // non-generic lambda would run once per container. As singletons, both would pin every + // consumer to whichever pipeline was current at the first resolution. Log.Logger does not + // stay put during a run: Configure installs it late, and Host.WriteErrorsAndWarnings swaps + // it again to render the end-of-build summary. + // + // Transient means each resolution binds to the pipeline that is current right now. It does + // not rescue a component that resolves a logger once and holds it across a swap. Any + // component that outlives a swap must read Logging.Logger at the point of writing instead. + services.TryAddTransient(typeof(ILogger<>), typeof(Logger<>)); + services.TryAddTransient(sp => sp.GetRequiredService().CreateLogger(Logging.DefaultCategoryName)); + + return services; + } +} diff --git a/src/Fallout.Build/Logging.cs b/src/Fallout.Build/Logging.cs index 978674058..107ddef32 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,61 @@ 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. Three consequences the callers + /// depend on. runs before the container is built, so a resolved logger + /// can never bind a pipeline that is already gone. The container registrations for + /// ILogger<T> and are transient, so each + /// resolution binds the pipeline that is current right now. And is not + /// cached, for the same reason. A component that resolves a logger once and holds it across a + /// reassignment still writes into the old pipeline, so anything living that long must read + /// at the point of writing. + /// + /// 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..5f92ab7d7 --- /dev/null +++ b/tests/Fallout.Build.Specs/LoggerBridgeSpecs.cs @@ -0,0 +1,333 @@ +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 Microsoft.Extensions.Logging.Abstractions; +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 A_container_logger_binds_the_pipeline_current_at_resolution() + { + // The container-side pair of The_facade_logger_tracks_the_current_pipeline. Logger binds + // its inner logger in its constructor, so the registration has to be transient. As a + // singleton it would strand every consumer on whichever pipeline was current at the first + // resolution, which is the failure Logging.Logger stays uncached to avoid. + var sink = new CollectingSink(); + + using var pipeline = PreserveAmbientPipeline(); + using var services = new ServiceCollection().AddFalloutLogging().BuildServiceProvider(); + + services.GetRequiredService>(); + + Log.Logger = CreateLogger(sink); + services.GetRequiredService>().LogWarning(Marker + " after the swap"); + + sink.Marked.Should().ContainSingle(); + } + + [Fact] + public void The_container_hands_out_a_new_logger_per_resolution() + { + using var pipeline = PreserveAmbientPipeline(); + using var services = new ServiceCollection().AddFalloutLogging().BuildServiceProvider(); + + services.GetRequiredService>() + .Should().NotBeSameAs(services.GetRequiredService>()); + services.GetRequiredService() + .Should().NotBeSameAs(services.GetRequiredService()); + } + + [Fact] + public void Registering_the_seam_leaves_the_pipeline_alone() + { + // AddFalloutLogging registers, it does not configure. Logging.Configure is not idempotent: + // with no build it installs a pipeline with no file sinks, no host sink and no filter. A + // second container calling AddFalloutLogging must not wipe out the pipeline the first one + // is using. + using var pipeline = PreserveAmbientPipeline(); + Log.Logger = CreateLogger(new CollectingSink()); + var installed = Log.Logger; + + using var services = new ServiceCollection().AddFalloutLogging().BuildServiceProvider(); + + Log.Logger.Should().BeSameAs(installed); + } + + [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 + { + // A no-op rather than a throw: this stub owns the process-wide Logging.Factory while it + // is installed, and #428 moves framework code onto Logging.Logger. A throwing stub would + // turn any unrelated log write during that window into an intermittent failure. + public ILogger CreateLogger(string categoryName) => NullLogger.Instance; + + public void AddProvider(ILoggerProvider provider) => throw new NotSupportedException(); + + public void Dispose() + { + } + } +}