${Callsite} method name for async methods are not correct in .NET Core #1805

Open
304NotModified opened this Issue Nov 30, 2016 · 8 comments

Projects

None yet

2 participants

@304NotModified
Member
304NotModified commented Nov 30, 2016 edited

Partly moved from NLog/NLog.Extensions.Logging#67

Current:Auth.Controllers.LoginController+<Post>d__4.MoveNext
should be: Auth.Controllers.LoginController.Post

callsite:CleanNamesOfAnonymousDelegates won't change anything.

With layout: layout="${longdate}|${uppercase:${level}}|${callsite:className=true:methodName=true}|${message}${newline}${stacktrace}"

Using
${callsite:CleanNamesOfAnonymousDelegates=true:ClassName=false}I get

2016-11-29 11:53:39.2654|INFO|Logged In foo@bar.com
MoveNext
ExecutionContext.Run => ExecutionContext.RunInternal => <Post>d__4.MoveNext

of course I'm looking to get something like Auth.LoginController.Post (fully qualified class name + method name)

using
${callsite:CleanNamesOfAnonymousDelegates=true:MethodName=false}
I get

2016-11-29 11:54:58.6905|INFO|Logged In foo@bar.com
Auth.Controllers.LoginController+<Post>d__4
ExecutionContext.Run => ExecutionContext.RunInternal => <Post>d__4.MoveNext

Current code:
https://github.com/NLog/NLog/blob/e77dba48c9140caeb8c0a28a54f92a3ee93b82a0/src/NLog/LayoutRenderers/CallSiteLayoutRenderer.cs#L145-L185

@304NotModified 304NotModified referenced this issue in NLog/NLog.Extensions.Logging Nov 30, 2016
Closed

asp.net Core $(callsite} rears its head #67

@304NotModified
Member

in methodname it searches for <, but it seems that methodname and classname are mixed.

@304NotModified
Member

@EltonInAtlanta could you provide us a sample call (including the method definition)? I would be nice if the case is without DI

@EltonInAtlanta
EltonInAtlanta commented Dec 1, 2016 edited

Here is the controller (sanitized slightly) I've been using throughout this discussion.

    public class LoginController :Controller
    {
        private readonly TokenProviderOptions TokenProviderOptions;
        private readonly ILogger Logger;
        private readonly IMembership Membership;

        public LoginController(TokenProviderOptions options, ILoggerFactory logFactory, IMembership membership)
        {
            TokenProviderOptions = options;
            Logger = logFactory.CreateLogger<LoginController>();
            Membership = membership;
        }

        [HttpPost]
        [AllowAnonymous]
        public async Task<IActionResult> Post([FromBody] Credentials creds)
        {
            if (creds != null)
            {
                if (creds.Application == null) creds.Application = MembershipApplications.ApplicationPublicNameParent;

...
                if (user == null)
                {
                    Logger.LogInformation($"Failed LogIn {creds.Username}");
                    return new UnauthorizedResult();
                }

...

                Logger.LogInformation($"Logged In {creds.Username}");
                return new JsonResult(token);
            }
            else
            {
                return new BadRequestResult();
            }

        }
    }

