Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Demonstrate compile-time logging source gen without message template #5553

Conversation

reyang
Copy link
Member

@reyang reyang commented Apr 19, 2024

Updating the doc/example to show that it is possible to have structured logging without requiring a message template string.

For users who don't need the format string, this could save computation and networking cost.

@reyang reyang requested a review from a team April 19, 2024 02:53
@reyang reyang added the documentation Documentation related label Apr 19, 2024
@reyang
Copy link
Member Author

reyang commented Apr 19, 2024

These are the warning messages I got:

D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\Program.cs(38,16): warning SYSLIB1015: Argument 'brandNa
me' is not referenced from the logging message (https://learn.microsoft.com/dotnet/fundamentals/syslib-diagnostics/sysl
ib1015) [D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\getting-started-console.csproj::TargetFramework
=net8.0]
D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\Program.cs(39,16): warning SYSLIB1015: Argument 'product
Description' is not referenced from the logging message (https://learn.microsoft.com/dotnet/fundamentals/syslib-diagnos
tics/syslib1015) [D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\getting-started-console.csproj::Target
Framework=net8.0]
D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\Program.cs(40,16): warning SYSLIB1015: Argument 'product
Type' is not referenced from the logging message (https://learn.microsoft.com/dotnet/fundamentals/syslib-diagnostics/sy
slib1015) [D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\getting-started-console.csproj::TargetFramewo
rk=net8.0]
D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\Program.cs(41,16): warning SYSLIB1015: Argument 'recallR
easonDescription' is not referenced from the logging message (https://learn.microsoft.com/dotnet/fundamentals/syslib-di
agnostics/syslib1015) [D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\getting-started-console.csproj::T
argetFramework=net8.0]
D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\Program.cs(42,16): warning SYSLIB1015: Argument 'company
Name' is not referenced from the logging message (https://learn.microsoft.com/dotnet/fundamentals/syslib-diagnostics/sy
slib1015) [D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\getting-started-console.csproj::TargetFramewo
rk=net8.0]

This is probably something that Microsoft.Extensions.Logging would want to consider: either remove the warning entirely if message template is not provided by the user, or provide a single warning message such as "warning SYSLIB1015: logging message is not specified, ..." instead of 5 individual warnings on each key-value pair.

I personally would suggest that we remove the warning message entirely, because this is better aligned with

