Address issue with legacy logger's calling ToString on the TState arg…

…uments. (#4798)

* Fix #4795

And while I was in the neighborhood, also addresses #4637

---------

Co-authored-by: Martin Taillefer <mataille@microsoft.com>
Co-authored-by: Igor Velikorossov <RussKie@users.noreply.github.com>

src/Generators/Microsoft.Gen.Logging/Parsing/Resources.resx

@@ -256,7 +256,7 @@
     <value>Tag provider method not found</value>
   </data>
   <data name="TagProviderMethodInvalidSignatureTitle" xml:space="preserve">
-    <value>Property provider method has an invalid signature</value>
+    <value>Tag provider method has an invalid signature</value>
   </data>
   <data name="LoggingMethodParameterRefKindMessage" xml:space="preserve">
     <value>Logging method "{0}" has parameter "{1}" with either "ref" or "out" modifier</value>
@@ -295,7 +295,7 @@
     <value>Logging method "{0}" doesn't have anything to be logged</value>
   </data>
   <data name="TagProviderMethodInvalidSignatureMessage" xml:space="preserve">
-    <value>Property provider method "{0}" in type "{1}" doesn't have a signature compatible with "{2}"</value>
+    <value>Tag provider method "{0}" in type "{1}" doesn't have a signature compatible with "{2}"</value>
   </data>
   <data name="TemplateStartsWithAtSymbolMessage" xml:space="preserve">
     <value>Logging method "{0}" has template(s) that start with "@": {1}</value>

src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogRecord.cs

@@ -3,7 +3,9 @@
 
 using System;
 using System.Collections.Generic;
+using System.Diagnostics.CodeAnalysis;
 using Microsoft.Extensions.Logging;
+using Microsoft.Shared.DiagnosticIds;
 using Microsoft.Shared.Diagnostics;
 
 namespace Microsoft.Extensions.Logging.Testing;
@@ -67,6 +69,31 @@ public FakeLogRecord(LogLevel level, EventId id, object? state, Exception? excep
     /// <exception cref="InvalidCastException">The state object is not compatible with supported logging model and is not a read-only list.</exception>
     public IReadOnlyList<KeyValuePair<string, string?>>? StructuredState => (IReadOnlyList<KeyValuePair<string, string?>>?)State;
 
+    /// <summary>
+    /// Gets the value of a particular key value pair in the record's structured state.
+    /// </summary>
+    /// <param name="key">The key to search for in the record's structured state.</param>
+    /// <returns>
+    /// The value associated with the key, or <see langword="null"/> if the key was not found. If the structured
+    /// state contains multiple entries with the same key, the value associated with the first matching key encountered is returned.
+    /// </returns>
+    [Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)]
+    public string? GetStructuredStateValue(string key)
+    {
+        if (StructuredState is not null)
+        {
+            foreach (var kvp in StructuredState)
+            {
+                if (kvp.Key == key)
+                {
+                    return kvp.Value;
+                }
+            }
+        }
+
+        return null;
+    }
+
     /// <summary>
     /// Gets an optional exception associated with the log record.
     /// </summary>

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

@@ -76,5 +76,7 @@ public void SetIncomingTags(IReadOnlyList<KeyValuePair<string, object?>> value)
         }
 
         IEnumerator IEnumerable.GetEnumerator() => GetEnumerator();
+
+        public override string? ToString() => State?.ToString();
     }
 }

test/Libraries/Microsoft.Extensions.Diagnostics.Testing.Tests/Logging/FakeLoggerTests.cs

@@ -91,6 +91,10 @@ public void State()
         Assert.Null(ss["K2"]);
         Assert.Equal("[\"0\",\"1\",\"2\"]", ss["K3"]);
 
+        Assert.Equal("V0", logger.LatestRecord.GetStructuredStateValue("K0"));
+        Assert.Equal("V1", logger.LatestRecord.GetStructuredStateValue("K1"));
+        Assert.Equal("[\"0\",\"1\",\"2\"]", logger.LatestRecord.GetStructuredStateValue("K3"));
+
         logger = new FakeLogger();
         logger.Log<object?>(LogLevel.Error, new EventId(0), null, null, (_, _) => "MESSAGE");
         Assert.Null(logger.LatestRecord.State);

test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/ExtendedLoggerTests.cs

@@ -74,18 +74,18 @@ public static void Basic()
         Assert.Null(snap[0].Exception);
         Assert.Equal(new EventId(0), snap[0].Id);
         Assert.Equal("MSG0", snap[0].Message);
-        Assert.Equal("EV1", snap[0].StructuredState!.GetValue("EK1"));
-        Assert.Equal("SEV1", snap[0].StructuredState!.GetValue("SEK1"));
+        Assert.Equal("EV1", snap[0].GetStructuredStateValue("EK1"));
+        Assert.Equal("SEV1", snap[0].GetStructuredStateValue("SEK1"));
 
         Assert.Equal(Category, snap[1].Category);
         Assert.Null(snap[1].Exception);
         Assert.Equal(new EventId(2, "ID2"), snap[1].Id);
         Assert.Equal("MSG2", snap[1].Message);
