Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Address issue with legacy logger's calling ToString on the TState arguments. #4798

Merged
merged 2 commits into from
Dec 11, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

4 changes: 2 additions & 2 deletions src/Generators/Microsoft.Gen.Logging/Parsing/Resources.resx
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Expand Down Expand Up @@ -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>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -76,5 +76,7 @@ public void SetIncomingTags(IReadOnlyList<KeyValuePair<string, object?>> value)
}

IEnumerator IEnumerable.GetEnumerator() => GetEnumerator();

public override string? ToString() => State?.ToString();
geeknoid marked this conversation as resolved.
Show resolved Hide resolved
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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]
Expand Down Expand Up @@ -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]
Expand Down Expand Up @@ -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]
Expand Down Expand Up @@ -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]
Expand Down Expand Up @@ -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]
Expand Down Expand Up @@ -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);
Expand All @@ -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);
Expand Down Expand Up @@ -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; }
Expand All @@ -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;
Expand Down