The LogRecord scopes are corrupted when using the BatchLogRecordExportProcessor

[justkao]

Bug Report

OpenTelemetry 1.1.0-beta1
Microsoft.Extensions.Logging 5.0.0

Runtime version netcoreapp3.1

Symptom

The BaseExporter<LogRecord> will process incorrect scopes if BatchLogRecordExportProcessor is used. If SimpleLogRecordExportProcessor is used everything is processed correctly. This is a symptom of BatchLogRecordExportProcessor processing the records after the original scopes are disposed.

What is the expected behavior?

The exporter should have access to correct scopes.

What is the actual behavior?

The scopes that the exported are not consistent.

Reproduce

The unit test bellow reproduces the issue:

        [TestCase(true)]
        [TestCase(false)]
        public void VerifyScopes(bool useBatching)
        {
            BaseProcessor<LogRecord> processor = useBatching ? new BatchLogRecordExportProcessor(new AssertScopesExporter()): new SimpleLogRecordExportProcessor(new AssertScopesExporter());

            var logger = LoggerFactory.Create(builder =>
            {
                builder.AddOpenTelemetry(options =>
                {
                    options.AddProcessor(processor);
                    options.IncludeFormattedMessage = true;
                    options.IncludeScopes = true;

                });
            }).CreateLogger(GetType());

            for (int i = 0; i < 1000; i++)
            {
                using (logger.BeginScope(i.ToString()))
                {
                    using (logger.BeginScope(i.ToString()))
                    {
                        using (logger.BeginScope(i.ToString()))
                        {
                            logger.LogInformation(i.ToString());
                        }
                    }
                }
            }

            processor.ForceFlush();
        }

        private class AssertScopesExporter : BaseExporter<LogRecord>
        {
            public override ExportResult Export(in Batch<LogRecord> batch)
            {
                foreach (var log in batch)
                {
                    int scopes = 0;

                    log.ForEachScope<object>(
                        (scope, _) =>
                        {
                            Assert.AreEqual(log.FormattedMessage, scope.ToString());
                            scopes++;
                        },
                        null);

                    Assert.AreEqual(3, scopes);
                }

                return ExportResult.Success;
            }
        }

We will close this issue if:

• The unit test above will pass for both test cases.

Additional Context

I think the LogRecord needs to be extended with Scopes property and these must be filled directly by the OpenTelemetryLogger. Current API LogRecord.ForEachScope will simply not work if BatchLogRecordExportProcessor is involved.

[Vijay-Nirmal]

Just encountered this issues. Here are some more details to add.

if (logRecord.State is IReadOnlyCollection<KeyValuePair<string, object>> stateDictionary)
{
    foreach (KeyValuePair<string, object> item in stateDictionary)
    {
        if (string.Equals(item.Key, "{OriginalFormat}", System.StringComparison.Ordinal))
        {
            customProperties["OriginalFormat"] = Convert.ToString(item.Value, CultureInfo.InvariantCulture);
        }
        else
        {
            customProperties[item.Key] = Convert.ToString(item.Value, CultureInfo.InvariantCulture);
        }
    }
}

Here are the exception details

System.ObjectDisposedException
  HResult=0x80131622
  Message=IFeatureCollection has been disposed.
Object name: 'Collection'.
  Source=Microsoft.AspNetCore.Http.Features
  StackTrace:
   at Microsoft.AspNetCore.Http.Features.FeatureReferences`1.ThrowContextDisposed()
   at Microsoft.AspNetCore.Http.Features.FeatureReferences`1.ContextDisposed()
   at Microsoft.AspNetCore.Http.Features.FeatureReferences`1.Fetch[TFeature,TState](TFeature& cached, TState state, Func`2 factory)
   at Microsoft.AspNetCore.Http.Features.FeatureReferences`1.Fetch[TFeature](TFeature& cached, Func`2 factory)
   at Microsoft.AspNetCore.Http.DefaultHttpRequest.get_Protocol()
   at Microsoft.AspNetCore.Hosting.HostingRequestStartingLog.get_Item(Int32 index)
   at Microsoft.AspNetCore.Hosting.HostingRequestStartingLog.<GetEnumerator>d__9.MoveNext()
   at MyCompany.Logging.AspNetCore.OpenTelemetry.OcapTelemtryUtil.ToOcapTelemetry(LogRecord logRecord) in C:\MyCompany\Logging\MyCompany.Logging.AspNetCore\OpenTelemetry\OcapTelemtryUtil.cs:line 39

[cijothomas]

Thanks for using the new feature and reporting the issue!
We'll try alternates to supporting scopes. :)

[tanaka-takayoshi]

Hi, I found this issue reproduced ASP.NET Core Instrumentation only on Windows. The same code is working fine on Mac but it crashed with the ObjectDisposedException on Windows. If I should file my case as a separate case, please let me know.

