Post

Logging and tracing in .NET applications

Introduction

Before you start

  • Make sure you are already familiar with the VS Code Debugger and how to use it.
  • Check out the VS Code Debugger Interface post to learn more about the VS Code Debugger.
  • Tracing is a way for you to monitor your application’s execution while it’s running.
  • You can add tracing and debugging instrumentation to your .NET application when you develop it.
  • You can use that instrumentation while you’re developing the application and after you’ve deployed it.

When to use logging and tracing

  • You can use it in situations where you need more than a debugger:
    • Issues that occur over long periods of time can be difficult to debug with a traditional debugger. Logs allow for detailed post-mortem review that spans long periods of time. In contrast, debuggers are constrained to real-time analysis.
    • Multi-threaded applications and distributed applications are often difficult to debug. Attaching a debugger tends to modify behaviors. You can analyze detailed logs as needed to understand complex systems.
    • Issues in distributed applications might arise from a complex interaction between many components. It might not be reasonable to connect a debugger to every part of the system.
    • Many services shouldn’t be stalled. Attaching a debugger often causes timeout failures.
    • Issues aren’t always foreseen. Logging and tracing are designed for low overhead so that programs can always be recording in case an issue occurs.

Write information to output windows

  • You may have been using the console to display information to the application user.
  • There are other types of applications built with .NET that have user interfaces, such as mobile, web, and desktop apps, and there’s no visible console.
  • In these applications, System.Console logs messages “behind the scenes.” These messages might show up in an output window in Visual Studio or Visual Studio Code. They also might be output to a system log such as Android’s logcat. As a result, you should take great consideration when you use System.Console.WriteLine in a non-console application.
  • This is where you can use System.Diagnostics.Debug and System.Diagnostics.Trace in addition to System.Console. Both Debug and Trace are part of System.Diagnostics and will only write to logs when an appropriate listener is attached.
  • The choice of which print style API to use is up to you. The key differences are:

  • System.Console
    • Always enabled and always writes to the console.
    • Useful for information that your customer might need to see in the release.
    • Because it’s the simplest approach, it’s often used for ad-hoc temporary debugging. This debug code is often never checked in to source control.
  • System.Diagnostics.Trace
    • Only enabled when TRACE is defined.
    • Writes to attached Listeners, by default, the DefaultTraceListener.
    • Use this API when you create logs that will be enabled in most builds.
  • System.Diagnostics.Debug
    • Only enabled when DEBUG is defined (when in debug mode).
    • Writes to an attached debugger.
    • Use this API when you create logs that will be enabled only in debug builds.
1
2
3
Console.WriteLine("This message is readable by the end user.");
Trace.WriteLine("This is a trace message when tracing the app.");
Debug.WriteLine("This is a debug message just for developers.");
  • When you design your tracing and debugging strategy, think about how you want the output to look.
    • Multiple Write statements filled with unrelated information creates a log that’s difficult to read.
    • On the other hand, using WriteLine to put related statements on separate lines might make it difficult to distinguish what information belongs together.
  • In general,
    • use multiple Write statements when you want to combine information from multiple sources to create a single informative message.
    • Use the WriteLine statement when you want to create a single complete message.
1
2
3
Debug.Write("Debug - ");
Debug.WriteLine("This is a full line.");
Debug.WriteLine("This is another full line.");
  • This output is from the preceding logging with Debug:
1
2
Debug - This is a full line.
This is another full line.

Define TRACE and DEBUG constants

By default, when an application is running under debug, the DEBUG constant is defined. You can control this by adding a DefineConstants entry in the project file in a property group. Here’s an example of turning on TRACE for both Debug and Release configurations in addition to DEBUG for Debug configurations.

1
2
3
4
5
6
<PropertyGroup Condition="'$(Configuration)|$(Platform)'=='Debug|AnyCPU'">
    <DefineConstants>DEBUG;TRACE</DefineConstants>
</PropertyGroup>
<PropertyGroup Condition="'$(Configuration)|$(Platform)'=='Release|AnyCPU'">
    <DefineConstants>TRACE</DefineConstants>
</PropertyGroup>
  • When you use Trace when not attached to the debugger, you’ll need to configure a trace listener such as dotnet-trace. This listener will write the trace messages to a file or another output.

Conditional tracing

  • In addition to simple Write and WriteLine methods, there’s also the capability to add conditions with WriteIf and WriteLineIf. As an example, the following logic checks if the count is zero and then writes a debug message:
1
2
3
4
if(count == 0)
{
    Debug.WriteLine("The count is 0 and this may cause an exception.");
}
  • You could rewrite this in a single line of code:
1
Debug.WriteLineIf(count == 0, "The count is 0 and this may cause an exception.");
  • You can also use these conditions with Trace and with flags that you define in your application:
1
2
3
4
bool errorFlag = false;
System.Diagnostics.Trace.WriteIf(errorFlag, "Error in AppendData procedure.");
System.Diagnostics.Debug.WriteIf(errorFlag, "Transaction abandoned.");
System.Diagnostics.Trace.Write("Invalid value for data request");

