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 <notifications@github.com> 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.

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.