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]

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?

[dimarobert]

For "HostName" and "AppDomain" they could be pushed to the LogContext at the start of the application (initialization of Serilog) as they would not change throughout the application lifetime.

For the "ThreadId", I do not see a good place where to push it. It is not related to a request, any code that executes (even background tasks), executes on a thread so it will have a ThreadId, but there would not be a single good place (or just a small amount of places) where to push it, it will probably be littered in a lot of places, becoming a burden for the logging. Also, in an async context, the ThreadId would change during the execution when the async continuations resume, making it even harder (maybe even impossible) to maintain accurate. I think the only viable place for it is an Enricher and if we already need one for it, makes sense to also put the other ones there to have them in a single place. There is no performance benefit of having them in the LogContext, as all items from the LogContext are added the same way to each logEvent through the AddProperty()/AddPropertyIfAbsent(). Additionally, in the enricher above, the LogEventProperty for HostName and AppDomain are cached the first time and not re-created for each log, similar to how would behave if pushed to the LogContext.

[donker]

I am not a big fan of the enricher (vs adding log properties) for the following reasons:

1. I prefer to see the "injection" of a context property happen in the same place where it is created (as now for userinfo and portalsettings). I first went the enricher route, but quickly realised that at the time that runs it would be unpredictable for me if these values were built or not.
2. It sets in stone what we do as a platform. The approach I've now chosen allows more flexibility to add new properties down the line.

I'm also concerned about performance. Having a ton of extra properties would weigh down the application as a whole.

In the current proposal I add a Guid for each request. This will allow us to trace individual requests. This also separates out threads I believe. Or: I don't know if thread IDs would add something meaningful. As to domain and host names: this is for quite specific use cases. Is this something we should burden everyone with? Why not create a custom enricher which is by default off but can be added in the config? Or add them as a log message so that the request ID is visible for it?

[dimarobert]

First things first, I only said about them because they existed in DNN previously in the Log4Net implementation and I thought this implementation would be feature compatible.

For me personally, the AppDomain came in handy while I was debugging some overlapping application startups during a batch update of extension packages. Gory details:

If during the installation (which copies dlls and marks currently running AppDomains for recycle) there are requests made to the site, new AppDomains are started, which create a mess when they are also marked for recycle (as the installation continued to copy its dlls), allowing new AppDomains to be created, etc. All these AppDomains will go through initialization and will start running migrations in parallel, as there is no locking mechanism that would work across AppDomains.

As for the ThreadId, there is not always a 1-to-1 relation between a request and a thread. Most often this happens for async-await (which I think is also impossible to do the "injection" of [the ThreadId] property happen in the same place where it is created), but also for code that needs to spawn some background work in parallel. Couple of examples here. A LogContext push would have to always be made every time such a background task is spawned. (I think a closer look at the PortalId and UserId is in order for these cases as well, as I think the AsyncLocal value that keeps track of the current LogContext will not flow to the spawned thread and their values will not be logged. AsyncLocal works only on the current thread and any async work that it awaits for)

Going back to the async-await case, here is an example of the ThreadId changing from one line to the other:

public async Task DoSomethingAsync() {
    Logger.Log(...); // Let's say ThreadId here would be `1`.

    var item = await DownloadSomethingAsync(); // If this is actually done async the current thread will be suspended and the code that follows will be scheduled as a continuation on another thread when the async work completes.

    Logger.Log(...); // ThreadId here would be different, let's say `2`. But could also be the same if the previous line completed synchronously (e.g. the value was already cached and simply returned).
}

I do not see how the ThreadId could be kept updated by injecting it "in the same place where it is created [changed]" in a case like this.

However, I am not against it being an optional enricher that can be added in the config when needed.

---

As for your second point, if I understood it correctly,

2. It sets in stone what we do as a platform. The approach I've now chosen allows more flexibility to add new properties down the line.

Enrichers and LogContext are not mutually exclusive, both can be used at the same time for different purposes, so I do not see why adding an enricher would lose flexibility to add new properties down the line. In fact, Serilog implements the LogContext behavior through an enricher of its own that is added with logConfig.Enrich.FromLogContext().

[donker]

OK, I like that idea. I've added it. And enrichers are now in the default config file. So if you don't want them you can just remove them.

[donker]

@dimarobert What I do notice, however, is that when using the Enricher the code in the Enrich method runs for every log message. Whereas the adding of a property to the beginning of the request thread just runs once and then gets output with every log message. So in terms of performance it's prudent to carefully select what you put where. The enricher constructor runs just once per app cycle, by the way. So the app domain id and hostname are determined just once. Is this intended behavior?

[dimarobert]

Adding of a property to the LogContext, yes it happens once per request, but that only adds the property to a collection on the LogContext, not in the log events themselves. That happens in the .Enrich.FromLogContext() enricher, which runs like any other enricher for each log event to copy the values from the LogContext to the event itself. So not really different from using any other enricher. Even the implementation of the LogContext itself is based on yet another collection of enrichers and LogContext.PushProperty() is just adding a PropertyEnricher to it for every call. So, it is enrichers all the way down.

As for the "app domain id and hostname being determined just once", the AppDomainId cannot change during the lifetime of the application, while the HostName could, but I would not expect it to happen very often, maybe only in cases where for example the provisioning of the machine (VM) to run the application on is automated through a series of scripts and it happens to set the machine name after deploying and starting the IIS Application. I do not expect that to be a frequent case, but if it needs to be supported, the additional cost of querying the HostName and constructing the property would have to be incurred for each log event. From a logical / hierarchical point of view I would expect these properties to be from most stable to least in the following order: HostName (the machine that the application runs on), AppDomainId (the instance of the running app), RequestId, and ThreadId.