Pooled objects in attibutes (working with Microsoft.Extensions.ComplianceRedaction) about opentelemetry-dotnet HOT 11 OPEN

Unless I'm missing something, I don't see how the BufferLogAttributes() method can prevent the issue.

I've read the associated issue mentioned in the method comment but we are not in the same case.
In 2905, the AttributesData property needed to be enumerated and copied because it was of type HostingRequestStartingLog and the enumeration need to be sync. However all the object in the KeyValuePair<string,object> are objects which does not have lifetime scope. Most of them are just good ol' primitive types.

Here the difference is that it is the Value property of KeyValuePair<string,object> which is scoped and the method don't freeze or copy its state.

Something like this would prevent the issue instead:

private void BufferLogAttributes()
{
    var attributes = this.AttributeData;
    if (attributes == null || attributes == this.AttributeStorage)
    {
        return;
    }

    var attributeStorage = this.AttributeStorage ??= new List<KeyValuePair<string, object?>>(attributes.Count);

    foreach(var (key, value) in attributes)
    {
        if(value is IDisposable || value is IResettable)
        {
            value = value.ToString();
        }
        attributeStorage.Add(KeyValuePair<string,object?>.Create(key, value));
    }

    this.AttributeData = attributeStorage;
}

from opentelemetry-dotnet.

Thanks!
I have re-added bug label, will reachout to @CodeBlanch to comment further.

from opentelemetry-dotnet.

My employer has some logging code that creates logging-specific wrappers for application-specific objects. These objects have limited lifetime and are not safe to access across threads. The wrappers exist to provide ToString() for logs but skip all string formatting if ToString() is not called. These wrappers do not implement IDisposable, because they just reference the application-specific objects rather than own those; and they do not implement Microsoft.Extensions.ObjectPool.IResettable, because they antedate .NET 8.0.

from opentelemetry-dotnet.

You can use a OTEL Collector and OTLP Exporter to show the repro. You may use this example app - https://github.com/open-telemetry/opentelemetry-dotnet/blob/main/examples/Console/TestOtlpExporter.cs#L16

The SDK's ILogger integration is expected to copy all attributes in the sync path itself, so if this is not working, it is likely a bug. But need to see a minimal repro to confirm.

from opentelemetry-dotnet.

Here's a repro:
https://github.com/NatMarchand/repro-dotnet-log-redactor/blob/main/ConsoleApp1/Program.cs
On my computer, I often (not every time) get a NullReferenceException in Microsoft.Extensions.Telemetry.dll!Microsoft.Extensions.Logging.JustInTimeRedactor.ToString
as the inner _redactor is null because the JustInTimeRedactor is reset when it gets back to the pool.
The issue is on a separated thread OpenTelemetry-BatchExportProcessor-OtlpLogExporter and the stack trace is the following:

Microsoft.Extensions.Telemetry.dll!Microsoft.Extensions.Logging.JustInTimeRedactor.ToString(string format, System.IFormatProvider formatProvider) Line 53
Microsoft.Extensions.Telemetry.dll!Microsoft.Extensions.Logging.JustInTimeRedactor.ToString() Line 45
OpenTelemetry.Exporter.OpenTelemetryProtocol.dll!OpenTelemetry.Internal.TagTransformer<OpenTelemetry.Proto.Common.V1.KeyValue>.TryTransformTag(System.Collections.Generic.KeyValuePair<string, object> tag, out OpenTelemetry.Proto.Common.V1.KeyValue result, int? maxLength) Line 73
OpenTelemetry.Exporter.OpenTelemetryProtocol.dll!OpenTelemetry.Exporter.OpenTelemetryProtocol.Implementation.OtlpLogRecordTransformer.ToOtlpLog(OpenTelemetry.Logs.LogRecord logRecord) Line 152
OpenTelemetry.Exporter.OpenTelemetryProtocol.dll!OpenTelemetry.Exporter.OpenTelemetryProtocol.Implementation.OtlpLogRecordTransformer.BuildExportRequest(OpenTelemetry.Proto.Resource.V1.Resource processResource, OpenTelemetry.Batch<OpenTelemetry.Logs.LogRecord> logRecordBatch) Line 42
OpenTelemetry.Exporter.OpenTelemetryProtocol.dll!OpenTelemetry.Exporter.OtlpLogExporter.Export(OpenTelemetry.Batch<OpenTelemetry.Logs.LogRecord> logRecordBatch) Line 55
OpenTelemetry.dll!OpenTelemetry.BatchExportProcessor<OpenTelemetry.Logs.LogRecord>.ExporterProc()	

from opentelemetry-dotnet.

On my computer, I often (not every time) get a NullReferenceException in Microsoft.Extensions.Telemetry.dll!Microsoft.Extensions.Logging.JustInTimeRedactor.ToString

This is something to be reported to the owners of Microsoft.Extensions.Telemetry itself.

The issue is on a separated thread OpenTelemetry-BatchExportProcessor-OtlpLogExporter and the stack trace is the following:

Are you seeing this exception escaping or its caught by OTLPExporter and proceeds without crashing the app?

https://github.com/open-telemetry/opentelemetry-dotnet/blob/main/src/Shared/TagTransformer.cs#L63-L74 is the place where the exception is thrown (and caught correctly as well). I am guessing the issue is with the JustInTimeRedactor itself, that it is incorrectly assuming the state can remain after the Log call is over..... (I don't have cycles to take a deeper look to confirm this...)

@CodeBlanch who fixed similar issue in the OTel SDK itself.

from opentelemetry-dotnet.

I removed the bug tag. When I saw "pool", I initially assumed the LogRecord pooling in this repo, but since then, it is clear that you were referring to the pooling done inside JustInTimeRedactor.

from opentelemetry-dotnet.

This is something to be reported to the owners of Microsoft.Extensions.Telemetry itself.

I'll try to report the issue on the other repo, but as you said at first glance it's ok to assume that after leaving Log in OpenTelemetryLogger the attributes are safe to collect as they should be "frozen" or projected to something safe. Like I do in my workaround.

Are you seeing this exception escaping or its caught by OTLPExporter and proceeds without crashing the app?

I catch it because for debugging purpose I configured VS to catch any CLR exception. With regular settings, it indeed doesn't break. However, in such case I don't have the attribute flowing in my log pipeline.

from opentelemetry-dotnet.

Hey @cijothomas, thanks for looking into this. As explained by @geeknoid in this comment we believe that the issue lies in OTel here as it shouldn't try to call ToString on object references that it keeps around as it cannot be guaranteed that doing so is safe (objects might be disposed, nulled out, or simply in a state that is no longer valid).

from opentelemetry-dotnet.

Hey @cijothomas, thanks for looking into this. As explained by @geeknoid in this comment we believe that the issue lies in OTel here as it shouldn't try to call ToString on object references that it keeps around as it cannot be guaranteed that doing so is safe (objects might be disposed, nulled out, or simply in a state that is no longer valid).

As suggested here, OTel SDK is expected to read everything off the state in the sync path itself. If it is not working, then it is a bug in OTel .NET sdk. Would you make a minimal repro app to confirm if this is indeed an issue in OTel .NET?
OTel code section doing the buffering: https://github.com/open-telemetry/opentelemetry-dotnet/blob/main/src/OpenTelemetry/Logs/LogRecord.cs#L475-L485

from opentelemetry-dotnet.

I don't believe value is IDisposable || value is IResettable will recognize all limited-lifetime types that can be logged.

from opentelemetry-dotnet.