Microsoft.Extensions.Compliance.Redaction.NullRedactor doesn't seem to work

[erwinkramer]

Description

Please see https://github.com/erwinkramer/bank-api/blob/main/BankApi.Service/Implementation/Model.AccessLog.cs

If i change RestrictedData to UnrestrictedData, i'm expecting the property to be visible in my logging, because in https://github.com/erwinkramer/bank-api/blob/main/BankApi.Service/Defaults/Builder.Compliance.cs i set UnrestrictedData with a NullRedactor.

Reproduction Steps

1. Clone the repo: https://github.com/erwinkramer/bank-api/tree/main
2. Debug in Aspire mode
3. Run the test at this line: http://{{host}}/{{apiVersion}}/teller

Expected behavior

NullRedactor should just return the value as-is, as documented.

Actual behavior

NullRedactor acts like the ErasingRedactor.

Regression?

No response

Known Workarounds

No response

Configuration

Not sure if specific to a version

.NET SDK:
Version: 9.0.100
Commit: 59db016f11
Workload version: 9.0.100-manifests.3068a692
MSBuild version: 17.12.7+5b8665660

Runtime Environment:
OS Name: Windows
OS Version: 10.0.26100
OS Platform: Windows
RID: win-x64
Base Path: C:\Program Files\dotnet\sdk\9.0.100\

Other information

No response

[RussKie]

/cc: @dotnet/dotnet-extensions-compliance

[amadeuszl]

Checking this one

[amadeuszl]

I can reproduce the issue. Seems like this problem is related to Aspire Dashboards as they do not show any properties marked with DataClassificationAttribute for structured logs at all. When you check how structured logs are looking with eg. JsonConsole they look as they should:

{
    "EventId": 964789645,
    "LogLevel": "Information",
    "Category": "API logger",
    "Message": "Access received for user to teller data",
    "State": {
        "Message": "Microsoft.Extensions.Logging.ExtendedLogger\u002BModernTagJoiner",
        "{OriginalFormat}": "Access received for user to {dataType} data",
        "accessLog.AuthenticationType": "TEST", // no classification and only this one is visible in Aspire Dashboard
        "dataType": "teller",
        "accessLog.IShouldNotSeeIt": "", // restricted with ErasingRedactor
        "accessLog.TestField": "***", // tested with custom redactor for confidebtial
        "accessLog.UserId": "myId:accessLog.UserId" // unrestricted with NullRedactor
    }
}

How it looks in Aspire:

Next, I'm going to check supported scenarios and what we can do for Aspire to make it work. We may need to create an issue on Aspire.
@eerhardt can you take a look before we go to Aspire repo?

[eerhardt]

The Aspire Dashboard displays the logs that get sent to it via OTLP (open telemetry logging protocol).

It would be good to understand what is getting emitted out of the app through the OTLP exporter. Perhaps there is something in OpenTelemetry causing the problem.

cc @JamesNK

[JamesNK]

Aspire dashboard blindly displays what is sent to it. The problem must happen before the log is received by the dashboard.

[amadeuszl]

Sorry for late response I was OOO for most of the December.

I was able to track down the issue. It's concurrency issue between ExtendedLogger and logic behind logging in OpenTelemetry.
ExtendedLogger builds the logging state of type ModernTagJoiner, it has RedactedTagArray. RedactedTagArray which is KeyValuePair list has values of objects of JustInTimeRedactor.

So now, ExtendedLogger will call LoggerLog() on all Loggers, one of them is OpenTelemetryLogger. It relies on BatchLogRecordExportProcessor, in the end it puts the attributes into buffer in BatchExportProcessor and runs exportTrigger.Set() to trigger execution on a different thread in ExporterProc. It causes the export to run on a different thread, while first thread with ExtendedLogger will continue execution, which ends up cleaning up the state by returning object to the pool thus cleaning up the redactors here.

The result is the race condition, redactors are cleaned before OTLP exporter writes attributes, to be precise it results in NullReferenceException on Redactor object in JustInTimeRedactor.

Potential solutions

1. Not use batch exporter, but I believe it has to be used with OTLP Exporter
2. Delay cleaning of the state and returning object to pool
3. Change the pattern in which JIT Redactor is passed to inner Loggers.

[amadeuszl]

That issue was already reported #5080 and it's being investigated in OTEL open-telemetry/opentelemetry-dotnet#5276. I think we can keep this issue here open, to track efforts on our end.

@erwinkramer suggested workaround from 5276 for now is:

Edit: I got around this issue with a workaround, by using a Processor and intercepting the redacted attribute (we only have a handful), removing it from Attributes and re-adding it as a ToString() value. Hopefully the SDK can natively support this soon :)