Question

Using log4net declared as:

private readonly ILog log = 
       LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType());

In an async method or task, like this one:

public async void CheckSomething()
{
    log.Info(null);
    //....
}

logs MoveNext instead of CheckSomething. Any idea how to make it log an actual method name?

Was it helpful?

Solution

All async methods are rewritten into a state machine to satisfy potential await values within the method. The final method in which the code lives is the MoveNext method which is what log4net is reporting.

There is really no good way at runtime to transition from MoveNext to the actual method in which the code was originally written. They are somewhat disconnected at a metadata level. You may just have to resort to logging the name directly

OTHER TIPS

Short: given the MoveNext() method, try this:

private static MethodBase GetRealMethodFromAsyncMethod(MethodBase asyncMethod)
{
    var generatedType = asyncMethod.DeclaringType;
    var originalType = generatedType.DeclaringType;
    var matchingMethods = 
        from methodInfo in originalType.GetMethods() 
        let attr = methodInfo.GetCustomAttribute<AsyncStateMachineAttribute>() 
        where attr != null && attr.StateMachineType == generatedType 
        select methodInfo;

    // If this throws, the async method scanning failed.
    var foundMethod = matchingMethods.Single();
    return foundMethod;
}

Long (Disclaimer)

Don't use this in production. It relies on compiler behavior, which may likely change in a future version without notice. The following assumptions about compiler are made:

  1. The actual running async method is generated inside a generated type.
  2. The generated type is a nested type of the original type containing the original, hand-written method.
  3. The original method gets a compiler-generated attribute AsyncStateMachine with the generated type supplied in it.

It works in my code, where I use it for runtime code analysis during debug/tests only. Again, please, don't use it in production code.

With thanks to the answer from Jacek Gorgoń, here is the utility I came up. It has a couple of improvements but still has a long way to go to work nicely with anonymous or lambda methods.

static string GetMethodContextName() {
    var name = new StackTrace().GetFrame(1).GetMethod().GetMethodContextName();
}

static string GetMethodContextName(this MethodBase method) {
    if (method.DeclaringType.GetInterfaces().Any(i => i == typeof(IAsyncStateMachine))) {
        var generatedType = method.DeclaringType;
        var originalType = generatedType.DeclaringType;
        var foundMethod = originalType.GetMethods(Instance | Static | Public | NonPublic | DeclaredOnly)
            .Single(m => m.GetCustomAttribute<AsyncStateMachineAttribute>()?.StateMachineType == generatedType);
        return foundMethod.DeclaringType.Name + "." + foundMethod.Name;
    } else {
        return method.DeclaringType.Name + "." + method.Name;
    }
}

Here's an example usage:

class Program { 
    static void Main(string[] args) {
        // outputs Program.Main
        Console.WriteLine(GetMethodContextName());
        Test().Wait();
    }
    static async Task Test() { 
        // outputs Program.Test
        Console.WriteLine(GetMethodContextName());
        await Task.CompletedTask;
    }
}

I wrote a simple wrapper around log4net.

public class Logger
{
    private ILog _Log { get; set; }

    public Logger(Type declaringType)
    {
        _Log = LogManager.GetLogger(declaringType);
    }

    public void Error(Exception exception, [CallerMemberName] string callerMemberName = "")
    {
        _Log.Error(callerMemberName, exception);
    }
}

In the code that is doing the logging, just do:

private Logger Log = new Logger(MethodBase.GetCurrentMethod().DeclaringType);

Of course if you want to do things like Info, Debug, etc, you can just add it to the wrapper class.

NOTE
this utilizes the c# 5.0 [CallerMemberName]

Use this, works great...

public void Log(Microsoft.Extensions.Logging.LogLevel level, string message,
        [System.Runtime.CompilerServices.CallerMemberName] string memberName = "",
        [System.Runtime.CompilerServices.CallerFilePath] string sourceFilePath = "",
        [System.Runtime.CompilerServices.CallerLineNumber] int sourceLineNumber = 0)
    { 
//do your logging here....
    }

With an extension method that just returns the caller member name for a MethodBase.

public static class MemberBaseExtension
{
    public static string GetDeclaringName(this MethodBase methodBase, [CallerMemberName] string memberName = "")
    {
        return memberName;
    }
}

You could do something like this from just using configuration, but it's not exactly what you mention. If you're able to read it and don't mind the weird syntax you could use the %type pattern to print out the qualified name of the method and then the %method pattern to print the method. You can even only print some of the qualified name to combat long namespaces.

From the docs:

Used to output the fully qualified type name of the caller issuing the logging request. This conversion specifier can be optionally followed by precision specifier, that is a decimal constant in brackets.

If a precision specifier is given, then only the corresponding number of right most components of the class name will be printed. By default the class name is output in fully qualified form.

For example, for the class name "log4net.Layout.PatternLayout", the pattern %type{1} will output "PatternLayout".

eg.

<layout type="log4net.Layout.PatternLayout">
  <conversionPattern value="%date %5level %logger %type{2}.%method [%line] - %message%newline %exception" />
</layout>

In terms of the MoveNext printing, it'll look like:

2021-03-10 11:45:29,203  INFO StackOverflowLogger SubNamespace.ClassName+<MethodNameAsync>d__15.MoveNext [123] - Logging is starting...

We didn't care about the d__15.MoveNext as long as the async method was there SubNamespace.ClassName+<MethodNameAsync>.

Licensed under: CC-BY-SA with attribution
Not affiliated with StackOverflow
scroll top