Add logging infrastructure

[axunonb]

Closes #838

Ical.Net:

• Added package Microsoft.Extensions.Logging.Abstractions to Ical.Net
• Introduced new logging classes and interfaces (ILogger, ILoggerFactory, NullLogger, NullLoggerFactory et al) in namespace Ical.Net.Logging
• Introduced LoggingProvider to support global logger factory configuration and create loggers
• NullLoggerFactory is the default factory

Ical.Net.Tests.Logging

• Added TestLoggingManager
• Added MicrosoftLoggerAdapter and MicrosoftLoggerFactoryAdapter to wrap ILogger and ILoggerFactory for Microsoft.Extensions.Logging

The TestLoggingManager supplies two type of factories:

• Ical.Net.Logging.ILoggerFactory that can be used with as the factory for Ical.Net.Logging.LoggingProvider. It allows for handling log message from inside Ical.Net`.
• Microsoft.Extensions.Logging.ILoggerFactory as a general usage logging factory in unit tests.

The log messages of the loggers created by the factories go to the same configurable output (memory, file, console).
Under the hood the Serilog nuget package is used.

Usage:

• Instantiate TestLoggingManager in unit or integration tests to capture and inspect log output generated by iCal.NET components and components from inside the unit tests.
• You can specify logging options (like minimum/maximum log levels and logger name patterns) to control which log messages are recorded.
• Retrieve log entries via the Logs property, which returns the most recent logs up to a configurable maximum count (Options.MaxLogsCount).
• Useful for verifying that expected log messages are produced during test execution, or for debugging test failures by examining log output.
• Logging can be disabled in case no debugger is attached (Options.DebugModeOnly) which is true by default.

---

Example Usage:

ical.net/Ical.Net.Tests/Logging.Tests/TestLoggingManagerTests.cs

Lines 62 to 99 in d659711

	[Test]
	public void DemoForOccurrences()
	{
	using var mgr = new TestLoggingManager(
	new Options { DebugModeOnly = false,
	MinLogLevel = LogLevel.Trace,
	LogToMemory = true,
	LogToConsole = true
	});
	var logger = mgr.TestFactory.CreateLogger("Occurrences");
	// Test
	var iCal = Calendar.Load(IcsFiles.YearlyComplex1)!;
	var evt = iCal.Events.First();
	var occurrences = evt.GetOccurrences(
	new CalDateTime(2025, 1, 1))
	.TakeWhileBefore(new CalDateTime(2027, 1, 1));
	// Log, using the extension methods for logging
	logger.LogTrace("{Occurrences}", occurrences.ToLog());
	// Analyze the logs
	var logs = mgr.Logs.ToList();
	/*
	2025-07-31 11:00:53.7022|TRACE|Occurrences|Occurrences:
	Start: 01/05/2025 08:30:00 -05:00 US-Eastern Period: PT1H End: 01/05/2025 09:30:00 -05:00 US-Eastern
	Start: 01/05/2025 09:30:00 -05:00 US-Eastern Period: PT1H End: 01/05/2025 10:30:00 -05:00 US-Eastern
	Start: 01/12/2025 08:30:00 -05:00 US-Eastern Period: PT1H End: 01/12/2025 09:30:00 -05:00 US-Eastern
	Start: 01/12/2025 09:30:00 -05:00 US-Eastern Period: PT1H End: 01/12/2025 10:30:00 -05:00 US-Eastern
	Start: 01/19/2025 08:30:00 -05:00 US-Eastern Period: PT1H End: 01/19/2025 09:30:00 -05:00 US-Eastern
	Start: 01/19/2025 09:30:00 -05:00 US-Eastern Period: PT1H End: 01/19/2025 10:30:00 -05:00 US-Eastern
	Start: 01/26/2025 08:30:00 -05:00 US-Eastern Period: PT1H End: 01/26/2025 09:30:00 -05:00 US-Eastern
	Start: 01/26/2025 09:30:00 -05:00 US-Eastern Period: PT1H End: 01/26/2025 10:30:00 -05:00 US-Eastern
	*/
	Assert.That(logs, Has.Count.EqualTo(1));
	Assert.That(logs[0], Does.Contain("Occurrences"));
	}

[codecov]

Codecov Report

❌ Patch coverage is 95.34884% with 2 lines in your changes missing coverage. Please review.

Files with missing lines	Patch %	Lines
Ical.Net/Logging/Internal/Logger.cs	90.0%	0 Missing and 1 partial ⚠️
Ical.Net/Logging/Internal/NullLoggerFactory.cs	85.7%	0 Missing and 1 partial ⚠️

@@           Coverage Diff           @@
##            main    #851     +/-   ##
=======================================
+ Coverage   67.7%   68.0%   +0.3%     
=======================================
  Files        106     112      +6     
  Lines       4224    4267     +43     
  Branches     951     956      +5     
=======================================
+ Hits        2860    2901     +41     
  Misses      1038    1038             
- Partials     326     328      +2     

Files with missing lines	Coverage Δ
Ical.Net/Logging/Internal/LoggerT.cs	100.0% <100.0%> (ø)
Ical.Net/Logging/Internal/NullLogger.cs	100.0% <100.0%> (ø)
Ical.Net/Logging/LoggerExtensions.cs	100.0% <100.0%> (ø)
Ical.Net/Logging/LoggingProvider.cs	100.0% <100.0%> (ø)
Ical.Net/Logging/Internal/Logger.cs	90.0% <90.0%> (ø)
Ical.Net/Logging/Internal/NullLoggerFactory.cs	85.7% <85.7%> (ø)

🚀 New features to boost your workflow:

• ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

[minichma]

I'll try to take a look at the weekend. Just a short thought upfront: It is quite a benefit that Ical.Net has no dependencies except NodaTime. To avoid introducing a new dependency, maybe introduce custom types instead? And provide some simple way for creating an adapter to Microsoft.Logging?

[axunonb]

Indeed, this was a consideration.
SetLoggerFactory(ILoggerFactory? loggerFactory) would then become SetLoggerFactory(IIcalLoggerFactory? loggerFactory) and consumers would have to implement IIcalLogger and IIcalLoggerFactory to wrap their preferred logging framework.
Wouldn't easy of use decrease compared to referencing the (quite lean) Microsoft.Extensions.Logging.Abstractions dependency?

[minichma]

Maybe a simpler approach, where we don't need additional types, would suffice as well. E.g. Entity Framework allows specifying an Action<string> that is used for logging (see https://learn.microsoft.com/en-us/ef/core/logging-events-diagnostics/simple-logging). In our case this could boil down to something like

LoggingProvider.SetLogger(Console.WriteLine)

or, to use Microsoft Logging something similar to (probably not fully correct example)

LoggingProvider.SetLogger(msg => LoggerFactory.CreateLogger("Ical.Net").LogInformation(msg));

Somewhat less flexible but would avoid the additional dependency.

[minichma]

Another aspect would be that the introduction of a new dependency would probably have to be considered a breaking change, so not something easily introduced in v5.

[axunonb]

Another aspect would be that the introduction of a new dependency would probably have to be considered a breaking change, so not something easily introduced in v5.

As it has no influence on users code at all, and we add logging internally using ILogger I'd rate this change as non-breaking.

Logging Delegates
They would only be kind of simple with a limitation to Log.Info(message, value)
For delegates that accept log level, category, message, and exception it would increases complexity. Users would also have to write integration code like this (depending on the logger library):

LoggingProvider.SetLogger((level, category, message, exception) =>
{
    var msLogger = LoggerFactory.CreateLogger(category);
    msLogger.Log(
        MapLogLevel(level), // Map Ical LogLevel to Microsoft’s
        new EventId(),      // Optional
        message,
        exception,
        (s, e) => s
    );
});

// Helper to map Ical LogLevel to Microsoft.Extensions.Logging.LogLevel
private static Microsoft.Extensions.Logging.LogLevel MapLogLevel(LogLevel level) =>
    level switch
    {
        LogLevel.Trace => Microsoft.Extensions.Logging.LogLevel.Trace,
        LogLevel.Debug => Microsoft.Extensions.Logging.LogLevel.Debug,
        LogLevel.Information => Microsoft.Extensions.Logging.LogLevel.Information,
        LogLevel.Warning => Microsoft.Extensions.Logging.LogLevel.Warning,
        LogLevel.Error => Microsoft.Extensions.Logging.LogLevel.Error,
        LogLevel.Critical => Microsoft.Extensions.Logging.LogLevel.Critical,
        _ => Microsoft.Extensions.Logging.LogLevel.None
    };

Maybe continue the discussion after you had the chance to look at the PR?

[minichma]

Setting the global static logger factory as a side effect of instantiating a class introduces additional complexities. I.e. it prevents tests from running in parallel if multiple test cases instantiate the type. Maybe use something like ThreadLocal, i.e. some provider that is instantiated only once globally and that can be used to register individual listeners or sub-providers per thread.

[axunonb]

Oh yes, right! AsyncLocal<ILoggerFactory> looks like the most up-to-date alternative.

[minichma]

I recommend not setting a global configuration (even if its AsyncLocal) in a constructor. I'd rather suggest to create the test logger in one step and set it as the current logger in a separate one. Something like this:

public void SomeTest() {
    var testLoggingFactory = new TestLoggingFactory();
    using var loggingReg = TestLoggingProvider.RegisterLoggingFactoryAsyncLocal(testLoggingFactory);
    ... test code
}

The TestLoggingProvider would be something like this:

public static class TestLoggingProvider {

    private class AsyncLocalLoggerFactory : ILoggerFactory {
        private readonly AsyncLocal<ILoggerFactory> _loggerFactories = new();
        ....
    }

    private static readonly AsyncLocalLoggerFactory _asyncLocalLoggerFactory = new();

    static TestLoggingProvider() {
         LoggingProvider.SetLoggerFactory(_asyncLocalLoggerFactory);
    }

    static IDisposable RegisterLoggingFactoryAsyncLocal(ILoggerFactory loggerFactory) {
        _loggerFactories.SetCurrent(loggerFactory);
        return <some IDisposable that unregisters the current logger factory>
    }
}

[minichma]

Maybe continue the discussion after you had the chance to look at the PR?

I had a first look. To what I see, most of the code is part of the test project. The main project contains the new LoggingProvider class and the additional dependency in the csproj file. The code in the main project lgtm except for the considerations I mentioned related to the additional dependency. Within the test projects we see the complexities that come with global static configurations. I.e. setting the global test provider as part of instantiating the test provider can easily cause concurrency issues. I think that this part of the code could also get simpler when opting for a simpler logging model that avoids the use of additional types.

Another aspect would be that the introduction of a new dependency would probably have to be considered a breaking change, so not something easily introduced in v5.

As it has no influence on users code at all, and we add logging internally using ILogger I'd rate this change as non-breaking.

I agree that it doesn't impact the source code itself, but it could still break user projects if they have conflicting dependencies. I.e. user projects might be referenceing a different version of Microsoft.Extensions.Logging.Abstractions (or of the transitive dependency Microsoft.Extensions.DependencyInjection.Abstractions) or even be stuck at an older one, in which case our change would immediately break the project's build. As a workaround we could specify an older minimum version, but whatever we specify, most likely there would always exist some other version that user projects could be using, that the new dependency would be conflicting with. For that reason I'd indeed consider the change a breaking one.

They would only be kind of simple with a limitation to Log.Info(message, value)
For delegates that accept log level, category, message, and exception it would increases complexity. Users would also have to write integration code like this (depending on the logger library):

Agree. The question is what the functionality is intended to provide. If it is intended to support during debugging, then to my experience the log level is not too important anyways. The user would reproduce some issue and check the whole log output to see whether there's something that points at the issue being debugged. If on the other hand it is configured in a production scenario, maybe on a web server, then it is probably a bigger, professional project. But in those cases the chance of having some legacy dependencies is high, so the additional effort of implementing a custom adapter might be neglectable compared to the challenges that come with conflicting dependencies.

[axunonb]

Mostly follow your arguments. So I added a logger implementation, as this is not too complex anyway. The Microsoft.Extensions.Logging.Abstractions dependency is now removed. The test project gets MicrosoftLoggerAdapter and MicrosoftLoggerFactoryAdapter that finally handle logging (wrapping our logger). Will update the PR after going through it once again.

[minichma]

Very nice! In order to keep the code lean, I would probably have gone for simple delegates rather than individual ILoggerFactory and ILogger types, but that's probably a matter of taste. Maybe consider moving the AsyncLocal to the test project to reduce overall complexity and stay in line with what we have in TimeZoneResolver (where we also have some global configuration).

[minichma]

Whether AsyncLocal should be used is rather specific to the individual application. In Ical.Net we need it for testing, but in most applications the users might not want to configure it per async flow but rather globally. In TimeZoneResolver we have a similar situation and don't use AsyncLocal. I recommend to use the AsyncLocal only within the test project, i.e. set a specific ILoggerFactory there that wraps a AsyncLocal and lets individual test cases configure individual loggers per async flow.

In a future version it would be good to get rid of the static global altogether. Just like in TimeZoneResolver it would be good to introduce some context that holds configuration like the logger or the TZ provider. But that's not a topic for now.

[minichma]

Why would we suppress the finalizer?

[minichma]

I recommend not setting a global configuration (even if its AsyncLocal) in a constructor. I'd rather suggest to create the test logger in one step and set it as the current logger in a separate one. Something like this:

public void SomeTest() {
    var testLoggingFactory = new TestLoggingFactory();
    using var loggingReg = TestLoggingProvider.RegisterLoggingFactoryAsyncLocal(testLoggingFactory);
    ... test code
}

The TestLoggingProvider would be something like this:

public static class TestLoggingProvider {

    private class AsyncLocalLoggerFactory : ILoggerFactory {
        private readonly AsyncLocal<ILoggerFactory> _loggerFactories = new();
        ....
    }

    private static readonly AsyncLocalLoggerFactory _asyncLocalLoggerFactory = new();

    static TestLoggingProvider() {
         LoggingProvider.SetLoggerFactory(_asyncLocalLoggerFactory);
    }

    static IDisposable RegisterLoggingFactoryAsyncLocal(ILoggerFactory loggerFactory) {
        _loggerFactories.SetCurrent(loggerFactory);
        return <some IDisposable that unregisters the current logger factory>
    }
}

[axunonb]

not setting a global configuration
moving the AsyncLocal to the test project

Oh yes of course, didn't occur to me 😉

[axunonb]

@minichma

After implementing AsyncLocal in the test project it turned out that the Nlog package uses a static logger configuration. This is a strong limitation for unit test implementations I had in mind. Luckily, the Serilog package takes a different approach, which makes it a perfect fit: Their configuration is fully AsyncLocal by default, which allows unit test to run in parallel even with different logging configurations. No need to care for AsyncLocal ourselves.

As suggested Ical.Net.Logging.LoggingProvider now stores the ILoggerFactory as static instead of AsyncLocal. Maybe we should rethink this, because the unit test factory implements AsyncLocal, and a static ILoggerFactory stops the tests for Ical.Net.Logging (and only these) from running in parallel.

Moving to Serilog unfortunately required quite some refactoring.
All remarks from the previous review should be addressed.

[sonarqubecloud]

Quality Gate passed

Issues
0 New issues
0 Accepted issues

Measures
0 Security Hotspots
0.0% Coverage on New Code
0.0% Duplication on New Code

See analysis details on SonarQube Cloud

[snakefoot]

Notice NLog supports both the NLog.LogManager-singleton, and isolated NLog.LogFactory-instance.

When using NLog.Extensions.Logging then it will use the NLog.LogManager-singleton if not having specified an isolated NLog.LogFactory-instance.

One can create an isolated LoggerFactory like this:

var loggerFactory = new NLogLoggerFactory(new NLogProviderOptions(), new LogFactory());

Or one can register NLog as Logging Provider with isolated NLog.LogFactory-instance like this:

var loggerFactory = LoggerFactory.Create(builder => builder.AddNLog(serviceProvider => new LogFactory()));