WIP: Implement Serilog in DNN

[donker]

This PR replaces our Log4net underpinning with Serilog. The advantages are:

1. Real-time changes in logging when editing the config file without a need for an app restart
2. Structured logging
3. The ability to add your own "sinks" (places the log is sent to)

WIP

Todo:

• Add new dlls to distribution
• Add writing out default config file to the root folder
• Add logic to repair a damaged/old config file
• Repairing all deprecated code in DNN (big effort)

[bdukes]

Thanks for all of the work on this one!

[bdukes]

I've opened a PR to this branch which migrates all logging calls to use LoggerMessage generated methods.

[dimarobert]

SerilogLoggerFactory should be a singleton. SerilogLoggerProvider should be a singleton.

SerilogLoggerFactory creates a new SerilogLoggerProvider in its constructor. The provider then creates its "root" logger _logger = logger.ForContext(new[] { this }); (where this is the provider instance). That root logger is then used (in our case only one time as the factory and provider are never used after this call) to create the logger returned by calling the SerilogLoggerFactory.CreateLogger<T>() (through SerilogLoggerFactory.CreateLogger(string categoryName) -> SerilogLoggerProvider.CreateLogger(string name)).

This means that for each call to any of the GetLogger methods in this DnnLoggingController class a new set of SerilogLoggerFactory, SerilogLoggerProvider, and that "root" logger of the provider will get created and persisted in memory for the entire duration of the application lifetime. Currently there are more that 270 references to the DnnLoggingController.GetLogger overloads, which will create and persist 270 or more of those sets of instances (in addition to the ILogger<T> instances that gets returned to the caller to perform the logging function).

Note that an additional SerilogLoggerProvider instance is also created as singleton through DI by the loggingBuilder.AddSerilog() registration call in StartupExtensions.cs which gets shared by all loggers that get resolved/created through DI.

Also, in Serilog, the SerilogLoggerProvider is the logging scope holder. It has a CurrentScope that looks like this:

readonly AsyncLocal<SerilogLoggerScope?> _value = new();

internal SerilogLoggerScope? CurrentScope
{
    get => _value.Value;
    set => _value.Value = value;
}

(note that it is not kept as a static field, it is a per instance, AsyncLocal field)

that gets used to keep track of the calls to logger.BeginScope() that is used to enrich logs based on the execution context, which is important for good, detailed structured logging. Having multiple instances of SerilogLoggerProvider or each logger having its own SerilogLoggerProvider instance mean that they have split brain and scopes from one logger cannot be shared with the other loggers. Think along the lines of ILogger<Installer> and ILogger<PackageInstaller> cannot share state in something like this:

public class Installer {
  private ILogger logger = DnnLoggingController.GetLogger<Installer>();

  public PackageInstaller[] Packages { get; set; }

  private void InstallPackages() {
    foreach (var installer in Packages) {
      using (logger.BeginScope(state: new Dictionary<string, object> {
          ["ScopeName"] = "PackageInstall",
          ["PackageName"] = installer.Package.Name,
          ["PackageVersion"] = installer.Package.Version 
      }) {
          installer.Install();
      }
    }
  }
}

public class PackageInstaller {
  private ILogger logger = DnnLoggingController.GetLogger<PackageInstaller>();

