Skip to content

Commit 36310b4

Browse files
304NotModified304NotModified
committed
Merge pull request #1333 from NLog/callsite-issue-4.3
Fix ${callsite} when loggerType can't be found due to inlining
2 parents 33efd9d + 5d41eb6 commit 36310b4

3 files changed

Lines changed: 70 additions & 31 deletions

File tree

‎src/NLog/Internal/StackTraceUsageUtils.cs‎

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -35,6 +35,7 @@ namespace NLog.Internal
3535
{
3636
using System;
3737
using NLog.Config;
38+
using System.Diagnostics;
3839

3940
/// <summary>
4041
/// Utilities for dealing with <see cref="StackTraceUsage"/> values.
@@ -45,5 +46,15 @@ internal static StackTraceUsage Max(StackTraceUsage u1, StackTraceUsage u2)
4546
{
4647
return (StackTraceUsage)Math.Max((int)u1, (int)u2);
4748
}
49+
50+
/// <summary>
51+
/// Get this stacktrace for inline unit test
52+
/// </summary>
53+
/// <param name="loggerType"></param>
54+
/// <returns></returns>
55+
internal static StackTrace GetWriteStackTrace(Type loggerType)
56+
{
57+
return new StackTrace();
58+
}
4859
}
4960
}

‎src/NLog/LoggerImpl.cs‎

Lines changed: 30 additions & 29 deletions
Original file line numberDiff line numberDiff line change
@@ -109,30 +109,43 @@ internal static void Write([NotNull] Type loggerType, TargetWithFilterChain targ
109109
/// <param name="stackTrace">The stack trace of the logging method invocation</param>
110110
/// <param name="loggerType">Type of the logger or logger wrapper. This is still Logger if it's a subclass of Logger.</param>
111111
/// <returns>Index of the first user stack frame or 0 if all stack frames are non-user</returns>
112-
private static int FindCallingMethodOnStackTrace([NotNull] StackTrace stackTrace, [NotNull] Type loggerType)
112+
internal static int FindCallingMethodOnStackTrace([NotNull] StackTrace stackTrace, [NotNull] Type loggerType)
113113
{
114114
var stackFrames = stackTrace.GetFrames();
115115
if (stackFrames == null)
116116
return 0;
117117

118-
var intermediate = stackFrames.Select((f, i) => new StackFrameWithIndex(i, f));
118+
//create StackFrameWithIndex so the index is know after filtering
119+
var allStackFrames = stackFrames.Select((f, i) => new StackFrameWithIndex(i, f)).ToList();
120+
//filter on assemblies
121+
var filteredStackframes = allStackFrames.Where(p => !SkipAssembly(p.StackFrame)).ToList();
119122
//find until logger type
120-
intermediate = intermediate.SkipWhile(p => !IsLoggerType(p.StackFrame, loggerType));
123+
var intermediate = filteredStackframes.SkipWhile(p => !IsLoggerType(p.StackFrame, loggerType));
121124
//skip the logger type
122-
intermediate = intermediate.SkipWhile(p => IsLoggerType(p.StackFrame, loggerType));
125+
var stackframesAfterLogger = intermediate.SkipWhile(p => IsLoggerType(p.StackFrame, loggerType)).ToList();
123126

124-
intermediate = FilterBySkipAssembly(intermediate);
125-
return FindIndexOfCallingMethod(intermediate);
127+
//get first call after logger (or skip if is moveNext)
128+
var candidateStackFrames = stackframesAfterLogger;
129+
if (!candidateStackFrames.Any())
130+
{
131+
//If some calls got inlined, we can't find LoggerType on the stack. Fallback to the filteredStackframes
132+
candidateStackFrames = filteredStackframes;
133+
}
134+
135+
return FindIndexOfCallingMethod(allStackFrames, candidateStackFrames);
126136
}
127137

128138
/// <summary>
129139
/// Get the index which correspondens to the calling method.
140+
///
141+
/// This is most of the time the first index after <paramref name="candidateStackFrames"/>.
130142
/// </summary>
131-
/// <param name="stackFrames"></param>
132-
/// <returns></returns>
133-
private static int FindIndexOfCallingMethod(IEnumerable<StackFrameWithIndex> stackFrames)
143+
/// <param name="allStackFrames">all the frames of the stacktrace</param>
144+
/// <param name="candidateStackFrames">frames which all hiddenAssemblies are removed</param>
145+
/// <returns>index on stacktrace</returns>
146+
private static int FindIndexOfCallingMethod(List<StackFrameWithIndex> allStackFrames, List<StackFrameWithIndex> candidateStackFrames)
134147
{
135-
var stackFrameWithIndex = stackFrames.FirstOrDefault();
148+
var stackFrameWithIndex = candidateStackFrames.FirstOrDefault();
136149
var last = stackFrameWithIndex;
137150

138151
if (last != null)
@@ -142,17 +155,16 @@ private static int FindIndexOfCallingMethod(IEnumerable<StackFrameWithIndex> sta
142155
//movenext and then AsyncTaskMethodBuilder (method start)? this is a generated MoveNext by async.
143156
if (last.StackFrame.GetMethod().Name == "MoveNext")
144157
{
145-
var next = stackFrames.Skip(1).FirstOrDefault();
146-
if (next != null)
158+
159+
if (allStackFrames.Count > last.StackFrameIndex)
147160
{
161+
var next = allStackFrames[last.StackFrameIndex + 1];
148162
var declaringType = next.StackFrame.GetMethod().DeclaringType;
149163
if (declaringType == typeof(System.Runtime.CompilerServices.AsyncTaskMethodBuilder))
150164
{
151-
152165
//async, search futher
153-
154-
stackFrames = FilterBySkipAssembly(stackFrames.Skip(1));
155-
return FindIndexOfCallingMethod(stackFrames);
166+
candidateStackFrames = candidateStackFrames.Skip(1).ToList();
167+
return FindIndexOfCallingMethod(allStackFrames, candidateStackFrames);
156168
}
157169
}
158170
}
@@ -163,18 +175,6 @@ private static int FindIndexOfCallingMethod(IEnumerable<StackFrameWithIndex> sta
163175
return 0;
164176
}
165177

166-
/// <summary>
167-
/// Filter strackframes by assembly filter
168-
/// </summary>
169-
/// <param name="stackFrames"></param>
170-
/// <returns></returns>
171-
private static IEnumerable<StackFrameWithIndex> FilterBySkipAssembly(IEnumerable<StackFrameWithIndex> stackFrames)
172-
{
173-
//skip while in "skip" assemlbl
174-
stackFrames = stackFrames.SkipWhile(p => SkipAssembly(p.StackFrame));
175-
return stackFrames;
176-
}
177-
178178
/// <summary>
179179
/// Assembly to skip?
180180
/// </summary>
@@ -185,7 +185,8 @@ private static bool SkipAssembly(StackFrame frame)
185185
var method = frame.GetMethod();
186186
var assembly = method.DeclaringType != null ? method.DeclaringType.Assembly : method.Module.Assembly;
187187
// skip stack frame if the method declaring type assembly is from hidden assemblies list
188-
return SkipAssembly(assembly);
188+
var skipAssembly = SkipAssembly(assembly);
189+
return skipAssembly;
189190
}
190191

191192
/// <summary>

‎tests/NLog.UnitTests/LayoutRenderers/CallSiteTests.cs‎

Lines changed: 29 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -31,8 +31,13 @@
3131
// THE POSSIBILITY OF SUCH DAMAGE.
3232
//
3333

34+
using System.Collections.Generic;
35+
using System.Diagnostics;
36+
using System.Linq;
3437
using System.Runtime.CompilerServices;
3538
using NLog.Config;
39+
using NLog.Internal;
40+
using NLog.Layouts;
3641
using NLog.Targets;
3742

3843
namespace NLog.UnitTests.LayoutRenderers
@@ -78,7 +83,7 @@ public void LogDebug(NLog.Logger logger)
7883
// compile code and generate assembly
7984
System.CodeDom.Compiler.CompilerResults results = provider.CompileAssemblyFromSource(parameters, code);
8085

81-
Assert.False(results.Errors.HasErrors,"Compiler errors: " + string.Join(";", results.Errors));
86+
Assert.False(results.Errors.HasErrors, "Compiler errors: " + string.Join(";", results.Errors));
8287

8388
// create nlog configuration
8489
LogManager.Configuration = CreateConfigurationFromString(@"
@@ -871,7 +876,29 @@ public NLogLogger Create(string name)
871876
return new NLogLogger(log);
872877
}
873878
}
874-
879+
880+
/// <summary>
881+
/// If some calls got inlined, we can't find LoggerType anymore. We should fallback if loggerType can be found
882+
///
883+
/// Example of those stacktraces:
884+
/// at NLog.LoggerImpl.Write(Type loggerType, TargetWithFilterChain targets, LogEventInfo logEvent, LogFactory factory) in c:\temp\NLog\src\NLog\LoggerImpl.cs:line 68
885+
/// at NLog.UnitTests.LayoutRenderers.NLogLogger.ErrorWithoutLoggerTypeArg(String message) in c:\temp\NLog\tests\NLog.UnitTests\LayoutRenderers\CallSiteTests.cs:line 989
886+
/// at NLog.UnitTests.LayoutRenderers.CallSiteTests.TestCallsiteWhileCallsGotInlined() in c:\temp\NLog\tests\NLog.UnitTests\LayoutRenderers\CallSiteTests.cs:line 893
887+
///
888+
/// </summary>
889+
[Fact]
890+
private void CallSiteShouldWorkEvenInlined()
891+
{
892+
Type loggerType = typeof(Logger);
893+
var stacktrace = StackTraceUsageUtils.GetWriteStackTrace(loggerType);
894+
var index = LoggerImpl.FindCallingMethodOnStackTrace(stacktrace, loggerType);
895+
var logEvent = new LogEventInfo(LogLevel.Error, "logger1", "message1");
896+
logEvent.SetStackTrace(stacktrace, index);
897+
Layout l = "${callsite}";
898+
var callSite = l.Render(logEvent);
899+
Assert.Equal("NLog.UnitTests.LayoutRenderers.CallSiteTests.CallSiteShouldWorkEvenInlined", callSite);
900+
}
901+
875902
}
876903

877904
/// <summary>

0 commit comments

Comments
 (0)