Microsoft.Extensions.Logging.Console: should log Exception.Data

[Davilink]

Is your feature request related to a problem? Please describe.

I add some data to my exception and i didn't see them in the Console.

var exceptions = new List<Exception>();
try
{
    await Task.WhenAll(queries);
}
catch(Exception)
{
    for (var j=0; j<queries.Count; j++)
    {
        if (queries[j].Exception?.InnerException != null)
        {
            var exception = queries[j].Exception!.InnerException!;
            // we add date for logging purpose
            exception.Data.Add("userTaskId", userTasksId[j]);
            exceptions.Add(exception);
        }
    }
}

if (exceptions.Any())
{
    throw _apiExceptionFactory.Create(
        await ProblemDetailsWithContextFactory(ApiErrors.UNKNOWN, StatusCodes.Status500InternalServerError, "", "Some reassignment failed."),
        new AggregateException(exceptions)
    );
}

// somewhere else
_loggerFactory.CreateLogger(exception.CategoryName)
                .Log(exception.LogLevel, exception, exception.ProblemDetails.Detail, exception.ProblemDetails.Extensions);

but when i go into the console, the output doesn't display the data.

fail: MyApp.Controllers.ReassignmentController[0]
      Some reassignment failed.
MyApp.Shared.Helper.ApiExceptions.ApiException`1[MyApp.Controllers.ReassignmentController]: Some reassignment failed.
 ---> System.AggregateException: One or more errors occurred. (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.) (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.) (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.) (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.) (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.) (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.) (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.) (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.) (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.) (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.)
 ---> System.Net.Http.HttpRequestException: Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.
 ---> System.Net.Sockets.SocketException (10061): Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.
   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.ConnectAsync(HttpRequestMessage request, Boolean allowHttp2, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.CreateHttp11ConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.GetHttpConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.DiagnosticsHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at Microsoft.Extensions.Http.Logging.LoggingScopeHttpMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at MyApp.CamundaClient.Implementations.UserTaskClient.SetAssignee(Boolean isAssignmentForced, Guid id, String userId, CancellationToken token) in C:\Users\MyUser\source\repos\MyRepo\MyApp.CamundaClient\Implementations\UserTaskClient.cs:line 287
   at MyApp.Controllers.ReassignmentController.UpdateAssignee(IList`1 userTasksId, String userId) in C:\Users\MyUser\source\repos\MyRepo\MyApp\Controllers\ReassignmentController.cs:line 280
   --- End of inner exception stack trace ---
 ---> (Inner Exception dotnet/extensions#1) System.Net.Http.HttpRequestException: Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.
 ---> System.Net.Sockets.SocketException (10061): Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.
   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.ConnectAsync(HttpRequestMessage request, Boolean allowHttp2, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.CreateHttp11ConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.GetHttpConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.DiagnosticsHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at Microsoft.Extensions.Http.Logging.LoggingScopeHttpMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at MyApp.CamundaClient.Implementations.UserTaskClient.SetAssignee(Boolean isAssignmentForced, Guid id, String userId, CancellationToken token) in C:\Users\MyUser\source\repos\MyRepo\MyApp.CamundaClient\Implementations\UserTaskClient.cs:line 287<---
 ---> (Inner Exception dotnet/extensions#2) System.Net.Http.HttpRequestException: Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.
 ---> System.Net.Sockets.SocketException (10061): Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.
   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   ...

i was expecting that the console log provider would display someting like

fail: MyApp.Controllers.ReassignmentController[0]
      Some reassignment failed.
MyApp.Shared.Helper.ApiExceptions.ApiException`1[MyApp.Controllers.ReassignmentController]: Some reassignment failed.
 ---> System.AggregateException: One or more errors occurred. (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.) (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.) (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.) (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.) (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.) (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.) (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.) (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.) (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.) (Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.)
 ---> System.Net.Http.HttpRequestException: Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.
 ---> System.Net.Sockets.SocketException (10061): Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.
   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.ConnectAsync(HttpRequestMessage request, Boolean allowHttp2, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.CreateHttp11ConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.GetHttpConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.DiagnosticsHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at Microsoft.Extensions.Http.Logging.LoggingScopeHttpMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at MyApp.CamundaClient.Implementations.UserTaskClient.SetAssignee(Boolean isAssignmentForced, Guid id, String userId, CancellationToken token) in C:\Users\MyUser\source\repos\MyRepo\MyApp.CamundaClient\Implementations\UserTaskClient.cs:line 287
   at MyApp.Controllers.ReassignmentController.UpdateAssignee(IList`1 userTasksId, String userId) in C:\Users\MyUser\source\repos\MyRepo\MyApp\Controllers\ReassignmentController.cs:line 280
   --- End of inner exception stack trace ---
 ---> (Inner Exception dotnet/extensions#1) System.Net.Http.HttpRequestException: Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.
 ---> System.Net.Sockets.SocketException (10061): Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.
   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.ConnectAsync(HttpRequestMessage request, Boolean allowHttp2, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.CreateHttp11ConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.GetHttpConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.DiagnosticsHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at Microsoft.Extensions.Http.Logging.LoggingScopeHttpMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at MyApp.CamundaClient.Implementations.UserTaskClient.SetAssignee(Boolean isAssignmentForced, Guid id, String userId, CancellationToken token) in C:\Users\MyUser\source\repos\MyRepo\MyApp.CamundaClient\Implementations\UserTaskClient.cs:line 287<---
    Data:
        userTaskId: {d69cd7a4-6e0b-11ea-93d6-94e6f7918376}
 ---> (Inner Exception dotnet/extensions#2) System.Net.Http.HttpRequestException: Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.
 ---> System.Net.Sockets.SocketException (10061): Aucune connexion n’a pu être établie car l’ordinateur cible l’a expressément refusée.
   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   ...

Describe the solution you'd like

Add the Data field in the log.

[Davilink]

something like https://gist.github.com/nblumhardt/dddaa2139bbf4b561fa7

[davidfowl]

This seems reasonable. Care to submit a PR.

[ericstj]

/cc @maryamariyan

[WernerMairl]

Hi,
working on this...

current implementation is:

WriteMessage(textWriter, exception.ToString(), singleLine);
we can replace/extend this with a key/value trace like this...

but, a few aspects must be considered

exception.Tostring() output has multiple "sections" separated by newlines:

• classname
• message
• innerexception.tostring()
• stacktrace

our trace can only be appended to the result of exception.ToString()
(re-implementing exception.tostring() locally may not a good idea

basically:

• we can append the key-value trace after the stacktrace - we should agree about the concrete format.

• what we do with innerexception.data() ? (and innerexception.innerexception.data.....) ?

"best" solution:
Modify/extend System.Exception (toString()) in a way that allows exception.data output in the right place of the hierarchy...

but touching System.Exception is a different story ;-)

My current playground

[maryamariyan]

@WernerMairl thank you for the prototype. A couple notes

---

• I see you are updating SimpleConsoleFormatter in the prototype. Also note, we have two other built-in formatters: systemd and json, (found under SystemdConsoleFormatter and JsonConsoleFormatter). (ConsoleFormatters are new concepts introduced since .NET5 preview8, you can follow instructions here to test them out). So perhaps those would need to be updated too to additionally log Exception.Data.
• I see you plan on adding a property to ConsoleFormatterOptions. That is fine it could then be accessed by all three formatters (simple, json and systemd). For this to work you would also need to update the Microsoft.Extensions.Logging.Console.cs ref file. (see link).
• (Since your prototype updates ConsoleFormatterOptions) note that adding any new APIs would need to go through a .NET API review process.
  I think we won't get to this in 5.0, but it can be considered in the next release.

---

One question that arrises here is that, do we want to have an option for the log formatter that toggles between logging Exception.Data or do we expect that to always be showing up for exceptions containing this information. If the answer is we do not need the toggling behaviour then there is no need for you to make the API addition.

---

@WernerMairl, while your at it you could also perhaps make use of the gist in this comment to play around with custom log formatting, not only the built-in ones if you like.

[WernerMairl]

@maryamariyan a few ideas and answers:

• "do we want to have an option for the log formatter"
  in my experience: yes, we se should implement this feature as Opt-In!
  why:
  Exception.Data is a long existing feature, and I'm not the only one that haa used this property really often.
  BUT there may be a lot of data (maybe data that is sensitive for security) inside the dictionary.
  Printing out this data as default may cause a lot of problems

  • security
  • performance (log tracer performance, log sizes)

• i have changed the ref file

• i have improved and simplified the entire implementation by modifying the System.Exception class....
  that may be cause a lot of discussions...

Why modifying exception.cs ?
the only/best way to implement this feature for the "innerException" hierarchy.
I cannot see a lot of value in this feature, if it does not print out the data- dictionary also for the innerexception hierarchy

• i have implemented this now for SimpleConsole and SystemDConsole.
  Not implemented yet for Jsonconsole because current implementation there has also some issue with formatting values...
  JSonConsoleFormatter is the one and only Formatter that is ignoring innerexception (intended ?) and does his own exception formatting implementation...

I need some feedback about going forward this way - specially adopting System.Exception in this or another way....
regards
Werner

[maryamariyan]

JSonConsoleFormatter is the one and only Formatter that is ignoring innerexception (intended ?) and does his own exception formatting implementation...

How is JsonConsoleFormatter the only one that is ignoring InnerException?

[WernerMairl]

SystemDConsoleFormatter and SimpleConsoleFormatter are calling exception.ToString() and the "ToString()" default implementation is calling innerException.ToString().

The JSonConsoleFormatter (in my understanding) is NOT calling exception.ToString() but it prints out all the exception properties one by one IGNORING innerexception.....

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

Line 55 in 51ad8e4

if (exception != null)

This is the result from a quick investigation on the JSonConsoleFormatter. I can write a test about this "innerException" thing to provide evidence if necessary....

[KalleOlaviNiemitalo]

The documentation of Exception.Data says that each key is "typically an identifying string". If a key is not a string, I think key.ToString() will be good enough for logging. From https://source.dot.net/ and https://referencesource.microsoft.com/, it looks like keys are almost always constant strings, except:

• System.Linq.Expressions.Interpreter.SaveTraceToException uses typeof(InterpretedFrameInfo) as a key. InterpreterFrame.SaveTraceToException publishes a private type #39433
• Microsoft.VisualBasic.FileIO.FileSystem.FxCopyOrMoveDirectory uses paths of files as keys, so they are not constants.
• In .NET Framework, System.Activities.XamlIntegration.ActivityXamlServices.Compile uses TextExpressionCompilerError instances as keys. TextExpressionCompilerError does not override ToString(), and there can be several in the same Exception.

Exception.InnerException in JsonConsoleFormatter is #40507.

(It might also be useful to translate properties like SqlException.Number to JSON properties, but doing that in JsonConsoleFormatter would require API changes to let the application control which properties of each exception type are interesting and how their values should be formatted. For instance, ReflectionTypeLoadException.Types is public but not interesting.)

[maryamariyan]

SystemDConsoleFormatter and SimpleConsoleFormatter are calling exception.ToString() and the "ToString()" default implementation is calling innerException.ToString().

Good point. Seems like a proper thing to do is for JsonConsoleFormatter to also call exception.ToString() as also described in this comment: #40507 (comment)

[yufeih]

It is possible for Exception.ToString() to print Exception.Data, potentially with an opt-in flag for security, performance reasons?

[Davilink]

Maybe we could create a new properties on the Exception making it explicit that it's will be logged, so with this suggestion no breaking change is inserted for previous code that used the data field and doesn't expect it to be logged.
Exception.LoggingData or maybe Exception.Details or other suggestion is welcome