In this article, we delve into the world of message templates for logging mechanisms. We’ll journey through the history leading to the current state of logging, laying a solid foundation for understanding. This knowledge equips us to tackle one of the most common compiler warnings: CA2254 – Template should be a static expression, by comprehending its root cause.
Let’s start.
A Brief History of Structured Logging APIs
Initially, in the early days of application logging, streaming text was the standard approach, effective for simple scenarios:
_logger.Log(LogLevel.Information, $"User {userName} logged on {loggedInTime}");
With a result:
User John Doe logged on 04/12/2023 23:01:39
However, as the industry evolved to tackle more complex cases, such as distributed systems, parsing these logs became increasingly burdensome. Consequently, this challenge gave rise to the concept of structured logging. The central idea was to treat log data as a stream of structured events with key-value properties. These structured events are far more manageable in large-scale services. Specifically, querying based on properties offers a more efficient and user-friendly experience compared to the regular expressions that were commonly used in the early days of logging. A prime example of this direct encoding of events is the JSON format:
var logEntry = new
{
EventId = "logged_in",
Username = userName,
Time = loggedInTime,
};
var message = JsonSerializer.Serialize(logEntry);
_logger.Log(LogLevel.Information, message);
This is the output we can find:
{"EventId":"logged_in","Username":"John Doe","Time":"2023-12-04T23:01:39.2034813+01:00"}
Subsequently, while this convention eases log filtering, allowing for queries such as Username = 'John Doe' to be performed directly on the unprocessed log stream, in practice, it introduces other challenges such as parsing ambiguities and inconsistent usage among development teams.
Furthermore, logging systems like Event Tracing for Windows attempted to address this issue by balancing good performance with human and machine readability. Nevertheless, the effort required for developers to assign event IDs and manage manifests often proved to be more trouble than it was worth.
Semantic or Structured Logging
Moving forward, message templates combine the strengths of various approaches, delivering optimal human readability, impeccable machine interpretability, and exceptional ease of use during development.
A template offers placeholders to be populated with event data:
_logger.Log(LogLevel.Information, "User {userName} logged on {loggedInTime}", userName, loggedInTime);
In this context, we are treating the sentence above as an event type, with the variables filling the gaps being the only changing elements. This approach allows sentences to be grouped by these gaps, thereby offering enhanced flexibility in data retrieval.
Log Message Templates in C#
Significantly, modern log libraries in C# support message templates, which are crucial when logging customizable data. These templates feature placeholders for which we provide corresponding arguments. Importantly, the use of placeholders within a message template comes with certain constraints. These placeholders are ordinal-based and should be named rather than numbered. This implies that the names assigned to placeholders in the string and as arguments are primarily for human readability, and not for the logger’s internal processing:
_logger.Log(LogLevel.Information, "User '{userName}' added apples to the basket.", userName);
The userName variable corresponds to the placeholder {userName}. Again, it’s important to note that what matters with variables and placeholders is their order, not their names. For example, the following code would also work successfully:
_logger.Log(LogLevel.Information, "User '{userName}' added apples to the basket.", randomSentence);
Both examples produce the same output:
User 'John Doe' added apples to the basket.
Formatting Log Message Templates in C#
Moreover, in C#, log message template placeholders support formatting, enabling us to specify any valid format for a given type of argument. This enhances the readability and usefulness of our log messages, which is particularly valuable when logging unique identifiers or timestamps.
Let’s consider a scenario where we need to log a user’s action along with the timestamp. A standard log entry might look like this:
_logger.Log(LogLevel.Information, "User {userId} logged in at {loggedInTime}.", userId, loggedInTime);
Example output:
User 5bc96623-0a1b-4ee0-983e-fe0335a418c4 logged in at 01/15/2024 21:00:11.
In the previous example, userId is a GUID and loggedInTime is a DateTime object. While this provides the necessary information, we can enhance the log’s readability by applying formatting to these values:
_logger.Log(LogLevel.Information, "User {userId:N} logged in at {loggedInTime:F}.", userId, loggedInTime);
In this revised example, {userId:N} applies a format specifier to the GUID, removing the dashes and shortening the overall string length. The {loggedInTime:F} specifier applies a full date/time pattern (long date and long time) to the DateTime object, resulting in a comprehensive and readable timestamp.
Which results in a log message similar to:
User 5bc966230a1b4ee0983efe0335a418c4 logged in at Monday, 15 January 2024 21:00:11.
With these format specifiers, the log entry becomes both compact and rich with detailed information. The 'N' format for GUIDs provides a cleaner, uninterrupted string, while the 'F' format for the DateTime yields a full, unambiguous timestamp. These enhancements aid significantly in log readability and analysis.
Code Analysis Rule CA2254
When performing logging, using concatenation or string interpolation can trigger the compiler warning CA2254:
In the given example, the message template is not constant. As we now understand, this can result in inefficient code for message templates.
Fixing Rule CA2254 in Log Message Templates
To resolve this warning, it’s important to follow the recommended practice of maintaining the structure of the log, including the names of placeholders. This improves observability for aggregation and monitoring tools like Grafana, Application Insights, and others:
_logger.Log(LogLevel.Information, "User {userName} logged on {loggedInTime}", userName, loggedInTime);
By indicating to the logger that the userName and loggedInTime properties in the message correspond with the placeholder values, the updated message template becomes a constant expression, effectively fixing the warning.
Conclusion