Microsoft.Extensions.Logging ILogger scopes are lost in async stream after `yield return`

[CXuesong]

Opened via #47802 (comment). While the previous issue focuses on the decision of whether AsyncLocals (and execution context) should flow acress yield return in async streams, I hope the current one can be triaged to MEL owners, in order to decide on whether the following scoped logging scenario should be supported.

Description

Consider the following use case on .NET 5.0 [.NET Fiddle]

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

async IAsyncEnumerable<int> IntSequence(ILogger logger)
{
    using var scope = logger.BeginScope("My scope");
    logger.LogWarning("Log 1");
    yield return 10;
    logger.LogWarning("Log 2");
    yield return 20;
    logger.LogWarning("Log 3");
    yield return 30;
}

using var lf = LoggerFactory.Create(b => b.AddSimpleConsole(o => o.IncludeScopes = true));
await foreach (var i in IntSequence(lf.CreateLogger("Root")))
{
    Console.WriteLine(i);
}

My expectation is

10
20
30
warn: Root[0]
      => My scope
      Log 1
warn: Root[0]
      => My scope
      Log 2
warn: Root[0]
      => My scope
      Log 3

Actual output is

10
20
30
warn: Root[0]
      => My scope
      Log 1
warn: Root[0]
      Log 2
warn: Root[0]
      Log 3

Scopes are lost for Log 2 and Log 3.

Configuration

• .NET 5 / .NET 6.0.100-preview.1.21103.9
• Microsoft.Extensions.Logging.Console v5.0.0

Regression?

N/A

Other information

The root cause of this issue is #47802, and LoggerFactoryScopeProvider uses AsyncLocal to keep logging scope information.

runtime/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactoryScopeProvider.cs

Lines 14 to 21 in f93fee4

	/// <summary>
	/// Default implementation of <see cref="IExternalScopeProvider"/>
	/// </summary>
	internal class LoggerFactoryScopeProvider : IExternalScopeProvider
	{
	private readonly AsyncLocal<Scope> _currentScope = new AsyncLocal<Scope>();
	private readonly ActivityTrackingOptions _activityTrackingOption;

Tagging subscribers to this area: @maryamariyan
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Opened via #47802 (comment). While the previous issue focuses on the decision of whether AsyncLocals (and execution context) should flow acress yield return in async streams, I hope the current one can be triaged to MEL owners, in order to decide on whether the following scoped logging scenario should be supported.

Description

Consider the following use case on .NET 5.0 [.NET Fiddle]

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

async IAsyncEnumerable<int> IntSequence(ILogger logger)
{
    using var scope = logger.BeginScope("My scope");
    logger.LogWarning("Log 1");
    yield return 10;
    logger.LogWarning("Log 2");
    yield return 20;
    logger.LogWarning("Log 3");
    yield return 30;
}

using var lf = LoggerFactory.Create(b => b.AddSimpleConsole(o => o.IncludeScopes = true));
await foreach (var i in IntSequence(lf.CreateLogger("Root")))
{
    Console.WriteLine(i);
}

My expectation is

10
20
30
warn: Root[0]
      => My scope
      Log 1
warn: Root[0]
      => My scope
      Log 2
warn: Root[0]
      => My scope
      Log 3

Actual output is

10
20
30
warn: Root[0]
      => My scope
      Log 1
warn: Root[0]
      Log 2
warn: Root[0]
      Log 3

Scopes are lost for Log 2 and Log 3.

Configuration

.NET 5 / .NET 6.0.100-preview.1.21103.9

Regression?

N/A

Other information

The root cause of this issue is #47802, and LoggerFactoryScopeProvider uses AsyncLocal to keep logging scope information.

runtime/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactoryScopeProvider.cs

Lines 14 to 21 in f93fee4

	/// <summary>
	/// Default implementation of <see cref="IExternalScopeProvider"/>
	/// </summary>
	internal class LoggerFactoryScopeProvider : IExternalScopeProvider
	{
	private readonly AsyncLocal<Scope> _currentScope = new AsyncLocal<Scope>();
	private readonly ActivityTrackingOptions _activityTrackingOption;

Author:	CXuesong
Assignees:	-
Labels:	area-Extensions-Logging, untriaged
Milestone:	-

[huoyaoyuan]

The context here are actually depending on the ConfigureAwait on await foreach. It it uses ConfigureAwait(true) AND there is valid context, the continuation after yield return will run on the same context(thread).

[CXuesong]

@huoyaoyuan I think ConfigureAwait controls whether to execute continuation on the same SynchronizationContext rather than ExecutionContext. ExecutionContext is always restored with await (but not yield return this time). And AsyncLocal (or ThreadLocal) depends on ExecutionContext to flow.

If you expand the foreach syntax as follows, you will see exactly the same situation

using var lf = LoggerFactory.Create(b => b.AddSimpleConsole(o => o.IncludeScopes = true));
await using (var it = IntSequence(lf.CreateLogger("Root")).GetAsyncEnumerator())
{
	while (await it.MoveNextAsync().ConfigureAwait(true)) {
    	Console.WriteLine(it.Current);
	}
}

[stephentoub]

I assume this behaves as you'd expect if you added await Task.Yield(); after you create the scope?

[CXuesong]

I assume this behaves as you'd expect if you added await Task.Yield(); after you create the scope?

@stephentoub Yes. No. awaits does not affect logging scopes, as you may experiment with the .NET Fiddle link posted above.

Actually AsyncStateMachineBox<T> is keeping ExecutionContext and restoring it in MoveNext call.

[stephentoub]

Right, my point was just that a workaround is to make sure you have an await like that after anything that changes EC.

[CXuesong]

Right, my point was just that a workaround is to make sure you have an await like that after anything that changes EC.

@stephentoub Oh… Did you mean something like this?

async IAsyncEnumerable<int> IntSequence(ILogger logger)
{
    using var scope = logger.BeginScope("My scope");
    logger.LogWarning("Log 1");
    yield return 10;
    await Task.Yield()        // <---- yield here
    logger.LogWarning("Log 2");
    yield return 20;
    logger.LogWarning("Log 3");
    yield return 30;
}

Then this doesn't work… I meant await captures the EC before leaving the function, and restores it when re-entering. Since we have already lost the EC after yield return, the EC captured before await is the default EC without AsyncLocal values.

[stephentoub]

Did you mean something like this?

No, as the first line after the using.

[CXuesong]

Did you mean something like this?

No, as the first line after the using.

@stephentoub Oh. Then the logging scopes are still lost since "Log 2", as if Yield never exists. I've corrected my answer above. Sorry for the confusion.

I assume you meant this:

async IAsyncEnumerable<int> IntSequence(ILogger logger)
{
    using var scope = logger.BeginScope("My scope");
    await Task.Yield();        // <-- yield here
    logger.LogWarning("Log 1");
    yield return 10;
    logger.LogWarning("Log 2");
    yield return 20;
    logger.LogWarning("Log 3");
    yield return 30;
}

Currently I'm using some hacky helper to restore the execution context by myself.