NLog TemplateParserException, expected '{' but found '\' instead in format?
I using NLog (4.7.2) in a project where I get the following exception in the NLog logfile:
2020-07-03 15:41:52.5324 Debug Watching path 'C:\DEVSTUFF\MyApp\Produkter\MyAppUtveckling\Solution\MyApp.Client.Main\bin\Debug' filter 'NLog.config' for changes. 2020-07-03 15:41:52.5324 Debug --- NLog configuration dump --- 2020-07-03 15:41:52.5324 Debug Targets: 2020-07-03 15:41:52.5513 Debug LogToService Target[LogToService] 2020-07-03 15:41:52.5513 Debug LogMessageEvent Target[communicationLogWindow] 2020-07-03 15:41:52.5633 Debug Rules: 2020-07-03 15:41:52.5633 Debug --- End of NLog configuration dump --- 2020-07-03 15:41:52.5853 Trace FindReachableObject<System.Object>: 2020-07-03 15:41:52.5942 Trace Scanning LogToServiceTarget 'LogToService Target[LogToService]' 2020-07-03 15:41:52.5942 Trace Scanning Property Layout ''${longdate}|${level:uppercase=true}|${logger}|${message}'' NLog.Layouts 2020-07-03 15:41:52.5942 Trace Scanning SimpleLayout ''${longdate}|${level:uppercase=true}|${logger}|${message}'' 2020-07-03 15:41:52.6132 Trace Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel 2020-07-03 15:41:52.6132 Trace Scanning LongDateLayoutRenderer 'Layout Renderer: ${longdate}' 2020-07-03 15:41:52.6271 Trace Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}' 2020-07-03 15:41:52.6271 Trace Scanning UppercaseLayoutRendererWrapper 'Layout Renderer: ${uppercase}' 2020-07-03 15:41:52.6271 Trace Scanning Property Inner 'SimpleLayout=Layout Renderer: ${level}' NLog.Layouts 2020-07-03 15:41:52.6561 Trace Scanning SimpleLayout 'SimpleLayout=Layout Renderer: ${level}' 2020-07-03 15:41:52.6561 Trace Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel 2020-07-03 15:41:52.6561 Trace Scanning LevelLayoutRenderer 'Layout Renderer: ${level}' 2020-07-03 15:41:52.6730 Trace Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}' 2020-07-03 15:41:52.6730 Trace Scanning LoggerNameLayoutRenderer 'Layout Renderer: ${logger}' 2020-07-03 15:41:52.6910 Trace Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}' 2020-07-03 15:41:52.6910 Trace Scanning MessageLayoutRenderer 'Layout Renderer: ${message}' 2020-07-03 15:41:52.7039 Trace Scanning LogMessageEventTarget 'LogMessageEvent Target[communicationLogWindow]' 2020-07-03 15:41:52.7039 Trace Scanning Property Layout ''${longdate}|${level:uppercase=true}|${logger}|${message}'' NLog.Layouts 2020-07-03 15:41:52.7039 Trace Scanning SimpleLayout ''${longdate}|${level:uppercase=true}|${logger}|${message}'' 2020-07-03 15:41:52.7219 Trace Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel 2020-07-03 15:41:52.7219 Trace Scanning LongDateLayoutRenderer 'Layout Renderer: ${longdate}' 2020-07-03 15:41:52.7219 Trace Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}' 2020-07-03 15:41:52.7388 Trace Scanning UppercaseLayoutRendererWrapper 'Layout Renderer: ${uppercase}' 2020-07-03 15:41:52.7388 Trace Scanning Property Inner 'SimpleLayout=Layout Renderer: ${level}' NLog.Layouts 2020-07-03 15:41:52.7498 Trace Scanning SimpleLayout 'SimpleLayout=Layout Renderer: ${level}' 2020-07-03 15:41:52.7498 Trace Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel 2020-07-03 15:41:52.7668 Trace Scanning LevelLayoutRenderer 'Layout Renderer: ${level}' 2020-07-03 15:41:52.7668 Trace Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}' 2020-07-03 15:41:52.7817 Trace Scanning LoggerNameLayoutRenderer 'Layout Renderer: ${logger}' 2020-07-03 15:41:52.7817 Trace Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}' 2020-07-03 15:41:52.7817 Trace Scanning MessageLayoutRenderer 'Layout Renderer: ${message}' 2020-07-03 15:41:52.8017 Info Found 22 configuration items 2020-07-03 15:41:52.8127 Debug Unused target checking is started... Rule Count: 0, Target Count: 2 2020-07-03 15:41:52.8127 Warn Unused target detected. Add a rule for this target to the configuration. TargetName: LogToService 2020-07-03 15:41:52.8296 Warn Unused target detected. Add a rule for this target to the configuration. TargetName: communicationLogWindow 2020-07-03 15:41:52.8296 Debug Unused target checking is completed. Total Rule Count: 0, Total Target Count: 2, Unused Target Count: 2 2020-07-03 15:41:52.8296 Trace Initializing Layout Renderer: ${message} 2020-07-03 15:41:52.8476 Trace Initializing Layout Renderer: ${literal} 2020-07-03 15:41:52.8476 Trace Initializing Layout Renderer: ${logger} 2020-07-03 15:41:52.8595 Trace Initializing Layout Renderer: ${literal} 2020-07-03 15:41:52.8595 Trace Initializing Layout Renderer: ${level} 2020-07-03 15:41:52.8595 Trace Initializing SimpleLayout=Layout Renderer: ${level} 2020-07-03 15:41:52.8805 Trace FindReachableObject<System.Object>: 2020-07-03 15:41:52.8805 Trace Scanning SimpleLayout 'SimpleLayout=Layout Renderer: ${level}' 2020-07-03 15:41:52.8924 Trace Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel 2020-07-03 15:41:52.8924 Trace Scanning LevelLayoutRenderer 'Layout Renderer: ${level}' 2020-07-03 15:41:52.9074 Trace Initializing Layout Renderer: ${uppercase} 2020-07-03 15:41:52.9074 Trace Initializing Layout Renderer: ${literal} 2020-07-03 15:41:52.9074 Trace Initializing Layout Renderer: ${longdate} 2020-07-03 15:41:52.9253 Trace Initializing '${longdate}|${level:uppercase=true}|${logger}|${message}' 2020-07-03 15:41:52.9253 Trace FindReachableObject<System.Object>: 2020-07-03 15:41:52.9373 Trace Scanning SimpleLayout ''${longdate}|${level:uppercase=true}|${logger}|${message}'' 2020-07-03 15:41:52.9373 Trace Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel 2020-07-03 15:41:52.9373 Trace Scanning LongDateLayoutRenderer 'Layout Renderer: ${longdate}' 2020-07-03 15:41:52.9523 Trace Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}' 2020-07-03 15:41:52.9523 Trace Scanning UppercaseLayoutRendererWrapper 'Layout Renderer: ${uppercase}' 2020-07-03 15:41:52.9523 Trace Scanning Property Inner 'SimpleLayout=Layout Renderer: ${level}' NLog.Layouts 2020-07-03 15:41:52.9697 Trace Scanning SimpleLayout 'SimpleLayout=Layout Renderer: ${level}' 2020-07-03 15:41:52.9697 Trace Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel 2020-07-03 15:41:52.9697 Trace Scanning LevelLayoutRenderer 'Layout Renderer: ${level}' 2020-07-03 15:41:52.9872 Trace Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}' 2020-07-03 15:41:52.9872 Trace Scanning LoggerNameLayoutRenderer 'Layout Renderer: ${logger}' 2020-07-03 15:41:52.9987 Trace Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}' 2020-07-03 15:41:52.9987 Trace Scanning MessageLayoutRenderer 'Layout Renderer: ${message}' 2020-07-03 15:41:52.9987 Trace Initializing LogMessageEvent Target[communicationLogWindow] 2020-07-03 15:41:53.0176 Trace FindReachableObject<NLog.Layouts.Layout>: 2020-07-03 15:41:53.0176 Trace Scanning LogMessageEventTarget 'LogMessageEvent Target[communicationLogWindow]' 2020-07-03 15:41:53.0316 Trace Scanning Property Layout ''${longdate}|${level:uppercase=true}|${logger}|${message}'' NLog.Layouts 2020-07-03 15:41:53.0316 Trace Scanning SimpleLayout ''${longdate}|${level:uppercase=true}|${logger}|${message}'' 2020-07-03 15:41:53.0475 Trace LogMessageEvent Target[communicationLogWindow] has 1 layouts 2020-07-03 15:41:53.0475 Trace Initializing Layout Renderer: ${message} 2020-07-03 15:41:53.0655 Trace Initializing Layout Renderer: ${literal} 2020-07-03 15:41:53.0655 Trace Initializing Layout Renderer: ${logger} 2020-07-03 15:41:53.0815 Trace Initializing Layout Renderer: ${literal} 2020-07-03 15:41:53.0815 Trace Initializing Layout Renderer: ${level} 2020-07-03 15:41:53.0934 Trace Initializing SimpleLayout=Layout Renderer: ${level} 2020-07-03 15:41:53.0934 Trace FindReachableObject<System.Object>: 2020-07-03 15:41:53.1094 Trace Scanning SimpleLayout 'SimpleLayout=Layout Renderer: ${level}' 2020-07-03 15:41:53.1094 Trace Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel 2020-07-03 15:41:53.1263 Trace Scanning LevelLayoutRenderer 'Layout Renderer: ${level}' 2020-07-03 15:41:53.1263 Trace Initializing Layout Renderer: ${uppercase} 2020-07-03 15:41:53.1403 Trace Initializing Layout Renderer: ${literal} 2020-07-03 15:41:53.1403 Trace Initializing Layout Renderer: ${longdate} 2020-07-03 15:41:53.1403 Trace Initializing '${longdate}|${level:uppercase=true}|${logger}|${message}' 2020-07-03 15:41:53.1583 Trace FindReachableObject<System.Object>: 2020-07-03 15:41:53.1583 Trace Scanning SimpleLayout ''${longdate}|${level:uppercase=true}|${logger}|${message}'' 2020-07-03 15:41:53.1583 Trace Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel 2020-07-03 15:41:53.1762 Trace Scanning LongDateLayoutRenderer 'Layout Renderer: ${longdate}' 2020-07-03 15:41:53.1762 Trace Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}' 2020-07-03 15:41:53.1872 Trace Scanning UppercaseLayoutRendererWrapper 'Layout Renderer: ${uppercase}' 2020-07-03 15:41:53.1872 Trace Scanning Property Inner 'SimpleLayout=Layout Renderer: ${level}' NLog.Layouts 2020-07-03 15:41:53.1872 Trace Scanning SimpleLayout 'SimpleLayout=Layout Renderer: ${level}' 2020-07-03 15:41:53.2073 Trace Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel 2020-07-03 15:41:53.2073 Trace Scanning LevelLayoutRenderer 'Layout Renderer: ${level}' 2020-07-03 15:41:53.2183 Trace Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}' 2020-07-03 15:41:53.2183 Trace Scanning LoggerNameLayoutRenderer 'Layout Renderer: ${logger}' 2020-07-03 15:41:53.2183 Trace Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}' 2020-07-03 15:41:53.2362 Trace Scanning MessageLayoutRenderer 'Layout Renderer: ${message}' 2020-07-03 15:41:53.2362 Trace Initializing LogToService Target[LogToService] 2020-07-03 15:41:53.2362 Trace FindReachableObject<NLog.Layouts.Layout>: 2020-07-03 15:41:53.2538 Trace Scanning LogToServiceTarget 'LogToService Target[LogToService]' 2020-07-03 15:41:53.2538 Trace Scanning Property Layout ''${longdate}|${level:uppercase=true}|${logger}|${message}'' NLog.Layouts 2020-07-03 15:41:53.2658 Trace Scanning SimpleLayout ''${longdate}|${level:uppercase=true}|${logger}|${message}'' 2020-07-03 15:41:53.2658 Trace LogToService Target[LogToService] has 1 layouts 2020-07-03 15:41:53.2658 Info Configuration initialized. 2020-07-03 15:41:53.2847 Info NLog, Version=4.0.0.0, Culture=neutral, PublicKeyToken=5120e14c03d0593c. File version: 4.7.0.11381. Product version: 4.7.0+4d138800820311d0b60b6437f1dd2ed1d571d47d. 2020-07-03 15:41:53.2847 Debug Targets not configured for logger: MyAppKontext.Kontext 2020-07-03 15:42:51.3143 Debug Targets not configured for logger: GeneralLogger 2020-07-03 15:42:51.3143 Debug Targets not configured for logger: CommunicationLogger 2020-07-03 15:42:51.3143 Debug Targets not configured for logger: FileLogger The C# code that trigger the Log function looks like this:
public void Log(LogData logData) { SerlizeParameters(logData); 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 nlog.config looks like this:
<targets> <target name="LogToService" xsi:type="LogToService"/> <target name="communicationLogWindow" xsi:type="LogMessageEvent"/> <target xsi:type="File" name="communicationFileLog" fileName="${basedir}/logs/${shortdate}.log" maxArchiveDays="5" maxArchiveFiles="10"> <!--SkipCharsInParameterObject = Starting position within the serialized string --> <!--TakeCharsInParameterObject = Lengh of data(char) to serialize --> <!--TakeCharsInParameterObject = 0 - No serialization --> <!--TakeCharsInParameterObject = -1 - Serialize everything --> <!--FilterServiceMethodName = Exact name of servicemethods to listen on, comma(,) can be used to filter on more then 1 method. --> <!--FilterCallDirection = Send, Receive, ReceiveMQ, Unknown(all) --> <layout xsi:type="JsonNetLayout" SkipCharsInParameterObject="0" TakeCharsInParameterObject="1000" FilterServiceMethodName="" FilterCallDirection="Unknown"/> </target> </targets> <rules> <logger name="GeneralLogger" minlevel="Warn" writeto="LogToService"></logger> <logger name="CommunicationLogger" minlevel="Trace" writeto="communicationLogWindow"></logger> </rules> My custom target is never triggered, probably the exception is thrown right before.
I have tried to set the logEvent.Message to "test" but that does nothing. Why do i get this exception?
Regards
EDIT: When I turn off the structure loggin(parseMessageTemplates="false") I get this in the log file instead of the exception:
2020-07-03 16:46:04.4968 Debug Targets not configured for logger: MyAppKontext.Kontext 2020-07-03 16:46:16.7226 Debug Targets not configured for logger: GeneralLogger 2020-07-03 16:46:16.7226 Debug Targets not configured for logger: CommunicationLogger 2020-07-03 16:46:16.7356 Debug Targets not configured for logger: FileLogger 
NLog is fine with assigning "blob"-data to LogEventInfo.Message-property. But if you also assign LogEventInfo.Parameters then NLog will try to parse the messsage and inject the parameters.
So just skip the Parameters-property, and Message will become a blob:
var logEvent = new LogEventInfo(); logEvent.Level = logData.LogLevel.ToLogLevel(); logEvent.Message = JsonConvert.SerializeObject(logData, Formatting.Indented); logEvent.Properties.Add("logdata", logData); // Skip this -> logEvent.Parameters = new object[1] { logData }; _genLogger.Log(logEvent); You could also inject the blob as format-parameter like this:
var logEvent = new LogEventInfo(); logEvent.Level = logData.LogLevel.ToLogLevel(); logEvent.Message = "{0}"; // Blob formatting logEvent.Properties.Add("logdata", logData); logEvent.Parameters = new object[1] { JsonConvert.SerializeObject(logData, Formatting.Indented); }; _genLogger.Log(logEvent); Another alternative is using message-templates like this (Will use NLog JsonSerializer to format logData):
_genLogger.Log(logData.LogLevel.ToLogLevel(), "{@logdata}", logData); See also: https://github.com/NLog/NLog/wiki/How-to-use-structured-logging
You can’t send JSON in the message. The message is parsed as a message template (with {0} or {Named} tokens.) The Parameters are used for creating the message, see it as a fancy string.Format.
You could pass the data in the properties, as in your example but don’t sent it also in the message or parameters.
So this is OK:
var logEvent = new LogEventInfo(); logEvent.Level = logData.LogLevel.ToLogLevel(); logEvent.Message = "normal message" logEvent.Properties.Add("logdata", logData); _genLogger.Log(logEvent); 
