Intercept the call to an async method using DynamicProxy

Question

Below is the code from the Intercept method on a custom type that implements IInterceptor of the Castle Dynamic Proxy library. This snippet is from an AOP based logging proof-of-concept console app that is posted here.

    public void Intercept(IInvocation invocation)
    {
        if (Log.IsDebugEnabled) Log.Debug(CreateInvocationLogString("Called", invocation));
        try
        {
            invocation.Proceed();
            if (Log.IsDebugEnabled)
                if (invocation.Method.ReturnType != typeof(void))
                    Log.Debug("Returning with: " + invocation.ReturnValue);
        }
        catch (Exception ex)
        {
            if (Log.IsErrorEnabled) Log.Error(CreateInvocationLogString("ERROR", invocation), ex);
            throw;
        }
    }

This is working as expected on regular method calls, but not when tried with async methods (using the async/await keywords from C# 5.0). And I believe, I understand the reasons behind this as well.

For the async/await to work, the compiler adds the functional body of the method into a state machine behind the scenes and the control will return to the caller, as soon as the first awaitable expression that cannot be completed synchronously, is encountered.

Also, we can interrogate the return type and figure out whether we are dealing with an async method like this:

            if (invocation.Method.ReturnType == typeof(Task) || 
                (invocation.Method.ReturnType.IsGenericType && 
                 invocation.Method.ReturnType.GetGenericTypeDefinition() == typeof(Task<>)))
                Log.Info("Asynchronous method found...");

This works for only those async methods that returns either Task or Task<> and not void but I am fine with that.

What changes have to made within the Intercept method so that the awaiter would return to there rather than the original caller?

Answer 1

Presumably the "problem" is that it's just logging that it's returning a task - and you want the value within that task?

Assuming that's the case, you still have to return the task to the caller, immediately - without waiting for it to complete. If you break that, you're fundamentally messing things up.

However, before you return the task to the caller, you should add a continuation (via Task.ContinueWith) which will log the result (or failure) when the task completes. That will still give the result information, but of course you'll be logging it potentially after some other logging. You may also want to log immediately before returning, leading to a log something like this:

Called FooAsync
Returned from FooAsync with a task
Task from FooAsync completed, with return value 5

The business of getting the result out of the task (if it completed successfully) would have to be done with reflection, which is a bit of a pain - or you could use dynamic typing. (Either way it will be a bit of a performance hit.)