Structured logging with json string

[DamianMuchlinski]

- Bug, NLog.Extensions.Logging. version : 1.4.0

**When you use json string combined with structure logging then Nlog fails,

examples:**

var someString = "string";
var someJson = "{\"jobName\": \"someJob\"}";

_logger.LogDebug("{someJson}  {someString}", someJson, someString); - WORKS
_logger.LogDebug(someString + "{someString}", someString); - WORKS
_logger.LogDebug(someJson + "{someString}", someString); - FAILS

Stacktrace

   at Microsoft.Extensions.Logging.Internal.LogValuesFormatter.GetValue(Object[] values, Int32 index)
   at NLog.Extensions.Logging.NLogMessageParameterList.IsValidParameterList(IReadOnlyList`1 parameterList, Nullable`1& originalMessageIndex, Boolean& hasMessageTemplateCapture, Boolean& isMixedPositional, Boolean& isPositional)
   at NLog.Extensions.Logging.NLogMessageParameterList..ctor(IReadOnlyList`1 parameterList)
   at NLog.Extensions.Logging.NLogMessageParameterList.TryParse(IReadOnlyList`1 parameterList)
   at NLog.Extensions.Logging.NLogLogger.TryParseMessageTemplate(LogLevel nLogLogLevel, IReadOnlyList`1 messageProperties, NLogMessageParameterList& messageParameters)
   at NLog.Extensions.Logging.NLogLogger.CreateLogEventInfo[TState](LogLevel nLogLogLevel, TState state, Exception exception, Func`3 formatter)
   at NLog.Extensions.Logging.NLogLogger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
   at Microsoft.Extensions.Logging.Logger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)

[304NotModified]

Thanks for reporting!

What's the exception message and type?

[DamianMuchlinski]

Could you please check example ? Then you have what's needed

[304NotModified]

I think this one:

System.IndexOutOfRangeException
  HResult=0x80131508
  Message=Index was outside the bounds of the array.
  Source=Microsoft.Extensions.Logging.Abstractions
  StackTrace:
   at Microsoft.Extensions.Logging.Internal.LogValuesFormatter.GetValue(Object[] values, Int32 index)
   at Microsoft.Extensions.Logging.Internal.FormattedLogValues.get_Item(Int32 index)
   at NLog.Extensions.Logging.NLogMessageParameterList.IsValidParameterList(IReadOnlyList`1 parameterList, Nullable`1& originalMessageIndex, Boolean& hasMessageTemplateCapture, Boolean& isMixedPositional, Boolean& isPositional) in D:\nlog\NLog.Extensions.Logging\src\NLog.Extensions.Logging\Logging\NLogMessageParameterList.cs:line 87
   at NLog.Extensions.Logging.NLogMessageParameterList..ctor(IReadOnlyList`1 parameterList) in D:\nlog\NLog.Extensions.Logging\src\NLog.Extensions.Logging\Logging\NLogMessageParameterList.cs:line 29
   at NLog.Extensions.Logging.NLogMessageParameterList.TryParse(IReadOnlyList`1 parameterList) in D:\nlog\NLog.Extensions.Logging\src\NLog.Extensions.Logging\Logging\NLogMessageParameterList.cs:line 49
   at NLog.Extensions.Logging.NLogLogger.TryParseMessageParameterList(IReadOnlyList`1 messageProperties) in D:\nlog\NLog.Extensions.Logging\src\NLog.Extensions.Logging\Logging\NLogLogger.cs:line 115
   at NLog.Extensions.Logging.NLogLogger.TryParseMessageTemplate(LogLevel nLogLogLevel, IReadOnlyList`1 messageProperties, NLogMessageParameterList& messageParameters) in D:\nlog\NLog.Extensions.Logging\src\NLog.Extensions.Logging\Logging\NLogLogger.cs:line 87
   at NLog.Extensions.Logging.NLogLogger.CreateLogEventInfo[TState](LogLevel nLogLogLevel, TState state, Exception exception, Func`3 formatter) in D:\nlog\NLog.Extensions.Logging\src\NLog.Extensions.Logging\Logging\NLogLogger.cs:line 60

[304NotModified]

So it's a bug in Microsoft.Extensions.Logging?

[304NotModified]

also an issue in Microsoft.Extensions.Logging 2.2 (latest stable) and Microsoft.Extensions.Logging 3.0.0-preview3.19153.1 (latest preview).

[304NotModified]

Doubting if we should work around this.

@DamianMuchlinski I think you need to escape the { and } with another { / }, so {{ etc

so

var someJson = "{{\"jobName\": \"someJob\"}}";

[DamianMuchlinski]

Thanks,

Here is my workaround : _logger.LogDebug("{someJson} {someString}", someJson, someString); - WORKS

These json come from other external component is well structured as json so I believe it should be properly escaped in Microsoft.Extensions.Logging , correct me if I am wrong

[snakefoot]

@DamianMuchlinski Well a properly formatted message-template and a properly formatted json-string are two different things. Trying to mix them together will not create butterflies.

Your workaround is the correct way of logging random blob-data. By providing it as parameters instead.

One could consider that NLog should swallow exceptions for badly formatted message-templates, but that is not the nature of Microsoft Extension Logging.

[snakefoot]

Created #272 so NLog.Extension.Logging throws FormatException instead of IndexOutOfRangeException when the logging-parameters provides doesn't match the format-string (Imitate Microsoft Extension Logging default behavior)

[DamianMuchlinski]

Well, two things 1) If we support structured logging it should be at least smart enough solution to understand most popular message format which json is nowadays 2) Logging subsystem should not crash application, at least we should be able to set if it throws exceptions or not, if not it should be logged to internal logger

One thing to note, keep in mind in business apps you might be using logger adapters which has additional features (ex. which uses also structured logging with some metadata) so consumers of logger does not need to know how we have to format string message

[snakefoot]

@DamianMuchlinski Think you are barking at the wrong tree. Go visit Microsoft and convince them instead:

https://github.com/aspnet/Extensions

If you use the default Microsoft ConsoleLogger then you will also get a very nice FormatException:

https://github.com/aspnet/Extensions/blob/398b67f8802f697cf5b3957b20766ddd9cb8fbdd/src/Logging/Logging.Console/src/ConsoleLogger.cs#L58

NLog.Extensions.Logging depends on the Microsoft Extension Logging message-parser, and it doesn't like your self-invented mixture of format-string with json-magic-dust. NLog.Extensions.Logging is not able to extract any usable details from the LogState-object because it throws exceptions when probed.

Nothing more to do here besides correcting your format-string (as you have already done), and worry about something else.

You can always create your own custom LogState-object (Instead of using Microsoft-parser) and then you can provide whatever exciting logic you want. Example can be found here:

https://github.com/NLog/NLog.Extensions.Logging/wiki/NLog-properties-with-Microsoft-Extension-Logging#logtstate-simple

[304NotModified]

I think someone should submit a bug report to MS. Count gives 3, but iterating gives an exception. That is really a bug!

[snakefoot]

I think someone should submit a bug report to MS. Count gives 3, but iterating gives an exception. That is really a bug!

Depends on how you see the logic. The message templates signals a certain number of parameter-place-holders (This is the parameter count). But if not providing enough parameters to match the parameter-place-holders then one get IndexOutOfRangeException.

NLog.Extensions.Logging is using the backdoor when casting the TState object into an IReadOnlyList and trying to iterate it (Operating in black waters). It will correctly throw FormatException when using the frontdoor:

var message = formatter(state, exception);

[304NotModified]

Fixed by #272