[BUG] OpenTelemetry-AzureMonitor-Exporter throws when LogLevel of Microsoft.AspNetCore is Information or lower

[davidelettieri]

Library name and version

Azure.Monitor.OpenTelemetry.Exporter 1.0.0-beta.7

Describe the bug

When using open telemetry logging with Azure Monitor Exporter if the LogLevel of Microsoft.AspNetCore is Information or lower, an error is logged in the debug windows and application logs are not sent to azure monitor.

For example, when calling an endpoint like this one, the log in not appearing on azure monitor and an exception is logged.

app.MapGet("/sample-endpoint", (ILogger<Program> logger) =>
{
    logger.LogInformation("Sample log message");

    return Results.NoContent();
});

Expected behavior

Azure Monitor Exporter should not give error and all logs should be available in azure monitor

Actual behavior

An exception is thrown and the log is not sent to azure monitor.

OpenTelemetry-AzureMonitor-Exporter - EventId: [2], EventName: [WriteError], Message: [FailedToExport - System.ObjectDisposedException: IFeatureCollection has been disposed.
Object name: 'Collection'.
   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](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()+MoveNext()
   at Azure.Monitor.OpenTelemetry.Exporter.Internals.LogsHelper.ExtractProperties(String& message, IDictionary`2 properties, IReadOnlyCollection`1 stateDictionary)
   at Azure.Monitor.OpenTelemetry.Exporter.Internals.LogsHelper.GetMessageAndSetProperties(LogRecord logRecord, IDictionary`2 properties)
   at Azure.Monitor.OpenTelemetry.Exporter.Models.MessageData..ctor(Int32 version, LogRecord logRecord)
   at Azure.Monitor.OpenTelemetry.Exporter.Internals.LogsHelper.OtelToAzureMonitorLogs(Batch`1 batchLogRecord, AzureMonitorResource resource, String instrumentationKey)
   at Azure.Monitor.OpenTelemetry.Exporter.AzureMonitorLogExporter.Export(Batch`1& batch)]

Reproduction Steps

Project with a minimal setup to experience the error

https://github.com/davidelettieri/open-telemetry-sample

Environment

Microsoft Visual Studio Enterprise 2022 Version 17.4.4

.NET SDK:
 Version:   7.0.102
 Commit:    4bbdd14480

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.22000
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Program Files\dotnet\sdk\7.0.102\

Host:
  Version:      7.0.2
  Architecture: x64
  Commit:       d037e070eb

.NET SDKs installed:
  6.0.406 [C:\Program Files\dotnet\sdk]
  7.0.102 [C:\Program Files\dotnet\sdk]

.NET runtimes installed:
  Microsoft.AspNetCore.App 6.0.13 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 6.0.14 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 7.0.2 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 5.0.17 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 6.0.9 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 6.0.13 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 6.0.14 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 7.0.2 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.WindowsDesktop.App 5.0.17 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 6.0.13 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 6.0.14 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 7.0.2 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]

Other architectures found:
  x86   [C:\Program Files (x86)\dotnet]
    registered at [HKLM\SOFTWARE\dotnet\Setup\InstalledVersions\x86\InstallLocation]

Environment variables:
  Not set

global.json file:
  Not found

[ghost]

Thank you for your feedback. This has been routed to the support team for assistance.

[vishweshbankwar]

@davidelettieri - Thanks for reporting this. However, I am not able to repro using your example. I can see the logger.LogInformation("Sample log message"); getting logged successfully.

[davidelettieri]

@vishweshbankwar thanks for checking the issue. The error shows up only when the LogLevel for Microsoft.AspNetCore is Information or lower and I accidentally committed the appsettings with level Warning.

Now the repo is updated with the LogLevel required to trigger the issue. You can change the loglevel back to Warning to see the logs flowing again.

[ghost]

Thanks for the feedback! We are routing this to the appropriate team for follow-up. cc @cijothomas, @reyang, @rajkumar-rangaraj, @TimothyMothra, @vishweshbankwar.

Issue Details

---

Library name and version

Azure.Monitor.OpenTelemetry.Exporter 1.0.0-beta.7

Describe the bug

When using open telemetry logging with Azure Monitor Exporter if the LogLevel of Microsoft.AspNetCore is Information or lower, an error is logged in the debug windows and application logs are not sent to azure monitor.

For example, when calling an endpoint like this one, the log in not appearing on azure monitor and an exception is logged.

app.MapGet("/sample-endpoint", (ILogger<Program> logger) =>
{
    logger.LogInformation("Sample log message");

    return Results.NoContent();
});

Expected behavior

Azure Monitor Exporter should not give error and all logs should be available in azure monitor

Actual behavior

An exception is thrown and the log is not sent to azure monitor.

OpenTelemetry-AzureMonitor-Exporter - EventId: [2], EventName: [WriteError], Message: [FailedToExport - System.ObjectDisposedException: IFeatureCollection has been disposed.
Object name: 'Collection'.
   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](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()+MoveNext()
   at Azure.Monitor.OpenTelemetry.Exporter.Internals.LogsHelper.ExtractProperties(String& message, IDictionary`2 properties, IReadOnlyCollection`1 stateDictionary)
   at Azure.Monitor.OpenTelemetry.Exporter.Internals.LogsHelper.GetMessageAndSetProperties(LogRecord logRecord, IDictionary`2 properties)
   at Azure.Monitor.OpenTelemetry.Exporter.Models.MessageData..ctor(Int32 version, LogRecord logRecord)
   at Azure.Monitor.OpenTelemetry.Exporter.Internals.LogsHelper.OtelToAzureMonitorLogs(Batch`1 batchLogRecord, AzureMonitorResource resource, String instrumentationKey)
   at Azure.Monitor.OpenTelemetry.Exporter.AzureMonitorLogExporter.Export(Batch`1& batch)]

