Supercharged .NET Core Logging With The PostSharp Logging Framework

Some time back, I wrote a post about PostSharp Threading. I was incredibly impressed by the fact that a complicated task such as thread synchronization had been boiled down to just a couple of C# attributes. While writing the post, I also took a look at the other libraries available from PostSharp, and something that caught my eye was the PostSharp Logging framework. Now I’ve seen my fair share of logging frameworks so at first, I wasn’t that jazzed. Generally speaking when I see a new logging library get released, it’s just another way to store text logs and that’s about it. But PostSharp Logging does something entirely new, without completely re-inventing the wheel.

Of course we are going to dig into all the goodness, but at an overview level. PostSharp Logging is more like a mini APM by automatically logging what’s going on inside your application, rather than just giving you some static “Logger.Error(string message)” method to output logs to. And instead of making you configure yet another logging platform with complicated XML files and boilerplate code, it just hooks into whatever logging framework you are already using. Serilog, Log4Net, and even just plain old ASP.NET Core logger factory are supported with very little setup.

Setting Up Logging

I’ve kind of sold the zero setup time a little bit here so let’s look at actually what’s required.

The first thing we have to do is install the nuget package for our particular logging framework. Now this might get complicated if you are using things like Serilog or Log4Net on top of the .NET Core logger, but for me, I’m just looking to pump all messages to the standard .NET Core output. So all I need to do is install the following two packages :

Install-Package PostSharp.Patterns.Diagnostics
Install-Package PostSharp.Patterns.Diagnostics.Microsoft

Next, I have to do a little bit of work in my program.cs to add the PostSharp logger :

public static void Main(string[] args)
{
    var host = CreateHostBuilder(args).Build();
    var loggerFactory = (ILoggerFactory)host.Services.GetService(typeof(ILoggerFactory));
    LoggingServices.DefaultBackend = new MicrosoftLoggingBackend(loggerFactory);
    host.Run();
}

This might seem a little complicated, but actually you’re just going to be copy and pasting this from the documentation from PostSharp, there actually isn’t much thought involved!

And that’s it! Now we can simply add the [Log] attribute to any method and have it log some pretty juicy stuff. For example, consider the following code :

[Log]
[HttpGet("Hello")]
public async Task Hello([FromQuery]string name)
{
    if(string.IsNullOrEmpty(name))
    {
        return BadRequest("A name is required");
    }

    return Ok($"Hello {name}!");
}

With nothing but the log attribute, I suddenly see these sorts of messages popping up when I call a URL such as /Hello?name=Bob.

dbug: PostSharpLogging.Controllers.TestController[2]
      TestController.Hello("Bob") | Starting.
dbug: PostSharpLogging.Controllers.TestController[4]
      TestController.Hello("Bob") | Succeeded: returnValue = {OkObjectResult}.

Notice how I now capture the method being executed, the parameters being executed, and what the result was. This can be incredibly important because not only are you capturing what methods are running, but you are capturing the input and output of those methods. This could be invaluable if you’re trying to debug under what circumstances a particular method fails or produces an unexpected response.

Writing Detailed APM Style Logging Messages

Earlier I spoke a little bit about how I thought PostSharp.Logging was more like a mini APM rather than a logging framework. That doesn’t mean it can’t log your standard text messages, but at the same time, it has incredible capability to “time” methods and capture exactly what’s going on in your application with very little set up.

All I need to do is create a file in the root of my project called postsharp.config. In it, I add the following :

<?xml version="1.0" encoding="utf-8"?>
<Project xmlns="http://schemas.postsharp.org/1.0/configuration">
  <Logging xmlns="clr-namespace:PostSharp.Patterns.Diagnostics;assembly:PostSharp.Patterns.Diagnostics">
    <Profiles>
      <LoggingProfile Name="Detailed" IncludeSourceLineInfo="True" IncludeExecutionTime="True" IncludeAwaitedTask="True">
      </LoggingProfile>
    </Profiles>
  </Logging>
</Project>

It may look confusing at first, but the PostSharp documentation gives you almost all of this out of the box. So what are we now adding to our logs?

• Capturing the source line info (e.g. What line number is being executed).
• Capturing the total execution time for a method.
• Including awaited tasks (More on this later!). But this means that we can actually see when a task is really awaited which is invaluable to solving deadlock issues.

All of this is combined to create named logging profile called “Detailed”. Named profiles are handy because we can now change all of the logging for our project from this one configuration file, instead of going around and modifying Log attributes one by one.

It does mean that we have to modify our Log attribute to look like this :

[Log("Detailed")] // Pass in our log profile name
[HttpGet("Hello")]
public async Task Hello([FromQuery]string name)
{
    if(string.IsNullOrEmpty(name))
    {
        return BadRequest("A name is required");
    }

    return Ok($"Hello {name}!");
}

And now if we run things?

dbug: PostSharpLogging.Controllers.TestController[4]
      TestController.Hello("Bob") | Succeeded: returnValue = {OkObjectResult}, 
      executionTime = 0.40 ms, 
      source = {WeatherForecastController.cs: line 18}.

So now not only are we capturing the input and output, but we are also capturing the total execution time of the method as well as the actual line number of the code. If there was a particular input to this method that caused a slow down or a noticeable performance impact, then we would be able to capture that easily. In fact, let’s test that out now!

Capturing Performance Degradations With PostSharp Logging

I want to create an artificial delay in my application to test how PostSharp Logging identifies this. But before I do this, I want to explain a concept called “Wall Time”.

Wall Time is also sometimes called Wall Clock Time, or even just Real World Time. What it means is that if I’m timing the performance of my application, the only real metric I care about is the actual time a user sits there waiting for a response. So it’s the time from a user say, clicking a button, to actually seeing a response. We call this Wall Time or Wall Clock Time, because if there was a clock on the wall, we could use it to time the response. Now where this can deviate slightly when compared to things such as “CPU Time”. CPU Time refers to how much time the CPU actually spent completing your task. This may differ because the CPU may be juggling work, or it may delay your work because it’s processing someone else’s request, or you may even have an intentional delay in your code.

Confused? Maybe this simplified diagram will help.

Notice how our user in blue sent a request to the CPU, but it was busy servicing our user in red. Once it finished red’s tasks, it then swapped to blue. If you asked the CPU how long it spent working on blue’s task, it will give a very different answer to if you asked the blue user how long they waited. Both timing’s are important, but it’s an important distinction to make when you are building software for end users.

OK, so with that out of the way, why do I bring it up now? Well there is a very large APM product on the market right now that gives timings in CPU Time. While helpful, this was actually incredibly irritating because it doesn’t capture the time a user actually spent waiting. And there is a very easy test for this, and that is to use Task.Delay to simulate the CPU not doing work.

Let’s modify our code to look like so :

[Log("Detailed")]
[HttpGet("Hello")]
public async Task Hello([FromQuery]string name)
{
    if(string.IsNullOrEmpty(name))
    {
        return BadRequest("A name is required");
    }

    if(name == "wade")
    {
        await Task.Delay(1000);
    }

    return Ok($"Hello {name}!");
}

Now if I pass in the name “wade”, I’ll be forced to wait an extra 1000ms before I am given a response. So how does PostSharp log this?

dbug: PostSharpLogging.Controllers.TestController[16]
      TestController.Hello("wade") | Awaiting: asyncCallId = 1, awaitedMethod = Task.Delay
dbug: PostSharpLogging.Controllers.TestController[32]
      TestController.Hello("wade") | Resuming: asyncCallId = 1, awaitedMethod = Task.Delay
dbug: PostSharpLogging.Controllers.TestController[4]
      TestController.Hello("wade") | Succeeded: returnValue = {OkObjectResult}, executionTime = 1038.39 ms

Interesting, the first thing to note is that because I earlier turned on logging for awaited methods, I can now even see when a method is actually awaited, and when it’s resumed. This is really important when working with async/await because not every time you await a method, do you truly await it (But more on that in another post).

Most importantly, look at our execution time! 1038ms. PostSharp is indeed logging the execution time correctly as it pertains to wall time. This is exactly what we want. It may seem like something so simple, but as I’ve said, I know of APM products on the market right now that can’t get this right.

There’s still something more I want to do with this code however. We’re still logging an awful lot when really we just want to capture logging if the performance is degraded. And of course, PostSharp Logging provides us with this. If we modify our logging profile to look like so :

<LoggingProfile Name="Detailed" ExecutionTimeThreshold="200" IncludeSourceLineInfo="True" IncludeExecutionTime="True" IncludeAwaitedTask="True"> 
</LoggingProfile>

We set the ExecutionTimeThreshold to be 200ms. And anything over that we get :

warn: PostSharpLogging.Controllers.TestController[32768]
      TestController.Hello("wade") | Overtime: returnValue = {OkObjectResult}, executionTime = 1012.60 ms, threshold = 200 ms}.

Notice how this is a “Warn” message, not a debug message. Now we can perfectly isolation performance impacts to this particular input, rather than sifting through thousands of logs.

Logging Multiple Methods

Let’s say that you’ve already got a large existing project, but you want to add logging to all controller actions. If we used our code above, we would have to go through copy and pasting our Log attribute everywhere which could be quite the task. And again, if we ever want to remove this logging, we have to go through deleting the attribute.

But PostSharp has us covered with “Multicasting”. Multicasting is the ability to apply the attribute to multiple declarations using a single line of code. And best of all, it allows us to filter where we apply it by using wildcards, regular expressions, or even filtering on some attributes. That means it’s not an all or nothing approach. We can almost fine tune where we log just as well as if we were placing the Log attribute manually on each method.

To get started, create a file called “GlobalLogging.cs” and place it in the root of your project.

Inside, we’re gonna add the following :

using PostSharp.Extensibility;
using PostSharp.Patterns.Diagnostics;

[assembly: Log(AttributePriority = 1,
ProfileName = “Detailed”,
AttributeTargetTypes =”MyProjectName.Controllers.*”,
AttributeTargetMemberAttributes = MulticastAttributes.Public)]

All we are saying is, add the Log attribute, with the ProfileName of “Detailed”, to all target types that are under the controllers namespace. I’m also going to add another filter to say only do this for public methods.

Running my project now, I receive all of the same logging on all of my controller methods, but without having to manually add the Log attribute!

Again, the simplicity of PostSharp stands out. We can add multiple of these global attributes to this file, all with specifically fine tuned wildcards/regexes, and just have it… work. I almost want to write more about all the options you can do with this, but it’s just all so simple and works out of the box, that I’m literally just giving one liners to completely re-invent your logging. It’s really great stuff.

Who Is This Library For?

If you’re working on a software stack that requires you to be constantly managing performance and fine tuning the system, then I think PostSharp Logging is kind of a no brainer. I think the name of “Logging” implies that all it’s really going to do is write text logs for you, but it’s so much more powerful than that.

I’ve used off the shelf APM products that don’t do as good of a job really isolating down to the method logging, and those come with a monthly subscription and a slow, lag ridden portal to boot. I think the bring-your-existing-logging-framework is one of the most powerful aspects of PostSharp, just being able to use what you already have, but supercharge those logs along the way.

This is a sponsored post however all opinions are mine and mine alone.