Merge pull request #1138 from NLog/callsite-async

Callsite fix for async methods
NLog · Jan 17, 2016 · adbaa48 · adbaa48
2 parents ab71d18 + ab025b0
commit adbaa48
Show file tree

Hide file tree

Showing 2 changed files with 202 additions and 9 deletions.
diff --git a/src/NLog/LoggerImpl.cs b/src/NLog/LoggerImpl.cs
@@ -114,21 +114,62 @@ 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));
-            var last = intermediate.FirstOrDefault();
+            intermediate = intermediate.SkipWhile(p => !IsLoggerType(p.StackFrame, loggerType));
+
+            intermediate = FilterBySkipAssembly(intermediate.Skip(1));
+            return FindIndexOfCallingMethod(intermediate);
+        }
+
+        /// <summary>
+        /// Get the index which correspondens to the calling method.
+        /// </summary>
+        /// <param name="stackFrames"></param>
+        /// <returns></returns>
+        private static int FindIndexOfCallingMethod(IEnumerable<StackFrameWithIndex> stackFrames)
+        {
+            var stackFrameWithIndex = stackFrames.FirstOrDefault();
+            var last = stackFrameWithIndex;
 
             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 = stackFrames.Skip(1).FirstOrDefault();
+                    if (next != null)
+                    {
+                        var declaringType = next.StackFrame.GetMethod().DeclaringType;
+                        if (declaringType  == typeof(System.Runtime.CompilerServices.AsyncTaskMethodBuilder))
+                        {
+
+                            //async, search futher
+
+                            stackFrames = FilterBySkipAssembly(stackFrames.Skip(1));
+                            return FindIndexOfCallingMethod(stackFrames);
+                        }
+                    }
+                }
+#endif
+
+                return last.StackFrameIndex;
             }
             return 0;
+        }
 
+        /// <summary>
+        /// Filter strackframes by assembly filter
+        /// </summary>
+        /// <param name="stackFrames"></param>
+        /// <returns></returns>
+        private static IEnumerable<StackFrameWithIndex> FilterBySkipAssembly(IEnumerable<StackFrameWithIndex> stackFrames)
+        {
+            //skip while in "skip" assemlbl
+            stackFrames = stackFrames.SkipWhile(p => SkipAssembly(p.StackFrame));
+            return stackFrames;
         }
 
         /// <summary>
@@ -249,5 +290,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;
+            }
+        }
     }
 }
diff --git a/tests/NLog.UnitTests/LayoutRenderers/CallSiteTests.cs b/tests/NLog.UnitTests/LayoutRenderers/CallSiteTests.cs
@@ -36,6 +36,8 @@ namespace NLog.UnitTests.LayoutRenderers
     using System;
     using System.Reflection;
     using System.Threading;
+    using System.IO;
+    using System.Threading.Tasks;
     using Xunit;
 
     public class CallSiteTests : NLogTestBase
@@ -191,7 +193,7 @@ public void ClassNameWithPaddingTestPadLeftAlignLeftTest()
             MethodBase currentMethod = MethodBase.GetCurrentMethod();
             AssertDebugLastMessage("debug", currentMethod.DeclaringType.FullName.Substring(0, 3) + " msg");
         }
-        
+
         [Fact]
         public void ClassNameWithPaddingTestPadLeftAlignRightTest()
         {
@@ -548,7 +550,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
         {