LoggerExtensions.MessageFormatter takes an exception as argument but ignores it. - TraceSourceProvider should take exception into account, even if the formatter is not null.

[rizi]

Describe the bug

We are using Asp.net Core (3.1) and the "TraceSourceProvider" (logging.AddTraceSource(sourceSwitchName), which in turn uses the Microsoft.Extensions.Logging.TraceSource.TraceSourceLogger --> the TraceSourceLogger relies on the given MessageFormatter and does nothing withe the given exception.
Because Func<TState, Exception, string> formatter of the ILogger interface is not null the TraceSourceLogger "thinks" the exception has already been taken into account by the formatter and does not add the exception (message/stacktrace,...) to the message that will be finally logged.

We are using Microsoft.Extensions.Logging 3.1.3, should this be fixed in the MessageFormatter method or should the TraceSourceLogger take care to add exception details?

To Reproduce

Steps to reproduce the behavior:

1. Configure Asp.Net Core logging to use the TraceSourceLogger (logging.AddTraceSource(sourceSwitchName))
2. Use ILogger<SomeClass> and log an exception, e.q logger.LogError("some message", someException);
3. Look at the log file, the exception is missing, the message ("some message") is available

Expected behavior

If an exception is available it should be taken care of in the MessageFormatter and therfore the exception should be visible in the log file.

[davidfowl]

This was intentional because most loggers want to do special formatting for the exception (that's why it's passed into the log call itself). To avoid the breaking change of removing the formatting of the exception was the only reasonable choice.

TraceSourceLogger

We should fix the TraceSourceLogger to write the exception.

[rizi]

This was intentional because most loggers want to do special formatting for the exception (that's why it's passed into the log call itself). To avoid the breaking change of removing the formatting of the exception was the only reasonable choice.

TraceSourceLogger

We should fix the TraceSourceLogger to write the exception.

Thx for the clarification, do I need to create another issue for the TraceSourceLogger, or do you take care of it?
Thx

[davidfowl]

You can re-title this issue and send a PR 😁.

cc @maryamariyan

[rizi]

Ok, I will do that after my holidays (in about 3 weeks). Br David Fowler <[email protected]> schrieb am Sa., 25. Juli 2020, 17:45:

…

You can re-title this issue and send a PR 😁. cc @maryamariyan <https://github.com/maryamariyan> — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <https://github.com/dotnet/extensions/issues/3359#issuecomment-663869589>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAGCMYRQQ33U32KTFNHTSR3R5L4XXANCNFSM4O2F2LHA> .

[KalleOlaviNiemitalo]

Should TraceSourceLogger.Log<TState> then throw ArgumentNullException if formatter == null, like e.g. ConsoleLogger and DebugLogger do?

The MessageFormatter change was announced as part of aspnet/Announcements#148 back in 2016.

[Dotnet-GitSync-Bot]

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

[ghost]

Tagging subscribers to this area: @maryamariyan
See info in area-owners.md if you want to be subscribed.

[ericstj]

Just to restate what's going on here with some code.

TraceSourceLogger only includes the exception when a formatter is not present:

runtime/src/libraries/Microsoft.Extensions.Logging.TraceSource/src/TraceSourceLogger.cs

Lines 26 to 40 in 8933510

	if (formatter != null)
	{
	message = formatter(state, exception);
	}
	else
	{
	if (state != null)
	{
	message += state;
	}
	if (exception != null)
	{
	message += Environment.NewLine + exception;
	}
	}

The default formatter used doesn't include exception:

runtime/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/LoggerExtensions.cs

Lines 425 to 428 in 92b125f

	private static string MessageFormatter(FormattedLogValues state, Exception error)
	{
	return state.ToString();
	}

As @KalleOlaviNiemitalo mentions above, @BrennanConroy stated this was by-design in aspnet/Announcements#148

We can look at other ILogger implementations and they all include the exception, even when formatter is not null.

runtime/src/libraries/Microsoft.Extensions.Logging.EventLog/src/EventLogLogger.cs

Lines 115 to 118 in 92b125f

	if (exception != null)
	{
	builder.AppendLine().AppendLine("Exception: ").Append(exception).AppendLine();
	}

runtime/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs

Lines 59 to 67 in 92b125f

	if (exception != null)
	{
	string exceptionMessage = exception.ToString();
	if (!FormatterOptions.JsonWriterOptions.Indented)
	{
	exceptionMessage = exceptionMessage.Replace(Environment.NewLine, " ");
	}
	writer.WriteString(nameof(Exception), exceptionMessage);
	}

runtime/src/libraries/Microsoft.Extensions.Logging.Console/src/SimpleConsoleFormatter.cs

Lines 94 to 98 in 92b125f

	if (exception != null)
	{
	// exception message
	WriteMessage(textWriter, exception.ToString(), singleLine);
	}

etc...

Should TraceSourceLogger.Log then throw ArgumentNullException if formatter == null, like e.g. ConsoleLogger and DebugLogger do?

I don't think so. That's a public API that already defines behavior for null. Throwing would be a breaking change and I don't see the value of making such a breaking change.

We just need to be sure to add the exception to the message even in the case formatter is non-null, just like the other ILogger implementations.

[ericstj]

@rizi I marked it as up for grabs if you wanted to submit a PR. Thanks for the report!

[rizi]

@ericstj I will definitely send a pull request as soon as possible.
Br

[jaymin93]

@ericstj so method " MessageFormatter " "private static string MessageFormatter(FormattedLogValues state, Exception error)" should include the exception details as well correct , if it is my correct understanding about the issue ? since i would like to do pr .
Thanks.

[ericstj]

so method " MessageFormatter " "private static string MessageFormatter(FormattedLogValues state, Exception error)" should include the exception details as well correct

I don't think so. If it did that would cause duplicate exception logging. My understanding is that the default formatter delegate MessageFormatter should remain untouched and the only change made should be to TraceSourceLogger to include the exception even when formatter is not null.

[rizi]

@ericstj
I've created a pull request for this issue: #42571, I was a little bit confused because I wasn't able to find tests in the corresponding solution (src\libraries\Microsoft.Extensions.Logging.TraceSourceMicrosoft.Extensions.Logging.TraceSource.sln).

Are the tests in a different solution or are there no tests atm?

br

[rizi]

@ericstj

Can someone please help me to compile the Microsoft.Extensions.Logging.sln

Here is what I did so far:

build.cmd clr+libs -rc Release (finished with 0 warnings and 0 errors)
build.cmd -vs Microsoft.Extensions.Logging

As soon as VS 2019 (16.8 preview 3) opens I can't compile the solution or run tests:
Error:
1>------ Build started: Project: TestUtilities, Configuration: Debug Any CPU ------
Error occurred while restoring NuGet packages: Invalid restore input. Duplicate frameworks found: 'net5.0, net461, net5.0'. Input files: C:\Dev\Git\runtime\src\libraries\Microsoft.Extensions.Logging\tests\Common\Microsoft.Extensions.Logging.Tests.csproj.
1>CSC : error CS0006: Metadata file 'C:\Dev\Git\runtime\artifacts\bin\System.Runtime.CompilerServices.Unsafe\net45-Debug\System.Runtime.CompilerServices.Unsafe.dll' could not be found
1>Done building project "TestUtilities.csproj" -- FAILED.
1>TestUtilities -> C:\Dev\Git\runtime\artifacts\bin\TestUtilities\net5.0-Debug\TestUtilities.dll
2>------ Build started: Project: Microsoft.Extensions.Logging.Tests, Configuration: Debug Any CPU ------

It seems that VS(nuget restore) are confused with $(NetCoreAppCurrent)-Windows_NT;$(NetCoreAppCurrent).

Is there no way make Visual Studio work? Compiling the solution via command like works fine (0 errors, 0 warnings).

Br

[ericstj]

The restore error is caused by #32205. You should be able to workaround it by restoring from the commandline and disabling restore in VS. This seems to be a worse state than it should be and I've asked some folks to follow up.

[rizi]

The restore error is caused by #32205. You should be able to workaround it by restoring from the commandline and disabling restore in VS. This seems to be a worse state than it should be and I've asked some folks to follow up.

Thx for your patience and support, I will try it tomorrow.

Br

[rizi]

@ericstj your solution was working fine, thx.