ASP.NET Core Distributed Tracing, using Steeltoe

Introduction

In the previous article I described about, how to create a simple scoped logging using Microsoft.Extensions.Logging with/without Serilog. Extending the same, here I describe on, how we can trace the logs in a distributed way across the communicating systems, using Steeltoe. For more information on Steeltoe’s Distributed Tracing, please refer here.

Distributed tracing really helps, applications running in cloud, especially when they are very much distributed. For example, if an application A starts a request, where is passes on to application B, C, D, etc. and then when it returns back, we wonder how to trace the request across these applications? It’s really going to be a very big challenge, even if we use external log monitoring and analysis tools like Splunk, Graylog, etc. Here comes an open source project OpenCensus which helps in distributed tracing where these traces can be exported to tracing systems like Zipkin. But the downside is, there is limited support for .NET from them. Here is where Steeltoe comes into play which helps us in using these tools across .NET applications.

Let’s go through the important steps one-by-one below. But as I mentioned above you can also find more details in Steeltoe.io.

1. Pre-requisites

• Make sure you have Visual Studio (latest version)/Visual Studio Code is installed in your machine
• Make sure you have .NET Core SDK version 2.1.x is installed in your developer machine

2. Install Nuget Packages

In your ASP.NET Core application, install latest version of below packages from NuGet.org

1. 1. Steeltoe.Management.TracingCore
   2. Steeltoe.Extensions.Logging.DynamicLogger

3. Add Dynamic Console Logging

In Program.cs, please add the below code to configure logging of the application. Here we are adding an extension method provided by Steeltoe, with adds a logging actuator (allows to control the log level of an application at runtime from PCF Apps Manager). But how is it going to help us here? It helps by appending the trace information to each log entry that the application emits. For e.g. if the usual log looks like info: Processing foo bar when you have distributed tracing turned on, the dynamic logger will append and emit the log as info: [app1,2485ec27856c56f4,2485ec27856c56f4,true], Processing foo bar where trace section detail is [app_name, trace_id, span_id, trace_flags]

If you have other logging providers, you may have to append this manually which we will discuss in another article.

Below is the code snippet with namespaces…

using Microsoft.Extensions.Logging;
using using Steeltoe.Extensions.Logging;

…

.ConfigureLogging((builderContext, loggingBuilder) =>
                {
                    loggingBuilder.ClearProviders();

                    loggingBuilder.AddConfiguration(builderContext.Configuration.GetSection("Logging"));
                    loggingBuilder.AddDynamicConsole();
                })

Please add necessary logging configurations under Logging as below sample.

"Logging": {
    "LogLevel": {
      "Default": "Debug",
      "System": "Information",
      "Microsoft": "Information"
    }
  }

4. Add Distributed Tracing

In Startup.cs, under ConfigureServices, add the services extension method AddDistributedTracing. This will inject all the necessary components to create tracing pieces like spans, traces, etc. within the scope of a particular request (request, response, exceptions, etc). For more details, please refer here.

Below is the code snippet with namespaces…

using Steeltoe.Management.Tracing;

…

public void ConfigureServices(IServiceCollection services)
        {
            services.AddDistributedTracing(Configuration);
            services.AddMvc().SetCompatibilityVersion(CompatibilityVersion.Version_2_1);
        }

You can also further configure tracing by adding below configuration section and customizing accordingly. For more details on options, please refer to 2.2.2 Configure Settings from here.

"management": {
    "tracing": {
      "alwaysSample": true,
      "egressIgnorePattern": "/api/v2/spans|/v2/apps/.*/permissions|/oauth/.*",
      "useShortTraceIds ": false
    }
  }

5. Observation

It would be interesting to see how 2 applications emits their tracing logs, when they communicate to each other. To observe this, please apply the above discussed, on at least 2 ASP.NET Core apps which communicates to each other and observer the logs. You will see the span_id same across the logs between the applications.

Just to illustrate visually with an example,

Let app Requestor be the request initiator and sending a request to app Processor, which process and sends back the result. For a particular request, you may notice the logs as below

App Requestor logs…

info: Requestor.Controllers.InvokeController[0]
[Requestor,e60364a65f97077b,c6078a62bdc53334,5bb9ae3641b6e2ec,true] Sending request to Processor application

App Processor logs…

info: Processor.Controllers.ProcessingController[0]
[Processor,e60364a65f97077b,a0035a832410efcc,54932218ecc222de,true] Processing the request sent from Requestor application

If you notice the above 2 application logs, you will notice that the span_id e60364a65f97077b is same across the 2 applications, for the same request.

Code Reference

Find the working sample application here for quick reference. You can also refer to SteeltoeOSS samples.

Hope you had fun coding!