fix: [LogProperties] avoid early ToString of Nullable Properties

[rwoll]

Fixes #5411.

Prior to this PR, when using the [LogProperties] on an object with nullable-typed properties (e.g. DateTime?), the nullable-typed properties were being forced to string before being added to the state.TagArray while their non-nullable type (DateTime) remained DateTime-typed in the TagArray. In our environment, this manifested as timestamp columns having different formats in logs!

Looking at the issue from a code perspective, given the following user-written code:

using Microsoft.Extensions.Logging;

public partial class MyLogger
{
  [LoggerMessage(
    EventId = 1,
    Level = LogLevel.Information,
    Message = "Event triggered!"
  )]
  public static partial void MyLogMessage(ILogger logger, [LogProperties] MyEvent myEvent);

  public class MyEvent
  {
    public DateTime TimeStamp { get; set; }
    public DateTime? TimeStampNullable { get; set; }
  }
}

In the autogenerated code, myEvent.TimeStamp field got added to the TagArray as a DateTime (same type as it was in the event), but myEvent.TimeStampNullable is added to the TagArray as a string:

        state.TagArray[2] = new("myEvent.TimeStamp", myEvent?.TimeStamp);
        state.TagArray[1] = new("myEvent.TimeStampNullable", myEvent?.TimeStampNullable?.ToString()); // <--- LINE WITH BUG

This PR:

1. Adds a test that originally repro'd the broken behavior.
2. Introduces a potential fix.

The root of the issue appears to have been in the determination of ImplementsISpanFormattable.

In the ShouldStringify* methods, p for System.Nullable<DateTime> was not passing the p.ImplementsISpanFormattable check:

       static bool ShouldStringifyParameter(LoggingMethodParameter p)
        {
            if (p.IsReference)
            {
                // pass object as-is
                return false;
            }

            if (p.ImplementsISpanFormattable)
            {
                // pass object as-is, it will be formatted directly into the output buffer
                return false;
            }

            if (!p.Type.Contains("."))
            {
                // no . means this is a primitive type, pass as-is 
                return false;
            }

            // should convert the object to a string before calling the Log function
            return true;
        }

This was b/c the computation of that property was not being computed on the type wrapped by Nullable.

Suggested Followup

