Skip to content

Commit 24819c4

Browse files
feat: Include structured log message arguments as context data for MEL (#3479)
* feat: Extract structured log message arguments as context data for MEL (#3470) * feat: Extract structured log message arguments as context data for MEL When using Microsoft.Extensions.Logging with structured logging (e.g., logger.LogInformation("User {UserId} did {Action}", userId, action)), the named parameters are now extracted from the TState state parameter and merged into context data. This makes them available as individual log attributes in New Relic (e.g., context.UserId, context.Action), matching the behavior already available for Serilog and NLog. The state extraction is wrapped in its own try/catch to ensure it cannot disrupt existing scope-based context data harvesting. The {OriginalFormat} key (the message template string) is excluded. Fixes #2519 * test: Add integration test for MEL structured log arg context data Adds StructuredLogArgContextDataTests that verifies structured log message arguments (e.g., {Name}, {Id}) are extracted as context data attributes when using Microsoft.Extensions.Logging. - Adds InfoWithStructuredArgs to MicrosoftLoggingLoggingAdapter - Adds CreateSingleLogMessageWithStructuredArgs to LoggingTester - Test asserts that Name and Id appear in the log line attributes * Fix build errors and start refactoring * Passing integration test for MEL * Expand tests to all relevant logging frameworks * Refactoring conditional code * Rename and reorder for clarity * Refactor LoggingTester Separate the context data handling testing from the main message logging paths * PR feedback part 1 * Document reason for goofy message template format. * Expand integration testing to cover the context + structured log args case --------- Co-authored-by: piekstra <piekstra@users.noreply.github.com>
1 parent 73de305 commit 24819c4

17 files changed

Lines changed: 930 additions & 330 deletions

File tree

src/Agent/NewRelic/Agent/Extensions/Providers/Wrapper/MicrosoftExtensionsLogging/MicrosoftLoggingWrapper.cs

Lines changed: 39 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,9 @@ public class MicrosoftLoggingWrapper : IWrapper
2626

2727
private const string WrapperName = "MicrosoftLogging";
2828

29+
// This is defined here: https://github.com/dotnet/runtime/blob/54e4456b01060f54e5bb7d715e77e5f41bac558f/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/LogValuesFormatter.cs#L233
30+
private const string OriginalFormatKey = "{OriginalFormat}";
31+
2932
public CanWrapResponse CanWrap(InstrumentedMethodInfo methodInfo)
3033
{
3134
return new CanWrapResponse(WrapperName.Equals(methodInfo.RequestedWrapperName));
@@ -58,14 +61,18 @@ private void RecordLogMessage(MethodCall methodCall, MEL.ILogger logger, IAgent
5861
Func<object, string> getLevelFunc = mc => ((MethodCall)mc).MethodArguments[0].ToString();
5962
Func<object, string> getRenderedMessageFunc = mc => ((MethodCall)mc).MethodArguments[2].ToString();
6063
Func<object, Exception> getLogExceptionFunc = mc => ((MethodCall)mc).MethodArguments[3] as Exception; // using "as" since we want a null if missing
61-
Func<object, Dictionary<string, object>> getContextDataFunc = _ => GetContextData(logger, agent);
64+
65+
// MethodArguments[2] is the TState state parameter, which for structured logging
66+
// typically implements IReadOnlyList<KeyValuePair<string, object?>>
67+
var state = methodCall.MethodArguments[2];
68+
Func<object, Dictionary<string, object>> getContextDataFunc = _ => GetContextData(logger, agent, state);
6269

6370
var xapi = agent.GetExperimentalApi();
6471
xapi.RecordLogMessage(WrapperName, methodCall, getTimestampFunc, getLevelFunc, getRenderedMessageFunc, getLogExceptionFunc, getContextDataFunc, agent.TraceMetadata.SpanId, agent.TraceMetadata.TraceId);
6572
}
6673
}
6774

68-
private static Dictionary<string, object> GetContextData(MEL.ILogger logger, IAgent agent)
75+
private static Dictionary<string, object> GetContextData(MEL.ILogger logger, IAgent agent, object state = null)
6976
{
7077
if (_contextDataNotSupported) // short circuit if we previously got an exception trying to access context data
7178
{
@@ -106,6 +113,35 @@ private static Dictionary<string, object> GetContextData(MEL.ILogger logger, IAg
106113
// Possibly handle case of IEnumerable<KeyValuePair<object, object>>, etc (not now though)
107114
}, harvestedKvps);
108115

116+
// Extract structured log message arguments from the TState state parameter.
117+
// For structured logging (e.g., _logger.LogInformation("User {UserId} did {Action}", userId, action)),
118+
// MEL's FormattedLogValues implements IReadOnlyList<KeyValuePair<string, object?>> containing
119+
// the individual named parameters. We merge these into context data so they appear as
120+
// separate log attributes in New Relic (e.g., context.UserId, context.Action).
121+
try
122+
{
123+
if (state is IEnumerable<KeyValuePair<string, object>> stateKvps)
124+
{
125+
foreach (var kvp in stateKvps)
126+
{
127+
// Skip the "{OriginalFormat}" key — it's the message template string, not a parameter
128+
if (kvp.Key == OriginalFormatKey)
129+
continue;
130+
131+
if (kvp.Value != null)
132+
{
133+
harvestedKvps[kvp.Key] = kvp.Value;
134+
}
135+
}
136+
}
137+
}
138+
catch (Exception e)
139+
{
140+
// Log once and continue — state extraction is best-effort and should not
141+
// prevent scope-based context data from being returned
142+
agent.Logger.Log(Level.Finest, e, "Unable to extract structured log message arguments from state.");
143+
}
144+
109145
return harvestedKvps;
110146
}
111147
catch (Exception e)
@@ -135,4 +171,4 @@ private AfterWrappedMethodDelegate DecorateLogMessage(MEL.ILogger logger, IAgent
135171

136172
return Delegates.GetDelegateFor(onComplete: () => handle?.Dispose());
137173
}
138-
}
174+
}