[LoggerMessage(LogLevel.Critical)]
public static partial void FoodRecallNotice(
this ILogger logger,
[LogProperties(OmitReferenceName = true)] FoodRecallNotice foodRecallNotice);
(where we don't get any warning). In addition, many users treat warnings as errors, such warning message might miscommunicate the intention and make the users feel they should always have the message template and pay the cost even if they don't actually benefit from it.

@reyang reyang added the logs Logging signal related label Apr 19, 2024
@@ -32,7 +32,7 @@ internal static partial class LoggerExtensions
[LoggerMessage(LogLevel.Information, "Food `{name}` price changed to `{price}`.")]
public static partial void FoodPriceChanged(this ILogger logger, string name, double price);

[LoggerMessage(LogLevel.Critical, "A `{productType}` recall notice was published for `{brandName} {productDescription}` produced by `{companyName}` ({recallReasonDescription}).")]
[LoggerMessage(LogLevel.Critical)]
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this is not intended to be merged, but to open discussion only right?

@CodeBlanch CodeBlanch marked this pull request as draft April 19, 2024 17:30
@reyang
Copy link
Member Author

reyang commented Apr 19, 2024

Using Microsoft.Extenions.Logging.* with a message template:

internal static partial class LoggerExtensions
{
    [LoggerMessage(LogLevel.Critical, "A `{productType}` recall notice was published for `{brandName} {productDescription}` produced by `{companyName}` ({recallReasonDescription}).")]
    public static partial void FoodRecallNotice(
        this ILogger logger,
        string brandName,
        string productDescription,
        string productType,
        string recallReasonDescription,
        string companyName);
}

logger.FoodRecallNotice(
    brandName: "Contoso",
    productDescription: "Salads",
    productType: "Food & Beverages",
    recallReasonDescription: "due to a possible health risk from Listeria monocytogenes",
    companyName: "Contoso Fresh Vegetables, Inc.");

ConsoleLoggerProvider output:

crit: Program[1338249384]
      A `Food & Beverages` recall notice was published for `Contoso Salads` produced by `Contoso Fresh Vegetables, Inc.` (due to a possible health risk from Listeria monocytogenes).

JSON output:

{
    "brandName": "Contoso",
    "productDescription": "Salads",
    "productType": "Food & Beverages",
    "recallReasonDescription": "due to a possible health risk from Listeria monocytogenes",
    "companyName": "Contoso Fresh Vegetables, Inc.",
    "{OriginalFormat}": "A `{productType}` recall notice was published for `{brandName} {productDescription}` produced by `{companyName}` ({recallReasonDescription})."
}

@reyang
Copy link
Member Author

reyang commented Apr 19, 2024

Using Microsoft.Extenions.Logging.* without a message template:

internal static partial class LoggerExtensions
{
    [LoggerMessage(LogLevel.Critical)]
    public static partial void FoodRecallNotice(
        this ILogger logger,
        string brandName,
        string productDescription,
        string productType,
        string recallReasonDescription,
        string companyName);
}

logger.FoodRecallNotice(
    brandName: "Contoso",
    productDescription: "Salads",
    productType: "Food & Beverages",
    recallReasonDescription: "due to a possible health risk from Listeria monocytogenes",
    companyName: "Contoso Fresh Vegetables, Inc.");

ConsoleLoggerProvider output:

crit: Program[1338249384]

JSON output:

{
    "brandName": "Contoso",
    "productDescription": "Salads",
    "productType": "Food & Beverages",
    "recallReasonDescription": "due to a possible health risk from Listeria monocytogenes",
    "companyName": "Contoso Fresh Vegetables, Inc.",
    "{OriginalFormat}": ""
}

Build warnings:

D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\Program.cs(39,16): warning SYSLIB1015: Argument 'brandNa
me' is not referenced from the logging message (https://learn.microsoft.com/dotnet/fundamentals/syslib-diagnostics/sysl
ib1015) [D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\getting-started-console.csproj::TargetFramework
=net8.0]
D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\Program.cs(40,16): warning SYSLIB1015: Argument 'product
Description' is not referenced from the logging message (https://learn.microsoft.com/dotnet/fundamentals/syslib-diagnos
tics/syslib1015) [D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\getting-started-console.csproj::Target
Framework=net8.0]
D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\Program.cs(41,16): warning SYSLIB1015: Argument 'product
Type' is not referenced from the logging message (https://learn.microsoft.com/dotnet/fundamentals/syslib-diagnostics/sy
slib1015) [D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\getting-started-console.csproj::TargetFramewo
rk=net8.0]
D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\Program.cs(42,16): warning SYSLIB1015: Argument 'recallR
easonDescription' is not referenced from the logging message (https://learn.microsoft.com/dotnet/fundamentals/syslib-di
agnostics/syslib1015) [D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\getting-started-console.csproj::T
argetFramework=net8.0]
D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\Program.cs(43,16): warning SYSLIB1015: Argument 'company
Name' is not referenced from the logging message (https://learn.microsoft.com/dotnet/fundamentals/syslib-diagnostics/sy
slib1015) [D:\repo\opentelemetry-dotnet\docs\logs\getting-started-console\getting-started-console.csproj::TargetFramewo
rk=net8.0]

Summary:

  • 5 build warnings that seem misleading/noisy
  • ConsoleLoggerProvider output looks weird
  • {OriginalFormat} shows up in the generated key-value pairs, the value is empty

@reyang
Copy link
Member Author

reyang commented Apr 19, 2024

Using Microsoft.Extensions.Telemetry.Abstractions without a message template:

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

logger.FoodRecallNotice(foodRecallNotice);


internal static partial class LoggerExtensions
{
    [LoggerMessage(LogLevel.Critical)]
    public static partial void FoodRecallNotice(
        this ILogger logger,
        [LogProperties(OmitReferenceName = true)] FoodRecallNotice foodRecallNotice);
}

ConsoleLoggerProvider output:

crit: Program[252550133]

JSON output:

{
    "CompanyName": "Contoso Fresh Vegetables, Inc.",
    "RecallReasonDescription": "due to a possible health risk from Listeria monocytogenes",
    "ProductType": "Food & Beverages",
    "ProductDescription": "Salads",
    "BrandName": "Contoso"
}

Summary:

  • no build warning
  • ConsoleLoggerProvider output looks weird
  • no {OriginalFormat} in the generated key-value pairs

Copy link
Contributor

This PR was marked stale due to lack of activity and will be closed in 7 days. Commenting or Pushing will instruct the bot to automatically remove the label. This bot runs once per day.

@github-actions github-actions bot added the Stale Issues and pull requests which have been flagged for closing due to inactivity label Apr 27, 2024
@reyang reyang added needs-runtime-change Issues which likely require changes from dotnet runtime - typically DiagnosticSource package and removed documentation Documentation related Stale Issues and pull requests which have been flagged for closing due to inactivity labels Apr 30, 2024
@reyang reyang closed this Apr 30, 2024
@reyang reyang deleted the reyang/ilogger-without-message-template branch April 30, 2024 17:20
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
logs Logging signal related needs-runtime-change Issues which likely require changes from dotnet runtime - typically DiagnosticSource package
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants