Implementing logging in .net core applications for logging, telemetry and your own sanity

It's best I start this post off with this statement. I love having logging in my applications, but I hate having to clutter my code with logging statements!

Logging is one of the most important things in most software developers daily work lives. It forms such a key of what we do on a day to day basis. If we get a bug report, or notification of a system failure or any notification that something has gone wrong, the first thing you'll resort to is to go "read the logs". In the hope that somewhere in those logs files will be a clue as to what events occurred to the lead up of the issue.

Analysing the statistics from application telemetry reports is also a great way to get handle on just how much Technical Debt your application stack has incurred overtime, by providing indicators of what the key areas that need some attention and refactoring opportunities. We accept that as software engineers our first attempt at solving problems may never be the best, and we can also inadvertently introduce bottlenecks in our code.

If your team is focused on developing products or services for customers or even business units then Logging and Telemetry will be an essential requirement, and not just for debugging and trouble shooting. As Marty Cagan points out in his book, Inspired : How to create tech products customers love , there are far too many products teams that do not have enough instrumentation within their software products to extract usage information. Products teams often have a set of assumptions on how products are used, but are then often surprised when they actually view the data.

In Chapter 54 Marty explains Quantitive Value Testing techniques, where logging and analytics provide the indepth data needed to inform product design decisions and inspire product work.

Logging becomes ever so more important when you enter the world of microservices. Sam Newman, presents the situation really well in his book Building Microservices: Designing Fine Grained Systems, primarily because when implementing microservices, monitoring and maintenance become more complicated.

In a microservice-based system the capabilities are served from multiple small services, some of which communicate with yet more services to accomplish tasks. There are many advantages to this approach, but in the world of monitoring, maintenance and problem finding engineers have complex problems to solve.

Top 5 reason for logging in application

1. Troubleshooting- Diagnose issues in applications
2. Audit - Significant events and activities in applications
3. Monitoring- System usage for preventing potential issues
4. Analysis- Improving system usage
5. Feed- Send data to other data analysis tools to support data-driven decision making

Implementing logging

A typical approach to logging is to interweave logging statements in your code for example your code may end up looking like the code below, and your actual logic of your function becomes cluttered up and worst of all contains more logging and telemetry code than actual functional code.

Personally, I find this also to ironically become the root cause of many bugs! It also increases the cyclomatic complexity of your code and as can be illustrated bad practices can slip in.

 public async override  Task<ActionResult<ArticleResponse>> HandleAsync([FromRoute] ArticleRequest request,
            CancellationToken cancellationToken = new CancellationToken())
{
     _telemetryService.RegisterRequest(nameof(Get));
     _logger.information($"ArticleRequest : {request.ToString()");
  try 
    {
       _logger.information($"Sending request via mediator function : {request.ToString()");
      var result = await _mediatr.Send(request)
      _logger.information($"function response : {result.ToString()");
      _telemetryService.ExitRequest(nameof(Get));
       return result;
    }
    catch (Exception ex)
   {
     _logger.Exception($" Exception raised {nameof(Get)}", ex);
     return null;
   }
}

Attributes and MiddleWare

Fortunately when using .net core, developers are able to use Attributes and Middleware which will enable you to implement this logic and separate concerns. However, it's not an entirely a trivial problem to solve, because there are questions like How do you pass data to the middelware for telemetry or logging? What about dynamic data?

All these challenges can be resolved just with a little bit of effort, and one were done or done our code. The purpose and intent of the code becomes clear and not lost within a myriad of cluttered logging code.

We've completely separated our telemetry and logging code and drastically simplified the cyclomatic complexity. It also makes it way easier and simpler to actually debug and step through the code!

[Telemetry(nameof(Get.HandleAsync)]
[Logging]  
public async override  Task<ActionResult<ArticleResponse>> HandleAsync([FromRoute] ArticleRequest request,
            CancellationToken cancellationToken = new CancellationToken())
 {            
     var result = await _mediatr.Send(request)
     return result;
 }

Developing a Simple Custom Attribute

Using .net core it is really simple to create custom middleware and attributes for your applications.

What are attributes in C#

An attribute is a declarative tag that is used to convey information to runtime about the behaviours of various elements like classes, methods, structures, enumerators, assemblies etc. in your program. You can add declarative information to a program by using an attribute. 

Attributes are used for adding metadata, such as compiler instruction and other information such as comments, description, methods and classes to a program. The .Net Framework provides two types of attributes: the pre-defined attributes and custom built attributes.

In this example we, focus on creating a Custom Built attribute, but if you're new to attributes or have not previously had exposure to them it's well worth taking 5 minutes to read the Attributes (C#) to get to know them a little better.

Lets create a first attribute, we'll create a highly simplified telemetry attribute to get started with. In our code sample which we created for the Developing Api’s using Http Endpoints

Code samples for all dotnet tutorials on my blog for reference
https://github.com/garywoodfine/Blog-Tutorials
5 forks.
20 stars.
0 open issues.

Recent commits:

• Reworked sample, Gary Woodfine
• working websoket, Gary Woodfine
• test, Gary Woodfine
• updated article example, Gary Woodfine
• Azure Blob tutorial completed, Gary Woodfine

In our example we'll create a folder in our web api project and name it Attributes, then we'll add a class in the folder and name it TelemetryAttribute.cs

public class TelemetryAttribute : Attribute
{
  public string ClassName { get; set; }
  public string Method { get; set; }
  public TelemetryAttribute(string className, string method)
 {
     Method = method;
     ClassName = className;
     Console.WriteLine($"Telemetry logging call {className}  {method}");
 }
}

We've created our very simple attribute, although it does do very much, we can still use it within our application.

We can now decorate our Get endpoint HandleAsync method as follows

[Telemetry(nameof(Get), nameof(Get.HandleAsync))]
public async override  Task<ActionResult<ArticleResponse>> HandleAsync([FromRoute] ArticleRequest request,
           CancellationToken cancellationToken = new CancellationToken())
{
    return await Task.Run(() =>
       new OkObjectResult(new ArticleResponse
        {
            Content = "blah blah blah blah blah ",
            Description = "This is a Fine Description",
            Published = DateTime.Now,
            Summary = "this is a fine Summary",
           SubHeading = "This is a sub heading"
        }), cancellationToken);
}

If we now run our application and execute a API endpoint we notice that we will see some new additional out in the console window

We have successfully implemented albeit very simple Telemetry attribute that we can now use through out our application to decorate on any method that we would like to carry out some telemetry reporting!

A couple of things worth taking note here, if at first not immediately obvious. You'll notice that when we named our class TelemetryAttribute but when we made use of it, we could just refer to it as [Telemetry] this is because of quirky convention in C# that any class inheriting from Attribute should have the postfix Attribute added when declaring, but when using the the attribute the postfix is entirely optional.

Its important to note that all attribute classes must inherit directly or indirectly from System.Attribute. Some key points to remember about attributes are

• You can apply one or more attributes to entire assemblies, modules, or smaller program elements such as classes and properties.
• Attributes can accept arguments in the same way as methods and properties.

Attributes can be placed on almost any declaration, though a specific attribute might restrict the types of declarations on which it is valid.

Developing a Custom Middleware

When developing attributes, you'll often want to make use of other aspects in your code base, for instance in our case, how do we get additional information about our method and even how do we dependency inject our Logger and make use of it in our attribute?

What is middleware in C#

Middleware are software components that are assembled into an application pipeline to handle requests and responses. Each component chooses whether to pass the request on to the next component in the pipeline, and can perform certain actions before and after the next component is invoked in the pipeline. Request delegates are used to build the request pipeline. The request delegates handle each HTTP request.

Request delegates are configured using Run, Map, and Use extension methods on the IApplicationBuilder type that are passed into the Configure method in the Startup class.

An individual request delegate can be specified in-line as an anonymous method, or it can be defined in a reusable class. These reusable classes are middleware, or middleware components. Each middleware component in the request pipeline is responsible for invoking the next component in the pipeline, or short-circuiting the chain if appropriate.

The ASP.net Core documentation discusses the ASP.net Core Middleware in detail

This can be a lot to understand all in one go, so lets get on and develop a very simple middleware component and see it action.

In our application create a folder, and we'll cunningly name it Middleware , then inside that folder create a new class which we'll call TelemetryMiddleware.cs then we'll just add the code below.

At this stage this Middleware is just still very simple, we're simply going to add just enough code to replicate the existing functionality in our previous attribute example.

using System;
using System.Threading.Tasks;
using Api.Attributes;
using Microsoft.AspNetCore.Http;
using Microsoft.AspNetCore.Http.Features;

namespace Api.Middleware
{
    public class TelemetryMiddleware
    {
        private RequestDelegate _next;

        public TelemetryMiddleware(RequestDelegate next)
        {
            _next = next;
        }

        public async Task Invoke(HttpContext context)
        {
            await _next(context);

            var endpoint = context.Features.Get<IEndpointFeature>()?.Endpoint;
            var attribute = endpoint?.Metadata.GetMetadata<TelemetryAttribute>();
            if (attribute != null)
            {
                var className = attribute.ClassName;
                var methodName = attribute.Method;
                Console.WriteLine($"Telemetry logging call {className}  {methodName}");
            }
        }
    }
}

We now need to register the middleware into the .net core pipeline, which is done in the Startup.cs in the Configure method.

public void Configure(IApplicationBuilder app, IHostingEnvironment env)
{
    // ...
    app.UseMiddleware<TelemetryMiddleware>();
    // ...
}

For the purpose of our Example we just need to our existing Attribute to remove the line of code that previously printing to the Console, because that responsibility has now shifted to the Middleware.

public class TelemetryAttribute : Attribute
{
  public string ClassName { get; set; }
  public string Method { get; set; }
  public TelemetryAttribute(string className, string method)
 {
     Method = method;
     ClassName = className;
 }
}

If we run our application now execute our endpoint, we notice that nothing much has changed, we still get out out in the Console window as expected. The only difference is now we have our Attribute and Middelware working in tandem with each other!

These are two important concepts to understand, because from these very simple beginnings we can now develop really powerful features!

We can evolve our very simple solution now that we have this very basic knowledge, let say we want to grab the values of the Parameters passed into our method, that we have decorated with our Telemetry attribute. We can achieve this will just a little but of refactoring.

I'll have to level with you that some of the refactoring will include actually removing some of the code we placed in our attribute, because we're going to find out what power middleware provides. We're going to remove the two properties we added to our TelemetryAttribute.cs

using System;
namespace Api.Attributes
{
    public class TelemetryAttribute : Attribute
    {
        public TelemetryAttribute()
        {
        }
    }
}

We can then also refactor the TelemetryMiddleware.cs , slighty to get the information from we need from the HttpContext and because we have that being injected into our middleware, we get the information and more from that.

using System;
using System.Threading.Tasks;
using Api.Attributes;
using Microsoft.AspNetCore.Http;
using Microsoft.AspNetCore.Http.Features;

namespace Api.Middleware
{
    public class TelemetryMiddleware
    {
        private RequestDelegate _next;

        public TelemetryMiddleware(RequestDelegate next)
        {
            _next = next;
        }

        public async Task Invoke(HttpContext context)
        {
            await _next(context);

            var endpoint = context.Features.Get<IEndpointFeature>()?.Endpoint;
            var attribute = endpoint?.Metadata.GetMetadata<TelemetryAttribute>();
            if (attribute != null)
            {
               Console.WriteLine($"Telemetry logging call { endpoint.DisplayName}");    
            }
        }
    }
}

If we just add the [Telemetry] to our API endpoint, and execute the code

To address our specific use case we are able to access a lot of options from the HttpContext that we may want to use in our Telemetry logging. The cool thing about this is that we can now customise our telemetry logging without having to go update it everywhere in our codebase.

We are able to drill down further into the HttpContext, as we have done in our code and derive more information about the Endpoint in current execution. Exploring around the details available on these properties will enable you to derive all the relevant information you need regarding the currently executing context.

Conclusion

Logging in code is extremely important and over the years having good logs have helped me solve all manner of weird bugs. Logging and monitoring are extremely important when embarking on microsevices based projects and ensuring you have a robust logging strategy will pay dividends.

I personally hate having to sprinkle logging statements throughout my code and I hate having to decipher what the business logic of a function does in between all the logging statements. The approaches I illustrated above is my preferred approach, and I find it extremely flexible and robust approach.