Compile-time source generation for structured log messages

[maryamariyan]

I gathered all my notes into this design doc. (this is a first draft)

/cc:
The Logging Generator Author: @geeknoid
@davidfowl @stephentoub @shirhatti @333fred @ericstj

TODO (completed)

• Add sample using exception as argument to log method: (As a general rule, the first instance of ILogger, LogLevel, and Exception are treated specially in the log method signature. Subsequent instances are treated like normal args)

// below works
        [LoggerMessage(110, LogLevel.Debug, "M1 {ex3} {ex2}")]
        static partial void LogMethod(ILogger logger, System.Exception ex, System.Exception ex2, System.Exception ex3);

// but this warns:
        // warning SYSLIB0013: Don't include a template for ex in the logging message since it is implicitly taken care
	// DiagnosticSeverity.Warning,
        [LoggerMessage(0, LogLevel.Debug, "M1 {ex} {ex2}")]
        static partial void LogMethod(ILogger logger, System.Exception ex, System.Exception ex2);

• Add note about ordering:
  There is no constraint in the ordering at this point. So user is able to add an Exception, ILogger, LogLevel signature, or LogLevel, ILogger, Exception, or whatever. Sample: (note ILogger argument is the last argument)

        [LoggerMessage(110, LogLevel.Debug, "M1 {ex3} {ex2}")]
        static partial void LogMethod(System.Exception ex, System.Exception ex2, System.Exception ex3, ILogger logger);

• Add a note, defining clearly the scope of uniqueness for event ids, the generator would have an event id uniqueness check as warning so it can be suppressed) + Add a sample.

We established during reviews that unique ids per assembly wouldn't work. So, we changed the scope of uniqueness for the event IDs to be the class in which the log method is declared. It doesn't check up the inheritance hierarchy for conflicting IDs because it also wouldn't be possible cross-assembly boundaries anyways. The diagnostic message for this condition would be a warning indicating the class name.

• Docs in the future would need to mention that event ID uniqueness is checked per class itself not at base classes.

• Explain how the source generator detects the ILogger when using instance mode. Could we support logger APIs from base class or on interfaces?

When generating instance-mode logging methods, the field that holds the logger is now determined by looking at available fields. You get an error if there isn't a field of the right type or if there is more than one such field. This also doesn't look up the inheritance hierarchy, but it would be possible to add this capability in the future. (show sample)

[davidfowl]

I would love the 2 ideas for what gets generated in here.

[stephentoub]

Also, the comment made back on the original issue stated:
"A benefit there is that we can use string format syntax as a natural way which we can consider for imperative logging, but the consensus there is to keep the logging generator to enable writing more declarative logging APIs."
FWIW, I think this is a strange line being drawn between "declarative" and "imperative". From the developer perspective, we're talking about the difference between (using one of your examples from earlier):

[LoggerMessage(0, LogLevel.Information, "Hello `{name}`")]
public static partial void LogName(this ILogger logger, string name);

and

public static void LogName(this ILogger logger, string name) =>
    logger.Log(0, LogLevel.Information, $"Hello `{name}`");

If we define "declarative" as using an attribute, sure, one does and one doesn't. But otherwise, we're still declaring the same information, just slightly different syntax, in one case as arguments to an attribute ctor and in one case to a log method.

The valid reasons I heard that we might prefer the source generator approach were:

• Wanting to enable the exact format syntax required by https://messagetemplates.org/
• Wanting to be able to pass all of original data as-is without any complication around how it's stored prior to something being done with it other than creating a string
• Wanting to be able to supply alternative names for the holes, if the C# 10 syntax doesn't end up allowing that (but Fred is investigating)

None of the other reasons I heard were compelling to me for why we'd go the source generator route.

[maryamariyan]

That's fair. I think they both offer declarative. I will update the proposal.

[davidfowl]

I honestly don't think these approaches are at odds but:

• The structure has to be preserved (Names), that's the main thing about the string builder approach that is missing (hopefully we can make something work in C# 10).
• Not being able to lazily ToString is a problem, we don't want to allocate until a logger provider asks for the string
• The approach is declarative and toolable. We can write rules against the attribute instead of call sites that use Log.

I say we treat the builder approach as distinct from the source generator. In fact, in the later proposals we're going to generate calls to LoggerMessage.Define<...>. This change basically re-enforces that the source generator is a declarative approach to the model we have today.

[stephentoub]

The structure has to be preserved (Names), that's the main thing about the string builder approach that is missing

This is my "Wanting to be able to supply alternative names for the holes" bullet. If just {name} is used, it can already support that. I suggest if specifying names separate from the expression itself is important, that the design document call that out and show it in examples: currently I don't see any examples that supply different names.

Not being able to lazily ToString is a problem, we don't want to allocate until a logger provider asks for the string

This is my "Wanting to be able to pass all of original data as-is without any complication around how it's stored prior to something being done with it other than creating a string" bullet. But it depends on what you mean by allocating. I imagine the builder would either format into an ArrayPool-rented char[] or serialize into an ArrayPool-rented byte[]. And of course only after checking whether logging was enabled at an appropriate logging level.

The approach is declarative and toolable

I still question the declarative statement here. An analyzer would search for attributes and look at attribute arguments, or an analyzer would search for Log method calls and look at method call arguments. Is the statement really that sites are implicitly constrained by what you're allowed to write in attributes?

