Category: c#

Categories
c#

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:

public class HomeController : Controller
{
public ILogger<HomeController> Logger { get; }
public HomeController(ILogger<HomeController> logger)
{
Logger = logger;
}
public IActionResult Index()
{
Logger.LogInformation("User loaded the home page");
return View();
}
// and the rest..
}
view raw HomeController.cs hosted with ❤ by GitHub

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):

public async Task<IActionResult> SignMeIn()
{
// Just do a real basic login.
var claims = new List<Claim>
{
new Claim(ClaimTypes.Name, "ajevans"),
new Claim("FullName", "Alistair Evans"),
new Claim(ClaimTypes.Role, "Administrator"),
};
var claimsIdentity = new ClaimsIdentity(claims, "AuthCookie");
await HttpContext.SignInAsync(
"AuthCookie",
new ClaimsPrincipal(claimsIdentity));
Logger.LogInformation("Signed in {user}", claimsIdentity.Name);
return RedirectToAction(nameof(Index));
}
view raw HomeController.cs hosted with ❤ by GitHub

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

public void Configure(IApplicationBuilder app)
{
app.UseStaticFiles();
app.UseCookiePolicy();
app.UseAuthentication();
app.Use(async (ctxt, next) =>
{
if(ctxt.User == null)
{
// Not logged in, so nothing to do.
await next();
}
else
{
// Set a scoped value in the NLog context, then call the next
// middleware.
var userName = ctxt.User.Identity.Name;
using (MappedDiagnosticsLogicalContext.SetScoped("userName", userName))
{
await next();
}
}
});
app.UseMvc(routes =>
{
routes.MapRoute(
name: "default",
template: "{controller=Home}/{action=Index}/{id?}");
});
}
view raw Startup.cs hosted with ❤ by GitHub

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:

<!-- the targets to write to -->
<targets>
<!-- write logs to file -->
<target xsi:type="File" name="allfile" fileName="c:\temp\nlog-all-${shortdate}.log"
layout="${longdate} | ${uppercase:${level:padding=5}} | ${mdlc:userName} | ${logger} | ${message} ${exception:format=tostring}" />
<!-- another file log, only own logs. Uses some ASP.NET core renderers -->
<target xsi:type="File" name="ownFile-web" fileName="c:\temp\nlog-own-${shortdate}.log"
layout="${longdate} | ${uppercase:${level:padding=5}} | ${mdlc:userName} | ${logger} | ${message} ${exception:format=tostring} | url: ${aspnet-request-url} | action: ${aspnet-mvc-action}" />
</targets>
view raw nlog.config hosted with ❤ by GitHub

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

2019-09-07 10:40:15.4822 | DEBUG | | Main.Program | Starting Application | url: | action:
2019-09-07 10:40:18.5081 | INFO | | Main.Controllers.HomeController | Home page | url: https://localhost/ | action: Index
2019-09-07 10:40:40.3932 | INFO | | Main.Controllers.HomeController | Signed in ajevans | url: https://localhost/Home/SignMeIn | action: SignMeIn
2019-09-07 10:40:40.4028 | INFO | ajevans | Main.Controllers.HomeController | Home page | url: https://localhost/ | action: Index
2019-09-07 10:40:58.8799 | INFO | ajevans | Main.Controllers.HomeController | Home page | url: https://localhost/ | action: Index
2019-09-07 10:41:05.0707 | INFO | ajevans | Main.Controllers.HomeController | Home page | url: https://localhost/ | action: Index
view raw logcontent.log hosted with ❤ by GitHub

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:

2019-09-07 10:41:05.0707 | INFO | | Microsoft.AspNetCore.Hosting.Internal.WebHost | Request starting HTTP/1.1 GET https://localhost:5001/
2019-09-07 10:41:05.0707 | INFO | ajevans | Microsoft.AspNetCore.Routing.EndpointMiddleware | Executing endpoint 'Main.Controllers.HomeController.Index (Main)'
2019-09-07 10:41:05.0707 | INFO | ajevans | Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker | Route matched with {action = "Index", controller = "Home"}. Executing controller action with signature Microsoft.AspNetCore.Mvc.IActionResult Index() on controller Main.Controllers.HomeController (Main).
2019-09-07 10:41:05.0707 | INFO | ajevans | Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker | Executing action method Main.Controllers.HomeController.Index (Main) - Validation state: Valid
2019-09-07 10:41:05.0707 | INFO | ajevans | Main.Controllers.HomeController | Home page
2019-09-07 10:41:05.0779 | INFO | ajevans | Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker | Executed action method Main.Controllers.HomeController.Index (Main), returned result Microsoft.AspNetCore.Mvc.ViewResult in 5.3381ms.
2019-09-07 10:41:05.0779 | INFO | ajevans | Microsoft.AspNetCore.Mvc.ViewFeatures.ViewResultExecutor | Executing ViewResult, running view Index.
2019-09-07 10:41:05.0779 | INFO | ajevans | Microsoft.AspNetCore.Mvc.ViewFeatures.ViewResultExecutor | Executed ViewResult - view Index executed in 1.978ms.
2019-09-07 10:41:05.0779 | INFO | ajevans | Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker | Executed action Main.Controllers.HomeController.Index (Main) in 8.4146ms
2019-09-07 10:41:05.0779 | INFO | ajevans | Microsoft.AspNetCore.Routing.EndpointMiddleware | Executed endpoint 'Main.Controllers.HomeController.Index (Main)'
2019-09-07 10:41:05.0779 | INFO | | Microsoft.AspNetCore.Hosting.Internal.WebHost | Request finished in 10.42ms 200 text/html; charset=utf-8
2019-09-07 10:41:05.1352 | INFO | | Microsoft.AspNetCore.Hosting.Internal.WebHost | Request starting HTTP/1.1 GET https://localhost:5001/favicon.ico
2019-09-07 10:41:05.1679 | INFO | | Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware | Sending file. Request path: '/favicon.ico'. Physical path: 'D:\AzureDevOps\ISA-Prototyping\Main\wwwroot\favicon.ico'
2019-09-07 10:41:05.1685 | INFO | | Microsoft.AspNetCore.Hosting.Internal.WebHost | Request finished in 33.3657ms 200 image/x-icon
view raw mslogcontent.log hosted with ❤ by GitHub

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.

Categories
architecture c#

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.

Categories
c#

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:

async static Task Main(string[] args)
{
var httpClient = new HttpClient();
httpClient.BaseAddress = new Uri("https://myserver");
using (var fileSource = new StreamReader(File.OpenRead(@"C:\Data\Sources\myfile.csv")))
{
await StreamData(fileSource, httpClient, "/api/send");
}
}
private static async Task StreamData(StreamReader fileSource, HttpClient httpClient, string path)
{
string line;
// Read from the file until it's empty
while ((line = await fileSource.ReadLineAsync()) != null)
{
// Convert a line of data into JSON compatible with the API
var jsonMsg = GetDataJson(line);
// Send it to the server
await httpClient.PostAsync(path, new StringContent(jsonMsg, Encoding.UTF8, "application/json"));
}
}
view raw program.cs hosted with ❤ by GitHub

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:

private static async Task StreamDataInParallel(StreamReader fileSource, HttpClient httpClient, string path, int maxParallel)
{
var block = new ActionBlock<string>(
async json =>
{
await httpClient.PostAsync(path, new StringContent(json, Encoding.UTF8, "application/json"));
}, new ExecutionDataflowBlockOptions
{
// Tells the action block how many we want to run at once.
MaxDegreeOfParallelism = maxParallel,
// 'Buffer' the same number of lines as there are parallel requests.
BoundedCapacity = maxParallel
});
string line;
while ((line = await fileSource.ReadLineAsync()) != null)
{
// This will not continue until there is space in the buffer.
await block.SendAsync(GetDataJson(line));
}
}
view raw program.cs hosted with ❤ by GitHub

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!