  public void Install() {
    foreach (var componentInstaller in componentInstallers) {
      using (logger.BeginScope(state: new Dictionary<string, object> {
          ["ScopeName"] = "ComponentInstall",
          ["ComponentType"] = compInstaller.Type
      }) {
          logger.LogInformation("Installing component");
      }
    }
  }
}

in this setup, that call to logger.LogInformation() would gather all the values passed in the opened scopes along the callstack and should result in the following structured log (represented in JSON format):

{
  "Message": "Installing component",
  "ScopeName": "ComponentInstall",
  "PackageName": "MyModule",
  "PackageVersion": "1.2.3.4",
  "ComponentType": "Assembly"
}

additionaly, the default implementation of Microsoft Logging is also composing an additional property "Scopes": ["PackageInstall", "ComponentInstall"], so that you can understand your log code path. Serilog does not do that by default, but probably can be extended to with a different implementation of the provider or some other extension point.

With the "split brain" issue above, this nesting would not be properly tracked as each logger (with its own provider) would only track its scopes, but would be unable to track scopes from loggers of other components / classes.

(and yes that logger.BeginScope(Dictionary<string, object> state) API from Microsoft is wild, they also have a logger.BeginScope(List<KeyValuePair<string, object>> state) which does not fare much better from an ease of use point of view, but they probably expect extension methods to be created by developers for each of their particular scopes and leveraging these lower APIs there. they also have logger.BeginScope(string messageTemplate, params object[] args) but that has its own problems, as any data you want to attach to the scope through the args MUST be a named token in the messageTemplate, otherwise it is discarded, which makes it cumbersome to construct an intelligible messageTemplate. first two are supported by Serilog, probably the third one as well)

[donker]

Thank you for your comments, Dima, I'm going to revise the PR based on your feedback. Trying to shoehorn DI stuff into the older classes in DNN is something of a challenge. What puzzles me is how the SerilogLoggerProvider holds the scope values but it should be a Singleton, which would share it between requests. But I'll give it a try and see how it goes. Using the BeginScope is a much more elegant solution than the enricher. But I don't want any Serilog reference to bleed beyond the Instrumentation project.

[dimarobert]

The key for how the SerilogLoggerProvider holds the scope values even when it itself is a Singleton, is the readonly AsyncLocal<SerilogLoggerScope?> _value = new(); field I described above. Similar to how ThreadLocal<T> values are specific to a thread, the value of that field (or any AsyncLocal object) is specific for that async execution and it is tracked by the ExecutionContext across the entire execution of an async operation (even across multiple threads if the operation happen to jump threads when resuming).

As for the BeginScope API, that is part of the Microsoft.Extensions.Logging.ILogger interface, so there should be no Serilog reference bleed beyond the Instrumentation project.

As for pulling services from DI in the older classes, there could be an alternative to create the singletons for the SerilogLoggerFactory and SerilogLoggerProvider outside of DI (in a static constructor of a class, maybe the DnnLoggingController) and then simply reimplement the SerilogLoggingBuilderExtensions.AddSerilog() to provide them to the DI container as instances:

public static ILoggingBuilder AddDnnSerilog(this ILoggingBuilder builder, SerilogLoggerProvider provider)
{
    if (builder == null) throw new ArgumentNullException(nameof(builder));

    builder.AddProvider(provider);
    builder.AddFilter<SerilogLoggerProvider>(null, LogLevel.Trace);

    return builder;
}

then replace the registration in StartupExtensions.cs:

services.AddLogging(loggingBuilder => loggingBuilder.AddDnnSerilog(DnnLoggingController.ProviderInstance));

or even omit the extension method and do it in-place in the services.AddLogging() lambda as there are only two lines of code loggingBuilder => loggingBuilder.AddProvider(DnnLoggingController.ProviderInstance).AddFilter<SerilogLoggerProvider>(null, LogLevel.Trace).

[dimarobert]

Another option to do this without having to use the HttpContext.Current is to leverage logger.BeginScope() instead.

For PortalId, looks like the HttpContext.Current.Items["PortalSettings"] is only ever set in BasicUrlRewriter or AdvancedUrlRewriter, so a call to var scope = logger.BeginScope(new Dictionary<string, object>{ ["PortalId"] = portalSettings.PortalId }) would be made there, which will enrich all logging calls made during the (request) scope. HttpContext.Current is already used there to assign the context.Items["PortalSettings"], so to correctly cleanup the scope at the right time (end of the request), the scope instance returned from the logger.BeginScope() would be added as a disposable to the HttpContext using context.DisposeOnPipelineCompleted(scope) after it is created. HttpContext would then take care of its disposal at the right time.

For the UserId, there are likely similar places where it gets assigned to the HttpContext.Current.Items["UserInfo"], where an approach similar to the PortalId above could be used.

[donker]

I've substantially rewritten the approach. Can you recheck your comments?

[dimarobert]

Small cleanup here?

[dimarobert]

Could this.serviceProvider be used as above?

[dimarobert]

Also, as noted in my initial review:

Note that an additional SerilogLoggerProvider instance is also created as singleton through DI by the loggingBuilder.AddSerilog() registration call in StartupExtensions.cs which gets shared by all loggers that get resolved/created through DI.

Which means that now there are two SerilogLoggerProvider instances, one part of the factory in DnnLoggingController and one part of DI through the loggingBuilder.AddSerilog() call.

That is why I also recommended manually registering Serilog instead:

As for pulling services from DI in the older classes, there could be an alternative to create the singletons for the SerilogLoggerFactory and SerilogLoggerProvider outside of DI (in a static constructor of a class, maybe the DnnLoggingController) and then simply reimplement the SerilogLoggingBuilderExtensions.AddSerilog() to provide them to the DI container as instances:

public static ILoggingBuilder AddDnnSerilog(this ILoggingBuilder builder, SerilogLoggerProvider provider)
{
    if (builder == null) throw new ArgumentNullException(nameof(builder));

    builder.AddProvider(provider);
    builder.AddFilter<SerilogLoggerProvider>(null, LogLevel.Trace);

    return builder;
}

then replace the registration in StartupExtensions.cs:

services.AddLogging(loggingBuilder => loggingBuilder.AddDnnSerilog(DnnLoggingController.ProviderInstance));

[dimarobert]

Looking a bit closer to it, does not look like there is a way to create a SerilogLoggerFactory from a provider or to retrieve the inner provider that the SerilogLoggerFactory creates, but at the same time, I do not think that the SerilogLoggerFactory is even needed for this implementation. As this issue serilog/serilog-extensions-logging#183 states, the factory was designed only for cases when the default Microsoft LoggerFactory needed to be replaced.
In our case I think that you can use the provider directly, the SerilogLoggerFactory simply forwards the calls to the provider and there is no other logic from the SerilogLoggerFactory that we need.

[donker]

Like this (new code uploaded)? I'm not sure I'm following what you're getting at as the code examples are not everything that would change.

[dimarobert]

I think something like this should work: donker/Dnn.Platform@serilog-2026...dimarobert:Dnn.Platform:serilog-2026

I did not notice initially that the ILoggerFactory extension methods from Microsoft, Microsoft.Extensions.Logging.LoggerFactoryExtensions.CreateLogger<T>(this ILoggerFactory factory) and Microsoft.Extensions.Logging.LoggerFactoryExtensions.CreateLogger(this ILoggerFactory factory, Type type) were used by the DnnLoggingController, so an ILoggerFactory was needed to leverage them.

So, the implementation above first ties together the initialization of the Log.Logger and the singleton Provider and ensures that it happens only once by leveraging the static class initializer. It then creates a SimpleLoggerFactory that simply forwards the calls made to ILoggerFactory.CreateLogger(string categoryName) to the provider, to support the implementation of the DnnLoggingController methods. This forwarding was the only thing that we actually needed from the SerilogLoggerFactory.

[dimarobert]

Another thing, I do not think that by default Serilog logs information like the current ThreadId, AppDomain, or HostName. Things that I think the logs in DNN had and were pretty useful. They should also be added to the default outputTemplate below for file logging.

[dimarobert]

Here is an enricher that I created for myself based on the existing code in DNN:

    class SystemInfoEnricher : Serilog.Core.ILogEventEnricher {
        private readonly string hostName;
        private readonly int appDomainId;

        private LogEventProperty hostNameProperty;
        private LogEventProperty appDomainProperty;

        public SystemInfoEnricher() {
            appDomainId = AppDomain.CurrentDomain.Id;
            try {
                hostName = System.Net.Dns.GetHostName();
            } catch {
                hostName = Environment.MachineName;
            }
        }

        public void Enrich(LogEvent logEvent, Serilog.Core.ILogEventPropertyFactory propertyFactory) {
            hostNameProperty = hostNameProperty ?? propertyFactory.CreateProperty("HostName", hostName);
            appDomainProperty = appDomainProperty ?? propertyFactory.CreateProperty("AppDomain", appDomainId);

            logEvent.AddPropertyIfAbsent(hostNameProperty);
            logEvent.AddPropertyIfAbsent(appDomainProperty);
            logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty("ThreadId", Thread.CurrentThread.ManagedThreadId));
        }
    }

[donker]

Do you prefer Enriching over Pushing properties? And if so, why?