Strong type support in Microsoft.Extensions.Logging

[reyang]

Problem Description

In a large codebase, there are cases people want to log with existing types defined for business logic (and these types might come from a 3rd party library which is not controlled by the dev), rather than having to invent another type (and do the mapping) or write lots of boilerplate code.

public struct Food
{
    public string Name { get; set; }
    public double Price { get; set; }
}

logger.Eat(new Food { Name = "artichoke", Price = 3.99 });

In order for the above code to work, one has to write the boilerplate code as follows, and will start to hit performance issue if there are more than 6 fields (based on the current implementation).

using System;
using Microsoft.Extensions.Logging;

public static class LoggerExtensions
{
    private static readonly Action<ILogger, Food, Exception> _eat = LoggerMessage.Define<Food>(
        LogLevel.Information,
        new EventId(1, nameof(Eat)),
        "Eat (Food = {food})."); // message template, not interpolated string

    public static void Eat(this ILogger logger, Food food)
    {
        _eat(logger, food, null);
    }
}

The Ask

Provide a vendor agnostic way for the user to log strong typed objects without having to write boilerplate code, yet with good/reasonable performance.

public struct Food
{
    public string Name { get; set; }
    public double Price { get; set; }
}

public class Dog
{
    public string Name { get; set; }
    public int Age { get; set; }
}

logger.Eat(new Food { Name = "Artichoke", Price = 3.99 });
logger.Log(new Dog { Name = "Labrador Retriever", Age = 2 });

Additional Information

• It is not clear if this should part of .NET runtime, or it should be provided by 3rd party (e.g. OpenTelemetry). I guess one goal could be - any existing provider (e.g. ConsoleLoggerProvider) should just work.
• This potentially could leverage compile-time logging source generation.
• Additional scenario 1
• Additional scenario 2

[ghost]

Tagging subscribers to this area: @maryamariyan
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Problem Description

In a large codebase, there are cases people want to log with existing types defined for business logic, rather than having to invent another type (and do the mapping) or write lots of boilerplate code.

public struct Food
{
    public string Name { get; set; }
    public double Price { get; set; }
}

logger.Eat(new Food { Name = "artichoke", Price = 3.99 });

In order for the above code to work, one has to write the boilerplate code as follows, and will start to hit performance issue if there are more than 6 fields (based on the current implementation).

using System;
using Microsoft.Extensions.Logging;

public static class LoggerExtensions
{
    private static readonly Action<ILogger, Food, Exception> _eat = LoggerMessage.Define<Food>(
        LogLevel.Information,
        new EventId(1, nameof(Eat)),
        "Eat (Food = {food})."); // message template, not interpolated string

    public static void Eat(this ILogger logger, Food food)
    {
        _eat(logger, food, null);
    }
}

The Ask

Provide a vendor agnostic way for the user to log strong typed objects without having to write boilerplate code, yet with good/reasonable performance.

public struct Food
{
    public string Name { get; set; }
    public double Price { get; set; }
}

public class Dog
{
    public string Name { get; set; }
    public int Age { get; set; }
}

logger.Eat(new Food { Name = "Artichoke", Price = 3.99 });
logger.Log(new Dog { Name = "Labrador Retriever", Age = 2 });

Additional Information

• It is not clear if this should part of .NET runtime, or it should be provided by 3rd party (e.g. OpenTelemetry). I guess one goal could be - any existing provider (e.g. ConsoleLoggerProvider) should just work.
• This potentially could leverage compile-time logging source generation.

Author:	reyang
Assignees:	-
Labels:	untriaged, area-Extensions-Logging
Milestone:	-

[yecril71pl]

The introduction says that named parameters can be used to attach properties to log entries.
I would like the opposite syntax to work in the following scenarios:

const string format = "Customer {Name} #{Serial} entered the shop.  {Name} left {Mood}.";

var customer = new { Name = "Joe", Sex = Sex .Male, Age = 50, Serial = 33 };
logger .LogInformation (format, customer with { Mood = Mood .Satisfied });

var customer = new Customer { Name = "Joe", Sex = Sex .Male, Age = 50, Serial = 33 };
customer .Mood = Mood .Satisfied;
logger .LogInformation (format, customer);

var customer = new Dictionary < string, object >
 { ["Name"] = "Joe", ["Sex"] = Sex .Male, ["Age"] = 50, ["Serial"] = 33 };
customer ["Mood"] = Mood .Satisfied;
logger .LogInformation (format, customer);

All these calls should translate to

logger .Log
 (LogLevel .Information, default, null,
 format, "Joe", 33, "Joe", Mood .Satisfied);

