Adding the Username to the Logs for every ASP.NET Core Request with NLog

I’m currently investigating how we port a large ASP.NET application to ASP.NET Core, and one of the things I had to figure out this morning was how to include information about the logged-in user in our logs.

The most important value to collect is the username, but I also need to be able to collect other information from the session at some point.

In the original ASP.NET app we did some slightly questionable HttpContext.Current access inside the logging providers, which I didn’t love.

In ASP.NET Core however, I can combine the use of the middleware system with NLog to add this information to my logs in a much better/easier way.

Adding NLog to my App

To add NLog to my ASP.NET Core app, I just followed the basic instructions at https://github.com/NLog/NLog/wiki/Getting-started-with-ASP.NET-Core-2 to get up and going (that guide tells you what you need to put in your Program and Startup classes to wire everything up).

I then updated the default HomeController to write a log message in the index page:

So when I launch my app, I get my log messages out (this is just the basic ASP.NET Core site template):

Adding our Username to Log Events

First up, I’m just going to add an extremely basic action to my HomeController that will sign me in with a test user (I’ve already set up the Startup class configuration to add cookie authentication):

Now we can do the middleware changes (this is the important bit). In the Startup class’ Configure method, we have an additional Use method:

The MappedDiagnosticsLogicalContext class is an NLog class that lets you provide values that are scoped to the current async context. These values are attached to every log event raised inside the using block. The call to next() inside our using means that the entirety of the middleware pipeline (from that point onwards) has the userName property attached to it.

Displaying the Username in the Log

The last part of this is to update our nlog.config to display the username.

To do this, we use the MDLC Layout Renderer to pull the userName property out of the log event, by adding ${mdlc:userName} inside our layout:

Now, if we start the application, and log in, we get our username in each log event!

The real bonus of assigning the username inside the middleware though is that the extra detail gets added to the internal Microsoft.* logs as well:

You’ll notice that not all the log messages have a username value. Why is that?

The reason is that those log messages come from middleware that occurs earlier in the pipeline than our middleware that assigns the username, so those log events won’t contain that property.

In conclusion…

So, you’ve seen here how to use the NLog MappedDiagnosticsLogicalContext class and ASP.NET Core middleware to add extra information to all the log messages for each request. Don’t forget that you can add as much information to the log as you need, for example you could pull some user session state value out of the Session and add that too.

Managing Big Enterprise Applications in the .NET Ecosystem

I’m going to spend a few minutes here discussing some advice for designing/maintaining large enterprise-grade .NET applications, particularly ones that you sell to others, rather than in-house creations.

Disclaimer: I work largely with big applications used by enterprise customers. I imagine a lot of people reading this do as well, but plenty of people may disagree with some of my thoughts/suggestions. What follows is just based on my experience of designing and deploying user-driven ASP.NET applications.

A Brief Defense of (Deployment) Monoliths

Microservices are all the rage right now, and they are very cool, I will not deny that; small blocks of easy-to-maintain logic that all build, deploy and start quickly are brilliant. They’re great when you are deploying your own software, either onto your own premises or in the cloud; but what if your software has to be deployed onto someone else’s environment, by the owner of that environment?

What if they don’t use containers, or even use virtualisation?
What if they have no DevOps pipeline at all, and everything must be done manually?
What if those global customers have disparate regulatory and internal governance concerns that govern how and where data is stored, and how your application is managed?

In these situations, deployment simplicity is one of the most important considerations we have, and microservices deployment is by no means simple.

What I need is to keep the number of deployable components to a minimum. My goal is a one-click installer, followed by minimal configuration.

I asked a panel at a recent Microsoft Azure conference what solutions/plans they had for taking a complex microservices architecture and deploying it in someone else’s infrastructure as a simple-to-install component. If they use Azure as well, then you might be in luck in the near future, but other than that I didn’t get any answers that gave me hope for distributable microservice packages.

Managing Monoliths

In the modern development ecosystem, some people think ‘monolith’ is a dirty word. They’re seen as inevitable blobs of spaghetti code, horrible bloat and painful development experiences. But that doesn’t have to be true.

