Log message assembled by concatenation or interpolation instead of a template
ID |
vbnet.maintainability.logger_constant_template |
Severity |
info |
Remediation Complexity |
trivial |
Remediation Risk |
low |
Remediation Effort |
low |
Resource |
Api Design |
Language |
VB.NET |
Description
Reports a log message that is assembled before the logging call receives it - a concatenation
with & or + that joins a string literal to a value, or an interpolated $"…" string -
rather than passed as a constant template with the values as separate arguments. The call is
recognised by a receiver named like a logger (log, _logger, Me.Logger) together with a
level method (Debug, Info, Information, Warn, Warning, Error, Fatal, Trace,
Verbose, Critical, or the LogXxx forms), and covers both the message-first and the
exception-first overloads. A concatenation passed as a later argument - a value being formatted
into an already-constant template - is not reported, and neither is a concatenation whose
operator sits inside the literal itself, as in "Q & A reloaded". Test sources are excluded.
The level method may be written escaped with brackets, as in log.[Error](…), which VB
requires when the name collides with a keyword; that form is recognised. One coverage gap is
worth stating: a message pre-built with String.Format inside the call, as in
log.Debug(String.Format("Bytes for {0}", msg)), has the same problem - the text is assembled
before the logger decides whether the level is enabled - but it is not reported.
Rationale
Once the values are pasted into the string, they stop being data. A logging backend that
receives a constant template plus its arguments can emit each value as a named field, so the
resulting event can be queried - every log line for one order id, a latency percentile across a
million requests - and the template itself becomes a stable identity that groups every
occurrence of the same event. A message assembled beforehand arrives as one opaque sentence:
the fields are gone, each line is textually unique, and retrieving anything from it means
regular expressions over log text that break the next time the wording changes. The cost is
paid whether or not the message is ever emitted, which is the part that surprises people. A
logging call takes its arguments by value, so the concatenation runs, allocates its
intermediate strings and formats every value at the call site - and only then does the logger
check whether the level is enabled and, in the usual production configuration, discard the
result. A Debug call in a hot loop therefore costs its full formatting even in a deployment
where debug logging is switched off, which is exactly the code that gets left in because it
looks free. Interpolation hides the same behaviour behind friendlier syntax.
The following code illustrates the pattern detected by this rule:
Public Sub Accept(orderId As Integer, total As Decimal)
' FLAGGED: Log message assembled by concatenation or interpolation instead of a template
_logger.LogInformation("Order " & orderId & " accepted")
' FLAGGED: Log message assembled by concatenation or interpolation instead of a template
_logger.LogInformation($"Order {orderId} totalling {total} accepted")
' FLAGGED: Log message assembled by concatenation or interpolation instead of a template
log.Warn("Retrying order " + CStr(orderId))
' FLAGGED: Log message assembled by concatenation or interpolation instead of a template
Me.Logger.Debug("Running total is " & total & " for order " & orderId)
Remediation
Pass a constant template as the message and let the logger supply the values: with
Microsoft.Extensions.Logging, named placeholders as in
_logger.LogInformation("Order {OrderId} accepted", orderId); with a logger that takes
positional arguments, the {0}-style overload. Keep the exception in the exception parameter
rather than concatenating ex.Message into the text, so the stack trace survives. Where a
genuinely expensive value has to be computed for the message, guard it with the logger’s
level check (If _logger.IsEnabled(LogLevel.Debug) Then) instead of paying for it
unconditionally.
' Before: one opaque sentence, formatted even when the level is off
_logger.LogInformation("Order " & orderId & " accepted for " & total)
' After: queryable fields, formatted only if the level is enabled
_logger.LogInformation("Order \{OrderId} accepted for \{Total}", orderId, total)