Implementing this using reflexion bumps into the following problem: support for enumerating parameter islands in a message format string, which was never officially supported, was removed from the public API in ASP.NET 3, so any independent solution would have to rely on undocumented features or contain a copy or a replica of internal code.

[maryamariyan]

To add strong type support, consider the Food struct in the issue description. If developer added an annotation like StructuredLogMessage shown below to a partial Foo struct, the logging source generator could potentially code generate the remaining code portion.

[StructuredLogMessage]
public partial struct Food
{
    public string Name { get; set; }
    public double Price { get; set; }
}

logger.Eat(new Food { Name = "artichoke", Price = 3.99 });

internal partial struct Food : IReadOnlyList<KeyValuePair<string, object?>>
{
    public int Count => 2;

    public KeyValuePair<string, object?> this[int index]
    {
        get => index switch
            {
                0 => new KeyValuePair<string, object?>(nameof(Name), Name),
                1 => new KeyValuePair<string, object?>(nameof(Price), Price),
                _ => throw new IndexOutOfRangeException(nameof(index)),
            };

    }

    // if developer does not override ToString themselves the generator would generate this as default ToString
    // Name and Price in this case are the public properties presented in Food
    public override string ToString()
    {
        return $"{nameof(Name)}={Name}, {nameof(Price)}={Price}";
    }
}

@davidfowl @reyang @noahfalk do you think if we added this to the logging source generator it would be something that could be adopted for open telemetry as-is?

[reyang]

@maryamariyan One challenge with this approach - if the type is not controlled by the developer.

Let's say if Food is coming from a third-party library and the developer would want to log it.

[geeknoid]

@maryamariyan This unfortunately only works if you own the types in question. In addition, you would need something to trigger the code generation (an attribute somewhere), and the type would need to be partial to allow code gen additions.

[reyang]

@davidfowl @noahfalk and I were discussing offline and this seems to be a viable alternative:

// Food is from a 3rd party lib where we have no control over
// We can use a surrogate struct

[StructureLogMessage]
public partial struct FoodLogMessage : LogMessage<Food> { }

[yecril71pl]

Besides, the attribute name StructuredLogMessage would be misleading in that Food is not a message.

OTOH, the type FoodLogMessage is precisely what this request is asking to avoid:

rather than having to invent another type

and that means this request will be effectively refused.

[reyang]

Additional Scenario 1 - Custom Event Types

In this scenario, strong-types are defined to represent "custom events". Each "custom event" can be considered as a self-contained log entry.

• It is common for large organization to have a "core/infra" team defining/owning the log schema.
• The dev team has control over these "custom event" types (e.g. they can change the code).
• There might be inheritance among these "custom event" types.

A possible experience might look like:

// this type is owned by the developer
[StructuredLogMessage(
    EventId = 100,
    LogLevel = LogLevel.Critical,
    Message = "A `{ProductType}` (#{ProductCode}) recall notice was published for `{BrandName} {ProductDescription}` produced by `{CompanyName}` ({RecallReasonDescription}).")]
public partial struct FoodRecallLogRecord
{
    public string BrandName;
    public string ProductDescription;
    public string ProductType;
    public int ProductCode;
    public string RecallReasonDescription;
    public string CompanyName;
}

logger.Log<FoodRecallLogRecord>(new
{
    BrandName = "Contoso",
    ProductDescription = "Salads",
    ProductType = "Food & Beverages",
    ProductCode = 123,
    RecallReasonDescription = "due to a possible health risk from Listeria monocytogenes",
    CompanyName = "Contoso Fresh Vegetables, Inc.",
});

[reyang]

Additional Scenario 2 - Log with Business Model Types

In this scenario, strong-types are coming from business model which are not tight to logs.

• It is common for developers to log something that involves complex business types.
• The developer could have no control over these business types - e.g. these types could come from a 3rd party library, so the dev team cannot change the code.
• Business types might have nested structures or even recursive references (loops, circular dependencies).
• A log entry might contain multiple business types.

A possible experience might look like:

// this type is not owned by the developer (e.g. coming from a 3rd party library)
public class Food
{
    public string BrandName;
    public string ProductDescription;
    public string ProductType;
    public string CompanyName;
}

