ASP.NET Core Logging & Telemetry Attributes

The business logic code can be changed without actually adding meta functionality. In this case, telemetry can be reported, logs can be created, or metrics can be added. This code must be written with the business logic, but it seems odd to write it alongside it. Business logic is hard to read, there is no separation of concerns, and bugs are common.

In ASP.NET Core, attributes and middleware systems can be used to add this kind of logic. It is easier to read code that is clean and separates concerns. Problems like this aren’t trivial. Using middleware, how do you feed telemetry or logging information to it? During runtime, do you have dynamic data? When doing an HTTP request, how do you get the values? This article will show you how to accomplish all of these things and more.

Let’s consider the following scenario for adding telemetry to your ASP.NET controllers. To put it another way, you are interested in analyzing user actions. Suppose you are interested in SignUp and SignIn. From within the action, you can call the following method:

public async Task<IActionResult> SignUp([FromBody]SignUpViewModel vm)
{
	_telemtryService.RegisterEvent(TelemetryEvent.SignUp);
	// ...
}

public async Task<IActionResult> SignIn([FromBody]SignInViewModel vm)
{
	_telemtryService.RegisterEvent(TelemetryEvent.SignIn);
	// ...
}

There’s nothing wrong with this, I won’t judge you, but wouldn’t it be better to create code that looks like this?

[TelemetryAttribute(TelemetryEvent.SignUp)]
public async Task<IActionResult> SignUp([FromBody]SignUpViewModel vm)
{
	// ...
}

[TelemetryAttribute(TelemetryEvent.SignIn)]
public async Task<IActionResult> SignIn([FromBody]SignInViewModel vm)
{
	// ...
}

This separates the concerns about telemetry from those about business logic. It is also easier to read the code.

ASP.NET Core users can use custom middleware to accomplish this easily.

Middleware that is simple to customize

Creating an attribute is the first step:

public class TelemetryAttribute : Attribute
{
    public TelemetryEvent Event { get; set; }
        
    public TelemetryAttribute(TelemetryEvent ev)
    {
        Event = ev;
    }
}

public enum TelemetryEvent { SignUp, SignIn}

Our middleware class should look like this:

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

    public async Task Invoke(HttpContext context)
    {
        await _next(context); // Here the action in the controller is called

        // a try/catch can be added here because you don't want middleware failures to interfere with normal functionality
        var endpoint = context.Features.Get<IEndpointFeature>()?.Endpoint;
        var attribute = endpoint?.Metadata.GetMetadata<TelemetryAttribute>();
        if (attribute != null)
        {
            var ev = attribute.Event;
            // add telemetry or logging here
        }
    }
}

In this case, we must make some creative choices. This code illustrates how controller actions occur before telemetry functions. Perhaps you would prefer it the other way around. Perhaps both at the same time. If the controller exception occurs, what should you do? Does the telemetry still need to be executed? Do nothing? Are you reporting telemetry events that indicate failure?

As a result, the middleware has to be registered into the pipeline of ASP.NET Core. This can be done by editing Startup.cs in Configure as follows:

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

All set, you should now be able to use the middleware.

Middleware makes use of request data

Adding a little complexity to this problem would be helpful. Take a look at SignUp telemetry and imagine that you want the email address of the user included.

Doesn’t that seem reasonable to you? The question then is, how can dynamic information be passed through a middleware and an attribute? Several ways can be used to accomplish this, but it’s a bit tricky. The business logic code can be modified by getting the attribute object and updating it.

As seen in the controller:

[HttpPost]
[TelemetryAttribute(TelemetryEvent.SignUp)]
public async Task<IActionResult> SignUp([FromBody]SignUpViewModel vm)
{
	var attribute = HttpContextHelper.GetEndPointAttribute<TelemetryAttribute>(Request.HttpContext);
	attribute.Data = vm.Email;
	// ...
}

Attributes:

public class TelemetryAttribute : Attribute
{
    public TelemetryEvent Event { get; set; }
    public string Data { get; set; } //added

    public TelemetryAttribute(TelemetryEvent ev)
    {
        Event = ev;
    }
}

This is what happens in the middleware:

public class TelemetryMiddleware
{
    private RequestDelegate _next;

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

    public async Task Invoke(HttpContext context)
    {
        await _next(context); // Should be called BEFORE the following for the Data to be populated
            
        var endpoint = context.Features.Get<IEndpointFeature>()?.Endpoint;
        var attribute = endpoint?.Metadata.GetMetadata<TelemetryAttribute>();
        if (attribute != null && attribute.Event == TelemetryEvent.SignUp)
        {
            var email = attribute.Data;
            // add telemetry or logging here
        }
    }
}

