Skip to content

Commit 6325da9

Browse files
snakefootsnakefoot
committed
Introduced CaptureMessageParameters to skip allocating Parameters-array
1 parent 42f006a commit 6325da9

5 files changed

Lines changed: 161 additions & 30 deletions

File tree

‎src/NLog.Extensions.Logging/Logging/NLogLogger.cs‎

Lines changed: 64 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -59,10 +59,11 @@ private LogEventInfo CreateLogEventInfo<TState>(LogLevel nLogLogLevel, EventId e
5959
var messageParameters = NLogMessageParameterList.TryParse(messagePropertyList);
6060
if (messageParameters.Count == 0)
6161
{
62-
var logEvent = LogEventInfo.Create(nLogLogLevel, _logger.Name, formatter(state, exception));
62+
var logEvent = TryParsePostionalMessageTemplate(nLogLogLevel, messagePropertyList, messageParameters)
63+
?? CaputureBasicLogEvent(nLogLogLevel, formatter(state, exception), messagePropertyList, messageParameters);
6364
CaptureEventIdProperties(logEvent, eventId);
6465
return logEvent;
65-
}
66+
}
6667
else
6768
{
6869
var logEvent = TryParseMessageTemplate(nLogLogLevel, messagePropertyList, messageParameters)
@@ -103,7 +104,7 @@ private LogEventInfo TryParseMessageTemplate(LogLevel nLogLogLevel, IReadOnlyLis
103104
{
104105
if (messageParameters.HasMessageTemplateSyntax(_options.ParseMessageTemplates))
105106
{
106-
var originalMessage = messageParameters?.GetOriginalMessage(messageProperties);
107+
var originalMessage = messageParameters.GetOriginalMessage(messageProperties);
107108
var logEvent = new LogEventInfo(nLogLogLevel, _logger.Name, null, originalMessage, SingleItemArray);
108109
var messageTemplateParameters = logEvent.MessageTemplateParameters; // Forces parsing of OriginalMessage
109110
if (messageTemplateParameters.Count > 0)
@@ -119,18 +120,75 @@ private LogEventInfo TryParseMessageTemplate(LogLevel nLogLogLevel, IReadOnlyLis
119120
return null; // Parsing not needed
120121
}
121122

123+
private LogEventInfo TryParsePostionalMessageTemplate(LogLevel nLogLogLevel, IReadOnlyList<KeyValuePair<string, object>> messageProperties, NLogMessageParameterList messageParameters)
124+
{
125+
if (messageParameters.IsPositional && _options.ParseMessageTemplates)
126+
{
127+
string originalMessage = TryParsePositionalParameters(messageProperties, out var parameters);
128+
if (originalMessage != null)
129+
{
130+
return new LogEventInfo(nLogLogLevel, _logger.Name, null, originalMessage, parameters);
131+
}
132+
}
133+
134+
return null;
135+
}
136+
122137
private LogEventInfo CaptureMessageTemplate(LogLevel nLogLogLevel, string message, IReadOnlyList<KeyValuePair<string, object>> messageProperties, NLogMessageParameterList messageParameters)
123138
{
124139
// Parsing not needed, we take the fast route
125140
var originalMessage = messageParameters.GetOriginalMessage(messageProperties) ?? message;
126-
var logEvent = new LogEventInfo(nLogLogLevel, _logger.Name, originalMessage, messageParameters);
127-
if (!ReferenceEquals(originalMessage, message))
141+
var logEvent = new LogEventInfo(nLogLogLevel, _logger.Name, message, originalMessage, messageParameters.IsPositional ? Array.Empty<MessageTemplateParameter>() : messageParameters);
142+
if (_options.CaptureMessageParameters && !ReferenceEquals(originalMessage, message))
128143
{
129-
SetLogEventMessageFormatter(logEvent, messageParameters, message);
144+
var parameterCount = messageParameters.Count;
145+
if (parameterCount > 0)
146+
{
147+
var parameters = new object[parameterCount];
148+
for (int i = 0; i < parameterCount; ++i)
149+
parameters[i] = messageParameters[i].Value;
150+
logEvent.Parameters = parameters;
151+
}
130152
}
131153
return logEvent;
132154
}
133155

156+
private LogEventInfo CaputureBasicLogEvent(LogLevel nLogLogLevel, string formattedMessage, IReadOnlyList<KeyValuePair<string, object>> messageProperties, NLogMessageParameterList messageParameters)
157+
{
158+
if (messageParameters.IsPositional && _options.CaptureMessageParameters)
159+
{
160+
string originalMessage = TryParsePositionalParameters(messageProperties, out var parameters);
161+
var logEvent = new LogEventInfo(nLogLogLevel, _logger.Name, formattedMessage, originalMessage ?? formattedMessage, Array.Empty<MessageTemplateParameter>());
162+
logEvent.Parameters = parameters;
163+
return logEvent;
164+
}
165+
else
166+
{
167+
return new LogEventInfo(nLogLogLevel, _logger.Name, formattedMessage, formattedMessage, Array.Empty<MessageTemplateParameter>());
168+
}
169+
}
170+
171+
private static string TryParsePositionalParameters(IReadOnlyList<KeyValuePair<string, object>> messageProperties, out object[] parameters)
172+
{
173+
var parameterCount = messageProperties.Count;
174+
var parameterIndex = 0;
175+
parameters = new object[parameterCount - 1];
176+
string originalMessage = null;
177+
for (int i = 0; i < parameterCount; ++i)
178+
{
179+
var parameter = messageProperties[i];
180+
if (OriginalFormatPropertyName.Equals(parameter.Key))
181+
{
182+
originalMessage = parameter.Value.ToString();
183+
}
184+
else
185+
{
186+
parameters[parameterIndex++] = parameter.Value;
187+
}
188+
}
189+
return originalMessage;
190+
}
191+
134192
/// <summary>
135193
/// Allocates object[]-array for <see cref="LogEventInfo.Parameters"/> after checking
136194
/// for mismatch between Microsoft Extension Logging and NLog Message Template Parser
@@ -284,16 +342,6 @@ private static int FindMaxIndex(MessageTemplateParameters messageTemplateParamet
284342
return maxIndex;
285343
}
286344

287-
private static void SetLogEventMessageFormatter(LogEventInfo logEvent, NLogMessageParameterList messageTemplateParameters, string formattedMessage)
288-
{
289-
var parameters = new object[messageTemplateParameters.Count + 1];
290-
for (int i = 0; i < parameters.Length - 1; ++i)
291-
parameters[i] = messageTemplateParameters[i].Value;
292-
parameters[parameters.Length - 1] = formattedMessage;
293-
logEvent.Parameters = parameters;
294-
logEvent.MessageFormatter = (l) => (string)l.Parameters[l.Parameters.Length - 1];
295-
}
296-
297345
private void CaptureEventIdProperties(LogEventInfo logEvent, EventId eventId)
298346
{
299347
var captureEventId = _options.CaptureEventId;

‎src/NLog.Extensions.Logging/Logging/NLogMessageParameterList.cs‎

Lines changed: 16 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -10,22 +10,28 @@ namespace NLog.Extensions.Logging
1010
/// </summary>
1111
internal class NLogMessageParameterList : IList<MessageTemplateParameter>
1212
{
13-
private readonly IReadOnlyList<KeyValuePair<string, object>> _parameterList;
14-
private static readonly NLogMessageParameterList EmptyList = new NLogMessageParameterList(Array.Empty<KeyValuePair<string, object>>(), default, default, default);
15-
private static readonly NLogMessageParameterList OriginalMessageList = new NLogMessageParameterList(new[] { new KeyValuePair<string, object>(NLogLogger.OriginalFormatPropertyName, string.Empty) }, 0, default, default);
13+
private static readonly NLogMessageParameterList EmptyList = new NLogMessageParameterList(Array.Empty<KeyValuePair<string, object>>(), default, default, default, default);
14+
private static readonly NLogMessageParameterList EmptyPositionalList = new NLogMessageParameterList(Array.Empty<KeyValuePair<string, object>>(), default, default, default, isPositional: true);
15+
private static readonly NLogMessageParameterList OriginalMessageList = new NLogMessageParameterList(new[] { new KeyValuePair<string, object>(NLogLogger.OriginalFormatPropertyName, string.Empty) }, 0, default, default, default);
1616

17+
private readonly IReadOnlyList<KeyValuePair<string, object>> _parameterList;
1718
private readonly int? _originalMessageIndex;
18-
19-
public bool HasComplexParameters => _hasMessageTemplateCapture || _isMixedPositional;
2019
private readonly bool _hasMessageTemplateCapture;
2120
private readonly bool _isMixedPositional;
21+
private readonly bool _isPositional;
22+
23+
public bool HasComplexParameters => _hasMessageTemplateCapture || _isMixedPositional;
24+
public bool IsPositional => _isPositional;
25+
public int Count => _parameterList.Count - (_originalMessageIndex.HasValue ? 1 : 0);
26+
public bool IsReadOnly => true;
2227

23-
private NLogMessageParameterList(IReadOnlyList<KeyValuePair<string, object>> parameterList, int? originalMessageIndex, bool hasMessageTemplateCapture, bool isMixedPositional)
28+
private NLogMessageParameterList(IReadOnlyList<KeyValuePair<string, object>> parameterList, int? originalMessageIndex, bool hasMessageTemplateCapture, bool isMixedPositional, bool isPositional)
2429
{
2530
_parameterList = parameterList;
2631
_originalMessageIndex = originalMessageIndex;
2732
_hasMessageTemplateCapture = hasMessageTemplateCapture;
2833
_isMixedPositional = isMixedPositional;
34+
_isPositional = isPositional;
2935
}
3036

3137
/// <summary>
@@ -43,16 +49,16 @@ public static NLogMessageParameterList TryParse(IReadOnlyList<KeyValuePair<strin
4349
{
4450
if (isPositional)
4551
{
46-
return EmptyList; // Skip allocation, will not capture LogEventInfo.Parameters-array
52+
return EmptyPositionalList; // Skip allocation, not needed to create Parameters-array
4753
}
4854
else
4955
{
50-
return new NLogMessageParameterList(parameterList, originalMessageIndex, hasMessageTemplateCapture, isMixedPositional);
56+
return new NLogMessageParameterList(parameterList, originalMessageIndex, hasMessageTemplateCapture, isMixedPositional, isPositional);
5157
}
5258
}
5359
else
5460
{
55-
return new NLogMessageParameterList(CreateValidParameterList(parameterList), originalMessageIndex, hasMessageTemplateCapture, isMixedPositional || isPositional);
61+
return new NLogMessageParameterList(CreateValidParameterList(parameterList), originalMessageIndex, hasMessageTemplateCapture, isMixedPositional || isPositional, isPositional);
5662
}
5763
}
5864
else if (parameterCount == 1)
@@ -105,7 +111,7 @@ private static bool IsValidParameterList(IReadOnlyList<KeyValuePair<string, obje
105111
{
106112
if (!isPositional)
107113
isMixedPositional = i != 0;
108-
isMixedPositional = isMixedPositional || i != (firstChar - '0');
114+
isMixedPositional |= i != (firstChar - '0');
109115
isPositional = true;
110116
}
111117
else
@@ -201,10 +207,6 @@ private static CaptureType GetCaptureType(char firstChar)
201207
return CaptureType.Normal;
202208
}
203209

204-
public int Count => _parameterList.Count - (_originalMessageIndex.HasValue ? 1 : 0);
205-
206-
public bool IsReadOnly => true;
207-
208210
public void Add(MessageTemplateParameter item)
209211
{
210212
throw new NotSupportedException();

‎src/NLog.Extensions.Logging/Logging/NLogProviderOptions.cs‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -35,6 +35,11 @@ public class NLogProviderOptions
3535
/// </summary>
3636
public bool CaptureMessageProperties { get; set; } = true;
3737

38+
/// <summary>
39+
/// Enable capture of <see cref="LogEventInfo.Parameters"/> from the ILogger-State-object. Only relevant when <see cref="CaptureMessageTemplates"/> = true
40+
/// </summary>
41+
public bool CaptureMessageParameters { get; set; }
42+
3843
/// <summary>
3944
/// Use the NLog engine for parsing the message template (again) and format using the NLog formatter
4045
/// </summary>

‎test/NLog.Extensions.Logging.Tests/LoggerTests.cs‎

Lines changed: 74 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -240,6 +240,80 @@ public void TestWithEmptyMessageAndNullException()
240240
Assert.Equal("NLog.Extensions.Logging.Tests.LoggerTests.Runner|DEBUG||EventId=20", runner.LastTargetMessage);
241241
}
242242

243+
[Fact]
244+
public void TestPositionalCaptureMessageParameters()
245+
{
246+
LogEventInfo logEvent = null;
247+
var debugTarget = new MethodCallTarget("output", (l, args) => logEvent = l);
248+
var runner = GetRunner<Runner>(new NLogProviderOptions() { CaptureMessageParameters = true }, debugTarget);
249+
string formatString = "{0,8:S} {1,8:S}";
250+
runner.Logger.LogDebug(formatString, "Hello", "World");
251+
252+
Assert.NotNull(logEvent);
253+
Assert.Equal(" Hello World", logEvent.FormattedMessage);
254+
Assert.Equal(formatString, logEvent.Message);
255+
Assert.NotNull(logEvent.Parameters);
256+
Assert.Equal(2, logEvent.Parameters.Length);
257+
Assert.Equal("Hello", logEvent.Parameters[0]);
258+
Assert.Equal("World", logEvent.Parameters[1]);
259+
260+
var messageParameters = logEvent.MessageTemplateParameters;
261+
Assert.True(messageParameters.IsPositional);
262+
Assert.Equal(2, messageParameters.Count);
263+
Assert.Equal("Hello", messageParameters[0].Value);
264+
Assert.Equal("S", messageParameters[0].Format);
265+
Assert.Equal("World", messageParameters[1].Value);
266+
Assert.Equal("S", messageParameters[1].Format);
267+
}
268+
269+
[Fact]
270+
public void TestParseMessageTemplates()
271+
{
272+
LogEventInfo logEvent = null;
273+
var debugTarget = new MethodCallTarget("output", (l, args) => logEvent = l);
274+
var runner = GetRunner<Runner>(new NLogProviderOptions() { ParseMessageTemplates = true }, debugTarget);
275+
var messageTemplate = "message with {ParameterCount} parameters";
276+
runner.Logger.LogDebug(messageTemplate, "1");
277+
278+
Assert.NotNull(logEvent);
279+
Assert.Equal(messageTemplate, logEvent.Message);
280+
Assert.NotNull(logEvent.Parameters);
281+
Assert.Single(logEvent.Parameters);
282+
Assert.Equal("1", logEvent.Parameters[0]);
283+
284+
var messageParameters = logEvent.MessageTemplateParameters;
285+
Assert.False(messageParameters.IsPositional);
286+
Assert.Equal(1, messageParameters.Count);
287+
Assert.Equal("ParameterCount", messageParameters[0].Name);
288+
Assert.Equal("1", messageParameters[0].Value);
289+
}
290+
291+
[Fact]
292+
public void TestPositionalParseMessageTemplates()
293+
{
294+
LogEventInfo logEvent = null;
295+
var debugTarget = new MethodCallTarget("output", (l, args) => logEvent = l);
296+
var runner = GetRunner<Runner>(new NLogProviderOptions() { ParseMessageTemplates = true }, debugTarget);
297+
string formatString = "{0,8:S} {1,8:S}";
298+
runner.Logger.LogDebug(formatString, "Hello", "World");
299+
300+
Assert.NotNull(logEvent);
301+
Assert.Equal(" Hello World", logEvent.FormattedMessage);
302+
Assert.Equal(formatString, logEvent.Message);
303+
Assert.NotNull(logEvent.Parameters);
304+
Assert.Equal(2, logEvent.Parameters.Length);
305+
Assert.Equal("Hello", logEvent.Parameters[0]);
306+
Assert.Equal("World", logEvent.Parameters[1]);
307+
308+
var messageParameters = logEvent.MessageTemplateParameters;
309+
Assert.True(messageParameters.IsPositional);
310+
Assert.Equal(2, messageParameters.Count);
311+
Assert.Equal("Hello", messageParameters[0].Value);
312+
Assert.Equal("S", messageParameters[0].Format);
313+
Assert.Equal("World", messageParameters[1].Value);
314+
Assert.Equal("S", messageParameters[1].Format);
315+
}
316+
243317
private Runner GetRunner()
244318
{
245319
return base.GetRunner<Runner>();

‎test/NLog.Extensions.Logging.Tests/NLogMessageParameterListTests.cs‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -58,6 +58,7 @@ public void CreateNLogMessageParameterDifferentCaptureTypes()
5858
Assert.Equal(new MessageTemplateParameter("b", 2, null, CaptureType.Stringify), list[1]);
5959
Assert.Equal(new MessageTemplateParameter("c", 3, null, CaptureType.Serialize), list[2]);
6060
Assert.True(list.HasComplexParameters);
61+
Assert.False(list.IsPositional);
6162
}
6263

6364
[Fact]
@@ -73,6 +74,7 @@ public void CreateNLogMessageParameterIsPositional()
7374

7475
Assert.Empty(list);
7576
Assert.False(list.HasComplexParameters);
77+
Assert.True(list.IsPositional);
7678
}
7779

7880
[Fact]

0 commit comments

Comments
 (0)