MoveNext instead of actual method/task name

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?

Vegetal

Is this a release build? The compiler could be inlining the methods. How are you getting the method name? Your logger name is defined as the type that contains the logger, so are you using a PatternLayout? – Hoagland

Answer 1

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

Bagwell

And for logging that name directly, you might want to use the C# 5.0 caller information parameters. – Constitutionalism

Answer 2

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.

Jeffery

Thanks for the suggestion. This works really well as an extension method too. Add the "this" keyword before the MethodBase asyncMethod param and you can simplify usage SomeHelper.GetRealMethodFromAsyncMethod(MethodBase.GetCurrentMethod()) becomes MethodBase.GetCurrentMethod().GetRealMethodFromAsyncMethod() – Conte

Looks like fun! :) many thanks for that explicit list of assumptions, that's a thing not seen often. – Bethune

You're welcome. I believe I've seen similar research in your own code in a project we've worked on ~10 years ago ;) – Clemenciaclemency

Answer 3

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;
    }
}

Determined

Answer 4

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]

Chandelle

Clean and clever. Thanks! – Pond

Answer 5

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....
    }

Barretter

Answer 6

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;
    }
}

Humanity

I confirm that this is working for async methods! But writing an extension method looks overkill to me, a simple static method would be enough. – Sneaker

Answer 7

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>.

Linolinocut