[Telemetry, Logging] Emit {OriginalFormat} as the last property of the 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

Author: iliar-turdushev

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