I’m going to write up a couple of blog posts that go into specific tips for maintaining enterprise ASP.NET monoliths, but I’ll start with some general advice.

All of the following applies to ASP.NET applications on the full .NET Framework, and .NET Core (soon to be known as .NET 5).

Make it Modular, Make it Patchable

The concept of a ‘Modular Monolith’ is not new. If you don’t break your application into multiple libraries (i.e. DLLs), you’re going to get into the world of spaghetti code so fast it will make your source control repository collapse in on itself.

I find that circular reference prevention actually ends up helping to enforce good design patterns, which you do not get if everything is in one big project.

Even if all your code is super tidy, if you’re distributing your software to enterprise customers, at some point you are going to need to patch something, because big customers just don’t upgrade to your latest version very often (once a decade is not that unusual). They certainly aren’t going to just upgrade to the latest build on trunk/master when they find a bug that needs fixing.

If you need to reissue the entire application to patch something, your customer’s internal test teams are going to cry foul, because they can’t predict the impact of your changes, so they’ll say they need to retest the whole thing. They definitely won’t go on trust when you say that all your automated tests pass.

So, to that end, do not build an ASP.NET (v4 or Core) web application that sits in one project (despite what most intro tutorials start off telling you to do). I don’t care what size it is, break it up.

You can add your own Assembly Loading startup process if you need to. The .NET loaders do a great job of loading your references for you, but I find you end up needing a bit more control than you get from the default behaviour. For example, you can explicitly load the libraries of your application based on some manifest file (helpful to control patched DLL versions).

Micro-kernels are your friend

If you can, then build your application using a micro-kernel architecture. By micro-kernel, I mean that there should be a central core of your application that provides base technical support features (data access, logging, dependency injection, etc) but adds no actual functionality to your application.

Once you’ve got that, you can:

  • Update (and patch) blocks of functionality in your application easily. These change much more often than your core.
  • Create customer-specific features (which happens all the time) without polluting your general application code.
  • Develop and test your functionality blocks in isolation.
  • Scale-out your development to multiple teams by giving them different blocks of functionality to work on.

Does that sound familiar? A lot of those advantages are shared with developing microservices; small blocks of functionality with a specific problem domain, that can be developed in isolation.

In terms of deployment we’ve still got one deployment package; it’s your CI system that should bring the Core and Functionality components together into one installer or other package, based on a list of required components for a given customer or branch.

I will say that defining a micro-kernel architecture is very hard to do properly, especially if you have to add it later on, to an existing application architecture.

Pro tip – define your own internal NuGet packages for your Core components, so they can be distributed easily; you can then easily ‘release’ new Core versions to other teams.

If you output NuGet packages from your CI system, you can even have some teams that need Core functionality in development working off an ‘alpha’ build of Core.

Enforce Layer Separation in your APIs
(or ‘if you use a data context in an MVC controller the compiler will slap you’)

Just because everything may be running in one process doesn’t mean you shouldn’t maintain strict separation of layers.

At a minimum, you should define a Business layer that is allowed to access your database, and a UI/Web Service layer, that is not.

The business layer should never consume a UI service, and the UI layer should never directly access/modify data.

Clients of your application should only ever see that UI or Web Service layer.

Escalating terrors in software design.

You could enforce all of this through code reviews, but I find things can still slip through the gaps, so I like to make my API layout do the work in my Core to enforce the layout.

I find a good way to do this in a big .NET application (micro-kernel or otherwise) is to:

  • Define clear base classes that support functionality in each layer.
    For example, create a MyAppBusiness class in your business layer, that all business services must derive from. Similarly, define a MyAppController class that all MVC controllers will derive from (which in turn derives from the normal Controller class).
  • In those classes, expose protected methods to access core services that each layer needs. So your base MyAppBusiness class can expose data access to derived classes, and your MyAppController class can provide localisation/view-rendering support.
  • In your start-up procedure (preferably when you register your Dependency Injection services, if you use it, which you should), only register valid services, that derive from the right base class. Enforce by namespace/assembly if necessary. Throw exceptions if someone has got it wrong.