-        Assert.Equal("PV2", snap[1].StructuredState!.GetValue("PK2"));
-        Assert.Equal("REDACTED<PV3>", snap[1].StructuredState!.GetValue("PK3"));
-        Assert.Null(snap[1].StructuredState!.GetValue("PK4"));
-        Assert.Equal("EV1", snap[1].StructuredState!.GetValue("EK1"));
-        Assert.Equal("SEV1", snap[1].StructuredState!.GetValue("SEK1"));
+        Assert.Equal("PV2", snap[1].GetStructuredStateValue("PK2"));
+        Assert.Equal("REDACTED<PV3>", snap[1].GetStructuredStateValue("PK3"));
+        Assert.Null(snap[1].GetStructuredStateValue("PK4"));
+        Assert.Equal("EV1", snap[1].GetStructuredStateValue("EK1"));
+        Assert.Equal("SEV1", snap[1].GetStructuredStateValue("SEK1"));
     }
 
     [Theory]
@@ -132,16 +132,16 @@ public static void BagAndJoiner(bool objectVersion)
         Assert.Null(snap[0].Exception);
         Assert.Equal(new EventId(0), snap[0].Id);
         Assert.Equal("MSG0", snap[0].Message);
-        Assert.Equal("EV1", snap[0].StructuredState!.GetValue("EK1"));
-        Assert.Equal("EV2", snap[0].StructuredState!.GetValue("EK2"));
+        Assert.Equal("EV1", snap[0].GetStructuredStateValue("EK1"));
+        Assert.Equal("EV2", snap[0].GetStructuredStateValue("EK2"));
 
         Assert.Equal(Category, snap[1].Category);
         Assert.Null(snap[1].Exception);
         Assert.Equal(new EventId(2, "ID2"), snap[1].Id);
         Assert.Equal("MSG2", snap[1].Message);
-        Assert.Equal("PV2", snap[1].StructuredState!.GetValue("PK2"));
-        Assert.Equal("EV1", snap[1].StructuredState!.GetValue("EK1"));
-        Assert.Equal("EV2", snap[1].StructuredState!.GetValue("EK2"));
+        Assert.Equal("PV2", snap[1].GetStructuredStateValue("PK2"));
+        Assert.Equal("EV1", snap[1].GetStructuredStateValue("EK1"));
+        Assert.Equal("EV2", snap[1].GetStructuredStateValue("EK2"));
     }
 
     [Fact]
@@ -197,29 +197,29 @@ public static void NullStateObject()
         Assert.Null(snap[0].Exception);
         Assert.Equal(new EventId(0, "ID0"), snap[0].Id);
         Assert.Equal("MSG0", snap[0].Message);
-        Assert.Equal("EV1", snap[0].StructuredState!.GetValue("EK1"));
-        Assert.Equal("SEV1", snap[0].StructuredState!.GetValue("SEK1"));
+        Assert.Equal("EV1", snap[0].GetStructuredStateValue("EK1"));
+        Assert.Equal("SEV1", snap[0].GetStructuredStateValue("SEK1"));
 
         Assert.Equal(Category, snap[1].Category);
         Assert.Null(snap[1].Exception);
         Assert.Equal(new EventId(0, "ID0b"), snap[1].Id);
         Assert.Equal("MSG0b", snap[1].Message);
-        Assert.Equal("EV1", snap[1].StructuredState!.GetValue("EK1"));
-        Assert.Equal("SEV1", snap[1].StructuredState!.GetValue("SEK1"));
+        Assert.Equal("EV1", snap[1].GetStructuredStateValue("EK1"));
+        Assert.Equal("SEV1", snap[1].GetStructuredStateValue("SEK1"));
 
         Assert.Equal(Category, snap[2].Category);
         Assert.Null(snap[2].Exception);
         Assert.Equal(new EventId(2, "ID2"), snap[2].Id);
         Assert.Equal("MSG2", snap[2].Message);
-        Assert.Equal("EV1", snap[2].StructuredState!.GetValue("EK1"));
-        Assert.Equal("SEV1", snap[2].StructuredState!.GetValue("SEK1"));
+        Assert.Equal("EV1", snap[2].GetStructuredStateValue("EK1"));
+        Assert.Equal("SEV1", snap[2].GetStructuredStateValue("SEK1"));
 
         Assert.Equal(Category, snap[3].Category);
         Assert.Null(snap[3].Exception);
         Assert.Equal(new EventId(2, "ID2b"), snap[3].Id);
         Assert.Equal("MSG2b", snap[3].Message);
-        Assert.Equal("EV1", snap[3].StructuredState!.GetValue("EK1"));
-        Assert.Equal("SEV1", snap[3].StructuredState!.GetValue("SEK1"));
+        Assert.Equal("EV1", snap[3].GetStructuredStateValue("EK1"));
+        Assert.Equal("SEV1", snap[3].GetStructuredStateValue("SEK1"));
     }
 
     [Fact]
