Skip to content

chore: Use logging source generators #189

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.

Sign up for GitHub

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

Merged
merged 2 commits into from
Apr 9, 2024
Merged

chore: Use logging source generators #189

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
a45f8cf
chore: Use logging source generators
austindrenski Jan 17, 2024
160dbb9
Merge branch 'main' into logging-cleanup
askpt Apr 9, 2024
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
3 changes: 2 additions & 1 deletion Directory.Packages.props
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,9 +6,10 @@

<ItemGroup Label="src">
<PackageVersion Include="Microsoft.Bcl.AsyncInterfaces" Version="8.0.0" />
<PackageVersion Include="Microsoft.Extensions.Logging.Abstractions" Version="2.0.0" />
<PackageVersion Include="Microsoft.Extensions.Logging.Abstractions" Version="8.0.0" />
<PackageVersion Include="System.Collections.Immutable" Version="1.7.1" />
<PackageVersion Include="System.Threading.Channels" Version="6.0.0" />
<PackageVersion Include="System.ValueTuple" Version="4.5.0" />
</ItemGroup>

<ItemGroup Label="test">
Expand Down
1 change: 1 addition & 0 deletions build/Common.props
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@
<ItemGroup>
<PackageReference Include="System.Collections.Immutable" Condition="'$(TargetFramework)' == 'net462' or '$(TargetFramework)' == 'netstandard2.0'" />
<PackageReference Include="System.Threading.Channels" Condition="'$(TargetFramework)' == 'net462' or '$(TargetFramework)' == 'netstandard2.0'" />
<PackageReference Include="System.ValueTuple" Condition="'$(TargetFramework)' == 'net462'" />
</ItemGroup>

<ItemGroup Condition="'$(OS)' == 'Unix'">
Expand Down
2 changes: 1 addition & 1 deletion src/OpenFeature/Api.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -280,7 +280,7 @@ public void RemoveHandler(ProviderEventTypes type, EventHandlerDelegate handler)
/// <param name="logger">The logger to be used</param>
public void SetLogger(ILogger logger)
{
this._eventExecutor.Logger = logger;
this._eventExecutor.SetLogger(logger);
}

internal void AddClientHandler(string client, ProviderEventTypes eventType, EventHandlerDelegate handler)
Expand Down
15 changes: 10 additions & 5 deletions src/OpenFeature/EventExecutor.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,7 +10,7 @@

namespace OpenFeature
{
internal class EventExecutor : IAsyncDisposable
internal sealed partial class EventExecutor : IAsyncDisposable
{
private readonly object _lockObj = new object();
public readonly Channel<object> EventChannel = Channel.CreateBounded<object>(1);
Expand All @@ -21,17 +21,19 @@ internal class EventExecutor : IAsyncDisposable
private readonly Dictionary<ProviderEventTypes, List<EventHandlerDelegate>> _apiHandlers = new Dictionary<ProviderEventTypes, List<EventHandlerDelegate>>();
private readonly Dictionary<string, Dictionary<ProviderEventTypes, List<EventHandlerDelegate>>> _clientHandlers = new Dictionary<string, Dictionary<ProviderEventTypes, List<EventHandlerDelegate>>>();

internal ILogger Logger { get; set; }
private ILogger _logger;

public EventExecutor()
{
this.Logger = new Logger<EventExecutor>(new NullLoggerFactory());
this._logger = NullLogger<EventExecutor>.Instance;
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is effectively the same thing, but (1) it saves two allocations (albeit insignificant ones), (2) its the common/recommended pattern, and (3) its sometimes nice to be able to drop a breakpoint inside NullLogger<T> and catch callers to it, so this makes it a little more obvious what's happening in those cases.

var eventProcessing = new Thread(this.ProcessEventAsync);
eventProcessing.Start();
}

public ValueTask DisposeAsync() => new(this.Shutdown());

internal void SetLogger(ILogger logger) => this._logger = logger;

internal void AddApiLevelHandler(ProviderEventTypes eventType, EventHandlerDelegate handler)
{
lock (this._lockObj)
Expand Down Expand Up @@ -209,7 +211,7 @@ private void EmitOnRegistration(FeatureProvider? provider, ProviderEventTypes ev
}
catch (Exception exc)
{
this.Logger.LogError(exc, "Error running handler");
this.ErrorRunningHandler(exc);
}
}
}
Expand Down Expand Up @@ -311,7 +313,7 @@ private void InvokeEventHandler(EventHandlerDelegate eventHandler, Event e)
}
catch (Exception exc)
{
this.Logger.LogError(exc, "Error running handler");
this.ErrorRunningHandler(exc);
}
}

