benaadams / Ben.Demystifier

High performance understanding for stack traces (Make error logs more productive)
Apache License 2.0
2.76k stars 118 forks source link

IndexOutOfRangeException in ILReader.ReadOpCode() line 36 #56

Closed KirillOsenkov closed 5 years ago

KirillOsenkov commented 6 years ago

When analyzing a certain exception I'm seeing an exception in ILReader.ReadOpCode() line 36 here: https://github.com/benaadams/Ben.Demystifier/blob/57e2d49ad1ebc0309c6f50f7555d159a6fcf820e/src/Ben.Demystifier/Internal/ILReader.cs#L36

The instruction is 235. singleByteOpCode only contains 225 entries.

Stack trace:

>   System.Diagnostics.Internal.ILReader.ReadOpCode Line 36 C#  Symbols loaded.
    System.Diagnostics.Internal.ILReader.Read Line 25   C#  Symbols loaded.
    System.Diagnostics.EnhancedStackTrace.TryResolveSourceMethod Line 350   C#  Symbols loaded.
    System.Diagnostics.EnhancedStackTrace.TryResolveGeneratedName Line 289  C#  Symbols loaded.
    System.Diagnostics.EnhancedStackTrace.GetMethodDisplayString Line 122   C#  Symbols loaded.
    System.Diagnostics.EnhancedStackTrace.GetFrames Line 71 C#  Symbols loaded.
    System.Diagnostics.EnhancedStackTrace.EnhancedStackTrace Line 46    C#  Symbols loaded.
KirillOsenkov commented 6 years ago

The stack trace being analyzed is:

at System.Type.InvokeMember(String name, BindingFlags invokeAttr, Binder binder, Object target, Object[] args, CultureInfo culture)
at Microsoft.Build.Evaluation.Expander`2.Function`1.Execute(Object objectInstance, IPropertyProvider`1 properties, ExpanderOptions options, IElementLocation elementLocation)
at Microsoft.Build.Evaluation.Expander`2.PropertyExpander`1.ExpandPropertyBody(String propertyBody, Object propertyValue, IPropertyProvider`1 properties, ExpanderOptions options, IElementLocation elementLocation, UsedUninitializedProperties usedUninitializedProperties)
at Microsoft.Build.Evaluation.Expander`2.PropertyExpander`1.ExpandPropertiesLeaveTypedAndEscaped(String expression, IPropertyProvider`1 properties, ExpanderOptions options, IElementLocation elementLocation, UsedUninitializedProperties usedUninitializedProperties)
at Microsoft.Build.Evaluation.Expander`2.PropertyExpander`1.ExpandPropertiesLeaveEscaped(String expression, IPropertyProvider`1 properties, ExpanderOptions options, IElementLocation elementLocation, UsedUninitializedProperties usedUninitializedProperties)
at Microsoft.Build.Evaluation.Expander`2.ExpandIntoStringLeaveEscaped(String expression, ExpanderOptions options, IElementLocation elementLocation)
at Microsoft.Build.Evaluation.Evaluator`4.EvaluatePropertyElement(ProjectPropertyElement propertyElement)
at Microsoft.Build.Evaluation.Evaluator`4.EvaluatePropertyGroupElement(ProjectPropertyGroupElement propertyGroupElement)
at Microsoft.Build.Evaluation.Evaluator`4.PerformDepthFirstPass(ProjectRootElement currentProjectOrImport)
at Microsoft.Build.Evaluation.Evaluator`4.EvaluateImportElement(String directoryOfImportingFile, ProjectImportElement importElement)
at Microsoft.Build.Evaluation.Evaluator`4.PerformDepthFirstPass(ProjectRootElement currentProjectOrImport)
at Microsoft.Build.Evaluation.Evaluator`4.EvaluateImportElement(String directoryOfImportingFile, ProjectImportElement importElement)
at Microsoft.Build.Evaluation.Evaluator`4.PerformDepthFirstPass(ProjectRootElement currentProjectOrImport)
at Microsoft.Build.Evaluation.Evaluator`4.EvaluateImportElement(String directoryOfImportingFile, ProjectImportElement importElement)
at Microsoft.Build.Evaluation.Evaluator`4.PerformDepthFirstPass(ProjectRootElement currentProjectOrImport)
at Microsoft.Build.Evaluation.Evaluator`4.EvaluateImportElement(String directoryOfImportingFile, ProjectImportElement importElement)
at Microsoft.Build.Evaluation.Evaluator`4.PerformDepthFirstPass(ProjectRootElement currentProjectOrImport)
at Microsoft.Build.Evaluation.Evaluator`4.EvaluateImportElement(String directoryOfImportingFile, ProjectImportElement importElement)
at Microsoft.Build.Evaluation.Evaluator`4.PerformDepthFirstPass(ProjectRootElement currentProjectOrImport)
at Microsoft.Build.Evaluation.Evaluator`4.EvaluateImportElement(String directoryOfImportingFile, ProjectImportElement importElement)
at Microsoft.Build.Evaluation.Evaluator`4.PerformDepthFirstPass(ProjectRootElement currentProjectOrImport)
at Microsoft.Build.Evaluation.Evaluator`4.Evaluate(ILoggingService loggingService, BuildEventContext buildEventContext)
at Microsoft.Build.Evaluation.Evaluator`4.Evaluate(IEvaluatorData`4 data, ProjectRootElement root, ProjectLoadSettings loadSettings, Int32 maxNodeCount, PropertyDictionary`1 environmentProperties, ILoggingService loggingService, IItemFactory`2 itemFactory, IToolsetProvider toolsetProvider, ProjectRootElementCache projectRootElementCache, BuildEventContext buildEventContext, ProjectInstance projectInstanceIfAnyForDebuggerOnly, SdkResolution sdkResolution)
at Microsoft.Build.Execution.ProjectInstance.Initialize(ProjectRootElement xml, IDictionary`2 globalProperties, String explicitToolsVersion, String explicitSubToolsetVersion, Int32 visualStudioVersionFromSolution, BuildParameters buildParameters, ILoggingService loggingService, BuildEventContext buildEventContext, SdkResolution sdkResolution)
at Microsoft.Build.Execution.ProjectInstance..ctor(String projectFile, IDictionary`2 globalProperties, String toolsVersion, BuildParameters buildParameters, ILoggingService loggingService, BuildEventContext buildEventContext)
at Microsoft.Build.BackEnd.RequestBuilder.LoadProjectFromFile()
at Microsoft.Build.BackEnd.BuildRequestConfiguration.InitializeProject(BuildParameters buildParameters, Func`1 loadProjectFromFile)
at Microsoft.Build.BackEnd.RequestBuilder.LoadProjectIntoConfiguration()
at Microsoft.Build.BackEnd.RequestBuilder.<BuildProject>d__57.MoveNext()
at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.Start[TStateMachine](TStateMachine& stateMachine)
at Microsoft.Build.BackEnd.RequestBuilder.BuildProject()
at Microsoft.Build.BackEnd.RequestBuilder.<BuildAndReport>d__49.MoveNext()
at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[TStateMachine](TStateMachine& stateMachine)
at Microsoft.Build.BackEnd.RequestBuilder.BuildAndReport()
at Microsoft.Build.BackEnd.RequestBuilder.<RequestThreadProc>d__48.MoveNext()
at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[TStateMachine](TStateMachine& stateMachine)
at Microsoft.Build.BackEnd.RequestBuilder.RequestThreadProc(Boolean setThreadParameters)
at Microsoft.Build.BackEnd.RequestBuilder.<StartBuilderThread>b__44_2()
at System.Threading.Tasks.Task`1.InnerInvoke()
at System.Threading.Tasks.Task.Execute()
at System.Threading.Tasks.Task.ExecutionContextCallback(Object obj)
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
at System.Threading.Tasks.Task.ExecuteEntry(Boolean bPreventDoubleExecution)
at System.Threading.Tasks.ThreadPoolTaskScheduler.LongRunningThreadWork(Object obj)
at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Threading.ThreadHelper.ThreadStart(Object obj)
KirillOsenkov commented 6 years ago

The frame is:

{<StartBuilderThread>b__44_2 at offset 42 in file:line:column <filename unknown>:0:0}

Method is:

{System.Threading.Tasks.Task <StartBuilderThread>b__44_2()}

candidateMethod is:

Microsoft.Build.BackEnd.RequestBuilder.StartBuilderThread()
KirillOsenkov commented 6 years ago

Raw IL of the method (byte[288]):

2 123 209 5 0 4 20 254 1 114 193 103 1 112 40 160 22 0 6 2 115 183 10 0 10 125 210 5 0 4 2 123 212 5 0 4 2 123 211 5 0 4 40 221 15 0 6 44 68 2 123 212 5 0 4 111 103 17 0 6 2 111 222 9 0 6 2 40 184 10 0 10 2 254 6 249 15 0 6 115 185 10 0 10 2 123 210 5 0 4 111 186 10 0 10 22 40 101 6 0 10 111 221 0 0 43 40 188 10 0 10 125 209 5 0 4 42 2 123 212 5 0 4 111 103 17 0 6 111 216 9 0 6 2 123 211 5 0 4 111 166 14 0 6 111 125 16 0 6 254 1 22 254 1 114 235 103 1 112 40 160 22 0 6 114 160 104 1 112 40 210 0 0 10 114 194 5 0 112 40 221 0 0 10 44 51 2 40 184 10 0 10 2 254 6 250 15 0 6 115 185 10 0 10 2 123 210 5 0 4 111 186 10 0 10 22 40 196 21 0 6 111 221 0 0 43 40 188 10 0 10 125 209 5 0 4 42 2 40 184 10 0 10 2 254 6 251 15 0 6 115 185 10 0 10 2 123 210 5 0 4 111 186 10 0 10 24 40 101 6 0 10 111 221 0 0 43 40 188 10 0 10 125 209 5 0 4 42 
KirillOsenkov commented 6 years ago

Hmm, I wonder what is the IL opcode 235. Any ideas @vsadov? This is when reading the IL method body above (the 288 bytes).

KirillOsenkov commented 6 years ago

This is same as https://github.com/benaadams/Ben.Demystifier/issues/32

benaadams commented 6 years ago

I've seen this; but not sure why; it suggests opcodes are missing from the OpCode class as that's where it pulls them from? https://msdn.microsoft.com/en-us/library/system.reflection.emit.opcodes%28v=vs.110%29.aspx

benaadams commented 6 years ago

Was thinking this initialization should have issues

https://github.com/benaadams/Ben.Demystifier/blob/57e2d49ad1ebc0309c6f50f7555d159a6fcf820e/src/Ben.Demystifier/Internal/ILReader.cs#L82-L102

But it skips Nternal types; maybe its one of those? Perhaps should add them to the list.

KirillOsenkov commented 6 years ago

Maybe @jkotas knows what opcode 235 means? And what Nternal opcodes are?

jkotas commented 6 years ago

235 is not valid opcode. It likely means that the IL reader has gotten out of sync and it is reading in the middle of IL instructions. You should disassemble the offending method using ildasm to figure this out.

onyxmaster commented 6 years ago

Same here, but the instruction is 253 in my case.

The IL for the method is the following:

.method private hidebysig 
    instance class System.Web.WebPages.HelperResult RenderPageCore (
        string path,
        bool isLayoutPage,
        object[] data
    ) cil managed 
{
    // Method begins at RVA 0x9074
    // Code size 79 (0x4f)
    .maxstack 3

    IL_0000: newobj instance void System.Web.WebPages.WebPageBase/'<>c__DisplayClass40_0'::.ctor()
    IL_0005: dup
    IL_0006: ldarg.0
    IL_0007: stfld class System.Web.WebPages.WebPageBase System.Web.WebPages.WebPageBase/'<>c__DisplayClass40_0'::'<>4__this'
    IL_000c: dup
    IL_000d: ldarg.1
    IL_000e: stfld string System.Web.WebPages.WebPageBase/'<>c__DisplayClass40_0'::path
    IL_0013: dup
    IL_0014: ldarg.2
    IL_0015: stfld bool System.Web.WebPages.WebPageBase/'<>c__DisplayClass40_0'::isLayoutPage
    IL_001a: dup
    IL_001b: ldarg.3
    IL_001c: stfld object[] System.Web.WebPages.WebPageBase/'<>c__DisplayClass40_0'::data
    IL_0021: dup
    IL_0022: ldfld string System.Web.WebPages.WebPageBase/'<>c__DisplayClass40_0'::path
    IL_0027: call bool [mscorlib]System.String::IsNullOrEmpty(string)
    IL_002c: brfalse.s IL_003e

    IL_002e: call string Microsoft.Internal.Web.Utils.CommonResources::get_Argument_Cannot_Be_Null_Or_Empty()
    IL_0033: ldstr "path"
    IL_0038: newobj instance void [mscorlib]System.ArgumentException::.ctor(string, string)
    IL_003d: throw

    IL_003e: ldftn instance void System.Web.WebPages.WebPageBase/'<>c__DisplayClass40_0'::'<RenderPageCore>b__0'(class [mscorlib]System.IO.TextWriter)
    IL_0044: newobj instance void class [mscorlib]System.Action`1<class [mscorlib]System.IO.TextWriter>::.ctor(object, native int)
    IL_0049: newobj instance void System.Web.WebPages.HelperResult::.ctor(class [mscorlib]System.Action`1<class [mscorlib]System.IO.TextWriter>)
    IL_004e: ret
} // end of method WebPageBase::RenderPageCore

The rawIL appears to match:

◢ | rawIL | {byte[79]}[]
  | [0] | 115
  | [1] | 31
  | [2] | 5
  | [3] | 0
  | [4] | 6
  | [5] | 37
  | [6] | 2
  | [7] | 125
  | [8] | 94
  | [9] | 1
  | [10] | 0
  | [11] | 4
  | [12] | 37
  | [13] | 3
  | [14] | 125
  | [15] | 91
  | [16] | 1
  | [17] | 0
  | [18] | 4
  | [19] | 37
  | [20] | 4
  | [21] | 125
  | [22] | 92
  | [23] | 1
  | [24] | 0
  | [25] | 4
  | [26] | 37
  | [27] | 5
  | [28] | 125
  | [29] | 93
  | [30] | 1
  | [31] | 0
  | [32] | 4
  | [33] | 37
  | [34] | 123
  | [35] | 91
  | [36] | 1
  | [37] | 0
  | [38] | 4
  | [39] | 40
  | [40] | 61
  | [41] | 0
  | [42] | 0
  | [43] | 10
  | [44] | 44
  | [45] | 16
  | [46] | 40
  | [47] | 160
  | [48] | 4
  | [49] | 0
  | [50] | 6
  | [51] | 114
  | [52] | 253
  | [53] | 15
  | [54] | 0
  | [55] | 112
  | [56] | 115
  | [57] | 90
  | [58] | 0
  | [59] | 0
  | [60] | 10
  | [61] | 122
  | [62] | 254
  | [63] | 6
  | [64] | 32
  | [65] | 5
  | [66] | 0
  | [67] | 6
  | [68] | 115
  | [69] | 137
  | [70] | 2
  | [71] | 0
  | [72] | 10
  | [73] | 115
  | [74] | 61
  | [75] | 2
  | [76] | 0
  | [77] | 6
  | [78] | 42

The ptr is (obviously) 53 in this case.

onyxmaster commented 6 years ago

Since it follows the 114 opcode as the original issue was too, I believe there is something wrong with ldstr opcode processing. Maybe inline strings are handled differently (I'm no expert on IL)?

onyxmaster commented 5 years ago

I believe this is fixed now.

benaadams commented 5 years ago

https://www.nuget.org/packages/Ben.Demystifier/0.1.4

KirillOsenkov commented 5 years ago

@onyxmaster thank you so much!