[geeknoid]

From my perspective "declarative" is really about the fact it is a "guided" experience. The code generator has deep semantic understanding of what the user is doing and provides useful error messages that don't exist using completely generic mechanisms.

For example, the code generator emits warnings for duplicate event ids. Or it'll auto-generate a message if you don't supply one to output parameters as a JSON blob, etc.

The generator model also makes it possible to provide parameters to the logging method which aren't reflected in the message string. This lets you pass name/value pairs to the ILogger without necessarily including that state in the summary string.

[geeknoid]

In terms of supplying different names, the current implementation provides a limited form of that as it optionally supports pascal casing of names. So you can supply "foo" as a method parameter, and call it "{Foo}" in the message text (and in the downstream IReadOnlyCollection produced on the TState given to ILogger). This feature is controlled by a global option on the generator.

[davidfowl]

This is my "Wanting to be able to supply alternative names for the holes" bullet. If just {name} is used, it can already support that. I suggest if specifying names separate from the expression itself is important, that the design document call that out and show it in examples: currently I don't see any examples that supply different names.

We change casing all of the time in ASP.NET Core. We also define templates separately from where we specify values so this happens all the time. The intent isn't to capture variables but to design log messages and their structure and pass the appropriate values after the fact.

This is my "Wanting to be able to pass all of original data as-is without any complication around how it's stored prior to something being done with it other than creating a string" bullet. But it depends on what you mean by allocating. I imagine the builder would either format into an ArrayPool-rented char[] or serialize into an ArrayPool-rented byte[]. And of course only after checking whether logging was enabled at an appropriate logging level.

We need to eagerly stash all of the state before we ToString the overall thing. This makes it hard to avoid boxing or calling ToString on the incoming parameters. So there's an allocation forced up front to produce the builder.

I still question the declarative statement here. An analyzer would search for attributes and look at attribute arguments, or an analyzer would search for Log method calls and look at method call arguments. Is the statement really that sites are implicitly constrained by what you're allowed to write in attributes?

Attributes force a particular pattern that we like and is easier to analyze than code. This is a style preference thing though.

[stephentoub]

We need to eagerly stash all of the state before we ToString the overall thing. This makes it hard to avoid boxing or calling ToString on the incoming parameters. So there's an allocation forced up front to produce the builder.

If you don't count ArrayPool rentals as allocation (waving my hands), then there's no allocation to create the builder. You're right there would be ToString allocations as part of formatting into that, for any non-primitive types that allocate in their ToString methods. I expect with ISpanFormattable that will go way down, though, since there wouldn't be allocation for anything implementing ISpanFormattable.

[maryamariyan]

@omajid as of #190 this PR is failing, what do I need to do to fix this?

[omajid]

Could you run ./update-index > INDEX.md? CI is running that command too and comparing the INDEX.md in this PR with the INDEX.md that update-index generates.

[ericstj]

Could you run ./update-index > INDEX.md?

That's not so friendly on Windows for all developers. I tried to run that command with windows bash.exe and got a bunch of errors around line endings. We should probably come up with a way to make it work regardless of developer platform.

[omajid]

That's not so friendly on Windows for all developers.

Ouch. I didn't realize that.

We should probably come up with a way to make it work regardless of developer platform.

I dont use Windows, but I am happy to help make this happen. Any suggestions on what a Windows-friendly workflow would look like?

I tried to run that command with windows bash.exe and got a bunch of errors around line endings.

Should it just update the file in-place directly? Would that help with the line ending issues?

[ericstj]

I tried to run that command with windows bash.exe and got a bunch of errors around line endings.
Should it just update the file in-place directly? Would that help with the line ending issues?

Nevermind, I see this is a python script. We can just tell folks to use python to run it. I see a couple path separator issues. I'll put up a fix.

[maryamariyan]

Note to reviewers:

• The API proposal and samples got updated with the approved feedback: https://github.com/dotnet/designs/blob/ced717fc77d218b3793aa68b4ccd3ac3fe59fe50/accepted/2021/logging-generator.md#api-proposal

• Updated this section with more items to explain limitations with using Define which source generators could handle one way or another: https://github.com/dotnet/designs/blob/ced717fc77d218b3793aa68b4ccd3ac3fe59fe50/accepted/2021/logging-generator.md#added-benefits-with-source-generators-not-supported-with-loggermessagedefine

[davidfowl]

I don't really understand this. This feels like a choice. We chose not to add those overloads. If we want to support more than 6 overloads then we need to add those overloads...

[maryamariyan]

even if there were overloads up to taking 16 parameter (Action limit). then the source generator would still be able to fallback to another approach to support arbitrary number of parameters

I think with this section I was trying to illustrate that source generator can deal with some of the existing limitations of Define, one way or another, if we wanted to allow more robust support. (arbitrary number of parameter is one of the several items of limitations explained in this section)

[maryamariyan]

Are recommending to switch that ability off for preview 4, to only allow up to 6 parameters until we find request for it?

[davidfowl]

Are recommending to switch that ability off for preview 4, to only allow up to 6 parameters until we find request for it?

I think so. I'm not sure why the API was rejected TBH. Maybe we're waiting until customers complain 😄 (which they have in the past)

[davidfowl]

@maryamariyan time to merge this?

[maryamariyan]

@maryamariyan time to merge this?

It should be ready now