Here is the project file.

<Project Sdk="Microsoft.NET.Sdk.Web">

	<PropertyGroup>
		<TargetFramework>net6.0</TargetFramework>
		<ImplicitUsings>enable</ImplicitUsings>
		<Nullable>enable</Nullable>
	</PropertyGroup>

	<ItemGroup>
		<PackageReference Include="Microsoft.Data.Sqlite" Version="6.0.2" />
		<PackageReference Include="Microsoft.EntityFrameworkCore.Sqlite" Version="6.0.2" />
		<PackageReference Include="Microsoft.EntityFrameworkCore.Tools" Version="6.0.2">
			<IncludeAssets>runtime; build; native; contentfiles; analyzers; buildtransitive</IncludeAssets>
			<PrivateAssets>all</PrivateAssets>
		</PackageReference>
		<PackageReference Include="OpenTelemetry.Contrib.Instrumentation.EntityFrameworkCore" Version="1.0.0-beta2" />
		<PackageReference Include="OpenTelemetry.Exporter.Console" Version="1.2.0-rc2" />
		<PackageReference Include="OpenTelemetry.Exporter.OpenTelemetryProtocol" Version="1.2.0-rc2" />
		<PackageReference Include="OpenTelemetry.Exporter.OpenTelemetryProtocol.Logs" Version="1.0.0-rc9" />
		<PackageReference Include="OpenTelemetry.Extensions.Hosting" Version="1.0.0-rc9" />
		<PackageReference Include="OpenTelemetry.Instrumentation.AspNetCore" Version="1.0.0-rc9" />
		<PackageReference Include="OpenTelemetry.Instrumentation.Http" Version="1.0.0-rc9" />
		<PackageReference Include="OpenTelemetry.Instrumentation.SqlClient" Version="1.0.0-rc9" />
		<PackageReference Include="Swashbuckle.AspNetCore" Version="6.2.3" />
	</ItemGroup>
</Project>

Here is how to configure the OTLP exporter in ASP.NET Core startup code.

builder.Logging.AddOpenTelemetry(builder =>
{
    builder.IncludeFormattedMessage = true;
    builder.IncludeScopes = true;
    builder.ParseStateValues = true;
    builder.SetResourceBuilder(ResourceBuilder.CreateDefault().AddService("Hello-Otel").AddAttributes(tags))
        .AddOtlpExporter(options =>
        {
            options.Endpoint = new Uri("http://localhost:4317/");
        });
});

Here is how to output the log.

app.MapGet("/weatherforecast", (ILogger<Program> logger) =>
{
    logger.LogInformation("Log!!");
    return "example";
});

And exception details.

System.ObjectDisposedException
  HResult=0x80131622
  Message=IFeatureCollection has been disposed.