Reproduction Steps

Project with a minimal setup to experience the error

https://github.com/davidelettieri/open-telemetry-sample

Environment

Microsoft Visual Studio Enterprise 2022 Version 17.4.4

.NET SDK:
 Version:   7.0.102
 Commit:    4bbdd14480

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.22000
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Program Files\dotnet\sdk\7.0.102\

Host:
  Version:      7.0.2
  Architecture: x64
  Commit:       d037e070eb

.NET SDKs installed:
  6.0.406 [C:\Program Files\dotnet\sdk]
  7.0.102 [C:\Program Files\dotnet\sdk]

.NET runtimes installed:
  Microsoft.AspNetCore.App 6.0.13 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 6.0.14 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 7.0.2 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 5.0.17 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 6.0.9 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 6.0.13 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 6.0.14 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 7.0.2 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.WindowsDesktop.App 5.0.17 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 6.0.13 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 6.0.14 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 7.0.2 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]

Other architectures found:
  x86   [C:\Program Files (x86)\dotnet]
    registered at [HKLM\SOFTWARE\dotnet\Setup\InstalledVersions\x86\InstallLocation]

Environment variables:
  Not set

global.json file:
  Not found

Author:	davidelettieri
Assignees:	-
Labels:	Service Attention, Client, customer-reported, question, needs-team-attention, Monitor - Exporter
Milestone:	-

[navba-MSFT]

Adding service team to look into this. @cijothomas, @reyang, @rajkumar-rangaraj, @TimothyMothra, @vishweshbankwar

[vishweshbankwar]

@davidelettieri - Able to repro this now, Thanks!. Will work on fixing missing logs issue. Note that error you see is due to the way ASP.NET Core is logging (needs separate investigation outside of Azure Monitor Exporter). You might continue to see this error. However, it should not impact other logs as it is doing currently (After the fix).

[cijothomas]

open-telemetry/opentelemetry-dotnet#2905

[vishweshbankwar]

@davidelettieri The fix for this will be included in next release. In the meantime you can set options.ParseStateValues = true to workaround this issue.