Logging refactoring

[ngbrown]

Using structured log processing can greatly benefit application development. Most logging libraries support sinks that can handle the structured nature of log messages. This means each of the parameters in a string.Format() can be become meaningful. The .NET Core logger, NLog, Serilog, and others support sinking to structured logging systems.

This is how the NHibernate.Example.Web logging can look with the changing values colored to be noticeable (this is the default settings for the Serilog console sink):

The legacy IInternalLogger is directly modeled after the log4net interface and limits the interaction with these modern logging systems. For example, any logging of an exception precludes also passing the string.Format params array into the logging system.

There were also many areas that either string concatenation was taking place to generate the log message or string.Format was called then a single string passed into the logger. These have been fixed.

This pull request adds the ability to implement and set an alternative INHibernateLoggerFactory which then returns implementations of the new IInternalLogger2 interface. It is not a breaking change for applications that are providing a custom ILoggerFactory and IInternalLogger implementation. The old factory will still be accepted.

There are some obsolete extension methods that are intended to catch any merges that are using the old logging function style with the exception as the second parameter. They can probably be removed at some point, because they generate an error if referenced.

[hazzik]

I think we should utilize FormattableString instead of message + params.

[ngbrown]

Using FormattableString might be possible with extension methods. It shouldn't be implemented directly on the interface. The structured logging frameworks, including Microsoft's, would prefer to name the parameters (something besides 0, 1, 2, etc).

[hazzik]

Sorry, I don't follow.

[ngbrown]

I mean, that when your application is using log4net or NLog (pre 4.5) with a structured log sink, then in your logging system, the name each of the parameters shows as '0', '1', '2', etc. If you were using Serilog or Microsoft's ILogger (from Microsoft.Extensions.Logging.Abstractions) they both allow the use of a name in the message string that is used in the structured output. See example from here:

_logger.LogInformation("Getting item {ID} at {RequestTime}", id, DateTime.Now);

For output at the logging server, I use Seq (see example of logged message), but I'm sure it's similar in most other systems such as Application Insights or Elasticsearch.

As for not adding more methods to the interface, it might actually be beneficial to collapse it down to just a few methods that have the level passed in as a parameter and do the per-level logging with extension methods. The Microsoft's ILogger interface only has three methods, and one of them is scope oriented, so NHibernate only needs two.

Alternatively, we could just directly rely on Microsoft.Extensions.Logging.Abstractions, but I didn't know if you wanted to take on that dependency.

[ngbrown]

Anyways, if FormattableString is desired instead of a string + params, then using extension methods + a raw string conversion class seems to be the way to do it. Otherwise, there are precedence issues with standard string.

[ngbrown]

I've moved most logging methods to extension methods so anything can be done with them in the future without breaking clients implementing custom logging. The interface in now just this:

public interface IInternalLogger2
{
	void Log(InternalLogLevel logLevel, InternalLogValues state, Exception exception);
	bool IsEnabled(InternalLogLevel logLevel);
}

The state object is built in the extension methods and it would be straightforward to use FormattableString in the future without changing the clients again.

[mstancombe]

Nice! log4net can use named attributes which can then be exposed to appenders such as app insights for richer analytics, so maybe this ticket should be 'structured logging' rather than 'modern logging', but nitpicking aside, it's a great addition to the base logging in nhib.👍

[hazzik]

I have a concern that this change can bring performance regression. Could you please check and doublecheck, that this is not the case?

[ngbrown]

The build times on TeamCity are equivalent, so they don't show any major change.

I wrote some performance tests that simulate 20 million log calls and timed them repeatedly for a statistically valid sample. Each test consists of making 20 million log calls, half formatted, and counting the characters in a mock logger (381 MiB worth).

var iterationCount = 10000000;
for (int i = 0; i < iterationCount; i++)
{
    logger2.Warn("message");
    logger2.Warn("message with parameters {0}, {1}", "string", 5);
}

This takes 3,677 ms with the old interfaces, and 3,922 ms with the new interfaces.