Expand All @@ -321,6 +323,9 @@ public async Task Shutdown()

await this.EventChannel.Reader.Completion.ConfigureAwait(false);
}

[LoggerMessage(100, LogLevel.Error, "Error running handler")]
partial void ErrorRunningHandler(Exception exception);
}

internal class Event
Expand Down
29 changes: 21 additions & 8 deletions src/OpenFeature/OpenFeatureClient.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,7 +15,7 @@ namespace OpenFeature
/// <summary>
///
/// </summary>
public sealed class FeatureClient : IFeatureClient
public sealed partial class FeatureClient : IFeatureClient
{
private readonly ClientMetadata _metadata;
private readonly ConcurrentStack<Hook> _hooks = new ConcurrentStack<Hook>();
Expand Down Expand Up @@ -76,7 +76,7 @@ public void SetContext(EvaluationContext? context)
public FeatureClient(string? name, string? version, ILogger? logger = null, EvaluationContext? context = null)
{
this._metadata = new ClientMetadata(name, version);
this._logger = logger ?? new Logger<Api>(new NullLoggerFactory());
this._logger = logger ?? NullLogger<FeatureClient>.Instance;
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Note the logger name/category change here. It doesn't actually matter for the no-op logger, but prestaging the change while I'm at it because this will matter in the post-#181 world because when #181 registers IFeatureClient it injects a named logger similar to how HttpClient loggers work so that consumer apps can exercise granular control over logging sources.

dotnet-sdk/src/OpenFeature.Extensions.Hosting/OpenFeatureBuilderExtensions.cs

Lines 109 to 113 in 9821a5b

builder.Services.TryAddKeyedSingleton(providerName, static (services, providerName) => providerName switch
{
null => services.GetRequiredService<ILogger<FeatureClient>>(),
not null => services.GetRequiredService<ILoggerFactory>().CreateLogger($"OpenFeature.FeatureClient.{providerName}")
});

Such that a consumer app could do something like this in their appsettings.json to vary the minimum log levels by provider:

{
  "Logging": {
    "LogLevel": {
      "Default": "Debug",
      "OpenFeature": "Information",
      "OpenFeature.FeatureClient": "Warning",
      "OpenFeature.FeatureClient.No-op Provider": "Warning",
      "OpenFeature.FeatureClient.flagd Provider": "Information",
    }
  }
}

this._evaluationContext = context ?? EvaluationContext.Empty;
}

Expand Down Expand Up @@ -252,15 +252,14 @@ private async Task<FlagEvaluationDetails<T>> EvaluateFlag<T>(
}
catch (FeatureProviderException ex)
{
this._logger.LogError(ex, "Error while evaluating flag {FlagKey}. Error {ErrorType}", flagKey,
ex.ErrorType.GetDescription());
this.FlagEvaluationErrorWithDescription(flagKey, ex.ErrorType.GetDescription(), ex);
evaluation = new FlagEvaluationDetails<T>(flagKey, defaultValue, ex.ErrorType, Reason.Error,
string.Empty, ex.Message);
await this.TriggerErrorHooks(allHooksReversed, hookContext, ex, options).ConfigureAwait(false);
}
catch (Exception ex)
{
this._logger.LogError(ex, "Error while evaluating flag {FlagKey}", flagKey);
this.FlagEvaluationError(flagKey, ex);
var errorCode = ex is InvalidCastException ? ErrorType.TypeMismatch : ErrorType.General;
evaluation = new FlagEvaluationDetails<T>(flagKey, defaultValue, errorCode, Reason.Error, string.Empty, ex.Message);
await this.TriggerErrorHooks(allHooksReversed, hookContext, ex, options).ConfigureAwait(false);
Expand Down Expand Up @@ -289,8 +288,7 @@ private async Task<HookContext<T>> TriggerBeforeHooks<T>(IReadOnlyList<Hook> hoo
}
else
{
this._logger.LogDebug("Hook {HookName} returned null, nothing to merge back into context",
hook.GetType().Name);
this.HookReturnedNull(hook.GetType().Name);
}
}

Expand All @@ -317,7 +315,7 @@ private async Task TriggerErrorHooks<T>(IReadOnlyList<Hook> hooks, HookContext<T
}
catch (Exception e)
{
this._logger.LogError(e, "Error while executing Error hook {HookName}", hook.GetType().Name);
this.ErrorHookError(hook.GetType().Name, e);
}
}
}
Expand All @@ -337,5 +335,20 @@ private async Task TriggerFinallyHooks<T>(IReadOnlyList<Hook> hooks, HookContext
}
}
}