Your first reaction would be to think this isn’t pretty. Within the business logic, both attributes and lines of code are present. The attribute should be removed and telemetry should be accessed directly. My agreement with you is without a doubt. Perhaps you’ve already added 20 attributes to your code without adding the additional information required for one telemetry event.

There are a few possible better ways to accomplish this than the above method, and I will not judge you for it.

Gathering request body data in middleware

There is a way to get the Email field in the middleware itself if you want to separate telemetry/logging functionality from business logic. As part of the middleware, you will need to parse and read the request body. You can do it by following these steps:

public class TelemetryMiddleware
{
    private RequestDelegate _next;

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

    public async Task Invoke(HttpContext context)
    {
        //This is important to call BEFORE invoking action to be able to read the body again afterwards
        context.Request.EnableBuffering(); // Use .EnableRewind() for ASP.NET Core 2.x

        await _next(context); // The action in the controller will be called here
            
        var endpoint = context.Features.Get<IEndpointFeature>()?.Endpoint;
        var attribute = endpoint?.Metadata.GetMetadata<TelemetryAttribute>();
        if (attribute != null && attribute.Event == TelemetryEvent.SignUp)
        {
            var bodyStr = await GetRequestBody(context);
            var vm = JsonConvert.DeserializeObject<SignUpViewModel>(bodyStr);
            var email = vm.Email;
            // add telemetry or logging here
        }
    }

    private static async Task<string> GetRequestBody(HttpContext context)
    {
        var req = context.Request;
        req.Body.Position = 0; //Rewind to initial position
		// The `leaveOpen` should be `true` if there's another middleware using this after or if the action going to be invoked AFTER this middleware
        using (StreamReader reader
            = new StreamReader(req.Body, Encoding.UTF8, detectEncodingFromByteOrderMarks: true, leaveOpen: true))
        {
            return await reader.ReadToEndAsync();
        }
    }
}

By reading the HTTP request body straight from JSON and deserializing it, the above code reads the email body directly. ASP.NET’s standard behavior needs to be changed for you to accomplish this. Request body streams are disposed of by default as soon as they are read. We have to call the EnableBuffering method in our case in order to prevent the stream from being read twice. Finally, rewind the stream to position 0.

Performance could be adversely affected by this code. The body’s JSON is read twice and deserialized twice, which is a waste. Memory pressure is also affected. You will have a greater chance of promoting the request body to a higher garbage collection generation if you keep the request body in memory for a longer period of time.

As a result, the GC will have to spend more time executing Gen 1 and Gen 2 collections, resulting in slower performance. When it comes to memory management, fast object collection is the rule of thumb. A collection from a higher generation costs more than one from a lower generation. The following techniques are described in my article 8 Techniques to Avoid GC Pressure and Improve Performance in C#.NET.

Request parameters can be used to determine dynamic properties

Despite its efficiency, the method above doesn’t seem very generic (performance issues aside). There may be different fields needed for different telemetry actions. The email address might be used for signing up, the full name might be used for logging in, and the item ID might be used for buying. This method makes it easy to convert middleware into a generic mechanism.

In the controller (note the queryParam addition):

[HttpPost]
[TelemetryAttribute(TelemetryEvent.SignUp, queryParam: "email")]
public async Task<IActionResult> SignUp(string email, string firstName, string lastName)
{
    // ...
}

In the attribute:

public class TelemetryAttribute : Attribute
{
    public TelemetryEvent Event { get; set; }
    public string QueryParam { get; set; } // Added

    public TelemetryAttribute(TelemetryEvent ev, string queryParam)
    {
        Event = ev;
        QueryParam = queryParam;
    }
}

In the middleware:

public class TelemetryMiddleware
{
    private RequestDelegate _next;

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

    public async Task Invoke(HttpContext context)
    {
        await _next(context); // The action in the controller will be called here

        var endpoint = context.Features.Get<IEndpointFeature>()?.Endpoint;
        var attribute = endpoint?.Metadata.GetMetadata<TelemetryAttribute>();
        if (attribute != null)
        {
            var data = context.Request.Query[attribute.QueryParam];// this will be the email
            // add telemetry or logging here
        }
    }
}

This approach really appeals to me. The middleware will not have to have multiple switches/cases for different types of events. Changing the value of queryParam in the attribute is the only thing that needs to be changed in the middleware code.

In order for this to work, it is necessary to pass the items as query parameters and not as body elements. However, you can use JSONPath (similar to XPath for JSON) to implement the same logic in the body as well. It’s up to you to handle that part.

Conclusion:

In this lesson, we learned how to separate telemetry code from business logic code using ASP.NET Core’s middleware system. The versatility of ASP.NET Core is one of the reasons I love it. Even though the request body was a bit tedious to get. I think it’s pretty cool to be able to simply add attributes to enable adding telemetry. If you have any thoughts, let me know in the comments.

Leave a Comment