If the 20 million log calls are all disabled (and the formatting and counting don't take place), then the calls took 244 ms with the old interface and 451 ms with the new interface.

These times are normalized to 95 percent confidence numbers. See logger analysis.xlsx.

I did notice that the times are slightly helped by making InternalLogValues a struct, so I made that change.

[gliljas]

Not really related. I'm 200% sure that the "default implementations" would be implemented as a syntactic sugar for extension/static methods. Otherwise, it will require changes to the runtime as an addition to the compiler, which MS would resist as hard as they can.

It is somewhat related, since the reason they are adding it is to make interfaces more change friendly. If they go ahead with it, they will change the runtime, according to Mads Torgensen.

[hazzik]

I would agree that the expectation is that such things are exposed as interfaces.

This expectation would be valid if we were doing a logging framework, but we are using logging, and so that expectation does not apply here. It might be exposed as whatever we please as it is not intended by the consumers (except by, probably, extension libraries as Caches). Using the same interface which a client implemented feels wrong.

Major logging frameworks do segregate "internal" logger and "public" logger. log4net for example: "public contract" that looks exctly as IIniternalLogger and "private contract" which looks exactly as new INHibernateLogger. The only exception that in our case these contracts are reversed.

[hazzik]

If they go ahead

Let's not implement things based on some hope, assumptions or predictions for some future. My gut feeling says that there will be no default methods for the interfaces in the next 5 years.

IMHO a logger should be a very stable contract

Apparently, it is not as demonstrated by this PR.

but LoggerProvider is what already existed. [And similar comments]

At this point, we have an opportunity to improve things, trying to hold back does not make it better. If we are doing this change, it needs to be designed and implemented properly (with a compatibility level of course).

[hazzik]

So are we talking about the factory then?

No, about LoggerProvider.For

[ngbrown]

So in summary, these are the changes I've made:

• Split the logging implementation into multiple files for easier understanding:
  • Logging.cs has the new implementations
  • Logging.log4net.cs has the factory and implementation for reflection based log4net logger.
  • Logging.extensions.cs is the new extension methods
  • Logging.obsolete.cs is the obsolete interfaces and implementations.
• LoggerProvider is now fully obsolete and exists just for compatibility. It contains just enough logic to stay synchronized with the active logging factory.
• NHibernateLogger is the new in-library logger and NHibernateLogger.For(typeof(SessionImpl)) would return an INHibernateLogger from the currently active INHibernateLoggerFactory. It is static and not meant to be inherited.
• INHibernateLogger and INHibernateLoggerFactory have not changed except the following rename:
  • InternalLogLevel and InternalLogValues are renamed to NHibernateLogLevel and NHibernateLogValues.

The IInternalLogger that this pull request is trying to obsolete mirrored the external logging interface of one specific log library and that was lacking. Seeing how INHibernateLogger is similar to the internal logging interfaces of various log libraries means that this is probably on the right track for what is the better format for converting to other loggers.

There can always be more learning the future.

[hazzik]

LGTM

[fredericDelaporte]

Good enough for me. You may wish to do some adjustments as I propose in comments.

[fredericDelaporte]

A bit strange to have a format parameter without argument. Maybe would be better to rename it message for this no args overload.

[hazzik]

Agree

[fredericDelaporte]

For casing and punctuation consistency, should be A composite format string..

[ngbrown]

Minor typo and parameter name adjustments made. Merge with master done.

This can be squash merged since I haven't been rebasing it.

[mxmissile]

Where is FormattedLogValues coming from, I'm unable to resolve? Greenfield project, asp.net core 3.1.

[ngbrown]

@mxmissile You're talking about an example, and the target for that example was .net core 2.0:

nhibernate-core/src/NHibernate.Example.Web/Infrastructure/NHibernateToMicrosoftLogger.cs

Lines 28 to 31 in ac39173

	public void Log(NHibernateLogLevel logLevel, NHibernateLogValues state, Exception exception)
	{
	_msLogger.Log(MapLevels[logLevel], 0, new FormattedLogValues(state.Format, state.Args), exception, MessageFormatter);
	}

The available extension methods for the Microsoft.Extensions.Logging.ILogger interface has changed slightly since then. In .net core 3.1, there's an extension overload that directly takes the format and args parameters:

public void Log(NHibernateLogLevel logLevel, NHibernateLogValues state, Exception exception)
{
    _msLogger.Log(MapLevels[logLevel], exception, state.Format, state.Args);
}