Verify that certain conditions exist

  • An assertion, or Assert statement, tests a condition that you specify as an argument to the Assert statement. If the condition evaluates to true, no action occurs. If the condition evaluates to false, the assertion fails. If you’re running with a debug build, your program enters break mode.

  • You can use the Assert method from either Debug or Trace, which are in the System.Diagnostics namespace. Debug class methods aren’t included in a release version of your program, so they don’t increase the size or reduce the speed of your release code.

  • Use the System.Diagnostics.Debug.Assert method freely to test conditions that should hold true if your code is correct. For example, suppose you’ve written an integer-divide function. By the rules of mathematics, the divisor can never be zero. You might test this condition by using an assertion:

1
2
3
4
5
6
int IntegerDivide(int dividend, int divisor)
{
    Debug.Assert(divisor != 0, $"{nameof(divisor)} is 0 and will cause an exception.");

    return dividend / divisor;
}
  • When you run this code under the debugger, the assertion statement is evaluated. However, the comparison isn’t made in the release version, so there’s no additional overhead.
  • When you use System.Diagnostics.Debug.Assert, make sure that any code inside Assert doesn’t change the results of the program if Assert is removed. Otherwise, you might accidentally introduce a bug that only shows up in the release version of your program. Be especially careful about asserts that contain function or procedure calls.
  • Using Debug and Trace from the System.Diagnostics namespace is a great way to provide additional context when you run and debug your application.

Logging and tracing a simple Fibonacci console application

  • Here is the starter code for a simple Fibonacci console application in the Program.cs file:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
int result = Fibonacci(5);
Console.WriteLine(result);

static int Fibonacci(int n)
{
    int n1 = 0;
    int n2 = 1;
    int sum;

    for (int i = 2; i <= n; i++)
    {
        sum = n1 + n2;
        n1 = n2;
        n2 = sum;
    }

    return n == 0 ? n1 : n2;
}

Write to the debug console

  • let’s add more debug diagnostics
  • Additional diagnostics will help diagnose the application while it’s being run under debug.
  • At the top of the Program.cs file, we’ll add a new using statement to bring in System.Diagnostics so we can use the Debug methods.
1
using System.Diagnostics;
  • Add a WriteLine statement at the start of the Fibonacci method to get clarity when you debug through the code.
1
2
Debug.WriteLine($"Entering {nameof(Fibonacci)} method");
Debug.WriteLine($"We are looking for the {n}th number");
  • At the end of our for loop, we could print out every value. We could also use a conditional print statement by using WriteIf or WriteLineIf to add a print line only when sum is 1 at the end of the for loop:
1
Debug.WriteLineIf(sum == 1, $"sum is 1, n1 is {n1}, n2 is {n2}");
  • The full code with the debug statements added:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
using System.Diagnostics;

int result = Fibonacci(5);
Console.WriteLine(result);

static int Fibonacci(int n)
{
    Debug.WriteLine($"Entering {nameof(Fibonacci)} method");
    Debug.WriteLine($"We are looking for the {n}th number");

    int n1 = 0;
    int n2 = 1;
    int sum;

    for (int i = 2; i <= n; i++)
    {
        sum = n1 + n2;
        n1 = n2;
        n2 = sum;

    Debug.WriteLineIf(sum == 1, $"sum is 1, n1 is {n1}, n2 is {n2}");
    }


    return n == 0 ? n1 : n2;
}
  • Debugging the application will now show the debug messages in the output window as follows:
1
2
3
Entering Fibonacci method
We are looking for the 5th number
sum is 1, n1 is 1, n2 is 1

Check for conditions with Assert

  • In some situations, you might want to stop the entire running application when a certain condition isn’t met. By using Debug.Assert, you can check for a condition and output additional information about the state of the application.
  • Let’s add a check right before the return statement to ensure n2 is 5.
1
2
3
// If n2 is 5 continue, else break.
Debug.Assert(n2 == 5, "The return value is not 5 and it should be.");
return n == 0 ? n1 : n2;
  • Our application logic is already correct, so let’s update our Fibonacci(5); to Fibonacci(6);, which will have a different result.
  • Debug the application.
  • When Debug.Assert is run in the code, the debugger stops the application so you can inspect variables, watch window, call stack, and more. It also outputs the message to the debug console.
1
2
3
4
5
6
7
---- DEBUG ASSERTION FAILED ----
---- Assert Short Message ----
The return value is not 5 and it should be.
---- Assert Long Message ----

   at Program.<<Main>$>g__Fibonacci|0_0(Int32 n) in C:\Users\Jon\Desktop\DotNetDebugging\Program.cs:line 23
   at Program.<Main>$(String[] args) in C:\Users\Jon\Desktop\DotNetDebugging\Program.cs:line 3
  • Stop debugging, and then run the application without debug by entering the following command in the terminal.
1
dotnet run
  • The application is terminated after the assertion has failed and information has been logged to the application output.
1
2
3
4
Process terminated. Assertion failed.
The return value is not 5 and it should be.
   at Program.<<Main>$>g__Fibonacci|0_0(Int32 n) in C:\Users\Jon\Desktop\DotNetDebugging\Program.cs:line 23
   at Program.<Main>$(String[] args) in C:\Users\Jon\Desktop\DotNetDebugging\Program.cs:line 3
  • Now, let’s run the application in Release configuration with the following command in the terminal.
1
dotnet run --configuration Release
  • The application successfully runs to completion because we’re no longer in the Debug configuration.

Congratulations, you’ve successfully and efficiently debugged code by using features of .NET, which include Debug.WriteLine and Debug.Assert. Well done!

This post is licensed under CC BY 4.0 by the author.