From 5285308d76f2f033aff0bc586f9c3e412ad00289 Mon Sep 17 00:00:00 2001 From: Iliar Turdushev Date: Fri, 14 Mar 2025 10:45:11 +0100 Subject: [PATCH 1/4] Fixes #5720 Now {OriginalFormat} is emitted as the last item in the TagArray --- .../Emission/Emitter.Method.cs | 17 ++++---- .../Generated/LogMethodTests.cs | 40 +++++++++++++++++++ .../OriginalFormatTestExtensions.cs | 22 ++++++++++ ...sts.ClassWithNullableProperty.verified.txt | 6 +-- 4 files changed, 75 insertions(+), 10 deletions(-) create mode 100644 test/Generators/Microsoft.Gen.Logging/TestClasses/OriginalFormatTestExtensions.cs diff --git a/src/Generators/Microsoft.Gen.Logging/Emission/Emitter.Method.cs b/src/Generators/Microsoft.Gen.Logging/Emission/Emitter.Method.cs index 286a419f209..68549c11540 100644 --- a/src/Generators/Microsoft.Gen.Logging/Emission/Emitter.Method.cs +++ b/src/Generators/Microsoft.Gen.Logging/Emission/Emitter.Method.cs @@ -102,7 +102,8 @@ private void GenLogMethod(LoggingMethod lm) OutLn($"[{GeneratorUtilities.GeneratedCodeAttribute}] static string ({lambdaStateName}, {exceptionLambdaName}) =>"); OutOpenBrace(); - if (GenVariableAssignments(lm, lambdaStateName, numReservedUnclassifiedTags, numReservedClassifiedTags)) + if (!string.IsNullOrEmpty(lm.Message) && + GenVariableAssignments(lm, lambdaStateName, numReservedUnclassifiedTags, numReservedClassifiedTags)) { var mapped = Parsing.TemplateProcessor.MapTemplates(lm.Message, t => { @@ -318,7 +319,14 @@ void GenTagWrites(LoggingMethod lm, string stateName, out int numReservedUnclass { OutLn(); OutLn($"_ = {stateName}.ReserveTagSpace({numReservedUnclassifiedTags});"); + int count = numReservedUnclassifiedTags; + + if (!string.IsNullOrEmpty(lm.Message)) + { + OutLn($"{stateName}.TagArray[{--count}] = new(\"{{OriginalFormat}}\", {EscapeMessageString(lm.Message)});"); + } + foreach (var p in lm.Parameters) { if (NeedsASlot(p) && !p.HasDataClassification) @@ -367,11 +375,6 @@ void GenTagWrites(LoggingMethod lm, string stateName, out int numReservedUnclass }); } } - - if (!string.IsNullOrEmpty(lm.Message)) - { - OutLn($"{stateName}.TagArray[{--count}] = new(\"{{OriginalFormat}}\", {EscapeMessageString(lm.Message)});"); - } } if (numReservedClassifiedTags > 0) @@ -516,7 +519,7 @@ bool GenVariableAssignments(LoggingMethod lm, string lambdaStateName, int numRes { bool generatedAssignments = false; - int index = numReservedUnclassifiedTags - 1; + int index = numReservedUnclassifiedTags - 2; foreach (var p in lm.Parameters) { if (NeedsASlot(p) && !p.HasDataClassification) diff --git a/test/Generators/Microsoft.Gen.Logging/Generated/LogMethodTests.cs b/test/Generators/Microsoft.Gen.Logging/Generated/LogMethodTests.cs index 609b60f5e21..1d74dc68713 100644 --- a/test/Generators/Microsoft.Gen.Logging/Generated/LogMethodTests.cs +++ b/test/Generators/Microsoft.Gen.Logging/Generated/LogMethodTests.cs @@ -5,6 +5,7 @@ using System.Collections.Generic; using System.Diagnostics.CodeAnalysis; using System.Globalization; +using System.Linq; using System.Threading; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Testing; @@ -923,6 +924,34 @@ public void FormattableTest() Assert.Equal("Converted!", collector.LatestRecord.StructuredState!.GetValue("p1")); } + [Fact] + public void OriginalFormatTest() + { + using var logger = Utils.GetLogger(); + var collector = logger.FakeLogCollector; + + OriginalFormatTestExtensions.M0(logger); + Assert.Equal(1, collector.Count); + EnsureOriginalFormatIsLastProperty(collector.LatestRecord, "M0", "M0"); + + collector.Clear(); + OriginalFormatTestExtensions.M1(logger, "0"); + Assert.Equal(1, collector.Count); + EnsureOriginalFormatIsLastProperty(collector.LatestRecord, "M1 {p0}", "M1 0"); + + collector.Clear(); + OriginalFormatTestExtensions.M2(logger, "0", "1"); + Assert.Equal(1, collector.Count); + EnsureOriginalFormatIsLastProperty(collector.LatestRecord, "M2 {p0}{p1}", "M2 01"); + + collector.Clear(); + OriginalFormatTestExtensions.M3(logger, "0", "1", "2"); + Assert.Equal(1, collector.Count); + Assert.Empty(collector.LatestRecord.Message); + Assert.Equal(3, collector.LatestRecord.StructuredState!.Count); + AssertLastState(collector, new("p0", "0"), new("p1", "1"), new("p2", "2")); + } + private static void AssertLastState(FakeLogCollector collector, params KeyValuePair[] expected) { var rol = (IReadOnlyList>)collector.LatestRecord.State!; @@ -949,4 +978,15 @@ private static void TestCollection(int expected, FakeLogCollector collector) } } } + + private static void EnsureOriginalFormatIsLastProperty(FakeLogRecord record, string format, string message) + { + var state = (IReadOnlyList>)record.State!; + Assert.NotNull(state); + + var pair = state.Last(); + Assert.Equal("{OriginalFormat}", pair.Key); + Assert.Equal(format, pair.Value); + Assert.Equal(message, record.Message); + } } diff --git a/test/Generators/Microsoft.Gen.Logging/TestClasses/OriginalFormatTestExtensions.cs b/test/Generators/Microsoft.Gen.Logging/TestClasses/OriginalFormatTestExtensions.cs new file mode 100644 index 00000000000..ac3ac26e2e0 --- /dev/null +++ b/test/Generators/Microsoft.Gen.Logging/TestClasses/OriginalFormatTestExtensions.cs @@ -0,0 +1,22 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using Microsoft.Extensions.Logging; + +namespace TestClasses +{ + internal static partial class OriginalFormatTestExtensions + { + [LoggerMessage(0, LogLevel.Information, "M0")] + public static partial void M0(ILogger logger); + + [LoggerMessage(1, LogLevel.Information, "M1 {p0}")] + public static partial void M1(ILogger logger, string p0); + + [LoggerMessage(2, LogLevel.Information, "M2 {p0}{p1}")] + public static partial void M2(ILogger logger, string p0, string p1); + + [LoggerMessage(LogLevel.Information)] + public static partial void M3(ILogger logger, string p0, string p1, string p2); + } +} diff --git a/test/Generators/Microsoft.Gen.Logging/Verified/ParserTests.ClassWithNullableProperty.verified.txt b/test/Generators/Microsoft.Gen.Logging/Verified/ParserTests.ClassWithNullableProperty.verified.txt index 174f9e63faa..fd3a7facd7c 100644 --- a/test/Generators/Microsoft.Gen.Logging/Verified/ParserTests.ClassWithNullableProperty.verified.txt +++ b/test/Generators/Microsoft.Gen.Logging/Verified/ParserTests.ClassWithNullableProperty.verified.txt @@ -23,9 +23,9 @@ namespace Test var state = global::Microsoft.Extensions.Logging.LoggerMessageHelper.ThreadLocalState; _ = state.ReserveTagSpace(3); - state.TagArray[2] = new("classWithNullablePropertyParam.NullableDateTime", classWithNullablePropertyParam?.NullableDateTime); - state.TagArray[1] = new("classWithNullablePropertyParam.NonNullableDateTime", classWithNullablePropertyParam?.NonNullableDateTime); - state.TagArray[0] = new("{OriginalFormat}", "Testing nullable property within class here..."); + state.TagArray[2] = new("{OriginalFormat}", "Testing nullable property within class here..."); + state.TagArray[1] = new("classWithNullablePropertyParam.NullableDateTime", classWithNullablePropertyParam?.NullableDateTime); + state.TagArray[0] = new("classWithNullablePropertyParam.NonNullableDateTime", classWithNullablePropertyParam?.NonNullableDateTime); logger.Log( global::Microsoft.Extensions.Logging.LogLevel.Information, From fb358253706b9173dae420e79a3d9e68673c0a4a Mon Sep 17 00:00:00 2001 From: Iliar Turdushev Date: Sat, 15 Mar 2025 16:26:43 +0100 Subject: [PATCH 2/4] Fixes #5720 Adjusts ExtendedLogger to always return {OriginalFormat} as the last tag in the list --- .../Logging/ExtendedLogger.LegacyTagJoiner.cs | 12 +- .../Logging/ExtendedLogger.ModernTagJoiner.cs | 16 ++- .../Logging/ExtendedLogger.cs | 38 ++--- .../Logging/ExtendedLoggerTests.cs | 131 ++++++++++++++++++ 4 files changed, 166 insertions(+), 31 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.LegacyTagJoiner.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.LegacyTagJoiner.cs index e72ce6964dc..17124daf89b 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.LegacyTagJoiner.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.LegacyTagJoiner.cs @@ -50,17 +50,19 @@ public void SetIncomingTags(IReadOnlyList> value) { get { - if (index < _incomingTagCount) + // Keep the order of the if-else statements. It ensures that the {OriginalFormat} + // property is always the last tag in the list. + if (index < StaticTags!.Length) { - return _incomingTags![index]; + return StaticTags[index]; } - else if (index < _incomingTagCount + _extraTags.Count) + else if (index < StaticTags.Length + _extraTags.Count) { - return _extraTags[index - _incomingTagCount]; + return _extraTags[index - StaticTags.Length]; } else { - return StaticTags![index - _incomingTagCount - _extraTags.Count]; + return _incomingTags![index - StaticTags.Length - _extraTags.Count]; } } } diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.ModernTagJoiner.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.ModernTagJoiner.cs index 5c54715e802..3efcd325f46 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.ModernTagJoiner.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.ModernTagJoiner.cs @@ -56,21 +56,23 @@ public void SetIncomingTags(LoggerMessageState value) { get { - if (index < _incomingTagsCount) + // Keep the order of the if-else statements. It ensures that the {OriginalFormat} + // property is always the last tag in the list. + if (index < _redactedTagsCount) { - return _incomingTags![index]; + return _redactedTags![index]; } - else if (index < _incomingTagsCount + _redactedTagsCount) + else if (index < _redactedTagsCount + _extraTags.Count) { - return _redactedTags![index - _incomingTagsCount]; + return _extraTags[index - _redactedTagsCount]; } - else if (index < _incomingTagsCount + _redactedTagsCount + _extraTags.Count) + else if (index < _redactedTagsCount + _extraTags.Count + StaticTags!.Length) { - return _extraTags[index - _incomingTagsCount - _redactedTagsCount]; + return StaticTags[index - _redactedTagsCount - _extraTags.Count]; } else { - return StaticTags![index - _incomingTagsCount - _redactedTagsCount - _extraTags.Count]; + return _incomingTags![index - _redactedTagsCount - _extraTags.Count - StaticTags.Length]; } } } diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs index fb5ced9e994..b36a7e0edac 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs @@ -322,24 +322,6 @@ private void LegacyPath(LogLevel logLevel, EventId eventId, TState state joiner.Formatter = formatter; joiner.State = state; - switch (state) - { - case IReadOnlyList> stateList: - joiner.SetIncomingTags(stateList); - break; - - case IEnumerable> stateList: - joiner.EnrichmentTagCollector.AddRange(stateList); - break; - - case null: - break; - - default: - joiner.EnrichmentTagCollector.Add("{OriginalFormat}", state); - break; - } - List? exceptions = null; // enrich @@ -356,12 +338,30 @@ private void LegacyPath(LogLevel logLevel, EventId eventId, TState state } } - // one last dedicated bit of enrichment + // enrich log data with exception information if (exception != null) { RecordException(exception, joiner.EnrichmentTagCollector, config); } + switch (state) + { + case IReadOnlyList> stateList: + joiner.SetIncomingTags(stateList); + break; + + case IEnumerable> stateList: + joiner.EnrichmentTagCollector.AddRange(stateList); + break; + + case null: + break; + + default: + joiner.EnrichmentTagCollector.Add("{OriginalFormat}", state); + break; + } + bool? samplingDecision = null; for (int i = 0; i < loggers.Length; i++) { diff --git a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/ExtendedLoggerTests.cs b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/ExtendedLoggerTests.cs index 0c4157e65b9..9ff23e11859 100644 --- a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/ExtendedLoggerTests.cs +++ b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/ExtendedLoggerTests.cs @@ -791,6 +791,130 @@ public static void CaptureScopesIsReadFromConfiguration() } } + [Theory] + [CombinatorialData] + public static void ModernLogging_OriginalFormatMustBeLastInTheListOfStateProperties( + bool enableRedaction, bool enableEnrichment, bool logException) + { + using var provider = new Provider(); + + var enricher = new ForcedEnricher(new[] + { + new KeyValuePair("K1", "V1"), + }); + var staticEnricher = new ForcedEnricher(new[] + { + new KeyValuePair("K2", "V2"), + }); + var redactorProvider = new FakeRedactorProvider(new FakeRedactorOptions + { + RedactionFormat = "REDACTED<{0}>", + }); + + var enrichmentOptions = enableEnrichment ? new StaticOptionsMonitor(new()) : null; + var redactionOptions = enableRedaction ? new StaticOptionsMonitor(new() { ApplyDiscriminator = false }) : null; + + using var factory = new ExtendedLoggerFactory( + providers: new[] { provider }, + enrichmentOptions: enrichmentOptions, + redactionOptions: redactionOptions, + enrichers: new[] { enricher }, + staticEnrichers: new[] { staticEnricher }, + redactorProvider: redactorProvider, + filterOptions: new StaticOptionsMonitor(new())); + + var logger = factory.CreateLogger("logger"); + + var state = LoggerMessageHelper.ThreadLocalState; + var index = state.ReserveTagSpace(2); + state.TagArray[index] = new("K3", "V3"); + state.TagArray[index + 1] = new("{OriginalFormat}", "V4"); + + index = state.ReserveClassifiedTagSpace(1); + state.ClassifiedTagArray[index] = new("K5", "V5", FakeTaxonomy.PrivateData); + + var exception = logException ? new InvalidOperationException() : null; + + logger.Log(LogLevel.Warning, new EventId(1, "ID1"), state, exception, (_, _) => "MSG"); + + var sink = provider.Logger!; + var collector = sink.Collector; + Assert.Equal(1, collector.Count); + + var record = collector.GetSnapshot().Single(); + var property = record.StructuredState!.Last(); + Assert.Equal("{OriginalFormat}", property.Key); + Assert.Equal("V4", property.Value); + } + + [Theory] + [CombinatorialData] + public static void LegacyLogging_OriginalFormatMustBeLastInTheListOfStateProperties( + bool enableEnrichment, bool logException, LegacyStateType stateType) + { + using var provider = new Provider(); + + var enricher = new ForcedEnricher(new[] + { + new KeyValuePair("K1", "V1"), + }); + var staticEnricher = new ForcedEnricher(new[] + { + new KeyValuePair("K2", "V2"), + }); + + var enrichmentOptions = enableEnrichment ? new StaticOptionsMonitor(new()) : null; + + using var factory = new ExtendedLoggerFactory( + providers: new[] { provider }, + enrichmentOptions: enrichmentOptions, + enrichers: new[] { enricher }, + staticEnrichers: new[] { staticEnricher }, + filterOptions: new StaticOptionsMonitor(new())); + + var logger = factory.CreateLogger("logger"); + var exception = logException ? new InvalidOperationException() : null; + + switch (stateType) + { + case LegacyStateType.ReadOnlyList: + List> list = + [ + new("K3", "V3"), + new("{OriginalFormat}", "V4") + ]; + logger.Log(LogLevel.Warning, new EventId(1, "ID1"), list, exception, (_, _) => "MSG"); + break; + + case LegacyStateType.Enumerable: + IEnumerable> enumerable = + new List> + { + new("K3", "V3"), + new("{OriginalFormat}", "V4") + } + .Select(x => x); + logger.Log(LogLevel.Warning, new EventId(1, "ID1"), enumerable, exception, (_, _) => "MSG"); + break; + + case LegacyStateType.String: + logger.Log(LogLevel.Warning, new EventId(1, "ID1"), "V4", exception, (_, _) => "MSG"); + break; + + default: + throw new InvalidOperationException($"Uknown state type: {stateType}"); + } + + var sink = provider.Logger!; + var collector = sink.Collector; + Assert.Equal(1, collector.Count); + + var record = collector.GetSnapshot().Single(); + var property = record.StructuredState!.Last(); + Assert.Equal("{OriginalFormat}", property.Key); + Assert.Equal("V4", property.Value); + } + private sealed class CustomLoggerProvider : ILoggerProvider { private readonly string _providerName; @@ -990,4 +1114,11 @@ public StaticOptionsMonitor(T currentValue) public T Get(string? name) => CurrentValue; public T CurrentValue { get; } } + + public enum LegacyStateType + { + ReadOnlyList, + Enumerable, + String + } } From 96ab74f07e9df969a06c271f856af52ba6f81b6d Mon Sep 17 00:00:00 2001 From: Iliar Turdushev Date: Sun, 16 Mar 2025 14:59:46 +0100 Subject: [PATCH 3/4] Fixes #5720 Fixes ResourceMonitoring tests --- ...roviderTests.Provider_EmitsLogRecord.verified.txt | 12 ++++++------ ...ationTracker_LogsSnapshotInformation.verified.txt | 12 ++++++------ ...apshotProvider_EmitsLogRecord.DotNet.verified.txt | 12 ++++++------ ....SnapshotProvider_EmitsLogRecord.Net.verified.txt | 12 ++++++------ 4 files changed, 24 insertions(+), 24 deletions(-) diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests/Linux/Verified/LinuxUtilizationProviderTests.Provider_EmitsLogRecord.verified.txt b/test/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests/Linux/Verified/LinuxUtilizationProviderTests.Provider_EmitsLogRecord.verified.txt index 4add260941f..90607719978 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests/Linux/Verified/LinuxUtilizationProviderTests.Provider_EmitsLogRecord.verified.txt +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests/Linux/Verified/LinuxUtilizationProviderTests.Provider_EmitsLogRecord.verified.txt @@ -6,9 +6,6 @@ Name: SystemResourcesInfo }, State: [ - { - {OriginalFormat}: System resources information: CpuLimit = {cpuLimit}, CpuRequest = {cpuRequest}, MemoryLimit = {memoryLimit}, MemoryRequest = {memoryRequest}. - }, { memoryRequest: 1048576 }, @@ -20,12 +17,12 @@ }, { cpuLimit: 20 + }, + { + {OriginalFormat}: System resources information: CpuLimit = {cpuLimit}, CpuRequest = {cpuRequest}, MemoryLimit = {memoryLimit}, MemoryRequest = {memoryRequest}. } ], StructuredState: [ - { - {OriginalFormat}: System resources information: CpuLimit = {cpuLimit}, CpuRequest = {cpuRequest}, MemoryLimit = {memoryLimit}, MemoryRequest = {memoryRequest}. - }, { memoryRequest: 1048576 }, @@ -37,6 +34,9 @@ }, { cpuLimit: 20 + }, + { + {OriginalFormat}: System resources information: CpuLimit = {cpuLimit}, CpuRequest = {cpuRequest}, MemoryLimit = {memoryLimit}, MemoryRequest = {memoryRequest}. } ], Message: System resources information: CpuLimit = 20, CpuRequest = 0.078125, MemoryLimit = 1048576, MemoryRequest = 1048576., diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests/Verified/ResourceMonitoringServiceTests.ResourceUtilizationTracker_LogsSnapshotInformation.verified.txt b/test/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests/Verified/ResourceMonitoringServiceTests.ResourceUtilizationTracker_LogsSnapshotInformation.verified.txt index 09294ad508a..b78285c1317 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests/Verified/ResourceMonitoringServiceTests.ResourceUtilizationTracker_LogsSnapshotInformation.verified.txt +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests/Verified/ResourceMonitoringServiceTests.ResourceUtilizationTracker_LogsSnapshotInformation.verified.txt @@ -5,9 +5,6 @@ Name: SnapshotReceived }, State: [ - { - {OriginalFormat}: Snapshot received: TotalTimeSinceStart={totalTimeSinceStart}, KernelTimeSinceStart={kernelTimeSinceStart}, UserTimeSinceStart={userTimeSinceStart}, MemoryUsageInBytes={memoryUsageInBytes}. - }, { memoryUsageInBytes: 500 }, @@ -19,12 +16,12 @@ }, { totalTimeSinceStart: 730119.00:00:00 + }, + { + {OriginalFormat}: Snapshot received: TotalTimeSinceStart={totalTimeSinceStart}, KernelTimeSinceStart={kernelTimeSinceStart}, UserTimeSinceStart={userTimeSinceStart}, MemoryUsageInBytes={memoryUsageInBytes}. } ], StructuredState: [ - { - {OriginalFormat}: Snapshot received: TotalTimeSinceStart={totalTimeSinceStart}, KernelTimeSinceStart={kernelTimeSinceStart}, UserTimeSinceStart={userTimeSinceStart}, MemoryUsageInBytes={memoryUsageInBytes}. - }, { memoryUsageInBytes: 500 }, @@ -36,6 +33,9 @@ }, { totalTimeSinceStart: 730119.00:00:00 + }, + { + {OriginalFormat}: Snapshot received: TotalTimeSinceStart={totalTimeSinceStart}, KernelTimeSinceStart={kernelTimeSinceStart}, UserTimeSinceStart={userTimeSinceStart}, MemoryUsageInBytes={memoryUsageInBytes}. } ], Message: Snapshot received: TotalTimeSinceStart=730119.00:00:00, KernelTimeSinceStart=00:00:01, UserTimeSinceStart=00:00:01, MemoryUsageInBytes=500., diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests/Windows/Verified/WindowsContainerSnapshotProviderTests.SnapshotProvider_EmitsLogRecord.DotNet.verified.txt b/test/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests/Windows/Verified/WindowsContainerSnapshotProviderTests.SnapshotProvider_EmitsLogRecord.DotNet.verified.txt index 228dccfb1c4..72cd46209ad 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests/Windows/Verified/WindowsContainerSnapshotProviderTests.SnapshotProvider_EmitsLogRecord.DotNet.verified.txt +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests/Windows/Verified/WindowsContainerSnapshotProviderTests.SnapshotProvider_EmitsLogRecord.DotNet.verified.txt @@ -27,9 +27,6 @@ Name: SystemResourcesInfo }, State: [ - { - {OriginalFormat}: System resources information: CpuLimit = {cpuLimit}, CpuRequest = {cpuRequest}, MemoryLimit = {memoryLimit}, MemoryRequest = {memoryRequest}. - }, { memoryRequest: 2000 }, @@ -41,12 +38,12 @@ }, { cpuLimit: 1 + }, + { + {OriginalFormat}: System resources information: CpuLimit = {cpuLimit}, CpuRequest = {cpuRequest}, MemoryLimit = {memoryLimit}, MemoryRequest = {memoryRequest}. } ], StructuredState: [ - { - {OriginalFormat}: System resources information: CpuLimit = {cpuLimit}, CpuRequest = {cpuRequest}, MemoryLimit = {memoryLimit}, MemoryRequest = {memoryRequest}. - }, { memoryRequest: 2000 }, @@ -58,6 +55,9 @@ }, { cpuLimit: 1 + }, + { + {OriginalFormat}: System resources information: CpuLimit = {cpuLimit}, CpuRequest = {cpuRequest}, MemoryLimit = {memoryLimit}, MemoryRequest = {memoryRequest}. } ], Message: System resources information: CpuLimit = 1, CpuRequest = 1, MemoryLimit = 2000, MemoryRequest = 2000., diff --git a/test/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests/Windows/Verified/WindowsContainerSnapshotProviderTests.SnapshotProvider_EmitsLogRecord.Net.verified.txt b/test/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests/Windows/Verified/WindowsContainerSnapshotProviderTests.SnapshotProvider_EmitsLogRecord.Net.verified.txt index 294a724db56..27d82da0b4e 100644 --- a/test/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests/Windows/Verified/WindowsContainerSnapshotProviderTests.SnapshotProvider_EmitsLogRecord.Net.verified.txt +++ b/test/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests/Windows/Verified/WindowsContainerSnapshotProviderTests.SnapshotProvider_EmitsLogRecord.Net.verified.txt @@ -27,9 +27,6 @@ Name: SystemResourcesInfo }, State: [ - { - {OriginalFormat}: System resources information: CpuLimit = {cpuLimit}, CpuRequest = {cpuRequest}, MemoryLimit = {memoryLimit}, MemoryRequest = {memoryRequest}. - }, { memoryRequest: 2000 }, @@ -41,12 +38,12 @@ }, { cpuLimit: 1 + }, + { + {OriginalFormat}: System resources information: CpuLimit = {cpuLimit}, CpuRequest = {cpuRequest}, MemoryLimit = {memoryLimit}, MemoryRequest = {memoryRequest}. } ], StructuredState: [ - { - {OriginalFormat}: System resources information: CpuLimit = {cpuLimit}, CpuRequest = {cpuRequest}, MemoryLimit = {memoryLimit}, MemoryRequest = {memoryRequest}. - }, { memoryRequest: 2000 }, @@ -58,6 +55,9 @@ }, { cpuLimit: 1 + }, + { + {OriginalFormat}: System resources information: CpuLimit = {cpuLimit}, CpuRequest = {cpuRequest}, MemoryLimit = {memoryLimit}, MemoryRequest = {memoryRequest}. } ], Message: System resources information: CpuLimit = 1, CpuRequest = 1, MemoryLimit = 2000, MemoryRequest = 2000., From 21b58f41544d2a2112669a9c27aff2b0d76f61ae Mon Sep 17 00:00:00 2001 From: Iliar Turdushev Date: Mon, 17 Mar 2025 13:04:37 +0100 Subject: [PATCH 4/4] Fixes #5720 Address PR comments --- .../Logging/ExtendedLogger.LegacyTagJoiner.cs | 22 ++++++++++++++----- .../Logging/ExtendedLogger.ModernTagJoiner.cs | 16 +++++++++----- 2 files changed, 26 insertions(+), 12 deletions(-) diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.LegacyTagJoiner.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.LegacyTagJoiner.cs index 17124daf89b..46bf77f0816 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.LegacyTagJoiner.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.LegacyTagJoiner.cs @@ -50,19 +50,29 @@ public void SetIncomingTags(IReadOnlyList> value) { get { - // Keep the order of the if-else statements. It ensures that the {OriginalFormat} - // property is always the last tag in the list. - if (index < StaticTags!.Length) + int staticTagsCount = StaticTags!.Length; + int extraTagsCount = _extraTags.Count; + + if (index < staticTagsCount) { return StaticTags[index]; } - else if (index < StaticTags.Length + _extraTags.Count) + + // Iterating over "_extraTags" and "_incomingTags" at the end, because they may contain + // the "{OriginalFormat}" property which needs to be the last tag in the list. The order + // "_extraTags" then "_incomingTags" is important because: + // 1. In the case when the "{OriginalFormat}" property is in "_extraTags", + // "_incomingTags" is always empty. + // 2. In the case when the "{OriginalFormat}" property is in "_incomingTags", + // "_extraTags" might contain other tags and we want them to be returned + // before "_incomingTags". + else if (index < staticTagsCount + extraTagsCount) { - return _extraTags[index - StaticTags.Length]; + return _extraTags[index - staticTagsCount]; } else { - return _incomingTags![index - StaticTags.Length - _extraTags.Count]; + return _incomingTags![index - staticTagsCount - extraTagsCount]; } } } diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.ModernTagJoiner.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.ModernTagJoiner.cs index 3efcd325f46..02a3804b76d 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.ModernTagJoiner.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.ModernTagJoiner.cs @@ -56,23 +56,27 @@ public void SetIncomingTags(LoggerMessageState value) { get { - // Keep the order of the if-else statements. It ensures that the {OriginalFormat} - // property is always the last tag in the list. + int staticTagsCount = StaticTags!.Length; + int extraTagsCount = _extraTags.Count; + if (index < _redactedTagsCount) { return _redactedTags![index]; } - else if (index < _redactedTagsCount + _extraTags.Count) + else if (index < _redactedTagsCount + extraTagsCount) { return _extraTags[index - _redactedTagsCount]; } - else if (index < _redactedTagsCount + _extraTags.Count + StaticTags!.Length) + else if (index < _redactedTagsCount + extraTagsCount + staticTagsCount) { - return StaticTags[index - _redactedTagsCount - _extraTags.Count]; + return StaticTags[index - _redactedTagsCount - extraTagsCount]; } + + // Iterating over "_incomingTags" at the end, because it may contain the + // "{OriginalFormat}" property which needs to be the last tag in the list. else { - return _incomingTags![index - _redactedTagsCount - _extraTags.Count - StaticTags.Length]; + return _incomingTags![index - _redactedTagsCount - extraTagsCount - staticTagsCount]; } } }