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]

SerilogController.AddSerilog() is used from 5 places throughout the code (3x DnnLoggingController, 1x LoggerSourceImpl, and this one), but the BASEDIR Environment Variable gets set only here. Could one of the other places ever get called first?

I think this should be part of SerilogController.AddSerilog() itself instead to be safe.

[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)

[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.