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 1 commit
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
5 changes: 3 additions & 2 deletions build/Common.props
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
<Project>
<PropertyGroup>
<LangVersion>7.3</LangVersion>
<LangVersion>latest</LangVersion>
<EnforceCodeStyleInBuild>true</EnforceCodeStyleInBuild>
<EnableNETAnalyzers>true</EnableNETAnalyzers>
</PropertyGroup>
Expand All @@ -19,12 +19,13 @@
Please sort alphabetically.
Refer to https://docs.microsoft.com/nuget/concepts/package-versioning for semver syntax.
-->
<MicrosoftExtensionsLoggerVer>[2.0,)</MicrosoftExtensionsLoggerVer>
<MicrosoftExtensionsLoggerVer>[8.0.0,)</MicrosoftExtensionsLoggerVer>
<MicrosoftSourceLinkGitHubPkgVer>[1.0.0,2.0)</MicrosoftSourceLinkGitHubPkgVer>
</PropertyGroup>

<ItemGroup>
<PackageReference Include="System.Collections.Immutable" Version="[1.7.1,)" />
<PackageReference Include="System.Threading.Channels" Version="[6.0.0,)" />
<PackageReference Include="System.ValueTuple" Version="[4.5.0,)" Condition="'$(TargetFramework)' == 'net462'" />
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 actually an interesting side-effect of bumping the MELA dependency.

Our original (ancient) MELA dependency resolves to 2.0.2 which only includes a target for netstandard2.0, whereas starting with version 6.0.0, MELA provided targets for net461, netstandard2.0, and net6.0. This continued into the 7.x series with targets for net462, netstandard2.0, net6.0, and net7.0, as well as into the 8.x series with targets for net462, netstandard2.0, net6.0, net7.0, and net8.0.

So by bumping to a modern MELA, our transitive reference to System.ValueTuple via the netstandard2.0 reference was lost, thus requiring us to take a direct dependency on System.ValueTuple.

Now it's been a minute since I had to deal with this in a real app, but when I last encountered this^ in the wild, IIRC, you always end up with a System.ValueTuple dependency somewhere in the graph, so if you were skirting it before with a faux target of net462 -> netstandard2.0, you still needed the impl bits from System.ValueTuple available by run-time, else chaos ensued.

</ItemGroup>
</Project>
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 @@ -246,7 +246,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);
}
}
}
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 @@ -13,7 +13,7 @@ namespace OpenFeature

internal delegate Task ShutdownDelegate();

internal class EventExecutor
internal sealed partial class EventExecutor
{
private readonly object _lockObj = new object();
public readonly Channel<object> EventChannel = Channel.CreateBounded<object>(1);
Expand All @@ -27,16 +27,18 @@ internal class EventExecutor
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.

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

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

internal void AddApiLevelHandler(ProviderEventTypes eventType, EventHandlerDelegate handler)
{
lock (this._lockObj)
Expand Down Expand Up @@ -218,7 +220,7 @@ private void EmitOnRegistration(FeatureProviderReference provider, ProviderEvent
}
catch (Exception exc)
{
this.Logger?.LogError("Error running handler: " + exc);
this.ErrorRunningHandler(exc);
}
}
}
Expand Down Expand Up @@ -323,7 +325,7 @@ private void InvokeEventHandler(EventHandlerDelegate eventHandler, Event e)
}
catch (Exception exc)
{
this.Logger?.LogError("Error running handler: " + exc);
this.ErrorRunningHandler(exc);
}
}

Expand All @@ -346,6 +348,9 @@ private async Task SignalShutdownAsync()
// Wait for the processing loop to acknowledge the shutdown
await this._shutdownSemaphore.WaitAsync().ConfigureAwait(false);
}

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

internal class ShutdownSignal
Expand Down
31 changes: 22 additions & 9 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);
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 {0}", hook.GetType().Name);
this.ErrorHookError(hook.GetType().Name, e);
}
}
}
Expand All @@ -333,9 +331,24 @@ private async Task TriggerFinallyHooks<T>(IReadOnlyList<Hook> hooks, HookContext
}
catch (Exception e)
{
this._logger.LogError(e, "Error while executing Finally hook {0}", hook.GetType().Name);
this.FinallyHookError(hook.GetType().Name, e);
}
}
}

[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 @@ -180,12 +179,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