tests/Agent/IntegrationTests/IntegrationTests/Logging/ContextDataNotSupportedTests.cs

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -42,9 +42,9 @@ public ContextDataNotSupportedTestsBase(TFixture fixture, ITestOutputHelper outp
4242
string context = string.Join(",", _expectedAttributes.Select(x => x.Key + "=" + x.Value).ToArray());
4343

4444
// should generate an exception message in the log since the dummy ILogger doesn't have the right properties
45-
_fixture.AddCommand($"LoggingTester CreateSingleLogMessage {InfoMessage} INFO {context}");
45+
_fixture.AddCommand($"LoggingTester CreateSingleLogMessage {InfoMessage} {context}");
4646
// do it again - this time, context data should be marked as unsupported and not generate an exception in the log
47-
_fixture.AddCommand($"LoggingTester CreateSingleLogMessage {InfoMessage} INFO {context}");
47+
_fixture.AddCommand($"LoggingTester CreateSingleLogMessage {InfoMessage} {context}");
4848

4949
_fixture.AddActions
5050
(
@@ -105,4 +105,4 @@ public ContextDataNotSupportedNetCoreOldestTests(ConsoleDynamicMethodFixtureCore
105105
: base(fixture, output, LoggingFramework.DummyMEL)
106106
{
107107
}
108-
}
108+
}

tests/Agent/IntegrationTests/IntegrationTests/Logging/ContextDataTests.cs

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -43,7 +43,7 @@ public ContextDataTestsBase(TFixture fixture, ITestOutputHelper output, bool tes
4343
_loggingFrameworks.ForEach(x => _fixture.AddCommand($"LoggingTester SetFramework {x} {RandomPortGenerator.NextPort()}"));
4444
_fixture.AddCommand($"LoggingTester Configure");
4545

46-
_loggingFrameworks.ForEach(x => _fixture.AddCommand($"LoggingTester CreateSingleLogMessage {x} {InfoMessage} INFO {FlattenExpectedAttributes(GetExpectedAttributes(x))}"));
46+
_loggingFrameworks.ForEach(x => _fixture.AddCommand($"LoggingTester CreateSingleLogMessageWithContext {x} {InfoMessage} {FlattenExpectedAttributes(GetExpectedAttributes(x))}"));
4747

4848
if (_testNestedContexts) // on supported frameworks, ensure that we don't blow up when accumulating the context key/value pairs
4949
_fixture.AddCommand($"LoggingTester LogMessageInNestedScopes");
@@ -368,4 +368,4 @@ public NELContextDataCoreLatestTests(ConsoleDynamicMethodFixtureCoreLatest fixtu
368368
}
369369
}
370370

371-
#endregion // NEL
371+
#endregion // NEL

tests/Agent/IntegrationTests/IntegrationTests/Logging/LocalDecorationTests.cs

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -41,7 +41,7 @@ public LocalDecorationTestsBase(TFixture fixture, ITestOutputHelper output, bool
4141
_fixture.AddCommand($"LoggingTester Configure{layoutType}LayoutAppenderForDecoration");
4242
if (logWithParam)
4343
{
44-
_fixture.AddCommand($"LoggingTester CreateSingleLogMessageInTransactionWithParam {_testMessage}{"{@param}"}");
44+
_fixture.AddCommand($"LoggingTester CreateSingleLogMessageInTransactionWithObjectParameter {_testMessage}{"{@param}"}");
4545
}
4646
else
4747
{
@@ -743,4 +743,4 @@ public NLogPatternLayoutDecorationDisabledTestsNetCoreOldestTests(ConsoleDynamic
743743

744744
#endregion
745745

746-
#endregion
746+
#endregion

0 commit comments

Comments
 (0)