Diagnostic output written with Console or Debug.Print instead of a logger
ID |
vbnet.maintainability.print_in_production |
Severity |
low |
Remediation Complexity |
medium |
Remediation Risk |
low |
Remediation Effort |
low |
Resource |
Api Design |
Language |
VB.NET |
Description
Reports diagnostic output written straight to the process: Console.Write,
Console.WriteLine and Debug.Print. These are the forms typically added while chasing a
problem and then left behind. Calls to a logging abstraction, and Trace output - which is
routed through configurable listeners rather than fixed to the console - are not reported.
Test sources are excluded, and so is console output inside a Module that declares the
program’s Sub Main entry point, because in a console application the console is the
program’s own interface rather than a debugging channel. MsgBox is not reported either: in
VB.NET it is the WinForms way of talking to the user, so in a desktop application it is the
program’s interface and not a diagnostic channel, and the two cannot be told apart from the
call site.
Rationale
Output written this way leaves the application with no way to control it. A logger decides per
message whether it is emitted, at what level, with what correlation identifier, and to which
destination; Console.WriteLine decides none of that at the point of use and nothing can turn
it off short of editing the code. Where the process runs as a service, a container entry point
or a web application, standard output is frequently discarded outright, so the message that was
meant to explain a failure is simply gone - and the line still costs a formatted string and a
synchronized write on every call, on a stream that in some hosts is slow and lock-contended.
Because these calls carry no level and no structure, they also cannot be filtered or searched
alongside real log output, so the one useful diagnostic in a batch job hides in a wall of
console noise. Left-behind statements are a maintenance signal too - they mark code that was debugged by printing, and they sometimes print
values that were never meant to be exposed.
The following code illustrates the pattern detected by this rule:
Public Sub Post(ByVal reference As String, ByVal amount As Decimal)
' FLAGGED: Diagnostic output written with Console or Debug.Print instead of a logger
Console.WriteLine("posting " & reference)
' FLAGGED: Diagnostic output written with Console or Debug.Print instead of a logger
Console.Write(amount)
' FLAGGED: Diagnostic output written with Console or Debug.Print instead of a logger
Debug.Print("amount was " & amount.ToString())
Try
Send(reference, amount)
Catch ex As InvalidOperationException
' MsgBox is the WinForms way of talking to the user, so it is the program's
' interface in a desktop application and cannot be told apart from a leftover
' debugging dialog at the call site. Not reported.Remediation
Route the message through the application’s logging abstraction and choose a level that matches
it: Debug or Trace for the detail that was being chased, Information for something worth
keeping, Warning or Error for a genuine problem, passing the exception object rather than
just its message. If the statement was only ever scaffolding, delete it. In a genuine console
application, keep Console output for the program’s real output - the results the user asked
for - and log diagnostics separately.
' Before: unconditional, unstructured, and often discarded by the host
Console.WriteLine("posting " & reference)
Debug.Print("amount was " & amount.ToString())
' After
_log.Debug("Posting \{Reference} for \{Amount}", reference, amount)
_log.Error(ex, "Could not post \{Reference}", reference)