Where possible, developer mistakes should be detectable/preventable in code. Bake it into your APIs and you can make people follow standards because they can’t do anything if they don’t.

Next Up

In future posts on these sort of topics, I’ll talk about:

  • Tips for working with Entity Framework in applications with a complex database
  • Automated testing of big applications
  • Using PostSharp to verify developer patterns at compile time

..and any other topics that spring to mind.

Easily loading lots of data in parallel over HTTP, using Dataflow in .NET Core

I recently had a requirement to load a large amount of data into an application, as fast as possible.

The data in question was about 100,000 transactions, stored line-by-line in a file, that needed to be sent over HTTP to a web application, that would process it and load it into a database.

This is actually pretty easy in .NET, and super efficient using async/await:

Run that through, and I get a time of 133 seconds; this isn’t too bad right? Around 750 records per second.

But I feel like I can definitely make this better. For one thing, my environment doesn’t look exactly look like the diagram above. It’s a scaled production environment, so looks more like this:

I’ve got lots of resources that I’m not using right now, because I’m only sending one request at a time, so what I want to do is start loading the data in parallel.

Let’s look at a convenient way of doing this, using the System.Threading.Tasks.Dataflow package, which is available for .NET Framework 4.5+ and .NET Core.

The Dataflow components provide various ways of doing asynchronous processing, but here I’m going to use the ActionBlock, which allows me to post messages that are subsequently processed by a Task, in a callback. More importantly, it let’s me process messages in parallel.

Let’s look at the code for my new StreamDataInParallel method:

The great thing about Dataflow is that in only about 18 lines of code, I’ve got parallel processing of data, pushing HTTP requests to a server at a rate of my choice (controlled by the maxParallel parameter).

Also, with the combination of the SendAsync method and specifying a BoundedCapacity, it means I’m only reading from my file when there are slots available in the buffer, so my memory consumption stays low.

I’ve run this a few times, increasing the number of parallel requests each time, and the results are below:

Sadly, I wasn’t able to run the benchmarking tests on the production environment (for what I hope are obvious reasons), so I’m running all this locally; the number of parallel requests I can scale to is way higher in production, but it’s all just a factor of total available cores and database server performance.

Value of maxParallelAverage Records/Second
1750
21293
31785
42150
52500
62777
72941
83125

With 8 parallel requests, we get over 3000 records/second, with a time of 32 seconds to load our 100,000 records.

You’ll notice that the speed does start to plateau (or at least I get diminishing returns); this will happen when we start to hit database contention (typically the main throttling factor, depending on your workload).

I’d suggest that you choose a sensible limit for how many requests you have going so you don’t accidentally denial-of-service your environment; we’ve got to assume that there’s other stuff going on at the same time.

Anyway, in conclusion, Dataflow has got loads of applications, this is just one of them that I took advantage of for my problem. So that’s it, go forth and load data faster!

Displaying Real-time Sensor Data in the Browser with SignalR and ChartJS

In my previous posts on Modding My Rowing Machine, I wired up an Arduino to my rowing machine, and streamed the speed sensor data to an ASP.NET core application.

In this post, I’m going to show you how to take sensor and counter data, push it to a browser as it arrives, and display it in a real-time chart.

If you want to skip ahead, I’ve uploaded all the code for the Arduino and ASP.NET components to a github repo at https://github.com/alistairjevans/rower-mod.

I’m using Visual Studio 2019 with the ASP.NET Core 3.0 Preview for all the server-side components, but the latest stable release of ASP.NET Core will work just fine, I’m not using any of the new features.

Pushing Data to the Browser

So, you will probably have heard of SignalR, the ASP.NET technology that can be used to push data to the browser from the server, and generally establish a closer relationship between the two.

I’m going to use it send data to the browser whenever new sensor data arrives, and also to let the browser request that the count be reset.

The overall component layout looks like this:

Setting up SignalR

This bit is pretty easy; first up, head over to the Startup.cs file in your ASP.NET app project, and in the ConfigureServices method, add SignalR:

Next, create a SignalR Hub. This is effectively the endpoint your clients will connect to, and will contain any methods a client needs to invoke on the server.

