Why do I get FormatException with NLog?

Question

I get the fllowing in the internal NLog log :

2020-05-10 16:38:09.9251 Warn Error when formatting a message. Exception: System.FormatException: The input string had an incorrect format.
   vid System.Text.StringBuilder.FormatError()
   vid System.Text.StringBuilder.AppendFormatHelper(IFormatProvider provider, String format, ParamsArray args)
   vid System.String.FormatHelper(IFormatProvider provider, String format, ParamsArray args)
   vid System.String.Format(IFormatProvider provider, String format, Object[] args)
   vid NLog.LogEventInfo.CalcFormattedMessage()

If fill the LogEventInfo like this :

var logEvent = new LogEventInfo();
                    logEvent.Level = logData.LogLevel.ToLogLevel();
                    logEvent.Message = JsonConvert.SerializeObject(logData, Formatting.Indented);
                    logEvent.Properties.Add("logdata", logData);
                    logEvent.Parameters = new object[1] { logData };
                    _genLogger.Log(logEvent);

The warning seems to come from when I set the Message to this :

{
  "ComputerName": null,
  "LogLevel": 5,
  "LogId": null,
  "PersonId": null,
  "Text": "Communication Message",
  "TimeStamp": "2020-05-10T16:42:55.9456429+02:00",
  "ExceptionTyp": 7,
  "UserMessage": null,
  "RelatedObjectJsonString": "[\r\n  {\r\n    \"Address\": \"https://192.168.130.29:44476/MyApp5Service/Client\",\r\n    \"IsEmpty\": false,\r\n    \"IsFaulted\": false,\r\n    \"Action\": \"GetUserConfigurations\",\r\n    \"CallDirection\": 0,\r\n    \"EventTime\": \"2020-05-10T16:42:55.9406583+02:00\",\r\n    \"IsCallback\": false\r\n  }\r\n]",
  "SystemInformation": ""
}

What am I doing wrong?

Regards

Answer 1

The message is string-formatted or structured-formatted message. The parameters are used for formatting the message.

Examples

String-formatted

When all template holders are numeric (between the { and }), the message is used as a string-formatted message.

logger.Info("Logon by user:{0} from ip_address:{1}", "Kenny", "127.0.0.1");

Where the first parameter is the message and the others the parameters

Structured format:

logger.Info("Logon by {user} from {ip_address}", "Kenny", "127.0.0.1"); // Logon by "Kenny" from "127.0.0.1"

Current issue

So we're doing here something like:

string.Format("{
  "ComputerName": null,
  "LogLevel": 5,
  "LogId": null,
  "PersonId": null,
  "Text": "Communication Message",
  "TimeStamp": "2020-05-10T16:42:55.9456429+02:00",
  "ExceptionTyp": 7,
  "UserMessage": null,
  "RelatedObjectJsonString": "[\r\n  {\r\n    \"Address\": \"https://192.168.130.29:44476/MyApp5Service/Client\",\r\n    \"IsEmpty\": false,\r\n    \"IsFaulted\": false,\r\n    \"Action\": \"GetUserConfigurations\",\r\n    \"CallDirection\": 0,\r\n    \"EventTime\": \"2020-05-10T16:42:55.9406583+02:00\",\r\n    \"IsCallback\": false\r\n  }\r\n]",
  "SystemInformation": ""
}", logData);

Don't think that is what you need ;)

Solution

I'm not sure if you need the data in your message. So listed both options.

There is no need to JSON convert the data yourself. That could be done in the config.

Data in message

I would recommend to use structured logging here.

logger.Log(loglevel, "Message with {LogData}", logData);

You could render the logData as JSON as follows in your config:

${event-properties:item=LogData:jsonEncode=true}

See ${json-encode} and ${event-properties}

Note: you have some control how the message (${message}) will be rendered, see How to use structured logging

Data not in message

Use the .WithProperty, which is syntactic sugar for the properties.

logger.WithProperty("LogData", logData).Log(loglevel, "Message without LogData");

Also here you could render the object as JSON with the ${event-properties:item=LogData:jsonEncode=true}