@@ -257,7 +257,7 @@ public static void EnumerableStateObject()
         Assert.Null(snap[0].Exception);
         Assert.Equal(new EventId(0, "ID0"), snap[0].Id);
         Assert.Equal("MSG0", snap[0].Message);
-        Assert.Equal("V1", snap[0].StructuredState!.GetValue("K1"));
+        Assert.Equal("V1", snap[0].GetStructuredStateValue("K1"));
     }
 
     [Fact]
@@ -326,7 +326,29 @@ public static void StringStateObject()
         Assert.Null(snap[0].Exception);
         Assert.Equal(new EventId(0, "ID0"), snap[0].Id);
         Assert.Equal("MSG0", snap[0].Message);
-        Assert.Equal("PAYLOAD", snap[0].StructuredState!.GetValue("{OriginalFormat}"));
+        Assert.Equal("PAYLOAD", snap[0].GetStructuredStateValue("{OriginalFormat}"));
+    }
+
+    [Fact]
+    public static void StateToStringWorks()
+    {
+        using var provider = new CapturingProvider();
+        using var lf = new ExtendedLoggerFactory(
+            providers: new[] { provider },
+            filterOptions: new StaticOptionsMonitor<LoggerFilterOptions>(new()),
+            enrichmentOptions: new StaticOptionsMonitor<LoggerEnrichmentOptions>(new()),
+            redactionOptions: new StaticOptionsMonitor<LoggerRedactionOptions>(new()),
+            enrichers: Array.Empty<ILogEnricher>(),
+            staticEnrichers: Array.Empty<IStaticLogEnricher>(),
+            redactorProvider: null,
+            scopeProvider: null,
+            factoryOptions: null);
+
+        var logger = lf.CreateLogger("FOO");
+
+        logger.Log(LogLevel.Information, new EventId(0, "ID0"), "PAYLOAD", null, (_, _) => "MSG0");
+
+        Assert.Equal("PAYLOAD", provider.State!);
     }
 
     [Theory]
@@ -429,20 +451,18 @@ public static void Exceptions(bool includeExceptionMessage)
         Assert.Equal(new EventId(2, "ID2b"), snap[3].Id);
         Assert.Equal("MSG2b", snap[3].Message);
 
-        var state = snap[3].StructuredState;
-
-        var exceptionType = state!.GetValue("exception.type")!;
+        var exceptionType = snap[3].GetStructuredStateValue("exception.type")!;
         Assert.Equal("System.AggregateException", exceptionType);
 
-        var stackTrace = state!.GetValue("exception.stacktrace")!;
+        var stackTrace = snap[3].GetStructuredStateValue("exception.stacktrace")!;
         Assert.Contains("AggregateException", stackTrace);
         Assert.Contains("ArgumentNullException", stackTrace);
         Assert.Contains("ArgumentOutOfRangeException", stackTrace);
         Assert.Contains("InvalidOperationException", stackTrace);
 
         if (includeExceptionMessage)
         {
-            var exceptionMessage = state!.GetValue("exception.message");
+            var exceptionMessage = snap[3].GetStructuredStateValue("exception.message");
             Assert.Equal("EM4 (EM1) (EM2) (EM3)", exceptionMessage);
 
             Assert.Contains("EM1", stackTrace);
@@ -452,6 +472,7 @@ public static void Exceptions(bool includeExceptionMessage)
         }
         else
         {
+            var state = snap[3].StructuredState;
             Assert.DoesNotContain(state!, x => x.Key == "exception.message");
 
             Assert.DoesNotContain("EM1", stackTrace);
@@ -795,19 +816,6 @@ private enum ThrowExceptionAt
         IsEnabled
     }
 
-    private static string? GetValue(this IReadOnlyList<KeyValuePair<string, string>> state, string name)
-    {
-        foreach (var kvp in state)
-        {
-            if (kvp.Key == name)
-            {
-                return kvp.Value;
-            }
-        }
-
-        return null;
-    }
-
     private sealed class Provider : ILoggerProvider
     {
         public FakeLogger? Logger { get; private set; }
@@ -824,6 +832,33 @@ public void Dispose()
         }
     }
 
+    private sealed class CapturingProvider : ILoggerProvider
+    {
+        public object? State { get; private set; }
+        public ILogger CreateLogger(string categoryName) => new Logger(this);
+
+        public void Dispose()
+        {
+            // nothing to do
+        }
+
+        private sealed class Logger : ILogger
+        {
+            private readonly CapturingProvider _provider;
+
+            public Logger(CapturingProvider provider)
+            {
+                _provider = provider;
+            }
+
+            public IDisposable? BeginScope<TState>(TState state)
+                where TState : notnull => throw new NotSupportedException();
+
+            public bool IsEnabled(LogLevel logLevel) => true;
+            public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter) => _provider.State = state?.ToString();
+        }
+    }
+
     private sealed class ForcedEnricher : ILogEnricher, IStaticLogEnricher
     {
         private readonly KeyValuePair<string, object?>[] _values;