[LoggerMessage(100, LogLevel.Debug, "Hook {HookName} returned null, nothing to merge back into context")]
partial void HookReturnedNull(string hookName);

[LoggerMessage(101, LogLevel.Error, "Error while evaluating flag {FlagKey}")]
partial void FlagEvaluationError(string flagKey, Exception exception);

[LoggerMessage(102, LogLevel.Error, "Error while evaluating flag {FlagKey}: {ErrorType}")]
partial void FlagEvaluationErrorWithDescription(string flagKey, string errorType, Exception exception);

[LoggerMessage(103, LogLevel.Error, "Error while executing Error hook {HookName}")]
partial void ErrorHookError(string hookName, Exception exception);

[LoggerMessage(104, LogLevel.Error, "Error while executing Finally hook {HookName}")]
partial void FinallyHookError(string hookName, Exception exception);
}
}
8 changes: 1 addition & 7 deletions test/OpenFeature.Tests/OpenFeatureClientTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,6 @@
using AutoFixture;
using FluentAssertions;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Internal;
using NSubstitute;
using NSubstitute.ExceptionExtensions;
using OpenFeature.Constant;
Expand Down Expand Up @@ -182,12 +181,7 @@ public async Task OpenFeatureClient_Should_Return_DefaultValue_When_Type_Mismatc

_ = mockedFeatureProvider.Received(1).ResolveStructureValue(flagName, defaultValue, Arg.Any<EvaluationContext>());

mockedLogger.Received(1).Log(
LogLevel.Error,
Arg.Any<EventId>(),
Arg.Is<FormattedLogValues>(t => string.Equals($"Error while evaluating flag {flagName}", t.ToString(), StringComparison.InvariantCultureIgnoreCase)),
Arg.Any<Exception>(),
Arg.Any<Func<object, Exception, string>>());
mockedLogger.Received(1).IsEnabled(LogLevel.Error);
Comment on lines -185 to +184
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This call still happens, but the arg type is an internal type (e.g. LoggerMessage.LogValues<T>) which makes call checking a little peevish since we can't reference the type, so opted to change this to just check that we made it to the IsEnabled(...) check.

If there are any strong feelings about this, I can hack together something closer to the original assertion using reflection, just let me know.

For reference, here's a snippet of what the source generator emits at compile-time:

// <auto-generated/>
#nullable enable

namespace OpenFeature
{
    partial class FeatureClient
    {
        [global::System.CodeDom.Compiler.GeneratedCodeAttribute("Microsoft.Extensions.Logging.Generators", "8.0.9.3103")]
        private static readonly global::System.Action<global::Microsoft.Extensions.Logging.ILogger, global::System.String, global::System.Exception?> __FlagEvaluationErrorCallback =
            global::Microsoft.Extensions.Logging.LoggerMessage.Define<global::System.String>(global::Microsoft.Extensions.Logging.LogLevel.Error, new global::Microsoft.Extensions.Logging.EventId(101, nameof(FlagEvaluationError)), "Error while evaluating flag {FlagKey}", new global::Microsoft.Extensions.Logging.LogDefineOptions() { SkipEnabledCheck = true }); 

        [global::System.CodeDom.Compiler.GeneratedCodeAttribute("Microsoft.Extensions.Logging.Generators", "8.0.9.3103")]
        partial void FlagEvaluationError(global::System.String flagKey, global::System.Exception exception)
        {
            if (_logger.IsEnabled(global::Microsoft.Extensions.Logging.LogLevel.Error))
            {
                __FlagEvaluationErrorCallback(_logger, flagKey, exception);
            }
        }
    }
}

}

[Fact]
Expand Down