Here's the relevant part of the startup configuration:

        public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
        {
...            
                loggerFactory.WithFilter(
                    new FilterLoggerSettings
                    {
                        { "Microsoft", LogLevel.Warning },
                        { "System", LogLevel.Warning }
                    }
                    ).AddNLog(); 
                env.ConfigureNLog(@".\nlog.config");

                NLog.LogManager.AddHiddenAssembly(Assembly.Load(new AssemblyName("Microsoft.Extensions.Logging.Filter")));

                ILogger log = loggerFactory.CreateLogger("Configure");
                log.LogInformation("Startup");
                DatabaseWarmupRead();
                log.LogInformation("Warmed Up");
               
@EltonInAtlanta
EltonInAtlanta commented Dec 1, 2016 edited

For comparison, I added a non DI created logger to test:

    public class AnnonTestController : Controller
    {
        // GET api/values/5
        [HttpGet("{id}")]
        public string Get(int id)
        {
            NLog.Logger logger = NLog.LogManager.GetLogger("AnnonTest");
            logger.Info("How now brown cow");

            return "value";
        }

Here is the output from the login call in the previous post, and the call to this test controller:

016-12-01 10:40:03.6020|INFO|How now brown cow
Auth.Controllers.AnnonTestController.Get
<InvokeActionMethodAsync>d__27.MoveNext => <no type>.lambda_method => AnnonTestController.Get

2016-12-01 10:41:14.5523|INFO|Logged In foo@bar.com
Auth.Controllers.LoginController+<Post>d__4.MoveNext
ExecutionContext.Run => ExecutionContext.RunInternal => <Post>d__4.MoveNext

This is the NLog configuration producing this output:

    <target xsi:type="File" name="debugFile" fileName="${basedir}/logs/debug-${shortdate}.log"
            layout="${longdate}|${uppercase:${level}}|${message}${newline}${callsite:CleanNamesOfAnonymousDelegates=true}${newline}${stacktrace}${newline}${newline}" />
@304NotModified
Member

For comparison, I added a non DI created logger to test:

It's even a problem when the action isn't async?

@EltonInAtlanta
EltonInAtlanta commented Dec 1, 2016 edited

Issue appears to be async only.

Here's my modified test controller:

using System.Collections.Generic;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Mvc;
using Microsoft.AspNetCore.Authorization;
using Auth.Code;
using Microsoft.Extensions.Logging;
//using wallet.Code;

// For more information on enabling Web API for empty projects, visit http://go.microsoft.com/fwlink/?LinkID=397860

namespace Auth.Controllers
{
    [Route("api/[controller]")]
    [AllowAnonymous]
    public class AnnonTestController : Controller
    {

        private readonly ILogger Logger;

        public AnnonTestController(ILoggerFactory logFactory)
        {
            Logger = logFactory.CreateLogger<AnnonTestController>();
        }

        [HttpGet]
        public async Task<IEnumerable<string>> Get()
        {
            NLog.Logger logger = NLog.LogManager.GetLogger("AnnonTest");
            logger.Info("Native, async method");

            Logger.LogInformation("Injected, async method");

            return await Task.FromResult( new string[] { "value1", "value2" });
        }

        // GET api/values/5
        [HttpGet("{id}")]
        public string Get(int id)
        {
            NLog.Logger logger = NLog.LogManager.GetLogger("AnnonTest");
            logger.Info("Native, not async");

            Logger.LogInformation("Injected, not async");
            return "value";
        }
}
}

And the output:

2016-12-01 16:53:45.4233|INFO|Startup
Auth.Startup.Configure
RuntimeMethodInfo.UnsafeInvokeInternal => RuntimeMethodHandle.InvokeMethod => Startup.Configure

2016-12-01 16:53:51.2155|INFO|Warmed Up
Auth.Startup.Configure
RuntimeMethodInfo.UnsafeInvokeInternal => RuntimeMethodHandle.InvokeMethod => Startup.Configure

2016-12-01 16:53:54.8998|INFO|Native, not async
Auth.Controllers.AnnonTestController.Get
<InvokeActionMethodAsync>d__27.MoveNext => <no type>.lambda_method => AnnonTestController.Get

2016-12-01 16:53:54.9627|INFO|Injected, not async
Auth.Controllers.AnnonTestController.Get
<InvokeActionMethodAsync>d__27.MoveNext => <no type>.lambda_method => AnnonTestController.Get

2016-12-01 16:53:58.4663|INFO|Native, async method
Auth.Controllers.AnnonTestController.Get
<InvokeActionMethodAsync>d__27.MoveNext => <no type>.lambda_method => AnnonTestController.Get

2016-12-01 16:53:58.4975|INFO|Injected, async method
Auth.Controllers.AnnonTestController.Get
<InvokeActionMethodAsync>d__27.MoveNext => <no type>.lambda_method => AnnonTestController.Get

2016-12-01 16:54:28.5551|INFO|Logged In foo@bar.com
Auth.Controllers.LoginController+<Post>d__4.MoveNext
ExecutionContext.Run => ExecutionContext.RunInternal => <Post>d__4.MoveNext

Looks pretty good here no matter what I do. So now I'm trying to understand why that last one is special. It's a call to the login controller in my first post on this thread.

@304NotModified
Member

@valuerr altough it's the same component, it's a different bug. I move your comments to a new issue, so it's easier to track/solve: #1813

@304NotModified
Member

This issue (method name), seems only an issue in .NET Core, as I could not reproduce it in NLog 4.3 (cf0d7cf)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment