LoggerMessage / LogProperties logs Object type instead of value for properties when Redaction is disabled.

[sjwaight]

Description

When using the Redaction libraries with the LoggerMessage / LogProperties I had expected that disabling Redaction would cause any property marked with redaction attributes would simply be logged in the clear. Instead, the logger appears to log the Redaction Attribute Object Type and not the underlying property value.

Reproduction Steps

Consider this sample .NET Azure Function: https://github.com/sjwaight/azure-functions-net-log-redaction

When redaction is enabled ("EnableRedaction" set to 'true' or missing in local.settings.json) the following appears in the console logs:

{
 "EventId":165309363,
 "LogLevel":"Information",
 "Category":"SiliconValve.Demo.SampleWebFunc",
 "Message":"Person record processed.",
 "State":
  {
   "Message":"Microsoft.Extensions.Logging.ExtendedLogger\u002BModernTagJoiner",
   "{OriginalFormat}":"Person record processed.",
   "person.LastName":"Doe",
   "person.FirstName":"John",
   "person.DateOfBirth":"**REDACTED**",
   "person.City":"**REDACTED**",
   "person.Address":"**REDACTED**",
   "person.PhoneNumber":"**REDACTED**",
   "person.Email":"**REDACTED**"
  }
}

Now, if we disable Redaction (which removes the Redaction extension from Logging and Services) instead of seeing the clear text values for previously redacted properties we see:

{
 "EventId":165309363,
 "LogLevel":"Information",
 "Category":"SiliconValve.Demo.SampleWebFunc",
 "Message":"Person record processed.",
 "State":
  {
   "Message":"{OriginalFormat}=Person record processed.,person.LastName=Doe,person.FirstName=John,person.DateOfBirth=\u003Comitted\u003E ([SiliconValve.Demo.Redaction.DemoTaxonomy:SensitiveData]),person.City=\u003Comitted\u003E ([SiliconValve.Demo.Redaction.DemoTaxonomy:SensitiveData]),person.Address=\u003Comitted\u003E ([SiliconValve.Demo.Redaction.DemoTaxonomy:SensitiveData]),person.PhoneNumber=\u003Comitted\u003E ([SiliconValve.Demo.Redaction.DemoTaxonomy:SensitiveData]),person.Email=\u003Comitted\u003E ([SiliconValve.Demo.Redaction.DemoTaxonomy:SensitiveData])",
   "{OriginalFormat}":"Person record processed.","person.LastName":"Doe","person.FirstName":"John"
  }
}

Expected behavior

Expected that with redaction disabled that the output would be:

{
 "EventId":165309363,
 "LogLevel":"Information",
 "Category":"SiliconValve.Demo.SampleWebFunc",
 "Message":"Person record processed.",
 "State":
  {
   "Message":"Microsoft.Extensions.Logging.ExtendedLogger\u002BModernTagJoiner",
   "{OriginalFormat}":"Person record processed.",
   "person.LastName":"Doe",
   "person.FirstName":"John",
   "person.DateOfBirth":"01/01/1980",
   "person.City":"Sydney",
   "person.Address":"123 Main St",
   "person.PhoneNumber":"555-555-5555",
   "person.Email":"johndoe@example.biz"
  }
}

Actual behavior

Property values are not captured in clear text.

{
 "EventId":165309363,
 "LogLevel":"Information",
 "Category":"SiliconValve.Demo.SampleWebFunc",
 "Message":"Person record processed.",
 "State":
  {
   "Message":"{OriginalFormat}=Person record processed.,person.LastName=Doe,person.FirstName=John,person.DateOfBirth=\u003Comitted\u003E ([SiliconValve.Demo.Redaction.DemoTaxonomy:SensitiveData]),person.City=\u003Comitted\u003E ([SiliconValve.Demo.Redaction.DemoTaxonomy:SensitiveData]),person.Address=\u003Comitted\u003E ([SiliconValve.Demo.Redaction.DemoTaxonomy:SensitiveData]),person.PhoneNumber=\u003Comitted\u003E ([SiliconValve.Demo.Redaction.DemoTaxonomy:SensitiveData]),person.Email=\u003Comitted\u003E ([SiliconValve.Demo.Redaction.DemoTaxonomy:SensitiveData])",
   "{OriginalFormat}":"Person record processed.","person.LastName":"Doe","person.FirstName":"John"
  }
}

Regression?

Unknown as just starting to use extensions.

Known Workarounds

None that I'm aware of.

Configuration

<Project Sdk="Microsoft.NET.Sdk">
  <PropertyGroup>
    <TargetFramework>net8.0</TargetFramework>
    <AzureFunctionsVersion>v4</AzureFunctionsVersion>
    <OutputType>Exe</OutputType>
    <ImplicitUsings>enable</ImplicitUsings>
    <Nullable>enable</Nullable>
    <RootNamespace>func_secured_02</RootNamespace>
  </PropertyGroup>
</Project>

Running on Ubuntu Linux 22.04

.NET SDK:
Version: 8.0.203
Commit: 5e1ceea679
Workload version: 8.0.200-manifests.4e94be9c

Runtime Environment:
OS Name: ubuntu
OS Version: 22.04
OS Platform: Linux
RID: linux-x64
Base Path: /usr/share/dotnet/sdk/8.0.203/

.NET workloads installed:
There are no installed workloads to display.

Host:
Version: 8.0.3
Architecture: x64
Commit: 9f4b1f5d66

.NET SDKs installed:
6.0.415 [/usr/share/dotnet/sdk]
8.0.203 [/usr/share/dotnet/sdk]

.NET runtimes installed:
Microsoft.AspNetCore.App 6.0.23 [/usr/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 8.0.3 [/usr/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.NETCore.App 6.0.23 [/usr/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 8.0.3 [/usr/share/dotnet/shared/Microsoft.NETCore.App]

Other architectures found:
None

Environment variables:
Not set

global.json file:
Not found

Other information

No response

[xakep139]

Hello @sjwaight, if you don't call either EnableRedaction() or EnableEnrichment(), then it means that https://github.com/dotnet/extensions/blob/main/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLoggerFactory.cs won't be used.
Instead, the default LoggerFactory will be used, which is outside of the dotnet/extensions repo.
@joperezr @RussKie do you think this issue should be moved to the runtime repo? Maybe there's one already, actually

[dotnet-policy-service]

Tagging subscribers to this area: @dotnet/area-extensions-logging
See info in area-owners.md if you want to be subscribed.

[sjwaight]

Thanks @xakep139. In order to resolve this issue I would need to:

1. Build custom enrichers for any object I may want to log clear text properties for.
2. Enable enrichment (in my scenario in Program.cs) when Redaction is disabled to ensure the object properties are logged as expected.

Is this right?

I'm using this site as a reference.

[xakep139]

Apologies for the confusion, I took a closer look to the issue and ran the code locally.
The source-gen produces the code, that adds all sensitive properties into a separate collection.
When you use AddRedaction(), the ExtendedLoggerFactory enumerates this special collection. But since you haven't enabled the redaction, it doesn't emit those values as individual tags and in "Message" field you can see their values being masked.

The default .NET's LoggerFactory enumerates only state itself. That's why you see only non-sensitive "person.LastName" and "person.FirstName" fields.

@geeknoid I believe this is intended behavior, can you please confirm that?

[tarekgh]

@xakep139 should this issue moved back to the extensions repo then? I transferred it back to the extensions repo as I am seeing this needs to be fixed there or suggest what exactly is expected from the runtime to do. Thanks!