SignalR Hubs are just classes that derive from the Hub class. I’ve got just the one method in mine at the moment, for resetting my counter.

Before that Hub will work, you need to register it in your Startup class’ Configure method:

You’re also going to want to add the necessary SignalR javascript to your project. I did it using the “Manage Client-Side Libraries” feature in Visual Studio; you can find my entire libman.json file (which defines which libraries I’m using) on my github repo

Sending Data to the Client

In the MVC Controller where the data arrives from the Arduino, I’m going to push the sensor data to all clients connected to the hub.

The way you access the clients of a hub from outside the hub (i.e. an MVC Controller) is by resolving an IHubContext<THubType>, and then accessing the Clients property.

Pro tip:
Got multiple IO operations to do in a single request, that don’t depend on each other? Don’t just await one, then await the other; use Task.WhenAll, and the operations will run in parallel.

In my example above I’m writing to a file and to SignalR clients at the same time, and only continuing when both are done.

Browser

Ok, so we’ve got the set-up to push data to the browser, but no HTML just yet. I don’t actually need any MVC Controller functionality, so I’m just going to create a Razor Page, which still gives me a Razor template, but without having to write the controller behind it.

If I put an ‘Index.cshtml’ file under a new ‘Pages’ folder in my project, and put the following content in it, that becomes the landing page of my app:

In my site.js file, I’m just going to open a connection to the SignalR hub and attach a callback for data being given to me:

That’s actually all we need to get data flowing down to the browser, and displaying the current speed and counter values!

I want something a little more visual though….

Displaying the Chart

I’m going to use the ChartJS library to render a chart, plus a handy plugin for ChartJS that helps with streaming live data and rendering it, the chartjs-plugin-streaming plugin.

First off, add the two libraries to your project (and your HTML file), plus MomentJS, which ChartJS requires to function.

Next, let’s set up our chart, by defining it’s configuration and attaching it to the 2d context of the canvas object:

Finally, let’s make our chart display new sensor data as it arrives:

With all that together, let’s see what we get!

Awesome, a real-time graph of my rowing!

As an aside, I used the excellent tool by @sarah_edo to generate a CSS grid really quickly, so thanks for that! You can find it at https://cssgrid-generator.netlify.com/

You can check out the entire solution, including all the code for the Arduino and the ASP.NET app, on the github repo at https://github.com/alistairjevans/rower-mod.

Next up for the rowing machine project, I want to put some form of gamification, achievements or progress tracking into the app, but not sure exactly how it will look yet.

Streaming real-time sensor data to an ASP.NET Core app from an Arduino

In my previous posts on Modding my Rowing Machine, I got started with an Arduino, and started collecting speed sensor data. The goal of this post is to connect to the WiFi network and upload sensor data to a server application I’ve got running on my laptop in as close to real-time as I can make it.

Connecting to WiFi

My Arduino Uno WiFi Rev 2 board has got a built-in WiFi module; it was considerably easier than I expected to get everything connected.

I first needed to install the necessary library to support the board, the WiFiNINA library:

Then you can just include the necessary header file and connect to the network:

To be honest, that code probably isn’t going to cut it, because WiFi networks don’t work that nicely. You need a retry mechanism with timeouts to keep trying to connect. Let’s take a look at the full example:

The Server

To receive the data from the Arduino, I created a light-weight ASP.NET Core 3.0 web application with a single controller endpoint to handle incoming data, taking a timestamp and the speed:

Then, in my Arduino, I put the following code in a method to send data to my application:

I just want to briefly mention one part of the above code, where I’m preparing body data to send.

The Arduino libraries do not support the %f specifier (for a float) in the sprintf method, so I can’t just add the speed as an argument there. Instead, you have to use the dtostrf method to insert a double into the string, specifying the number of decimal points you want.

Also, if you specify %d (int) instead of %lu (unsigned long) for the timestamp, the sprintf method treats the value as a signed int and you get very strange numbers being sent through for the timestamp.

Once that was uploaded, I started getting requests through!

Performance

We now have HTTP requests from the Arduino to our ASP.NET Core app. But I’m not thrilled with the amount of time it takes to execute a single request.

