Skip to content

Microsoft.Gen.Logging  does not clear  ThreadLocalState  when  ILogger.Log  throws #7634

Description

@jboelter

Description

Generated logging methods use LoggerMessageHelper.ThreadLocalState, but call
state.Clear() only after ILogger.Log returns normally.

If a logging provider throws, cleanup is skipped. A subsequent generated log on
the same thread can emit structured fields left behind by the failed log.

This reproduces with Microsoft.Extensions.Telemetry.Abstractions 9.0.0 and is
still present on current dotnet/extensions main:

  • Commit: 10133db4f4860f4fea6aa56cc8456a5f8640462d
  • Source:
    src/Generators/Microsoft.Gen.Logging/Emission/Emitter.Method.cs

Reproduction Steps

Project reference:

<PackageReference Include="Microsoft.Extensions.Telemetry.Abstractions"
                  Version="9.0.0" />

Program:

using Microsoft.Extensions.Logging;

try
{
    ReproLog.Poison(
        ThrowingLogger.Instance,
        "stale-request",
        "alpha",
        "beta",
        "gamma");
}
catch (InvalidOperationException exception)
{
    Console.WriteLine($"First log threw: {exception.Message}");
}

var capturingLogger = new CapturingLogger();
ReproLog.Observe(capturingLogger, "req-123");

Console.WriteLine("Expected RequestId: req-123");
Console.WriteLine($"Actual RequestId:   {capturingLogger.Fields["RequestId"]}");

internal static partial class ReproLog
{
    [LoggerMessage(
        Level = LogLevel.Information,
        Message = "{RequestId} {First} {Second} {Third}")]
    public static partial void Poison(
        ILogger logger,
        string requestId,
        string first,
        string second,
        string third);

    [LoggerMessage(
        Level = LogLevel.Information,
        Message = "{RequestId}")]
    public static partial void Observe(ILogger logger, string requestId);
}

internal sealed class ThrowingLogger : ILogger
{
    public static readonly ThrowingLogger Instance = new();

    public IDisposable? BeginScope<TState>(TState state)
        where TState : notnull => null;

    public bool IsEnabled(LogLevel logLevel) => true;

    public void Log<TState>(
        LogLevel logLevel,
        EventId eventId,
        TState state,
        Exception? exception,
        Func<TState, Exception?, string> formatter)
        => throw new InvalidOperationException("Provider failed.");
}

internal sealed class CapturingLogger : ILogger
{
    public Dictionary<string, object?> Fields { get; } = [];

    public IDisposable? BeginScope<TState>(TState state)
        where TState : notnull => null;

    public bool IsEnabled(LogLevel logLevel) => true;

    public void Log<TState>(
        LogLevel logLevel,
        EventId eventId,
        TState state,
        Exception? exception,
        Func<TState, Exception?, string> formatter)
    {
        if (state is IReadOnlyList<KeyValuePair<string, object?>> fields)
        {
            foreach (var field in fields)
            {
                if (field.Key is not null)
                {
                    Fields[field.Key] = field.Value;
                }
            }
        }
    }
}

Actual result

First log threw: Provider failed.
Expected RequestId: req-123
Actual RequestId: stale-request

Generated code

The generated method has this shape:

var state = LoggerMessageHelper.ThreadLocalState;

_ = state.ReserveTagSpace(...);
// Populate state...

logger.Log(...);

state.Clear();

Because  logger.Log(...)  throws,  state.Clear()  is never reached. The next
generated method reuses the same thread-static state and exposes its stale tags.

Expected behavior

Generator-owned thread-local state should always be cleared, including when a
provider or generated value conversion throws.

The generated code should use a finally around all state usage:

var state = LoggerMessageHelper.ThreadLocalState;

try
{
    // Reserve and populate state...
    logger.Log(...);
}
finally
{
    state.Clear();
}

Impact

A transient or custom logging-provider failure can corrupt later structured log
records on the same thread. Duplicate fields may cause stale values to overwrite
the current log's values, including correlation identifiers such as RequestId .

Actual behavior

When the first generated log encounters an exception from  ILogger.Log , its thread-local state is not cleared. The next generated log on the same thread contains stale structured fields:

First log threw: Provider failed.
Expected RequestId: req-123
Actual RequestId: stale-request

Regression?

Unknown

Known Workarounds

No response

Configuration

.NET SDK:       10.0.109
.NET runtime:   10.0.9
Architecture:   x64
OS:             Ubuntu 24.04 on WSL2
RID:            ubuntu.24.04-x64
Package:        Microsoft.Extensions.Telemetry.Abstractions 9.0.0
Generator:      Microsoft.Gen.Logging 9.0.0.0
Environment:    Local console application, Release configuration

Other information

The generated code should use a finally around all state usage:

var state = LoggerMessageHelper.ThreadLocalState;

try
{
    // Reserve and populate state...
    logger.Log(...);
}
finally
{
    state.Clear();
}

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugThis issue describes a behavior which is not expected - a bug.

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions