ASP.NET 5 and Log Correlation by Request Id

ASP.NET 5 is full of big new features and enhancements but besides these, I am mostly impressed by little, tiny features of ASP.NET 5 Log Correlation which is provided out of the box. Let me quickly show you what it is in this post.
2015-10-28 00:44
Tugberk Ugurlu


ASP.NET 5 is full of big new features and enhancements like being able to run on multiple operating systems, incredible CLI tools, hassle-free building for multiple framework targets, build only dependencies and many more. Besides these, I am mostly impressed by little, tiny features of ASP.NET 5 because these generally tend to be ignored in this type of rearchitecturing works. One of these little features is log correlation. Let me quickly show you what it is and why it made me smile.

BIG ASS CAUTION! At the time of this writing, I am using DNX 1.0.0-beta8 version. As things are moving really fast in this new world, it’s very likely that the things explained here will have been changed as you read this post. So, be aware of this and try to explore the things that are changed to figure out what are the corresponding new things.

Also, inside this post I am referencing a lot of things from ASP.NET GitHub repositories. In order to be sure that the links won’t break in the future, I’m actually referring them by getting permanent links to the files on GitHub. So, these links are actually referring the files from the latest commit at the time of this writing and they have a potential to be changed, too. Read the "Getting permanent links to files" post to figure what this actually is.

Brief Introduction to Logging in ASP.NET 5 World

If you want to skip this part, you can directly go to "Log Correlation" section below.

As you probably know, ASP.NET 5 also has a great support for logging. The nicest thing about this new logging abstraction is that it’s the only logging abstraction which every provided library and framework is relying on. So, when you enable logging in your application, you will enable it in all components (which is perfect)! Here is a sample in my MVC 6 application. I am just adding MVC to pipeline here, enabling logging by hooking Serilog and configuring it to write the logs to console:

using System;
using Microsoft.AspNet.Builder;
using Microsoft.Framework.DependencyInjection;
using Microsoft.Framework.Logging;
using Serilog;

namespace LoggingCorrelationSample
{
    public class Startup
    {
        public Startup(ILoggerFactory loggerFactory)
        {
            var serilogLogger = new LoggerConfiguration()
                .WriteTo
                .TextWriter(Console.Out)
                .MinimumLevel.Verbose()
                .CreateLogger();

            loggerFactory.MinimumLevel = LogLevel.Debug;
            loggerFactory.AddSerilog(serilogLogger);
        }

        public void ConfigureServices(IServiceCollection services)
        {
            services.AddMvc();
        }

        public void Configure(IApplicationBuilder app)
        {
            app.UseMvc();
        }
    }
}

When I run the application and hit a valid endpoint, I will see bunch of things being logged to console:

image

Remember, I haven’t logged anything myself yet. It’s just the stuff I hooked in which were already relying on ASP.NET 5 logging infrastructure. This doesn’t mean I can’t though. Hooking into logging is super easy since an instance of ILoggerFactory is already inside the DI system. Here is an example class which I have for my application and it is responsible for getting the cars (forgive the stupid example here but I am sure you will get the idea):

public class CarsContext : IDisposable
{
    private readonly ILogger _logger;

    public CarsContext(ILoggerFactory loggerFactory)
    {
        _logger = loggerFactory.CreateLogger<CarsContext>();
        _logger.LogDebug("Constructing CarsContext");
    }

    public IEnumerable<string> GetCars()
    {
        _logger.LogInformation("Found 3 cars.");
        
        return new[]
        {
            "Car 1",
            "Car 2",
            "Car 3"
        };
    }
    
    public void Dispose()
    {
        _logger.LogDebug("Disposing CarsContext");
    }
}

I will register this class so that it can get the dependencies it needs and also, it can be injected into other places:

public void ConfigureServices(IServiceCollection services)
{
    services.AddMvc();
    services.AddScoped<CarsContext, CarsContext>();
}

Finally, I will use it inside my controller:

public class CarsController : Controller
{
    private readonly CarsContext _carsContext;
    
    public CarsController(CarsContext carsContext)
    {
        _carsContext = carsContext;
    }
    
    [Route("cars")]
    public IActionResult Get()
    {
        var cars = _carsContext.GetCars();
        return Ok(cars);
    }
}

Just seeing how beautifully things are coming together is really great! When I run the application and hit the /cars endpoint now, I will see my logs appearing along side the framework and library logs:

image

Same goes for your middlewares. You can naturally hook into logging system from your middleware thanks to first class middleware DI support.

public class RequestUrlLoggerMiddleware 
{
    private readonly RequestDelegate _next;
    private readonly Microsoft.Framework.Logging.ILogger _logger;
    
    public RequestUrlLoggerMiddleware(RequestDelegate next, ILoggerFactory loggerFactory) 
    {
        _next = next;
        _logger = loggerFactory.CreateLogger<RequestUrlLoggerMiddleware>();
    }
    
    public Task Invoke (HttpContext context)
    {
        _logger.LogInformation("{Method}: {Url}", context.Request.Method, context.Request.Path);
        return _next(context);
    }
}

Notice that we have a log message template rather the actual log message here. This is another great feature of the new logging system which is pretty much the same as what Serilog have had for log time.

When we run this, we should see the middleware log appear, too:

image

Log Correlation

Without doing anything else first, let me also write logs to Elasticsearch by pulling in Serilog Elasticsearch sink and hooking it in. After hitting the same endpoint, I have the below result inside my Elasticsearch index:

image

You can see that each log message has got richer and we can see new things like RequestId which will allow you to correlate your logs per request. This information is being logged because the hosting layer starts a new log scope for each request. RequestId is particularly useful when you have an unexpected behavior with an HTTP request and you want to see what was happening with that request. In order to take advantage this, you should send the the RequestId along side your response (ideally among the response headers). The below is a sample middleware which you can hook into your pipeline in order to add RequestId to your response:

public class RequestIdMiddleware
{
    private readonly RequestDelegate _next;

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

    public async Task Invoke(HttpContext context)
    {
        var requestIdFeature = context.Features.Get<IHttpRequestIdentifierFeature>();
        if (requestIdFeature?.TraceIdentifier != null)
        {
            context.Response.Headers["RequestId"] = requestIdFeature.TraceIdentifier;
        }

        await _next(context);
    }
}

Note that, IHttpRequestIdentifierFeature is the way to get a hold of RequestId in beta8 but in upcoming versions, it’s likely to change to HttpContext.TraceIdentifier.

If you look at the response headers now, you should see the RequestId header there:

HTTP/1.1 200 OK
Date: Wed, 28 Oct 2015 00:32:22 GMT
Content-Type: application/json; charset=utf-8
Server: Kestrel
RequestId: 0b66784c-eb98-4a53-9247-8563fad85857
Transfer-Encoding: chunked

Assuming that I have problems with this request and I have been handed the RequestId, I should be able to see what happened in that request by running a simple query on my Elasticsearch index:

image

That’s pretty much it and as mentioned, this is one those tiny features which was always possible but painful to get it all right. If you are also interested, you can find the full source code of the sample under my GitHub repository.

Profiling ASP.NET 5 Applications with ANTS Performance Profiler

ANTS Performance Profiler from Redgate supports ASP.NET 5 applications running on DNX and it allows you to profile your ASP.NET 5 applications to spot performance problems in a really easy and unobtrusive way. In this blog post, I will show you how it can help you with a sample.
2015-10-20 19:16
Tugberk Ugurlu


One of the biggest challenges with ASP.NET 5 is the fact that most of the existing tools and libraries are not supporting the ecosystem as it’s a complete revamp of the runtime and some of the concept we have been used to in both development and production. However, some tools catch up quite surprisingly fast and one of those tools is ANTS Performance Profiler from Redgate and it allows you to profile your ASP.NET 5 applications to spot performance problems in a really easy and unobtrusive way.

ANTS Performance Profiler is a paid tool but it has a 14-day free trial option. Also, if you are a Microsoft MVP, you can get a free license for this tool. If this sounds like you, visit Redgate community page and claim your free license by following the instructions there.

When you open up ANTS .NET Performance Profiler, you should immediately notice the ASP.NET 5 section:

image

From there, it’s all pretty straight forward to move along. Just select the project.json file path for your application and the DNX runtime that your application should run on. Optionally, you can configure other profiling options like collecting additional performance counters. When you are ready, you can just hit the "Start profiling" button and go!

2015-10-20_19-31-35

One feature that I am in love with here is incoming HTTP requests view. The tool knows about received requests during the profiling session and you can see where they started on the class stack:

image

You can see that you are able to see the hint count and average times for request to complete. From here, I can jump straight to the HTTP request that I am interested in:

image

Notice that it starts with ErrorHandlerMiddleware on the call tree. The reason is that it’s the first middleware in my middleware chain and I configured ANTS Performance Profiler to only show me the methods with source as you can see at top on the screenshot above. So, it filtered the call stack a little for me and I can look at the source of the actual methods if I want to:

image

Profiling Bottlenecks

ANTS Performance Profiler makes it extremely easy to spot bottlenecks in your applications. I will show you a sample based on a personal experience I had before but I will fake the problem here a little :) However, the narrative is quite similar to what I went through but I struggled a lot more that this as I didn’t use a profiling tool to understand the problem.

In my simple sample, I have an object which I know that it will take a bit time to construct because of its nature and I am fine with that. The good news is that this object is thread safe and I can share it among multiple requests. However, I am seeing big CPU spikes when I run my application. To spot the problem, I ran a profiling session with ANTS Performance Profiler. Right after stopping the profiling session, I landed on the problem. So easy and that makes me perfectly happy!

image

I know that the constructor could have been the problem but I really didn’t expect it to be this much. I know that it takes around ~2 seconds to be constructed under a good functioning CPU but when I look at the actual time spent there, it’s around ~32 seconds:

image

So, that’s not normal at all and as soon as I saw that number, I turned my eyes to hit count. There, I saw that it has been called 9 times! That’s way more than expected as I only wanted a single object for the whole application. I am only constructing this object through my IoC container and in this case, it should only mean that my IoC container has been configured wrong. When I look at the configuration of my services, I saw the actual problem:

image

This should have been registered as singleton but as you can see, it is scoped per request which causes it to be constructed for each request. It is not like I wouldn’t be able to spot this without the profiling tool but it makes it so much easy and fast. I actually wanted to try this as a sample because I had the first hand experience on this problem. Believe me! Spotting the exact problem was so much harder through debugging!

OK, if we go back to our issue again: changing the dependency registration to make it singleton solves the problem nicely:

image

Check out ANTS Performance Profiler documentation for more information about this tool. The other perfect resource on .NET performance profiling is Practical Performance Profiling book which you can download the PDF version for free.

Happy profiling .NET people :)

Setting IHostingEnvironment.IsDevelopment as True in an ASP.NET 5 Application

Wondering why IHostingEnvironment.IsDevelopment returns false even when you are on you development machine? I did indeed wonder and here is why :)
2015-09-13 15:35
Tugberk Ugurlu


I am now in Frankfurt, sipping my coffee in a Starbucks shop and enjoying its rubbish internet connection (as usual). I have just thrown away 10 minutes from my life by trying to figure out why my ASP.NET 5 application wasn't showing the error page. So, I wanted to write this quick and dirty blog post for people who will potentially have the same problem :)

Here is the piece of code I have inside the Configure method of my Startup class:

public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
{
    // ...

    // Add the following to the request pipeline only in development environment.
    if (env.IsDevelopment())
    {
        app.UseErrorPage();
    }
    else
    {
        // Add Error handling middleware which catches all application specific errors and
        // send the request to the following path or controller action.
        app.UseErrorHandler("/Home/Error");
    }

    // ...

So, I should see the beautiful and detailed error page when I am in development. However, all I get is nothing but an empty response body when I run the application:

image

image

With a little bit of digging, I remembered that your environment is being determined through an environment variable which is ASPNET_ENV. Setting this to Development will return true from IHostingEnvironment.IsDevelopment. Also, the IHostingEnvironment.EnvironmentName will get you the value of this environment variable. You can set this environment variable per process, per user or per machine. Whatever floats your boat. I have set this for process on windows with the below script and I was able to get the lovely error page:

set ASPNET_ENV=Development

image

image

When you are on Visual Studio 2015, you can handle this better by adding a launchSettings.json file as here. VS will pick this up and set the environment variable for IIS Express process.

Speaking at Web European Conference 2015 in Milan

Web European Conference 2015 will happen in Milan on the 26th of September and I will be talking about ASP.NET 5 there!
2015-09-12 12:14
Tugberk Ugurlu


I am really excited that I will be speaking at Web European Conference 2015 in Milan on the 26th of September.

web-euro-conf

If you haven't heard of Web European Conference before, here is the description I am copying from the official web site:

The first European Conference dedicated to the future of Development on all technologies. Everything about the newest and coolest framework for building modern web applications and websites: ASP.NET vNext, node.js, ruby, angular.js and much more.

You can view the conference schedule here. Just look at the details of the conference and ask this question: how more awesome can a conference be? It's all about Web, it's in Milan and the keynote speaker is Scott Hanselman :)

I will give a talk on getting into the bowels of ASP.NET 5. It should be fun. For the talk, I will assume that you have a prior knowledge on ASP.NET 5, and know how it’s different from its previous versions. If you want to benefit from this session and haven't got the chance to get up to speed wıth ASP.NET 5 yet, here are a few links to help you:

Looking at web site now and it seems like you still have a chance to register. I hope to see you there :)

That Conference 2015 and My ASP.NET 5 Talk

This week, I had the privilege to attend That Conference as a speaker to give a talk on ASP.NET 5. Here is a quick blog post on my conference experience.
2015-08-16 18:02
Tugberk Ugurlu


This week, I had the privilege to attend That Conference as a speaker to give a talk on ASP.NET 5. The conference is all done and dusted now. Also, I am tired traveling between Turkey, US and UK :) Even if I now want to lie down lazily all day long and do nothing else, I still want to write about my conference experience.

The Conference

2015-08-12 16.15.08

That Conference was a unique experience for me. It marked my first ever visit to US and I had a chance to visit two cities: Chicago and Wisconsin Dells. As for the conference, it is a well-organized family friendly conference. I can say that this might even be the best conference I have ever attended. I also had a chance to meet some great people like Steve Cleary, Ryan Niemeyer, Seth Juarez and many more that I already had known from the community. I also made some new friends like Anabella Watson and engaged in very interesting conversations with those. I will be definitely keeping in touch with them for sure!

It was a three days conference and in each day, there was a keynote held. The first day was very special but I missed it :s It was Uncle Bob giving the keynote that day. The second day was a bit different because the keynote speaker was an FBI agent (yes, #AchievementUnlocked!). Byron Franz talked about cyber threat during his keynote. The last day's keynote speaker was Max Lynch, the co-founder of Ionic. To be honest, I really liked the concept of having a keynote each day. It was really empowering to start each day with an inspiring session.

I really loved the concept of Open Spaces! You can just go and block an available time to hold a discussion on a topic and people who are interested in the topic will participate you for an hour to geek out on that topic. How amazing is that! You have 8 more choices if none of the sessions happening in a block is not interesting for you. The best part about the Open Spaces is that you engage in conversation with others and share experience. I had a chance to host one on DLM (Database Lifecycle Management) and it was really enjoyable:

2015-08-12 11.28.22

I also loved having 30 minute breaks between each session. There were no rush to catch sessions, it allowed speaker to engage conversations right after the session ends. The another advantage of this was that everybody were able to meet and talk to each other during these break. I absolutely loved this concept!

One bad thing about the conference is that the talks were not recorded :s There are so many great sessions going on at the same time and it's hard to choose. As the talks are not recorded for you to watch later, making decision on sessions was a bit more difficult. I am sure I had to sacrifice some great sessions.

My Session on ASP.NET 5

2015-08-12 14.29.03

I had a great time delivering my ASP.NET 5 talk. Even though it was the last session of the conference, there was a lot of interest in the topic. You can find the slides from my ASP.NET 5 talk under my Speakerdeck account and the project I have shown on GitHub. I also had bunch of interesting questions about ASP.NET 5, specifically how the the existing pieces fit into this new world. Some of those questions will make great blog posts here in my blog :) If you are specifically interested in the session topic, I gave the same talk at Progressive .NET Tutorials 2015 in London a month ago and it was recoded.

I also had a chance to join MS Dev Show podcast for a quick discussion on ASP.NET 5, which was really fun. You can check that out here.

Special Thanks

I would like to specifically thank Redgate for making it possible for me to attend the conference by covering and arranging all my travel. For the record, I am not exaggerating :) We have a Travel department at Redgate to basically handle everything about your trip. I also want to thank Chris Massey who runs the Conference Club at Redgate and helped me on getting better at presenting by giving his input on certain areas to improve. Finally, thanks That Conference people for inviting me to speak and organizing a very special conference!

Tags