Callsite fix for async methods

src/NLog/LoggerImpl.cs

@@ -114,21 +114,54 @@ private static int FindCallingMethodOnStackTrace([NotNull] StackTrace stackTrace
             var stackFrames = stackTrace.GetFrames();
             if (stackFrames == null)
                 return 0;
-            var intermediate = stackFrames.Select((f, i) => new {index = i, frame = f});
+            var intermediate = stackFrames.Select((f, i) => new StackFrameWithIndex(i, f));
             //find until logger type
-            intermediate = intermediate.SkipWhile(p => !IsLoggerType(p.frame, loggerType));
-            //skip to next
-            intermediate = intermediate.Skip(1);
-            //skip while in "skip" assemlbl
-            intermediate = intermediate.SkipWhile(p => SkipAssembly(p.frame));
+            intermediate = intermediate.SkipWhile(p => !IsLoggerType(p.StackFrame, loggerType));
+
+            intermediate = FilterBySkipAssembly(intermediate);
+            return GetIndexOfNonAsync(intermediate);
+        }
+
+        private static int GetIndexOfNonAsync(IEnumerable<StackFrameWithIndex> intermediate)
+        {
             var last = intermediate.FirstOrDefault();
 
             if (last != null)
             {
-                return last.index;
+#if ASYNC_SUPPORTED
+
+                //movenext and then AsyncTaskMethodBuilder (method start)? this is a generated MoveNext by async.
+                if (last.StackFrame.GetMethod().Name == "MoveNext")
+                {
+                    var next = intermediate.Skip(1).FirstOrDefault();
+                    if (next != null)
+                    {
+                        var declaringType = next.StackFrame.GetMethod().DeclaringType;
+                        if (declaringType != null && declaringType.FullName == "System.Runtime.CompilerServices.AsyncTaskMethodBuilder")
+                        {
+
+                            //async, search futher
+
+                            intermediate = FilterBySkipAssembly(intermediate);
+                            return GetIndexOfNonAsync(intermediate);
+                        }
+                    }
+                }
+#endif
+
+                return last.StackFrameIndex;
             }
             return 0;
+        }
+
+        private static IEnumerable<StackFrameWithIndex> FilterBySkipAssembly(IEnumerable<StackFrameWithIndex> intermediate)
+        {
 
+            //skip to next
+            intermediate = intermediate.Skip(1);
+            //skip while in "skip" assemlbl
+            intermediate = intermediate.SkipWhile(p => SkipAssembly(p.StackFrame));
+            return intermediate;
         }
 
         /// <summary>
@@ -249,5 +282,32 @@ private static FilterResult GetFilterResult(IList<Filter> filterChain, LogEventI
                 return FilterResult.Ignore;
             }
         }
+
+        /// <summary>
+        /// Stackframe with correspending index on the stracktrace
+        /// </summary>
+        private class StackFrameWithIndex
+        {
+            /// <summary>
+            /// Index of <see cref="StackFrame"/> on the stack.
+            /// </summary>
+            public int StackFrameIndex { get; private set; }
+
+            /// <summary>
+            /// A stackframe
+            /// </summary>
+            public StackFrame StackFrame { get; private set; }
+
+            /// <summary>
+            /// New item
+            /// </summary>
+            /// <param name="stackFrameIndex">Index of <paramref name="stackFrame"/> on the stack.</param>
+            /// <param name="stackFrame">A stackframe</param>
+            public StackFrameWithIndex(int stackFrameIndex, StackFrame stackFrame)
+            {
+                StackFrameIndex = stackFrameIndex;
+                StackFrame = stackFrame;
+            }
+        }
     }
 }

tests/NLog.UnitTests/LayoutRenderers/CallSiteTests.cs

@@ -31,6 +31,9 @@
 // THE POSSIBILITY OF SUCH DAMAGE.
 // 
 
+using System.IO;
+using System.Threading.Tasks;
+
 namespace NLog.UnitTests.LayoutRenderers
 {
     using System;
@@ -191,7 +194,7 @@ public void ClassNameWithPaddingTestPadLeftAlignLeftTest()
             MethodBase currentMethod = MethodBase.GetCurrentMethod();
             AssertDebugLastMessage("debug", currentMethod.DeclaringType.FullName.Substring(0, 3) + " msg");
         }
