diff --git a/docs/articles/concepts/bootstrap-lifecycle.md b/docs/articles/concepts/bootstrap-lifecycle.md index 6b45aa98..36d2d8a9 100644 --- a/docs/articles/concepts/bootstrap-lifecycle.md +++ b/docs/articles/concepts/bootstrap-lifecycle.md @@ -55,6 +55,8 @@ builder.UseSquidStd(options => options.ConfigName = "myapp", c => c.RegisterCore Services implementing `ISquidStdService` participate in the lifecycle. On `StartAsync` they are started in registration order; on `StopAsync` they are stopped in reverse order, so dependencies remain available while their dependents shut down. +The bootstrap logs its whole lifecycle: a startup banner with the application name and version (set `SquidStdOptions.AppName`; it defaults to the entry assembly name and is attached to every event as the `Application` / `ApplicationVersion` properties), a registration summary (per-registration detail at Debug), one line per service started with its duration, and the shutdown sequence. A service that fails to stop is logged as a warning and the remaining services are still stopped. Extra Serilog sinks can be plugged by registering `ILogEventSink` instances in the container before start. + ```mermaid sequenceDiagram participant App diff --git a/src/SquidStd.Core/Data/Bootstrap/SquidStdOptions.cs b/src/SquidStd.Core/Data/Bootstrap/SquidStdOptions.cs index 614508d6..ac97e729 100644 --- a/src/SquidStd.Core/Data/Bootstrap/SquidStdOptions.cs +++ b/src/SquidStd.Core/Data/Bootstrap/SquidStdOptions.cs @@ -14,4 +14,10 @@ public sealed class SquidStdOptions /// Gets or sets the logical configuration name or YAML file name. /// public string ConfigName { get; set; } = "squidstd"; + + /// + /// Gets or sets the application name used in the startup banner and as the Serilog + /// "Application" property. When null or empty, the entry assembly name is used. + /// + public string? AppName { get; set; } } diff --git a/src/SquidStd.Services.Core/Services/Bootstrap/SquidStdBootstrap.cs b/src/SquidStd.Services.Core/Services/Bootstrap/SquidStdBootstrap.cs index 2db87fec..fe534e06 100644 --- a/src/SquidStd.Services.Core/Services/Bootstrap/SquidStdBootstrap.cs +++ b/src/SquidStd.Services.Core/Services/Bootstrap/SquidStdBootstrap.cs @@ -1,5 +1,10 @@ +using System.Diagnostics; +using System.Reflection; using DryIoc; using Serilog; +using Serilog.Core; +using Serilog.Events; +using SquidStd.Abstractions.Data.Internal.Config; using SquidStd.Abstractions.Data.Internal.Services; using SquidStd.Abstractions.Interfaces.Services; using SquidStd.Core.Data.Bootstrap; @@ -159,8 +164,25 @@ public async ValueTask StartAsync(CancellationToken cancellationToken = default) try { + ConfigureLogging(); + + var logger = Log.ForContext(); + var appName = ResolveAppName(Options); + + logger.Information( + "{Application:l} {ApplicationVersion:l} starting (SquidStd {SquidStdVersion:l}, config {ConfigName}, root {RootDirectory})", + appName, + ResolveVersion(Assembly.GetEntryAssembly()), + ResolveVersion(typeof(SquidStdBootstrap).Assembly), + Options.ConfigName, + Options.RootDirectory + ); + var registrations = GetServiceRegistrations(); + LogRegistrations(logger, registrations); + var startedInstances = new HashSet(ReferenceEqualityComparer.Instance); + var totalStopwatch = Stopwatch.StartNew(); for (var i = 0; i < registrations.Length; i++) { @@ -173,14 +195,33 @@ public async ValueTask StartAsync(CancellationToken cancellationToken = default) continue; } - await service.StartAsync(cancellationToken); - _startedServices.Add(service); + var serviceStopwatch = Stopwatch.StartNew(); - if (service is IConfigManagerService) + try { - ConfigureLogger(); + await service.StartAsync(cancellationToken); } + catch (Exception ex) + { + logger.Error(ex, "Service {Service:l} failed to start", service.GetType().Name); + + throw; + } + + _startedServices.Add(service); + logger.Information( + "Started {Service:l} in {Elapsed:0.#}ms", + service.GetType().Name, + serviceStopwatch.Elapsed.TotalMilliseconds + ); } + + logger.Information( + "{Application:l} started: {Count} service(s) in {TotalElapsed:0.#}ms", + appName, + _startedServices.Count, + totalStopwatch.Elapsed.TotalMilliseconds + ); } catch { @@ -198,13 +239,33 @@ public async ValueTask StopAsync(CancellationToken cancellationToken = default) return; } + var logger = Log.ForContext(); + var appName = ResolveAppName(Options); + logger.Information("{Application:l} stopping ({Count} service(s))", appName, _startedServices.Count); + try { for (var i = _startedServices.Count - 1; i >= 0; i--) { cancellationToken.ThrowIfCancellationRequested(); - await _startedServices[i].StopAsync(cancellationToken); + var service = _startedServices[i]; + + try + { + await service.StopAsync(cancellationToken); + logger.Information("Stopped {Service:l}", service.GetType().Name); + } + catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) + { + throw; + } + catch (Exception ex) + { + logger.Warning(ex, "Service {Service:l} failed to stop", service.GetType().Name); + } } + + logger.Information("{Application:l} shutdown complete", appName); } finally { @@ -251,6 +312,26 @@ public static SquidStdBootstrap Create(Action configure) return Create(options); } + private static string ResolveAppName(SquidStdOptions options) + => !string.IsNullOrWhiteSpace(options.AppName) + ? options.AppName + : Assembly.GetEntryAssembly()?.GetName().Name ?? "SquidStd"; + + private static string ResolveVersion(Assembly? assembly) + { + var informational = assembly?.GetCustomAttribute() + ?.InformationalVersion; + + if (string.IsNullOrWhiteSpace(informational)) + { + return assembly?.GetName().Version?.ToString() ?? "0.0.0"; + } + + var metadataStart = informational.IndexOf('+'); + + return metadataStart > 0 ? informational[..metadataStart] : informational; + } + private void ConfigureLogger() { if (_loggerConfigured || !Container.IsRegistered()) @@ -261,6 +342,10 @@ private void ConfigureLogger() var options = Container.Resolve(); var loggerConfiguration = new LoggerConfiguration(); + loggerConfiguration + .Enrich.WithProperty("Application", ResolveAppName(Options)) + .Enrich.WithProperty("ApplicationVersion", ResolveVersion(Assembly.GetEntryAssembly())); + if (options.MinimumLevel != LogLevelType.None) { var minimumLevel = options.MinimumLevel.ToSerilogLogLevel(); @@ -279,6 +364,11 @@ private void ConfigureLogger() restrictedToMinimumLevel: minimumLevel ); } + + foreach (var sink in Container.ResolveMany()) + { + loggerConfiguration.WriteTo.Sink(sink, minimumLevel); + } } var logger = loggerConfiguration.CreateLogger(); @@ -287,6 +377,58 @@ private void ConfigureLogger() _loggerConfigured = true; } + private void LogRegistrations(ILogger logger, ServiceRegistrationData[] lifecycleRegistrations) + { + List sections = Container.IsRegistered>() + ? Container.Resolve>() + : []; + var containerRegistrations = Container.GetServiceRegistrations().ToArray(); + + logger.Information( + "Registered {LifecycleCount} lifecycle service(s), {SectionCount} config section(s), {ContainerCount} container registration(s)", + lifecycleRegistrations.Length, + sections.Count, + containerRegistrations.Length + ); + + if (!logger.IsEnabled(LogEventLevel.Debug)) + { + return; + } + + foreach (var registration in lifecycleRegistrations) + { + logger.Debug( + "Lifecycle service {Service} -> {Implementation} (priority {Priority})", + registration.ServiceType.Name, + registration.ImplementationType.Name, + registration.Priority + ); + } + + foreach (var section in sections) + { + logger.Debug("Config section '{Section}' -> {Type}", section.SectionName, section.ConfigType.Name); + } + + foreach (var group in containerRegistrations + .GroupBy(registration => registration.ServiceType.Assembly.GetName().Name ?? "unknown") + .OrderBy(group => group.Key, StringComparer.Ordinal)) + { + logger.Debug( + "{Assembly}: {Count} registration(s): {Services}", + group.Key, + group.Count(), + string.Join( + ", ", + group.Select(registration => registration.ServiceType.Name) + .Distinct() + .Order(StringComparer.Ordinal) + ) + ); + } + } + private ServiceRegistrationData[] GetServiceRegistrations() { if (!Container.IsRegistered>()) diff --git a/tests/SquidStd.Tests/Bootstrap/SquidStdBootstrapLifecycleLoggingTests.cs b/tests/SquidStd.Tests/Bootstrap/SquidStdBootstrapLifecycleLoggingTests.cs new file mode 100644 index 00000000..4bbb0cb3 --- /dev/null +++ b/tests/SquidStd.Tests/Bootstrap/SquidStdBootstrapLifecycleLoggingTests.cs @@ -0,0 +1,216 @@ +using DryIoc; +using Serilog.Core; +using Serilog.Events; +using SquidStd.Abstractions.Data.Internal.Services; +using SquidStd.Abstractions.Extensions.Container; +using SquidStd.Core.Data.Bootstrap; +using SquidStd.Services.Core.Extensions; +using SquidStd.Services.Core.Services.Bootstrap; +using SquidStd.Tests.Support; + +namespace SquidStd.Tests.Bootstrap; + +[Collection(SerilogEventSinkCollection.Name)] +public class SquidStdBootstrapLifecycleLoggingTests +{ + [Fact] + public async Task ConfigureLogging_AttachesContainerSinksAndEnrichesEvents() + { + using var temp = new TempDirectory(); + var sink = new CapturingLogSink(); + await using var bootstrap = SquidStdBootstrap.Create( + new SquidStdOptions { ConfigName = "app", RootDirectory = temp.Path, AppName = "MyApp" } + ); + bootstrap.ConfigureServices(c => + { + c.RegisterInstance(sink); + return c; + }); + + bootstrap.ConfigureLogging(); + Serilog.Log.Information("probe"); + + var probe = sink.Events.Single(e => e.MessageTemplate.Text == "probe"); + Assert.Equal("\"MyApp\"", probe.Properties["Application"].ToString()); + Assert.True(probe.Properties.ContainsKey("ApplicationVersion")); + } + + [Fact] + public async Task AppName_DefaultsToEntryAssemblyName() + { + using var temp = new TempDirectory(); + var sink = new CapturingLogSink(); + await using var bootstrap = SquidStdBootstrap.Create( + new SquidStdOptions { ConfigName = "app", RootDirectory = temp.Path } + ); + bootstrap.ConfigureServices(c => + { + c.RegisterInstance(sink); + return c; + }); + + bootstrap.ConfigureLogging(); + Serilog.Log.Information("probe"); + + var probe = sink.Events.Single(e => e.MessageTemplate.Text == "probe"); + var application = probe.Properties["Application"].ToString().Trim('"'); + Assert.False(string.IsNullOrWhiteSpace(application)); + Assert.NotEqual("MyApp", application); + } + + [Fact] + public async Task StartAsync_LogsBannerRegistrationsAndServices() + { + using var temp = new TempDirectory(); + var (bootstrap, sink) = NewBootstrapWithSink(temp.Path, "MyApp"); + await using var _ = bootstrap; + bootstrap.ConfigureServices(c => c.RegisterCoreServices()); + + try + { + await bootstrap.StartAsync(); + + Assert.True(HasMessage(sink, "MyApp")); + Assert.True(HasMessage(sink, "starting (SquidStd")); + Assert.True(HasMessage(sink, "Registered")); + Assert.True(HasMessage(sink, "Started JobSystemService")); + Assert.True(HasMessage(sink, "started:")); + } + finally + { + await bootstrap.StopAsync(); + } + } + + [Fact] + public async Task StartAsync_FailingService_LogsErrorWithServiceNameAndRethrows() + { + using var temp = new TempDirectory(); + var (bootstrap, sink) = NewBootstrapWithSink(temp.Path); + await using var _ = bootstrap; + var fake = new FakeLifecycleService { ThrowOnStart = true }; + bootstrap.ConfigureServices(c => + { + c.RegisterInstance(fake); + c.AddToRegisterTypedList( + new ServiceRegistrationData(typeof(FakeLifecycleService), typeof(FakeLifecycleService), 0) + ); + return c; + }); + + await Assert.ThrowsAsync(async () => await bootstrap.StartAsync()); + + Assert.Contains( + sink.Events, + e => + { + var rendered = e.RenderMessage(); + + return rendered.Contains("failed to start", StringComparison.Ordinal) + && rendered.Contains("FakeLifecycleService", StringComparison.Ordinal); + } + ); + } + + [Fact] + public async Task StartAsync_ServiceBeforeConfigManager_IsStillLogged() + { + using var temp = new TempDirectory(); + var (bootstrap, sink) = NewBootstrapWithSink(temp.Path); + await using var _ = bootstrap; + var fake = new FakeLifecycleService(); + bootstrap.ConfigureServices(c => + { + c.RegisterInstance(fake); + c.AddToRegisterTypedList( + new ServiceRegistrationData(typeof(FakeLifecycleService), typeof(FakeLifecycleService), -2000) + ); + return c; + }); + + try + { + await bootstrap.StartAsync(); + + Assert.True(HasMessage(sink, "Started FakeLifecycleService")); + } + finally + { + await bootstrap.StopAsync(); + } + } + + [Fact] + public async Task StopAsync_LogsStoppedServicesAndShutdownComplete() + { + using var temp = new TempDirectory(); + var (bootstrap, sink) = NewBootstrapWithSink(temp.Path, "MyApp"); + await using var _ = bootstrap; + bootstrap.ConfigureServices(c => c.RegisterCoreServices()); + + await bootstrap.StartAsync(); + await bootstrap.StopAsync(); + + Assert.True(HasMessage(sink, "MyApp stopping")); + Assert.True(HasMessage(sink, "Stopped JobSystemService")); + Assert.True(HasMessage(sink, "shutdown complete")); + } + + [Fact] + public async Task StopAsync_FailingService_WarnsAndStopsTheOthers() + { + using var temp = new TempDirectory(); + var (bootstrap, sink) = NewBootstrapWithSink(temp.Path); + await using var _ = bootstrap; + var healthy = new HealthyFake(); + var failing = new FailingFake { ThrowOnStop = true }; + bootstrap.ConfigureServices(c => + { + c.RegisterInstance(healthy); + c.AddToRegisterTypedList( + new ServiceRegistrationData(typeof(HealthyFake), typeof(HealthyFake), -50) + ); + c.RegisterInstance(failing); + c.AddToRegisterTypedList( + new ServiceRegistrationData(typeof(FailingFake), typeof(FailingFake), -40) + ); + return c; + }); + + await bootstrap.StartAsync(); + await bootstrap.StopAsync(); + + Assert.True(healthy.Stopped); + Assert.Contains( + sink.Events, + e => e.Level == LogEventLevel.Warning + && e.RenderMessage().Contains("failed to stop", StringComparison.Ordinal) + ); + Assert.True(HasMessage(sink, "shutdown complete")); + } + + private static (SquidStdBootstrap Bootstrap, CapturingLogSink Sink) NewBootstrapWithSink( + string root, + string? appName = null + ) + { + var sink = new CapturingLogSink(); + var bootstrap = SquidStdBootstrap.Create( + new SquidStdOptions { ConfigName = "app", RootDirectory = root, AppName = appName } + ); + bootstrap.ConfigureServices(c => + { + c.RegisterInstance(sink); + return c; + }); + + return (bootstrap, sink); + } + + private static bool HasMessage(CapturingLogSink sink, string fragment) + => sink.Events.Any(e => e.RenderMessage().Contains(fragment, StringComparison.Ordinal)); + + private sealed class HealthyFake : FakeLifecycleService; + + private sealed class FailingFake : FakeLifecycleService; +} diff --git a/tests/SquidStd.Tests/Support/FakeLifecycleService.cs b/tests/SquidStd.Tests/Support/FakeLifecycleService.cs new file mode 100644 index 00000000..45358e11 --- /dev/null +++ b/tests/SquidStd.Tests/Support/FakeLifecycleService.cs @@ -0,0 +1,32 @@ +using SquidStd.Abstractions.Interfaces.Services; + +namespace SquidStd.Tests.Support; + +/// +/// Configurable test double: can throw on start or stop and +/// records whether it was stopped. Not sealed: tests derive empty subclasses when they need +/// two distinct service types. +/// +public class FakeLifecycleService : ISquidStdService +{ + public bool ThrowOnStart { get; set; } + + public bool ThrowOnStop { get; set; } + + public bool Stopped { get; private set; } + + public ValueTask StartAsync(CancellationToken cancellationToken = default) + => ThrowOnStart ? throw new InvalidOperationException("start boom") : ValueTask.CompletedTask; + + public ValueTask StopAsync(CancellationToken cancellationToken = default) + { + if (ThrowOnStop) + { + throw new InvalidOperationException("stop boom"); + } + + Stopped = true; + + return ValueTask.CompletedTask; + } +}