Implement Serilog in DNN#7044
Implement Serilog in DNN#7044donker wants to merge 66 commits into
Conversation
…s/JwtController.cs Co-authored-by: Mitchel Sellers <msellers@Iowacomputergurus.com>
…into serilog-2026
bdukes
left a comment
There was a problem hiding this comment.
Thanks for all of the work on this one!
# Conflicts: # DNN Platform/Website/web.config
| Environment.SetEnvironmentVariable("BASEDIR", applicationMapPath); | ||
| SerilogController.AddSerilog(applicationMapPath); | ||
| DnnLoggingController.InitializeLoggerFactory(); | ||
| services.AddLogging(loggingBuilder => loggingBuilder.AddSerilog(null, true)); |
There was a problem hiding this comment.
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));
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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.
| if (File.Exists(configFile)) | ||
| { | ||
| config = new LoggerConfiguration() | ||
| .Enrich.FromLogContext() |
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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));
}
}There was a problem hiding this comment.
Do you prefer Enriching over Pushing properties? And if so, why?
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
I am not a big fan of the enricher (vs adding log properties) for the following reasons:
- 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.
- 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?
There was a problem hiding this comment.
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,
- 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().
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
@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?
There was a problem hiding this comment.
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.
# Conflicts: # DNN Platform/Admin Modules/Dnn.Modules.Console/ViewConsole.ascx.cs # DNN Platform/DotNetNuke.Web/InternalServices/ControlBarController.cs # DNN Platform/DotNetNuke.Web/InternalServices/EventLogServiceController.cs # DNN Platform/DotNetNuke.Web/InternalServices/FileUploadController.cs # DNN Platform/DotNetNuke.Web/InternalServices/ItemListServiceController.cs # DNN Platform/DotNetNuke.Web/InternalServices/MessagingServiceController.cs # DNN Platform/DotNetNuke.Web/InternalServices/ModuleServiceController.cs # DNN Platform/DotNetNuke.Web/InternalServices/NotificationsServiceController.cs # DNN Platform/DotNetNuke.Web/InternalServices/RelationshipServiceController.cs # DNN Platform/DotNetNuke.Web/InternalServices/UserFileController.cs # DNN Platform/Modules/CoreMessaging/Services/MessagingServiceController.cs # DNN Platform/Modules/Journal/ServicesController.cs # Dnn.AdminExperience/Dnn.PersonaBar.Extensions/Components/Themes/ThemesController.cs # Dnn.AdminExperience/Dnn.PersonaBar.Extensions/Services/PagesController.cs
| config = new LoggerConfiguration() | ||
| .WriteTo.File( | ||
| Path.Combine(applicationMapPath, "Portals\\_default\\Logs\\log.resources"), | ||
| outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] [{SourceContext}] {Message:lj}{NewLine}{Exception}", |
There was a problem hiding this comment.
With this outputTemplate all of the extra (structured) log properties (added through enrichers, LogContext, or BeginScope) would not get into the log file. Only the properties that are part of the Message will be written (in string form as part of the message) to the file. To fix this, the {Properties:j} format token can be used. Note that an additional new line after it is needed, so the outputTemplate will have to have {Properties:j}{NewLine} appended to it.
(I see that the Serilog.default.config sets the same outputTemplate)
This PR replaces our Log4net underpinning with Serilog. The advantages are:
WIP
Todo: