Categories
Uncategorized

.NET Asynchronous Disposal – Tips for Implementing IAsyncDisposable on your own Types

Background – Why Async Dispose?

The .NET Team recently added support for asynchronous disposal of objects, via a new IAsyncDisposable interface.

A lot of the examples you can find will use this to let you dispose of asynchronous streams, but it’s also useful for disposal of other objects that may potentially trigger I/O.

This allows you to write code like this (which works in .NET Core 3.0, with C# 8):

await using (var dbConnection = new SqlConnection(connString))
{
// Use your DB connection.
// The connection will get disposed of asynchronously at the end of the using block.
}
view raw program.cs hosted with ❤ by GitHub

Notice the await in front of the using statement? That will tell the using block to call DisposeAsync on the SqlConnection object when we exit the using block, instead of the regular Dispose method, and await on the result.

What’s the benefit of this over a typical using? Well, if the database connection needs to go over the network to reset the connection, it will return the thread to the thread pool to do other work, rather than blocking it while the Dispose takes place.

The great thing about .NET Core 3.0 is that for any services you have registered as Scoped (i.e. they only live for the duration of the current HTTP request) that implement IAsyncDisposable will be disposed of asynchronously at the end of the request, giving valuable thread time back to processing actual requests.

I recently added the functionality in the Autofac Dependency Injection library to support calling DisposeAsync on a lifetime scope, which in turn calls DisposeAsync on all services in that scope that implement IAsyncDisposable. This extends to if you use Autofac as your .NET Core Service Provider as well. The functionality will be released in Autofac 5.0.0, or you can check out the relevant GitHub PR now to see what changes went in.

I thought I’d use this blog post to help people write their own classes that implement IAsyncDisposable, since I couldn’t find a lot of documentation on it, and had to go digging into .NET Core code on GitHub to figure out the best approach.

Implement IDisposable As Well

IAsyncDisposable isn’t a replacement for IDisposable, it’s an additional way to dispose.

Basically, if you implement IAsyncDisposable in your class, you should probably implement IDisposable too and perform the synchronous equivalent of your disposal operation.

public class MyDisposableObject : IDisposable, IAsyncDisposable
{
private SqlConnection myResource = new SqlConnection("connection string");
public void Dispose()
{
// Sync dispose on my resource
myResource.Dispose();
}
public async ValueTask DisposeAsync()
{
// Async dispose on the resource
await myResource.DisposeAsync();
}
}

This goes double for library authors, who are not in control of the code that creates the object that needs to be disposed.

There’s a couple of reasons for this:

  1. If you don’t have a regular Dispose method, code that doesn’t run in an async context will have to block on your DisposeAsync to make it sync, which kind of defies the point, and is unpleasant:
private void NotAnAsyncMethod()
{
var disposableObject = new MyDisposableObject();
// Unpleasant
disposableObject.DisposeAsync().GetAwaiter().GetResult();
}
view raw NotAsync.cs hosted with ❤ by GitHub
  1. If your class gets put in a container, and then the container is disposed synchronously, an exception will be thrown (this is the behaviour of Autofac and the default .NET Core DI system), because these containers will refuse to call DisposeAsync from inside a regular Dispose:
// Get a host builder
var hostBuilder = CreateHostBuilder(args);
// Add our service as scoped.
hostBuilder.ConfigureServices(srv =>
{
srv.AddScoped<MyAsyncOnlyDisposableObject>();
});
// Get our container
var host = hostBuilder.Build();
using(var serviceScope = host.Services.CreateScope())
{
var myObject = serviceScope.ServiceProvider.GetRequiredService<MyAsyncOnlyDisposableObject>();
} // Exception thrown here
view raw program.cs hosted with ❤ by GitHub
The exception we get if we don’t dispose asynchronously.

Only Add IAsyncDisposable If You Need To

This one is pretty simple; you should only add IAsyncDisposable to your class if you or a derived class may allocate resources that also implement IAsyncDisposable.

Don’t do this:

class MyObjectWithALock : IDisposable, IAsyncDisposable
{
private SemaphoreSlim semaphore = new SemaphoreSlim(1, 1);
public void Dispose()
{
semaphore.Dispose();
}
public async ValueTask DisposeAsync()
{
// Please, no, no.
await Task.Run(() => semaphore.Dispose());
}
}
view raw MyObjectWithALock.cs hosted with ❤ by GitHub

SemaphoreSlim doesn’t implement IAsyncDisposable, so all this does is use up another thread pool thread to run the Dispose.

Derived Classes

If you are writing a base class that might have derived classes with resources that need disposing asynchronously, you may wish to introduce a virtual DisposeAsync method if you also have a base Dispose method.

In this case, I would suggest making your default implementation call Dispose directly without awaiting and return synchronously:

class BaseClassThatMightHaveChildrenWithResources : IDisposable, IAsyncDisposable
{
public virtual void Dispose()
{
}
public virtual ValueTask DisposeAsync()
{
Dispose();
return default;
}
}

Base classes can override the DisposeAsync method if they have resources that can be disposed of asynchronously, otherwise they can just override Dispose.

Only Dispose Once (Sync or Async)

It’s recommended practice to make Dispose re-entrant, and only dispose of its resources once. With the asynchronous disposal behaviour, this is still true, and importantly, you should only allow either Dispose or DisposeAsync to actually do the dispose.

So your classes should have this pattern:

private class MyDisposableObject : IDisposable, IAsyncDisposable
{
private SqlConnection myResource = new SqlConnection();
private bool isDisposed = false;
public void Dispose()
{
if (!isDisposed)
{
isDisposed = true;
myResource.Dispose();
}
}
public async ValueTask DisposeAsync()
{
if (!isDisposed)
{
// Set isDisposed to true first
isDisposed = true;
await myResource.DisposeAsync();
}
}
}

The reason I set isDisposed to true in the above example before awaiting is because setting it afterwards would make it possible for a caller to double-dispose, by not awaiting on DisposeAsync, then calling Dispose. It’s unlikely, but possible.

If the class may be used in a multi-threaded context, consider using Interlocked methods to set isDisposed, to make sure two threads don’t try disposing at the same time.

Targeting netstandard2.0

This bit is mostly targeted at library developers, who might be targeting netstandard versions.

While the language implementations for asynchronous disposal are only available in netstandard2.1, there is a package from Microsoft that provides the IAsyncDisposable interface and related types for netstandard2.0 and .NET 4.6.1, Microsoft.Bcl.AsyncInterfaces (as David Fowler kindly pointed out to me in the Autofac PR).

This allows you to add conditional references that mean your library can implement asynchronous disposal in versions prior to .NET Standard 2.1, by adding the following conditional package reference:

<ItemGroup Condition=" '$(TargetFramework)' == 'netstandard2.0' or '$(TargetFramework)' == 'net461' ">
<PackageReference Include="Microsoft.Bcl.AsyncInterfaces" Version="1.1.0-preview1.19504.10" />
</ItemGroup>
view raw myproject.csproj hosted with ❤ by GitHub

Consider Adding GC.SuppressFinalize to DisposeAsync

If your class has a finalizer (or a derived class may have one), then you may already be calling GC.SuppressFinalize(this) in your Dispose method.

Because your DisposeAsync method is another Dispose method, it should also call GC.SuppressFinalize so the GC doesn’t have to call your destructor later.

This is a more complete example that provides protected virtual methods for disposal, in line with the recommended IDisposable pattern:

private class MyDisposableObject : IDisposable, IAsyncDisposable
{
private SqlConnection myResource = new SqlConnection();
private bool isDisposed = false;
public void Dispose()
{
if (!isDisposed)
{
isDisposed = true;
Dispose(true);
GC.SuppressFinalize(this);
}
}
protected virtual void Dispose(bool disposing)
{
if(disposing)
{
myResource.Dispose();
}
}
public async ValueTask DisposeAsync()
{
if (!isDisposed)
{
isDisposed = true;
await DisposeAsync(true);
GC.SuppressFinalize(this);
}
}
protected async ValueTask DisposeAsync(bool disposing)
{
if (disposing)
{
await myResource.DisposeAsync();
}
}
}

Putting GC.SuppressFinalize in the DisposeAsync method will actually cause a violation of the CA1816 analyzer rule if you have the analyzers installed, that says GC.SuppressFinalize should only be called from Dispose. I’m hoping that the rule will get updated at some point, but for now you may need to suppress that rule for the DisposeAsync method.

Wrap-Up

So, IAsyncDisposable can be really handy if you have resources to dispose of that may use I/O in that disposal, but be careful using it, and only add it if you actually need to!

Categories
Uncategorized

ASP.NET Core 3.0 – Logging in the Startup Class (with NLog)

With ASP.NET Core 3.0, the ability to inject an ILogger or ILoggerFactory into the Startup class has been removed, so we can no longer do this:

public class Startup
{
public Startup(IConfiguration configuration, ILoggerFactory logFactory)
{
Logger = logFactory.CreateLogger<Startup>();
}
private ILogger Logger { get; }
public void ConfigureServices(IServiceCollection services)
{
Logger.LogInformation("Registering Services");
// And the rest
}
}
view raw Startup.cs hosted with ❤ by GitHub

I understand why this has been done, because creating a temporary DI container just for the startup process adds a lot of complexity and potential for errors.

However, my ConfigureServices method (and the new ConfigureContainer method added in 3.0) does quite a bit of work, including loading extension assemblies; I want to be able to log during that time.

I also want to make sure I only pass around the ILogger from the Microsoft.Extensions.Logging namespace to other objects used at startup.

The Workaround

I use NLog for my logging (https://nlog-project.org/). In my Program’s Main method I configure it like so:

public static void Main(string[] args)
{
// NLog: setup the nlog config first; this will configure all subsequent nlog factories
// with our nlog config.
NLogBuilder.ConfigureNLog("nlog.config");
var host = Host.CreateDefaultBuilder(args)
.ConfigureWebHostDefaults(webHostBuilder =>
{
webHostBuilder
.UseContentRoot(Directory.GetCurrentDirectory())
.UseStartup<Startup>();
})
.ConfigureLogging(logging =>
{
logging.ClearProviders();
logging.SetMinimumLevel(LogLevel.Trace);
})
// Use NLog to provide ILogger instances.
.UseNLog()
.Build();
host.Run();
}
view raw Program.cs hosted with ❤ by GitHub

You can grab details on how to create an nlog.config file from the NLog docs, I won’t go into it here.

Then, in my Startup class, I can create the NLogLoggerProvider class (this is sort of a factory for creating the Microsoft ILogger instances), and from that I can get my logger instance:

public class Startup
{
public Startup(IConfiguration configuration)
{
// Get the factory for ILogger instances.
var nlogLoggerProvider = new NLogLoggerProvider();
// Create an ILogger.
Logger = nlogLoggerProvider.CreateLogger(typeof(Startup).FullName);
}
public void ConfigureServices(IServiceCollection services)
{
Logger.LogInformation("Registering Services");
// And the rest
}
}
view raw Startup.cs hosted with ❤ by GitHub

Hey presto, logging in the Startup class. Note that we are obviously outside the entire DI system for this logging (which is sort of the point).

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.