// this type is owned by the developer
[StructuredLogMessage(
    EventId = 100,
    LogLevel = LogLevel.Critical]
public partial class FoodRecallLogRecord
{
    [StructuredLogMessage]
    public Food Food;
    public int ProductCode;
    public string RecallReasonDescription;
}

var food = new Food {
    BrandName = "Contoso",
    ProductDescription = "Salads",
    ProductType = "Food & Beverages",
    CompanyName = "Contoso Fresh Vegetables, Inc.",
};

logger.Log<FoodRecallLogRecord>(new
{
    Food = food,
    ProductCode = 123,
    RecallReasonDescription = "due to a possible health risk from Listeria monocytogenes",
});

[noahfalk]

@reyang, For scenario 1 could they write this using functionality .NET already supports?

public static partial class Log
{
    [LoggerMessage(
        EventId = 100,
        LogLevel = LogLevel.Critical,
        Message = "A `{ProductType}` (#{ProductCode}) recall notice was published for `{BrandName} {ProductDescription}` produced by `{CompanyName}` ({RecallReasonDescription}).")]
        public static partial void FoodRecall(
            ILogger logger,
            string brandName,
            string productDescription,
            string productType,
            int productCode,
            string recallReasonDescription,
            string companyName
        );
        
    // more messages can follow
}

// at the site where the record should be logged
Log.FoodRecall(
    logger,
    brandName: "Contoso",
    productDescription: "Salads",
    productType: "Food & Beverages",
    productCode: 123,
    recallReasonDescription: "due to a possible health risk from Listeria monocytogenes",
    companyName: "Contoso Fresh Vegetables, Inc.");

[reyang]

@reyang, For scenario 1 could they write this using functionality .NET already supports?

Definitely YES! I consider it more of a preference / esthetics thing.

One advantage I could imagine with the strong-typed approach, is that folks can organize their code flow in a more readable way. For example:

var record = new FoodRecallRecord {
    BrandName = "Contoso",
    ProductDescription = "Salads",
    ProductType = "Food & Beverages",
    RecallReasonDescription = "due to a possible health risk from Listeria monocytogenes",
    CompanyName = "Contoso Fresh Vegetables, Inc.",
};

foreach (var productCode in ManufactureDatabase.GetProductCodes(product, timespan))
{
    record.ProductCode = productCode;
    logger.Log<FoodRecallRecord>(record);
}

And I can imagine folks putting additional constraints on the strong-type, so if the code is setting some invalid value, the assignment could throw (e.g. having setter logic to make sure ProductCode is non-zero and BrandName is a registered brand in the system).

[CodeBlanch]

If I log something with nested types like...

public class Order
{
   public string? ProductId { get; set; }
   public string? CustomerId { get; set; }
   public IReadOnlyList<OrderItem>? Items { get; set; }
}

public class OrderItem
{
   public string? SomeProperty { get; set; }
   // Note: Could contain additional nested types.
}

logger.Log<Order>(someOrder);

What is the expectation in a LoggerProvider doing this?

foreach (KeyValuePair<string, object> stateItem in stateKvps)
{
	Console.WriteLine($"{stateItem.Key} = {stateItem.Value}");
}

Would it be something like...

Order:ProductId = 0
Order:CustomerId = 0
Order:Items[0]:SomeProperty = value1
Order:Items[1]:SomeProperty = value2

[yecril71pl]

These are not nested types, they are navigation properties.

[yecril71pl]

@reyang, For scenario 1 could they write this using functionality .NET already supports?

Why didn’t you make LogFoodRecall an extension method for ILogger?

[noahfalk]

@reyang, For scenario 1 could they write this using functionality .NET already supports?

Definitely YES! I consider it more of a preference / esthetics thing.

I'd propose treating scenario 1 as a sufficiently solved problem in that case using the existing ILogger source generator support and focus this issue solely on scenario 2. At the moment scenario 2 proposes potential code the developer would write, but it doesn't indicate what the developer expects to find in their log afterwards. @CodeBlanch was probing part of that same question I think.

[CodeBlanch]

@noahfalk Yes, that is what I'm getting at. There are really two parts to this, as I see it: 1) Some API on ILogger that lets users pass a complex type to Log/BeginScope calls and 2) some API/feature to pass the complex type to the LoggerProvider(s). The second part is more challenging/interesting IMO, especially if we try to make it so any existing provider (e.g. ConsoleLoggerProvider) should just work as @reyang put it.

ConsoleLogger (and OpenTelemetry LogExporter) would probably be good with everything being exposed through the state as some kind of flattened IReadOnlyList<KeyValuePair<string, object>> (kind of like what I have above). Assuming most loggers special case like this or this. But something like a JSON logger probably doesn't want to do this...

{
   "LogLevel": "Information",
   "Order:ProductId": 0,
   "Order:CustomerId": 0,
   "Order:Items[0]:SomeProperty": "value1",
   "Order:Items[1]:SomeProperty": "value2"
}

JSON logger probably wants to represent the same log as...

{
   "LogLevel": "Information",
   "Order": {
      "ProductId": 0,
      "CustomerId": 0,
      "Items": [
         { "SomeProperty": "value1" },
         { "SomeProperty": "value2" },
      ]
   }
}

In which case moving everything to IReadOnlyList<KeyValuePair<string, object>> might not work.

Just some thoughts 🤔

[KalleOlaviNiemitalo]

[StructureLogMessage]
public partial struct FoodLogMessage : LogMessage<Food> { }

Would LogMessage<> be an interface type there, or are you proposing a C# change as well?

[noahfalk]

Would LogMessage<> be an interface type there, or are you proposing a C# change as well?

No intent to propose a C# change I think (I was part of the offline discussion that came from), it was just handwavy brainstorming. I'm hoping that portion of the problem is sufficiently solved by the pre-existing source generator work that we can do nothing.

There are really two parts to this, as I see it: 1) Some API on ILogger that lets users pass a complex type to Log/BeginScope calls and 2) some API/feature to pass the complex type to the LoggerProvider(s).