While the original bug manifested as string formatting discrepancies, a test asserting the string result of the log is insufficient to robustly test. Asserting the generated output is helpful (as we've also added here), but may easily be incorrectly re-baselined.

To help create a more robust test in the future, I recommend:

1. Adding a test against the Type of each value in state.TagArray
2. Adding tests directly for TypeSymbolExtensions.{ImplementsIConvertible,ImplementsIFormattable,ImplementsISpanFormattable and the newly introduced helper, TypeSymbolExtensions.GetPossiblyNullWrappedType.

[rwoll]

@dariusclay - I've updated this PR to address:

1. The need to make type-assertions around what ends up in state to properly test the original issue.
2. Introduce a potential fix to the original issue!

Reviewing the CI failures, they are expected at the moment (and I will resolve once you've done an initial review pass to let me know if this PR is headed in the correct direction):

1. Some style/formatting bits.
2. Golden snapshot tests that are expected to change due to the introduction of StateTypes in the FakeLogRecord.

A few questions/reservations about what I have so far:

1. I'm not a fan of how I've bolted on the StateTypes. Do you have suggestions for making this cleaner?
2. As for the literal fix, is this the correct place to do the resolution to the underlying type? How will this interact with the experimental Transitive annotation feature?

[rwoll]

Thanks for the review pass @RussKie. I plan to address/update in the next 24 hours.

[rwoll]

@RussKie - I've addressed a few of the comments and errors. However, I'm a bit stuck:

• src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogRecord.cs(70,20): error LA0003: (NETCORE_ENGINEERING_TELEMETRY=Build) Newly added symbol 'Microsoft.Extensions.Logging.Testing.FakeLogRecord.StateTypes' must be marked as experimental - what's the proper fix for this? The sybmol is in a test file, why does it need to be marked experimental?
• Re-baselining the snapshots - how do I re-baseline the failing snapshot tests across all platforms?

Full disclosure: I'm reaching the end of my allocated time to work on this issue so depending on how much further work is required, I may not be able to finish this PR off. However, I'm happy for your team to take it over when you have time, or — if it's easier — close the PR, and then y'all can create a fresh one when it comes time (either re-using bits here or taking a fresh pass).

[RussKie]

@RussKie - I've addressed a few of the comments and errors. However, I'm a bit stuck:

• src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogRecord.cs(70,20): error LA0003: (NETCORE_ENGINEERING_TELEMETRY=Build) Newly added symbol 'Microsoft.Extensions.Logging.Testing.FakeLogRecord.StateTypes' must be marked as experimental - what's the proper fix for this? The sybmol is in a test file, why does it need to be marked experimental?

You're adding a new public API, which is not allowed without an API proposal/review/etc.
Do these new API need to be public?

• Re-baselining the snapshots - how do I re-baseline the failing snapshot tests across all platforms?

You need to run the tests locally and accept the new snapshot (via the diff/merge tool or by manually renaming files).
For these tests the snapshots must be identical across all platforms.

Full disclosure: I'm reaching the end of my allocated time to work on this issue so depending on how much further work is required, I may not be able to finish this PR off. However, I'm happy for your team to take it over when you have time, or — if it's easier — close the PR, and then y'all can create a fresh one when it comes time (either re-using bits here or taking a fresh pass).

Noted. @dariusclay please prioritise this review.

[rwoll]

You're adding a new public API, which is not allowed without an API proposal/review/etc.

OH, I didn't realize the Testing.* packages are actually shipped, but now see that they are (https://learn.microsoft.com/en-us/dotnet/api/microsoft.extensions.logging.testing.fakelogrecord?view=net-8.0). Neat! And especially neat that the analyzers alert on it!

Do these new API need to be public?

No, these bits don't need to be public. And if they do, I'm not a fan of the API I've introduced. It was simply a "bolt-on" to repro/test. Not intended to ship to production. If you or @dariusclay think we need to ship to production, then I'd like to brainstorm a cleaner API. Even if they are changed to be internal-implementation only, the implementation would need to be cleaned up from what I have it at this iteration.

[RussKie]

OH, I didn't realize the Testing.* packages are actually shipped, but now see that they are (learn.microsoft.com/en-us/dotnet/api/microsoft.extensions.logging.testing.fakelogrecord?view=net-8.0). Neat! And especially neat that the analyzers alert on it!

Yes, this is a public package that helps simplifying telemetry-related testing --> https://github.com/dotnet/extensions/tree/main/src/Libraries/Microsoft.Extensions.Diagnostics.Testing.
Essentially, everything located under https://github.com/dotnet/extensions/tree/main/src/Libraries folder is shipped to public.
Our tests are located under the https://github.com/dotnet/extensions/tree/main/test folder.

Do these new API need to be public?

No, these bits don't need to be public. And if they do, I'm not a fan of the API I've introduced. It was simply a "bolt-on" to repro/test. Not intended to ship to production. If you or @dariusclay think we need to ship to production, then I'd like to brainstorm a cleaner API. Even if they are changed to be internal-implementation only, the implementation would need to be cleaned up from what I have it at this iteration.

So, if those changes aren't required - please revert those and only keep the necessary changes.

[dariusclay]

@rwoll thank you for starting this PR!

[rwoll]

@dariusclay / @RussKie - I've backed out the changed to the public API and added some more tests. CI is now green. Let me know once you've reviewed.

I won't get to it, but I also recommend (either as a prereq for this to merge) or as a followup:

• Adding a test directly against the Type of each value in state.TagArray. We're incidentally testing it with my test additions, but a more targeted test would be ideal.
• Adding tests directly for TypeSymbolExtensions.{ImplementsIConvertible,ImplementsIFormattable,ImplementsISpanFormattable and the newly introduced helper, TypeSymbolExtensions.GetPossiblyNullWrappedType. This is incidentally being tested with my test additions, but not directly.

Thanks!

[dariusclay]

@RussKie everything looks good here to me. We can follow up after this merge to include additional tests.

[RussKie]

Thank you @rwoll.

Thank you @dariusclay. Could you please raise a tracking issue for follow up on the outstanding work?