Refactor serilog initialization and add module initialization logging (#2871)

Co-authored-by: Oleg Zhuk <[email protected]>

Author: asvishnyakov

src/VirtoCommerce.Platform.Core/Logger/ConsoleLog.cs

@@ -2,6 +2,7 @@
 
 namespace VirtoCommerce.Platform.Core.Logger
 {
+    [Obsolete("Use Serilog's static Log.Logger or inject ILogger instead", DiagnosticId = "VC0010", UrlFormat = "https://docs.virtocommerce.org/platform/user-guide/versions/virto3-products-versions/")]
     public static class ConsoleLog
     {
         public static void BeginOperation(string message)

src/VirtoCommerce.Platform.Modules/ModuleInitializer.cs

@@ -48,7 +48,7 @@ public ModuleInitializer(
         /// <summary>
         /// Initializes the specified module.
         /// </summary>
-        /// <param name="moduleInfo">The module to initialize</param>        
+        /// <param name="moduleInfo">The module to initialize</param>
         public void Initialize(ModuleInfo moduleInfo)
         {
             if (moduleInfo == null)
@@ -80,6 +80,7 @@ public void Initialize(ModuleInfo moduleInfo)
                         hasModuleCatalog.ModuleCatalog = _moduleCatalog;
                     }
 
+                    _loggerFacade.LogDebug("Initializing module {ModuleName}.", moduleInfo.ModuleName);
                     moduleInstance.Initialize(_serviceCollection);
                     moduleInfo.State = ModuleState.Initialized;
                 }
@@ -103,6 +104,7 @@ public void PostInitialize(ModuleInfo moduleInfo, IApplicationBuilder appBuilder
             {
                 if (moduleInstance != null)
                 {
+                    _loggerFacade.LogDebug("Post-initializing module {ModuleName}.", moduleInfo.ModuleName);
                     moduleInstance.PostInitialize(appBuilder);
                 }
             }
@@ -115,7 +117,7 @@ public void PostInitialize(ModuleInfo moduleInfo, IApplicationBuilder appBuilder
         /// <summary>
         /// Handles any exception occurred in the module Initialization process,
         /// logs the error using the <see cref="ILogger"/> and throws a <see cref="ModuleInitializeException"/>.
-        /// This method can be overridden to provide a different behavior. 
+        /// This method can be overridden to provide a different behavior.
         /// </summary>
         /// <param name="moduleInfo">The module metadata where the error happened.</param>
         /// <param name="exception">The exception thrown that is the cause of the current error.</param>

src/VirtoCommerce.Platform.Modules/ModuleManager.cs

@@ -3,14 +3,13 @@
 using System.Linq;
 using Microsoft.AspNetCore.Builder;
 using Microsoft.Extensions.Logging;
-using VirtoCommerce.Platform.Core.Logger;
 using VirtoCommerce.Platform.Core.Modularity;
 using VirtoCommerce.Platform.Core.Modularity.Exceptions;
 
 namespace VirtoCommerce.Platform.Modules
 {
     /// <summary>
-    /// Component responsible for coordinating the modules' type loading and module initialization process. 
+    /// Component responsible for coordinating the modules' type loading and module initialization process.
     /// </summary>
     public class ModuleManager : IModuleManager, IDisposable
     {
@@ -77,17 +76,13 @@ private void RaiseLoadModuleCompleted(LoadModuleCompletedEventArgs e)
         /// </summary>
         public void Run()
         {
-            ConsoleLog.BeginOperation("Initializing module catalog");
+            _loggerFacade.LogInformation("Initializing module catalog");
 
             this.ModuleCatalog.Initialize();
 
-            ConsoleLog.EndOperation();
-
-            ConsoleLog.BeginOperation("Loading modules");
+            _loggerFacade.LogInformation("Loading modules");
 
             this.LoadModulesWhenAvailable();
-
-            ConsoleLog.EndOperation();
         }
 
 
@@ -117,8 +112,8 @@ public void PostInitializeModule(ModuleInfo moduleInfo, IApplicationBuilder appl
         }
 
         /// <summary>
-        /// Returns the list of registered <see cref="IModuleTypeLoader"/> instances that will be 
-        /// used to load the types of modules. 
+        /// Returns the list of registered <see cref="IModuleTypeLoader"/> instances that will be
+        /// used to load the types of modules.
         /// </summary>
         /// <value>The module type loaders.</value>
         public virtual IEnumerable<IModuleTypeLoader> ModuleTypeLoaders
@@ -161,8 +156,8 @@ protected virtual bool ModuleNeedsRetrieval(ModuleInfo moduleInfo)
 
             if (moduleInfo.State == ModuleState.NotStarted)
             {
-                // If we can instantiate the type, that means the module's assembly is already loaded into 
-                // the AppDomain and we don't need to retrieve it. 
+                // If we can instantiate the type, that means the module's assembly is already loaded into
+                // the AppDomain and we don't need to retrieve it.
                 bool isAvailable = Type.GetType(moduleInfo.ModuleType) != null;
                 if (isAvailable)
                 {
@@ -286,7 +281,7 @@ private void IModuleTypeLoader_LoadModuleCompleted(object sender, LoadModuleComp
         /// <summary>
         /// Handles any exception occurred in the module type loading process,
         /// logs the error using the <see cref="ILogger"/> and throws a <see cref="ModuleTypeLoadingException"/>.
-        /// This method can be overridden to provide a different behavior. 
+        /// This method can be overridden to provide a different behavior.
         /// </summary>
         /// <param name="moduleInfo">The module metadata where the error happened.</param>
         /// <param name="exception">The exception thrown that is the cause of the current error.</param>

src/VirtoCommerce.Platform.Web/Extensions/ServiceCollectionExtensions.cs

@@ -4,10 +4,11 @@
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.Hosting;
 using Microsoft.Extensions.Logging;
+using Serilog;
 using VirtoCommerce.Platform.Core.Common;
-using VirtoCommerce.Platform.Core.Logger;
 using VirtoCommerce.Platform.Core.Modularity;
 using VirtoCommerce.Platform.Modules.External;
+using VirtoCommerce.Platform.Web;
 
 namespace VirtoCommerce.Platform.Modules
 {
@@ -38,7 +39,7 @@ public static IServiceCollection AddModules(this IServiceCollection services, IM
             manager.Run();
 
             // Ensure all modules are loaded
-            ConsoleLog.BeginOperation("Registering API controllers");
+            Log.ForContext<Startup>().Information("Registering API controllers");
 
             var notStartedModules = moduleCatalog.Modules.Where(x => x.State == ModuleState.NotStarted);
             var modules = moduleCatalog.CompleteListWithDependencies(notStartedModules)
@@ -59,8 +60,6 @@ public static IServiceCollection AddModules(this IServiceCollection services, IM
                 }
             }
 
-            ConsoleLog.EndOperation();
-
             services.AddSingleton(moduleCatalog);
             return services;
         }

src/VirtoCommerce.Platform.Web/Program.cs

@@ -59,7 +59,7 @@ public static IHostBuilder CreateHostBuilder(string[] args) =>
             })
             .ConfigureServices((hostingContext, services) =>
             {
-                //Conditionally use the hangFire server for this app instance to have possibility to disable processing background jobs  
+                //Conditionally use the hangFire server for this app instance to have possibility to disable processing background jobs
                 if (hostingContext.Configuration.GetValue("VirtoCommerce:Hangfire:UseHangfireServer", true))
                 {
                     // Add & start hangfire server immediately.
@@ -83,18 +83,6 @@ public static IHostBuilder CreateHostBuilder(string[] args) =>
                         }
                     });
                 }
-            })
-            .UseSerilog((context, services, loggerConfiguration) =>
-            {
-                // read from configuration
-                _ = loggerConfiguration.ReadFrom.Configuration(context.Configuration);
-
-                // enrich configuration from external sources
-                var configurationServices = services.GetService<IEnumerable<ILoggerConfigurationService>>();
-                foreach (var service in configurationServices)
-                {
-                    service.Configure(loggerConfiguration);
-                }
             });
     }
 }

src/VirtoCommerce.Platform.Web/Startup.cs

@@ -33,6 +33,7 @@
 using Newtonsoft.Json.Converters;
 using OpenIddict.Abstractions;
 using OpenIddict.Validation.AspNetCore;
+using Serilog;
 using VirtoCommerce.Platform.Core;
 using VirtoCommerce.Platform.Core.Common;
 using VirtoCommerce.Platform.Core.DynamicProperties;
@@ -98,11 +99,26 @@ public Startup(IConfiguration configuration, IWebHostEnvironment hostingEnvironm
         // This method gets called by the runtime. Use this method to add services to the container.
         public void ConfigureServices(IServiceCollection services)
         {
-            ConsoleLog.BeginOperation("Virto Commerce is loading");
+            // Use temporary bootstrap logger (which will be replaced with configured version later) until DI initialization completed
+            Log.Logger = new LoggerConfiguration().ReadFrom.Configuration(Configuration).CreateBootstrapLogger();
 
-            var databaseProvider = Configuration.GetValue("DatabaseProvider", "SqlServer");
+            services.AddSerilog((serviceProvider, loggerConfiguration) =>
+            {
+                _ = loggerConfiguration.ReadFrom.Configuration(Configuration);
+
+                // Enrich configuration from external sources
+                var configurationServices = serviceProvider.GetService<IEnumerable<ILoggerConfigurationService>>();
+                foreach (var service in configurationServices)
+                {
+                    service.Configure(loggerConfiguration);
+                }
+                // Preserve static logger (i.e. create new logger for DI, instead of reconfiguring existing)
+                // to avoid exception about frozen logger because BuildServiceProvider is called multiple times
+            }, preserveStaticLogger: true);
+
+            Log.ForContext<Startup>().Information("Virto Commerce is loading");
 
-            ConsoleLog.EndOperation();
+            var databaseProvider = Configuration.GetValue("DatabaseProvider", "SqlServer");
 
             // Optional Modules Dependecy Resolving
             services.Add(ServiceDescriptor.Singleton(typeof(IOptionalDependency<>), typeof(OptionalDependencyManager<>)));
@@ -301,9 +317,8 @@ public void ConfigureServices(IServiceCollection services)
                     break;
             }
 
-            ConsoleLog.BeginOperation("Getting server certificate");
+            Log.ForContext<Startup>().Information("Getting server certificate");
             ServerCertificate = GetServerCertificate(certificateLoader);
-            ConsoleLog.EndOperation();
 
             //Create backup of token handler before default claim maps are cleared
             // [Obsolete("Use JsonWebToken", DiagnosticId = "VC0009", UrlFormat = "https://docs.virtocommerce.org/products/products-virto3-versions/")]
@@ -671,11 +686,9 @@ public void Configure(IApplicationBuilder app, IWebHostEnvironment env, ILogger<
                 app.UseAutoAccountsLockoutJob(options.Value);
 
                 // Complete modules startup and apply their migrations
-                ConsoleLog.BeginOperation("Post initializing modules");
+                Log.ForContext<Startup>().Information("Post initializing modules");
 
                 app.UseModules();
-
-                ConsoleLog.EndOperation();
             });
 
             app.UseEndpoints(SetupEndpoints);

src/VirtoCommerce.Platform.Web/appsettings.Development.json

@@ -10,7 +10,9 @@
         "System": "Information",
         "Microsoft": "Information",
         "Microsoft.AspNetCore.SignalR": "Verbose",
-        "Microsoft.AspNetCore.Http.Connections": "Verbose"
+        "Microsoft.AspNetCore.Http.Connections": "Verbose",
+        "VirtoCommerce.Platform.Modules": "Information",
+        "VirtoCommerce.Platform.Web.Startup": "Information"
       }
     },
     "WriteTo": [

src/VirtoCommerce.Platform.Web/appsettings.Production.json

@@ -9,6 +9,7 @@
         "System": "Error",
         "Microsoft": "Warning",
         "Microsoft.Hosting.Lifetime": "Information",
+        "VirtoCommerce.Platform.Modules": "Debug",
         "VirtoCommerce.Platform.Web.Startup": "Information"
       }
     },