ObjectDisposed_ObjectName_Name
  Source=Microsoft.Extensions.Features
  StackTrace:
   at Microsoft.AspNetCore.Http.Features.FeatureReferences`1.ThrowContextDisposed()
   at Microsoft.AspNetCore.Http.Features.FeatureReferences`1.ContextDisposed()
   at Microsoft.AspNetCore.Http.Features.FeatureReferences`1.Fetch[TFeature,TState](TFeature& cached, TState state, Func`2 factory)
   at Microsoft.AspNetCore.Http.Features.FeatureReferences`1.Fetch[TFeature](TFeature& cached, Func`2 factory)
   at Microsoft.AspNetCore.Http.DefaultHttpRequest.get_Protocol()
   at Microsoft.AspNetCore.Hosting.HostingRequestStartingLog.get_Item(Int32 index)
   at Microsoft.AspNetCore.Hosting.HostingRequestStartingLog.<GetEnumerator>d__11.MoveNext()
   at OpenTelemetry.Exporter.OpenTelemetryProtocol.Implementation.LogRecordExtensions.ToOtlpLog(LogRecord logRecord)
   at OpenTelemetry.Exporter.OpenTelemetryProtocol.Implementation.LogRecordExtensions.AddBatch(ExportLogsServiceRequest request, Resource processResource, Batch`1& logRecordBatch)
   at OpenTelemetry.Exporter.OtlpLogExporter.Export(Batch`1& logRecordBatch)
   at OpenTelemetry.BatchExportProcessor`1.ExporterProc()
   at System.Threading.Thread.StartCallback()

To avoid this issue, we can add options.ExportProcessorType = OpenTelemetry.ExportProcessorType.Simple; as @justkao mentioned in additonal context.

[cijothomas]

The original issue about scopes being accessed outside its lifecycle is fixed by #2026 We can close this issue.

[cijothomas]

Hi, I found this issue reproduced ASP.NET Core Instrumentation only on Windows. The same code is working fine on Mac but it crashed with the ObjectDisposedException on Windows. If I should file my case as a separate case, please let me know.

Here is the project file.

<Project Sdk="Microsoft.NET.Sdk.Web">

	<PropertyGroup>
		<TargetFramework>net6.0</TargetFramework>
		<ImplicitUsings>enable</ImplicitUsings>
		<Nullable>enable</Nullable>
	</PropertyGroup>

	<ItemGroup>
		<PackageReference Include="Microsoft.Data.Sqlite" Version="6.0.2" />
		<PackageReference Include="Microsoft.EntityFrameworkCore.Sqlite" Version="6.0.2" />
		<PackageReference Include="Microsoft.EntityFrameworkCore.Tools" Version="6.0.2">
			<IncludeAssets>runtime; build; native; contentfiles; analyzers; buildtransitive</IncludeAssets>
			<PrivateAssets>all</PrivateAssets>
		</PackageReference>
		<PackageReference Include="OpenTelemetry.Contrib.Instrumentation.EntityFrameworkCore" Version="1.0.0-beta2" />
		<PackageReference Include="OpenTelemetry.Exporter.Console" Version="1.2.0-rc2" />
		<PackageReference Include="OpenTelemetry.Exporter.OpenTelemetryProtocol" Version="1.2.0-rc2" />
		<PackageReference Include="OpenTelemetry.Exporter.OpenTelemetryProtocol.Logs" Version="1.0.0-rc9" />
		<PackageReference Include="OpenTelemetry.Extensions.Hosting" Version="1.0.0-rc9" />
		<PackageReference Include="OpenTelemetry.Instrumentation.AspNetCore" Version="1.0.0-rc9" />
		<PackageReference Include="OpenTelemetry.Instrumentation.Http" Version="1.0.0-rc9" />
		<PackageReference Include="OpenTelemetry.Instrumentation.SqlClient" Version="1.0.0-rc9" />
		<PackageReference Include="Swashbuckle.AspNetCore" Version="6.2.3" />
	</ItemGroup>
</Project>

Here is how to configure the OTLP exporter in ASP.NET Core startup code.

builder.Logging.AddOpenTelemetry(builder =>
{
    builder.IncludeFormattedMessage = true;
    builder.IncludeScopes = true;
    builder.ParseStateValues = true;
    builder.SetResourceBuilder(ResourceBuilder.CreateDefault().AddService("Hello-Otel").AddAttributes(tags))
        .AddOtlpExporter(options =>
        {
            options.Endpoint = new Uri("http://localhost:4317/");
        });
});

Here is how to output the log.

app.MapGet("/weatherforecast", (ILogger<Program> logger) =>
{
    logger.LogInformation("Log!!");
    return "example";
});

And exception details.

System.ObjectDisposedException
  HResult=0x80131622
  Message=IFeatureCollection has been disposed.
ObjectDisposed_ObjectName_Name
  Source=Microsoft.Extensions.Features
  StackTrace:
   at Microsoft.AspNetCore.Http.Features.FeatureReferences`1.ThrowContextDisposed()
   at Microsoft.AspNetCore.Http.Features.FeatureReferences`1.ContextDisposed()
   at Microsoft.AspNetCore.Http.Features.FeatureReferences`1.Fetch[TFeature,TState](TFeature& cached, TState state, Func`2 factory)
   at Microsoft.AspNetCore.Http.Features.FeatureReferences`1.Fetch[TFeature](TFeature& cached, Func`2 factory)
   at Microsoft.AspNetCore.Http.DefaultHttpRequest.get_Protocol()
   at Microsoft.AspNetCore.Hosting.HostingRequestStartingLog.get_Item(Int32 index)
   at Microsoft.AspNetCore.Hosting.HostingRequestStartingLog.<GetEnumerator>d__11.MoveNext()
   at OpenTelemetry.Exporter.OpenTelemetryProtocol.Implementation.LogRecordExtensions.ToOtlpLog(LogRecord logRecord)
   at OpenTelemetry.Exporter.OpenTelemetryProtocol.Implementation.LogRecordExtensions.AddBatch(ExportLogsServiceRequest request, Resource processResource, Batch`1& logRecordBatch)
   at OpenTelemetry.Exporter.OtlpLogExporter.Export(Batch`1& logRecordBatch)
   at OpenTelemetry.BatchExportProcessor`1.ExporterProc()
   at System.Threading.Thread.StartCallback()

To avoid this issue, we can add options.ExportProcessorType = OpenTelemetry.ExportProcessorType.Simple; as @justkao mentioned in additonal context.

Thanks for reporting this. This issue is about scopes being corrupted, but your scenario is exposing a different bug, likely related to #2905. Could you open a new issue, and use 2905 to report this, for better tracking and fix.