[Telemetry, Logging] Emit {OriginalFormat} as the last property of the log record

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,19 @@ public void SetIncomingTags(IReadOnlyList<KeyValuePair<string, object?>> 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];
                 }
             }
         }

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];
                 }
             }
         }

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.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
+    }
 }