Merge pull request #46 from tgiachi/feature/lifecycle-logging

feat(bootstrap): lifecycle logging with AppName, versions and registration summary

Author: tgiachi

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

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.
     /// </summary>
     public string ConfigName { get; set; } = "squidstd";
+
+    /// <summary>
+    /// 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.
+    /// </summary>
+    public string? AppName { get; set; }
 }

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<SquidStdBootstrap>();
+            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<ISquidStdService>(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<SquidStdBootstrap>();
+        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<SquidStdOptions> 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<AssemblyInformationalVersionAttribute>()
+                                    ?.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<SquidStdLoggerOptions>())
@@ -261,6 +342,10 @@ private void ConfigureLogger()
         var options = Container.Resolve<SquidStdLoggerOptions>();
         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<ILogEventSink>())
+            {
+                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<ConfigRegistrationData> sections = Container.IsRegistered<List<ConfigRegistrationData>>()
+                                                    ? Container.Resolve<List<ConfigRegistrationData>>()
+                                                    : [];
+        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<List<ServiceRegistrationData>>())