-        
+
         [Fact]
         public void ClassNameWithPaddingTestPadLeftAlignRightTest()
         {
@@ -548,7 +551,130 @@ public void When_WrappedInCompsition_Ignore_Wrapper_Methods_In_Callstack()
 
         }
 
+#if ASYNC_SUPPORTED
+        [Fact]
+        public void Show_correct_method_with_async()
+        {
+
+            //namespace en name of current method
+            const string currentMethodFullName = "NLog.UnitTests.LayoutRenderers.CallSiteTests.AsyncMethod";
+
+            LogManager.Configuration = CreateConfigurationFromString(@"
+           <nlog>
+               <targets><target name='debug' type='Debug' layout='${callsite}|${message}' /></targets>
+               <rules>
+                   <logger name='*' levels='Warn' writeTo='debug' />
+               </rules>
+           </nlog>");
+
+            AsyncMethod().Wait();
+            AssertDebugLastMessage("debug", string.Format("{0}|direct", currentMethodFullName));
+
+        }
+
+        private async Task AsyncMethod()
+        {
+            var logger = LogManager.GetCurrentClassLogger();
+            logger.Warn("direct");
+            var reader = new StreamReader(new MemoryStream(new byte[0]));
+            await reader.ReadLineAsync();
+        }
 
+        [Fact]
+        public void Show_correct_method_with_async2()
+        {
+
+            //namespace en name of current method
+            const string currentMethodFullName = "NLog.UnitTests.LayoutRenderers.CallSiteTests.AsyncMethod2b";
+
+            LogManager.Configuration = CreateConfigurationFromString(@"
+           <nlog>
+               <targets><target name='debug' type='Debug' layout='${callsite}|${message}' /></targets>
+               <rules>
+                   <logger name='*' levels='Warn' writeTo='debug' />
+               </rules>
+           </nlog>");
+
+            AsyncMethod2a().Wait();
+            AssertDebugLastMessage("debug", string.Format("{0}|direct", currentMethodFullName));
+
+        }
+
+        private async Task AsyncMethod2a()
+        {
+            await AsyncMethod2b();
+        }
+        private async Task AsyncMethod2b()
+        {
+            var logger = LogManager.GetCurrentClassLogger();
+            logger.Warn("direct");
+            var reader = new StreamReader(new MemoryStream(new byte[0]));
+            await reader.ReadLineAsync();
+        }
+
+
+        [Fact]
+        public void Show_correct_method_with_async3()
+        {
+
+            //namespace en name of current method
+            const string currentMethodFullName = "NLog.UnitTests.LayoutRenderers.CallSiteTests.AsyncMethod3b";
+
+            LogManager.Configuration = CreateConfigurationFromString(@"
+           <nlog>
+               <targets><target name='debug' type='Debug' layout='${callsite}|${message}' /></targets>
+               <rules>
+                   <logger name='*' levels='Warn' writeTo='debug' />
+               </rules>
+           </nlog>");
+
+            AsyncMethod3a().Wait();
+            AssertDebugLastMessage("debug", string.Format("{0}|direct", currentMethodFullName));
+
+        }
+
+        private async Task AsyncMethod3a()
+        {
+            var reader = new StreamReader(new MemoryStream(new byte[0]));
+            await reader.ReadLineAsync();
+            AsyncMethod3b();
+        }
+        private void AsyncMethod3b()
+        {
+            var logger = LogManager.GetCurrentClassLogger();
+            logger.Warn("direct");
+
+        }
+
+#endif
+
+        [Fact]
+        public void Show_correct_method_for_moveNext()
+        {
+
+            //namespace en name of current method
+            const string currentMethodFullName = "NLog.UnitTests.LayoutRenderers.CallSiteTests.MoveNext";
+
+            LogManager.Configuration = CreateConfigurationFromString(@"
+           <nlog>
+               <targets><target name='debug' type='Debug' layout='${callsite}|${message}' /></targets>
+               <rules>
+                   <logger name='*' levels='Warn' writeTo='debug' />
+               </rules>
+           </nlog>");
+
+            MoveNext();
+            AssertDebugLastMessage("debug", string.Format("{0}|direct", currentMethodFullName));
+
+        }
+
+
+        private void MoveNext()
+        {
+            var logger = LogManager.GetCurrentClassLogger();
+            logger.Warn("direct");
+
+        }
 
         public class CompositeWrapper
         {