[Telemetry, Logging] Emit {OriginalFormat} as the last property of th…

…e log record (#6111)

* Fixes #5720

Now {OriginalFormat} is emitted as the last item in the TagArray

* Fixes #5720

Adjusts ExtendedLogger to always return {OriginalFormat} as the last tag in the list

* Fixes #5720

Fixes ResourceMonitoring tests

* Fixes #5720

Address PR comments

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)

src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.LegacyTagJoiner.cs

@@ -50,17 +50,29 @@ public void SetIncomingTags(IReadOnlyList<KeyValuePair<string, object?>> value)
         {
             get
             {
-                if (index < _incomingTagCount)
+                int staticTagsCount = StaticTags!.Length;
+                int extraTagsCount = _extraTags.Count;
+
+                if (index < staticTagsCount)
                 {
-                    return _incomingTags![index];
+                    return StaticTags[index];
                 }
-                else if (index < _incomingTagCount + _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 - _incomingTagCount];
+                    return _extraTags[index - staticTagsCount];
                 }
                 else
                 {
-                    return StaticTags![index - _incomingTagCount - _extraTags.Count];
+                    return _incomingTags![index - staticTagsCount - extraTagsCount];
                 }
             }
         }

src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.ModernTagJoiner.cs

@@ -56,21 +56,27 @@ public void SetIncomingTags(LoggerMessageState value)
         {
             get
             {
-                if (index < _incomingTagsCount)
+                int staticTagsCount = StaticTags!.Length;
+                int extraTagsCount = _extraTags.Count;
+
+                if (index < _redactedTagsCount)
                 {
-                    return _incomingTags![index];
+                    return _redactedTags![index];
                 }
-                else if (index < _incomingTagsCount + _redactedTagsCount)
+                else if (index < _redactedTagsCount + extraTagsCount)
                 {
-                    return _redactedTags![index - _incomingTagsCount];
+                    return _extraTags[index - _redactedTagsCount];
                 }
-                else if (index < _incomingTagsCount + _redactedTagsCount + _extraTags.Count)
+                else if (index < _redactedTagsCount + extraTagsCount + staticTagsCount)
                 {
-                    return _extraTags[index - _incomingTagsCount - _redactedTagsCount];
+                    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 StaticTags![index - _incomingTagsCount - _redactedTagsCount - _extraTags.Count];
+                    return _incomingTags![index - _redactedTagsCount - extraTagsCount - staticTagsCount];
                 }
             }
         }

src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs

@@ -322,24 +322,6 @@ private void LegacyPath<TState>(LogLevel logLevel, EventId eventId, TState state
         joiner.Formatter = formatter;
         joiner.State = state;
 
-        switch (state)
-        {
-            case IReadOnlyList<KeyValuePair<string, object?>> stateList:
-                joiner.SetIncomingTags(stateList);
-                break;
-
-            case IEnumerable<KeyValuePair<string, object?>> stateList:
-                joiner.EnrichmentTagCollector.AddRange(stateList);
-                break;
-
-            case null:
-                break;
-
-            default:
-                joiner.EnrichmentTagCollector.Add("{OriginalFormat}", state);
-                break;
-        }
-
         List<Exception>? exceptions = null;
 
         // enrich
@@ -356,12 +338,30 @@ private void LegacyPath<TState>(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<KeyValuePair<string, object?>> stateList:
+                joiner.SetIncomingTags(stateList);
+                break;
+
+            case IEnumerable<KeyValuePair<string, object?>> 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++)
         {

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<string, string?>[] expected)
     {
         var rol = (IReadOnlyList<KeyValuePair<string, string>>)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<KeyValuePair<string, string>>)record.State!;
+        Assert.NotNull(state);
+
+        var pair = state.Last();
+        Assert.Equal("{OriginalFormat}", pair.Key);
+        Assert.Equal(format, pair.Value);
+        Assert.Equal(message, record.Message);
+    }
 }

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);
+    }
+}

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,

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.,

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.,

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.,

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.,

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<string, object?>("K1", "V1"),
+        });
+        var staticEnricher = new ForcedEnricher(new[]
+        {
+            new KeyValuePair<string, object?>("K2", "V2"),
+        });
+        var redactorProvider = new FakeRedactorProvider(new FakeRedactorOptions
+        {
+            RedactionFormat = "REDACTED<{0}>",
+        });
+
+        var enrichmentOptions = enableEnrichment ? new StaticOptionsMonitor<LoggerEnrichmentOptions>(new()) : null;
+        var redactionOptions = enableRedaction ? new StaticOptionsMonitor<LoggerRedactionOptions>(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<LoggerFilterOptions>(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<string, object?>("K1", "V1"),
+        });
+        var staticEnricher = new ForcedEnricher(new[]
+        {
+            new KeyValuePair<string, object?>("K2", "V2"),
+        });
+
+        var enrichmentOptions = enableEnrichment ? new StaticOptionsMonitor<LoggerEnrichmentOptions>(new()) : null;
+
+        using var factory = new ExtendedLoggerFactory(
+            providers: new[] { provider },
+            enrichmentOptions: enrichmentOptions,
+            enrichers: new[] { enricher },
+            staticEnrichers: new[] { staticEnricher },
+            filterOptions: new StaticOptionsMonitor<LoggerFilterOptions>(new()));
+
+        var logger = factory.CreateLogger("logger");
+        var exception = logException ? new InvalidOperationException() : null;
+
+        switch (stateType)
+        {
+            case LegacyStateType.ReadOnlyList:
+                List<KeyValuePair<string, object?>> list =
+                [
+                    new("K3", "V3"),
+                    new("{OriginalFormat}", "V4")
+                ];
+                logger.Log(LogLevel.Warning, new EventId(1, "ID1"), list, exception, (_, _) => "MSG");
+                break;
+
+            case LegacyStateType.Enumerable:
+                IEnumerable<KeyValuePair<string, object?>> enumerable =
+                    new List<KeyValuePair<string, object?>>
+                    {
+                        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
+    }
 }