Different designs might do portions of the serialization work at different stages, for example between the source generator and ILogger, between the ILogger implementation and ILoggerProvider, or in ILoggerProvider. I am hoping we don't need to consider implementation concerns quite yet though. My suggestion is to figure out if users could wave a magic wand at their logging code to serialize data however they wished, what would that serialized output look like?

[yecril71pl]

My suggestion is to figure out if users could wave a magic wand at their logging code to serialize data however they wished, what would that serialized output look like?

The text must not be too long (unless a dedicated log book is used). It should contain key information that is specific, variable and hard to deduce from the context. If there is too much key information, there is a chance that the object itself is too rich and should be split.

[tbolon]

I am not sure if it is really related to your use case, but Serilog (which is one of the defacto logging library for .net) supports '@' prefix in parameter names in logs, and "destructure" the object into the output message:

var position = new { Latitude = 25, Longitude = 134 };
var elapsedMs = 34;

log.Information("Processed {@Position} in {Elapsed:000} ms.", position, elapsedMs);

renders:

09:14:22 [Information] Processed { Latitude: 25, Longitude: 134 } in 034 ms.

Tools such as seq can process such objects and make them useable when searching logs.
Obviously, it heavily makes use of reflection.

I suppose your goal here is to make more explicit choices about what to log, and get rid of any reflection cost. So my comment will only be there to be sure that you are aware of the ecosystem about object logging :)

[p10tyr]

This is not strictly about Strong type support but a request to allow us to add our own Attributes to the LogRecord class

I understand the States get enumerated and pushed onto repeated opentelemetry.proto.common.v1.KeyValue attributes with the exporter.

But we have absolutely no way to add our own attributes here when ParseStateValues is false or true.

The use case in my situation is that I always want to add a tenant attribute to everything Log and Trace for grouping in the APM. I can create my own BaseProcessor<LogRecord and add it as a Processor to LogBuilder.. But honestly.. its quite pointless because I cant add attributes .. easily.

Even if I were to hand roll out or customise OpentTelemetryLogProvider the OTLPLoggerClass does not really accept any kind of extra attributes.

It just assumes you are going to use Scopes (which is put on the Scopes Proto Attribute any way) or Provide States which is impractical to do and police on every single line that tries to log.

If LogRecord has something like .AddAtrribute(KeyValue) and OpenTelemetryLogger passed it along it would be easy to add what is needed with a processor. (Even if Scopes and States are turned off)

--Edit
I was helped out with an example on how to leverage Scopes to achieve what I needed. I was just stuck in my own tunnel vision.

Thank you for the great work on OTLP (and sorry for hijacking this thread a bit)

I am definitely going to follow this as it does look like a really awesome feature to have!

[obondarenko1]

Subscribing to this issue, as not being able to have a structured object written out as a JSON using high-performance logging making subsequent log analysis a very unpleasant chore.

[geeknoid]

Note that .NET 8 introduced https://learn.microsoft.com/dotnet/api/microsoft.extensions.logging.logpropertiesattribute which knows how to log complex objects.

[reyang]

Closing this issue since it was resolved by https://github.com/dotnet/extensions/blob/main/src/Libraries/Microsoft.Extensions.Telemetry.Abstractions/README.md as mentioned here. Related to #81730.

Here is a simple example open-telemetry/opentelemetry-dotnet#5214.