If we take a look at the WireShark trace (I love WireShark), you can see that each request from start to finish is taking in the order of 100ms!

This is loads, and I can’t have my Arduino sitting there for that long.

ASP.NET Core Performance

You can see in the above trace that the web app handling the request is taking 20ms to return the response, which is a lot. I know that ASP.NET Core can do better than that.

Turns out this problem was actually due to the fact I had console logging switched on. Due to the synchronisation that takes place when writing to the console, it can add a lot of time to requests to print all that information-level data.

Once I turned the logging down from Information to Warning in my appsettings.json file, it got way better.

That’s better!

That actually gives us sub-millisecond response times from the server, which is awesome.

TCP Handshake Overhead

Annoyingly, each request is still taking up to 100ms from start of connection to the end. How come?

If you look at those WireShark traces, we spend a lot of time in the TCP handshaking process. Opening a TCP connection does generally come with lots of network overhead, and that call to client.connect(SERVER, SERVERPORT) in my code blocks until the TCP connection is open; I don’t want to sit there waiting for that every time I want to send a sample.

The simple solution to this is to make the connection stay open between samples, so we can just repeatedly sent data on the same connection, only needing to do the handshake once.

Let’s rework our previous sendData code on the Arduino to keep the connection open:

In this version, we ask the server to leave the connection open after the request, and only open the connection if it is closed. I’m also not blocking waiting for a response.

This gives us way better behaviour, and we’re now down to about 40ms total:

There’s one more thing that I don’t love about this though…

TCP Packet Fragmentation

So, what’s left to look at?

TCP segments

I’ve got a packet preceding each of my POST requests, that seems to hold things up by around 40ms. What’s going on here? Let’s look at the content of that packet:

Wireshark data view

What I can tell from this is that rather than wait for my HTTP request data, the Arduino is not buffering for long enough, and is just sending what it has after the first println call containing POST /data/providereading HTTP/1.1. This packet fragmentation slows everything up because the Arduino has to wait for an ACK from the server before it continues.

I just wanted to point out that it looks like the software in the Arduino libraries isn’t responsible for the fragmentation; it looks all the TCP behaviour is handled by the hardware WiFi module, that’s what is splitting my packets.

To stop this packet fragmentation, let’s adjust the sending code to prepare the entire request and send it all at once:

Once uploaded, let’s look at the new WireShark trace:

No TCP Fragmentation

There we go! Sub-millisecond responses from the server, and precisely hitting my desired 50ms window between each sample send.

There’s still ACKs going on obviously, but they aren’t blocking packet issuing, which is the important thing.

Summary

It’s always good to look at the WireShark trace for your requests to see if you’re getting the performance you want, and don’t dismiss the overhead of opening a new TCP connection each time!

Next Steps

Next up in the ‘Modding my Rowing Machine’ series, I’ll be taking this speed data and generating a real-time graph in my browser, that updates continuously! Stay tuned…

Value Tuples for passing Lists of Key-Value Pairs in C# 7

Prior to C# 7, I have many, many times found myself needing to pass a hard-coded list of key-value pairs to a method, and I’ve had to do it painfully:

We can make this marginally better with a factory function:

Then we can swap the list with an array to improve it a little more:

Finally, we can use ‘params’ on the method so we don’t need to declare an array on the caller:

Okay, so it’s not too bad, but we still have that factory function which I’m not a fan of.

Value Tuples

Briefly, Value Tuples let you do things like this:

You get a small value type containing your two values, that you can declare inline, and access the individual values in the result.

You don’t just have to use these in return types, you can use them anywhere a type definition could be used.

I’ve generally been a little reticent to use this new-ish feature too heavily, because I’m worried about people using them where they should actually be defining types.

That being said…

Making Our Parameters Nicer

In C# 7, now we get to pass those key-value lists the nice way:

Look at that! No factory function required, we can simply pass in the pairs, just as I’ve wanted to be able to do for years, and it’s super readable.

Just define the array type of your params argument as the tuple you want, and away you go!

I’m still a little wary of Value Tuples generally, but this is definitely a lovely use case for them.