Skip to content

Commit

Permalink
Address a couple log generator issues.
Browse files Browse the repository at this point in the history
- Fix a bug where a tag provider attached to an enumerable parameter
or property wouldn't behave as expected. Fixes #4883.

- When an event id is not specified, instead of emitting 0 for the
the id, we now hash the event name and/or method name. This matches
the behavior of the generator in dotnet/runtime and is generally
more useful.
  • Loading branch information
Martin Taillefer committed Jan 19, 2024
1 parent 855b57b commit 2dc7395
Show file tree
Hide file tree
Showing 5 changed files with 75 additions and 21 deletions.
21 changes: 19 additions & 2 deletions src/Generators/Microsoft.Gen.Logging/Emission/Emitter.Method.cs
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
using System.Collections.Generic;
using System.Linq;
using System.Text;
using Microsoft.CodeAnalysis;

Check failure on line 8 in src/Generators/Microsoft.Gen.Logging/Emission/Emitter.Method.cs

View check run for this annotation

Azure Pipelines / extensions-ci (Correctness WarningsCheck)

src/Generators/Microsoft.Gen.Logging/Emission/Emitter.Method.cs#L8

src/Generators/Microsoft.Gen.Logging/Emission/Emitter.Method.cs(8,1): error S1128: (NETCORE_ENGINEERING_TELEMETRY=Build) Remove this unnecessary 'using'. (https://rules.sonarsource.com/csharp/RSPEC-1128)
using Microsoft.Gen.Logging.Model;
using Microsoft.Gen.Shared;

Expand Down Expand Up @@ -91,7 +92,7 @@ private void GenLogMethod(LoggingMethod lm)
}
else
{
OutLn($"new(0, {eventName}),");
OutLn($"new({GetNonRandomizedHashCode(eventName)}, {eventName}),");
}

OutLn($"{stateName},");
Expand Down Expand Up @@ -134,6 +135,22 @@ private void GenLogMethod(LoggingMethod lm)
OutLn($"{stateName}.Clear();");
OutCloseBrace();

/// <summary>
/// Returns a non-randomized hash code for the given string.
/// We always return a positive value.
/// </summary>
static int GetNonRandomizedHashCode(string s)
{
const int Mult = 16_777_619;
uint result = 2_166_136_261u;
foreach (char c in s)
{
result = (c ^ result) * Mult;
}

return Math.Abs((int)result);
}

