Autofac Interception async execution order

Question

So I have this class:

public class MappingBootstrap : IMappingBootstrap
{
    public virtual async Task Map()
    {
        // Order is very important

        await this.mapper1.Map();

        await this.mapper2.Map();

        await this.mapper3.Map();

        await this.mapper4.Map();
    }
}

I have Autofac Interceptor:

public class LoggingInterceptor : IInterceptor
{
    public void Intercept(IInvocation invocation)
    {
        var methodReference = Guid.NewGuid();
        Console.WriteLine($"Calling {invocation?.Method?.DeclaringType?.Name}.{invocation?.Method?.Name} : {methodReference}");

        var startNew = Stopwatch.StartNew();

        invocation?.Proceed();

        startNew.Stop();

        Console.WriteLine($"{methodReference} : Done, time taken: {startNew.ElapsedMilliseconds}ms");
    }
}

This produces the output:

Calling IMapperBootstrap.Map : 54425559-71fe-4f23-ab47-d0f3371ec819
Calling IMapper1.Map : 51babb34-fa83-42ed-84e7-a1e979528116
51babb34-fa83-42ed-84e7-a1e979528116 : Done, time taken: 219ms
54425559-71fe-4f23-ab47-d0f3371ec819 : Done, time taken: 221ms
Calling IMapper2.Map : 41c812a2-d82d-48f6-9b8d-139b52eb28e3
41c812a2-d82d-48f6-9b8d-139b52eb28e3 : Done, time taken: 9ms
Calling IMapper3.Map : c91bed04-8f86-47d3-a35a-417e354c2c5f
c91bed04-8f86-47d3-a35a-417e354c2c5f : Done, time taken: 994ms
Calling IMapper4.Map : 035cad27-1ba8-4bd1-b85f-396f64998d97
035cad27-1ba8-4bd1-b85f-396f64998d97 : Done, time taken: 18ms

As you can see, the MappingBoostrap.Map finishes after the first Mapper1.Map rather than what I expect which is when all the functions have completed. Why?

Autofac Config:

builder.Register(context => new LoggingInterceptor());

builder
    .RegisterAssemblyTypes(typeof(Bootstrapper).Assembly)
    .Where(x => x.Namespace.Contains("Mapping"))
    .AsImplementedInterfaces()
    .EnableInterfaceInterceptors()
    .InterceptedBy(typeof(LoggingInterceptor));

Stephen Cleary · Accepted Answer · 2015-10-14T13:44:37.150

7

Why?

When you call an asynchronous method like this:

mapping.Map();

it only starts the method. This is how asynchronous methods work (as I explain on my blog). If you await the task returned by the asynchronous method, then the current method will pause until the asynchronous method completes:

await mapping.Map();

In the case of interception, the ideal solution would be to have the Proceed and Intercept methods asynchronous:

public async Task InterceptAsync(IInvocation invocation)
{
  ...
  await invocation?.ProceedAsync();
  ...
}

Unfortunately, Autofac has no built-in understanding of asynchronous methods, so this isn't possible. Instead, you have to call Proceed, which just starts the asynchronous method. The asynchronous method returns a Task, which represents the execution of that method. To hook into the completion of the method, you should replace that Task with one of your own.

For a plain Task-returning method, you can use something like this:

public void Intercept(IInvocation invocation)
{
  var methodReference = Guid.NewGuid();
  Console.WriteLine($"Calling {invocation?.Method?.DeclaringType?.Name}.{invocation?.Method?.Name} : {methodReference}");

  var startNew = Stopwatch.StartNew();

  invocation.Proceed();
  invocation.ReturnValue = WatchAsync(methodReference, startNew, (Task)invocation.ReturnValue);
}

private static async Task WatchAsync(Guid methodReference,
    Stopwatch stopwatch, Task methodExecution)
{
  try
  {
    await methodExecution.ConfigureAwait(false);
  }
  finally
  {
    stopwatch.Stop();
    Console.WriteLine($"{methodReference} : Done, time taken: {stopwatch.ElapsedMilliseconds}ms");
  }
}

edited Oct 14 '15 at 13:44

answered Oct 07 '15 at 15:44

Stephen Cleary

437,863
77
675
810

I was wondering whether that was the reason, but some part of me said why would Autofac not support `await/async`, but this seems like a simple solution. The thing is do you want to have the interception handle how you await `Task`s or the code where the actual invocation is taking place. I guess it's one of those things that you have to bear in mind when intercepting asynchronous code. – Callum Linington Oct 08 '15 at 07:58
@CallumLinington: To be clear, the code being intercepted should still use `await`. The intercepting code just intercepts the returned `Task` and replaces it with one of its own (which happens to be implemented with `async`/`await`). – Stephen Cleary Oct 08 '15 at 10:18
1

Note the interception is done by Castle.DynamicProxy, not Autofac. Autofac just makes wiring it up easier. – Travis Illig Oct 08 '15 at 14:08
Just as an FYI @StephenCleary the `WatchAsync` method is called with an incorrect number of parameters – Callum Linington Oct 14 '15 at 13:12
Am I correct this approach will fail if invocation returned task has parameters? If so, what we can do if we don't want to write code for each possible invoked method? – astef Jan 04 '18 at 23:27
Yes, and here's the solution: https://stackoverflow.com/questions/28099669/intercept-async-method-that-returns-generic-task-via-dynamicproxy – astef Jan 04 '18 at 23:29

Autofac Interception async execution order

1 Answers1