serilog / serilog-sinks-periodicbatching

Infrastructure for Serilog sinks that process events in batches.
Apache License 2.0
71 stars 29 forks source link

Suggestion: Suppress ExecutionContext flow on Timer created by PortableTimer #52

Closed CodeBlanch closed 3 years ago

CodeBlanch commented 3 years ago

An OpenTelemetry user brought this up via Gitter:

A less obvious example of this occurring can happen with the Serilog logging library. If you use a sink that relies on periodic batching, the first attempt to log something will start a timer, I believe, to periodically send data. If that first call to log something happened when there's an available Activity.Current it will indefinitely hold onto that activity.

OpenTelemetry is using System.Diagnostics.DiagnosticSource.Activity.Current, which is backed by an AsyncLocal.

What's going on is this code in PortableTimer: https://github.com/serilog/serilog-sinks-periodicbatching/blob/313598fd6c0747489c0fdf3949238dd75e60dae0/src/Serilog.Sinks.PeriodicBatching/Sinks/PeriodicBatching/PortableTimer.cs#L43

Captures whatever Activity.Current happens to be set when the ctor is invoked because the .NET Framework & .NET Core Timers capture execution context by default.

Thought I would suggest updating the code to wrap the ctor in an ExecutionContext.SuppressFlow() because I don't think the capture is intentional and it might prevent other mysterious things from happening in the future to serilog users.

/cc @nrcventura

nblumhardt commented 3 years ago

Sounds like a worthwhile improvement; thanks for the note, @CodeBlanch .

Any chance anyone following this is interested in submitting a PR?

Cheers! Nick

nrcventura commented 3 years ago

A change like this will be useful for multiple telemetry/observability providers because AsyncLocal is a commonly used tool to track state across async hops for a logical execution flow.

CodeBlanch commented 3 years ago

@nblumhardt I just took a stab at making the change but ran into an issue I'm not quite sure what to do about.

The csproj has this:

    <!-- Don't reference the full NETStandard.Library -->
    <DisableImplicitFrameworkReferences>true</DisableImplicitFrameworkReferences>

With that enabled, ExecutionContext.SuppressFlow is unavailable. I looked for a NuGet package that I could add in, but couldn't find a fit. There's System.Threading.ExecutionContext but it never left beta & conflicts with System.Threading. First time I've seen DisableImplicitFrameworkReferences, any guidance on what to do?

nblumhardt commented 3 years ago

Hi @CodeBlanch - ExecutionContext.SuppressFlow() is present in netstandard2.0; I think we should add a condition to <DisableImplicitFrameworkReferences> so that it is only applied to the earlier targets (it avoids crazy-huge dependency graphs from netstandard1.x packages). We should probably also add a netstandard2.1 target while we're at it.

Where you see:

  <PropertyGroup Condition=" '$(TargetFramework)' == 'netstandard2.0' ">
    <DefineConstants>$(DefineConstants);THREADING_TIMER</DefineConstants>
  </PropertyGroup>

an additional constant could be added, e.g.

    <DefineConstants>$(DefineConstants);THREADING_TIMER;EXECUTION_CONTEXT</DefineConstants>

and then #if EXECUTION_CONTEXT can be used to surround the code that relies on it.

HTH!