static bool ShouldStringifyParameter(LoggingMethodParameter p)
{
if (p.IsReference)
Expand Down Expand Up @@ -395,7 +412,7 @@ void GenTagWrites(LoggingMethod lm, string stateName, out int numReservedUnclass

foreach (var p in lm.Parameters)
{
if (p.HasProperties && p.SkipNullProperties)
if (p.HasProperties && p.SkipNullProperties && !p.HasTagProvider)
{
p.TraverseParameterPropertiesTransitively((propertyChain, member) =>
{
Expand Down
20 changes: 10 additions & 10 deletions test/Generators/Microsoft.Gen.Logging/Generated/LogMethodTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -231,47 +231,47 @@ public void ConstructorVariationsTests()
Assert.Null(collector.LatestRecord.Exception);
Assert.Equal("M1 One", collector.LatestRecord.Message);
Assert.Equal(LogLevel.Error, collector.LatestRecord.Level);
Assert.Equal(0, collector.LatestRecord.Id.Id);
Assert.NotEqual(0, collector.LatestRecord.Id.Id);
Assert.Equal(1, collector.Count);

collector.Clear();
ConstructorVariationsTestExtensions.M2(logger, "Two");
Assert.Null(collector.LatestRecord.Exception);
Assert.Equal(string.Empty, collector.LatestRecord.Message);
Assert.Equal(LogLevel.Debug, collector.LatestRecord.Level);
Assert.Equal(0, collector.LatestRecord.Id.Id);
Assert.NotEqual(0, collector.LatestRecord.Id.Id);
Assert.Equal(1, collector.Count);

collector.Clear();
ConstructorVariationsTestExtensions.M3(logger, LogLevel.Error, "Three");
Assert.Null(collector.LatestRecord.Exception);
Assert.Equal(string.Empty, collector.LatestRecord.Message);
Assert.Equal(LogLevel.Error, collector.LatestRecord.Level);
Assert.Equal(0, collector.LatestRecord.Id.Id);
Assert.NotEqual(0, collector.LatestRecord.Id.Id);
Assert.Equal(1, collector.Count);

collector.Clear();
ConstructorVariationsTestExtensions.M4(logger, "Four");
Assert.Null(collector.LatestRecord.Exception);
Assert.Equal("M4 Four", collector.LatestRecord.Message);
Assert.Equal(LogLevel.Debug, collector.LatestRecord.Level);
Assert.Equal(0, collector.LatestRecord.Id.Id);
Assert.NotEqual(0, collector.LatestRecord.Id.Id);
Assert.Equal(1, collector.Count);

collector.Clear();
ConstructorVariationsTestExtensions.M5(logger, LogLevel.Error, "Five");
Assert.Null(collector.LatestRecord.Exception);
Assert.Equal("M5 Five", collector.LatestRecord.Message);
Assert.Equal(LogLevel.Error, collector.LatestRecord.Level);
Assert.Equal(0, collector.LatestRecord.Id.Id);
Assert.NotEqual(0, collector.LatestRecord.Id.Id);
Assert.Equal(1, collector.Count);

collector.Clear();
ConstructorVariationsTestExtensions.M6(logger, "Six");
Assert.Null(collector.LatestRecord.Exception);
Assert.Equal(string.Empty, collector.LatestRecord.Message);
Assert.Equal(LogLevel.Debug, collector.LatestRecord.Level);
Assert.Equal(0, collector.LatestRecord.Id.Id);
Assert.NotEqual(0, collector.LatestRecord.Id.Id);
Assert.Equal(1, collector.Count);

collector.Clear();
Expand All @@ -282,7 +282,7 @@ public void ConstructorVariationsTests()
Assert.Null(logRecord.Exception);
Assert.Equal(string.Empty, logRecord.Message);
Assert.Equal(LogLevel.Information, logRecord.Level);
Assert.Equal(0, logRecord.Id.Id);
Assert.NotEqual(0, logRecord.Id.Id);
Assert.Equal("M7", logRecord.Id.Name);

collector.Clear();
Expand Down Expand Up @@ -336,15 +336,15 @@ public void MessageTests()
Assert.Null(collector.LatestRecord.Exception);
Assert.Equal("\"p\" -> \"q\"", collector.LatestRecord.Message);
Assert.Equal(LogLevel.Warning, collector.LatestRecord.Level);
Assert.Equal(0, collector.LatestRecord.Id.Id);
Assert.NotEqual(0, collector.LatestRecord.Id.Id);
Assert.Equal(1, collector.Count);

collector.Clear();
MessageTestExtensions.M7(logger);
Assert.Null(collector.LatestRecord.Exception);
Assert.Equal("\"\n\r\\", collector.LatestRecord.Message);
Assert.Equal(LogLevel.Debug, collector.LatestRecord.Level);
Assert.Equal(0, collector.LatestRecord.Id.Id);
Assert.NotEqual(0, collector.LatestRecord.Id.Id);
Assert.Equal(1, collector.Count);
}

Expand Down Expand Up @@ -575,7 +575,7 @@ public void EventNameTests()
Assert.Null(logRecord.Exception);
Assert.Equal(string.Empty, logRecord.Message);
Assert.Equal(LogLevel.Warning, logRecord.Level);
Assert.Equal(0, logRecord.Id.Id);
Assert.NotEqual(0, logRecord.Id.Id);
Assert.Equal("M1_Event", logRecord.Id.Name);
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -431,7 +431,7 @@ public void LogPropertiesDefaultAttrCtor()
Assert.Equal(1, _logger.Collector.Count);
var latestRecord = _logger.Collector.LatestRecord;
Assert.Null(latestRecord.Exception);
Assert.Equal(0, latestRecord.Id.Id);
Assert.NotEqual(0, latestRecord.Id.Id);
Assert.Equal(LogLevel.Critical, latestRecord.Level);
Assert.Equal(string.Empty, latestRecord.Message);

Expand Down Expand Up @@ -482,7 +482,7 @@ public void LogPropertiesRecordClassArgument()
Assert.Equal(1, _logger.Collector.Count);
var latestRecord = _logger.Collector.LatestRecord;
Assert.Null(latestRecord.Exception);
Assert.Equal(0, latestRecord.Id.Id);
Assert.NotEqual(0, latestRecord.Id.Id);
Assert.Equal(LogLevel.Debug, latestRecord.Level);
Assert.Empty(latestRecord.Message);

Expand All @@ -507,7 +507,7 @@ public void LogPropertiesRecordStructArgument()
Assert.Equal(1, _logger.Collector.Count);
var latestRecord = _logger.Collector.LatestRecord;
Assert.Null(latestRecord.Exception);
Assert.Equal(0, latestRecord.Id.Id);
Assert.NotEqual(0, latestRecord.Id.Id);
Assert.Equal(LogLevel.Debug, latestRecord.Level);
Assert.Equal($"Struct is: {recordToLog}", latestRecord.Message);

Expand All @@ -533,7 +533,7 @@ public void LogPropertiesReadonlyRecordStructArgument()
Assert.Equal(1, _logger.Collector.Count);
var latestRecord = _logger.Collector.LatestRecord;
Assert.Null(latestRecord.Exception);
Assert.Equal(0, latestRecord.Id.Id);
Assert.NotEqual(0, latestRecord.Id.Id);
Assert.Equal(LogLevel.Debug, latestRecord.Level);
Assert.Equal($"Readonly struct is: {recordToLog}", latestRecord.Message);

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -80,7 +80,7 @@ public void LogsWhenDefaultAttrCtorInNonStaticClass()
Assert.Equal(1, _logger.Collector.Count);
var latestRecord = _logger.Collector.LatestRecord;
Assert.Null(latestRecord.Exception);
Assert.Equal(0, latestRecord.Id.Id);
Assert.NotEqual(0, latestRecord.Id.Id);
Assert.Equal(LogLevel.Debug, latestRecord.Level);
Assert.Equal(string.Empty, latestRecord.Message);

Expand All @@ -103,7 +103,7 @@ public void LogsWhenDefaultAttrCtorInStaticClass()
Assert.Equal(1, _logger.Collector.Count);
var latestRecord = _logger.Collector.LatestRecord;
Assert.Null(latestRecord.Exception);
Assert.Equal(0, latestRecord.Id.Id);
Assert.NotEqual(0, latestRecord.Id.Id);
Assert.Equal(LogLevel.Trace, latestRecord.Level);
Assert.Equal(string.Empty, latestRecord.Message);

Expand All @@ -124,7 +124,7 @@ public void LogsWithNullable()
Assert.Equal(1, _logger.Collector.Count);
var latestRecord = _logger.Collector.LatestRecord;
Assert.Null(latestRecord.Exception);
Assert.Equal(0, latestRecord.Id.Id);
Assert.NotEqual(0, latestRecord.Id.Id);
Assert.Equal(LogLevel.Trace, latestRecord.Level);
Assert.Equal(string.Empty, latestRecord.Message);
Assert.Empty(latestRecord.StructuredState!);
Expand All @@ -135,7 +135,7 @@ public void LogsWithNullable()
Assert.Equal(1, _logger.Collector.Count);
latestRecord = _logger.Collector.LatestRecord;
Assert.Null(latestRecord.Exception);
Assert.Equal(0, latestRecord.Id.Id);
Assert.NotEqual(0, latestRecord.Id.Id);
Assert.Equal(LogLevel.Trace, latestRecord.Level);
Assert.Equal(string.Empty, latestRecord.Message);

Expand Down Expand Up @@ -185,7 +185,7 @@ public void LogsWhenOmitParamNameIsTrueWithDefaultAttrCtor()
Assert.Equal(1, _logger.Collector.Count);
var latestRecord = _logger.Collector.LatestRecord;
Assert.Null(latestRecord.Exception);
Assert.Equal(0, latestRecord.Id.Id);
Assert.NotEqual(0, latestRecord.Id.Id);
Assert.Equal(LogLevel.Error, latestRecord.Level);
Assert.Equal(string.Empty, latestRecord.Message);

Expand Down Expand Up @@ -300,6 +300,26 @@ public void LogsWhenInterface()
latestRecord.StructuredState.Should().NotBeNull().And.Equal(expectedState);
}

[Fact]
public void LogsWhenEnumerable()
{
var a = new[] { "Zero", "One", "Two" };
TagProviderExtensions.Enumerable(_logger, LogLevel.Debug, a);

Assert.Equal(1, _logger.Collector.Count);
var latestRecord = _logger.Collector.LatestRecord;
Assert.Equal(LogLevel.Debug, latestRecord.Level);

var expectedState = new Dictionary<string, string?>
{
["things.Foo0"] = a[0],
["things.Foo1"] = a[1],
["things.Foo2"] = a[2],
};

latestRecord.StructuredState.Should().NotBeNull().And.Equal(expectedState);
}

[Fact]
public void LogsWhenProviderCombinedWithLogProperties()
{
Expand Down
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.

using System.Collections.Generic;
using Microsoft.Extensions.Logging;
using Microsoft.Shared.Text;

Expand Down Expand Up @@ -49,6 +50,12 @@ internal static partial void Nullable(
ILogger logger,
LogLevel level,
[TagProvider(typeof(CustomProvider), nameof(CustomProvider.ProvideTags))] int? param);

[LoggerMessage]
internal static partial void Enumerable(
ILogger logger,
LogLevel level,
[TagProvider(typeof(CustomProvider), nameof(CustomProvider.ProvideForEnumerable))] IEnumerable<string> things);
}

internal static class CustomProvider
Expand Down Expand Up @@ -95,6 +102,16 @@ public static void ProvideForInterface(ITagCollector list, IInterfaceToLog param
list.Add(nameof(ClassToLog.MyIntProperty), param.MyIntProperty);
list.Add("Custom_property_name", param.MyStringProperty);
}

public static void ProvideForEnumerable(ITagCollector list, IEnumerable<string> e)
{
int i = 0;
foreach (var s in e)
{
list.Add($"Foo{i}", s);
i++;
}
}
}

internal sealed class ClassToLog
Expand Down

0 comments on commit 2dc7395

Please sign in to comment.