search

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

Some stacks cannot be captured because GetMethodDisplayString doesn't handle generic types #75

Closed ayende closed 3 years ago

ayende commented 6 years ago 
  HResult=0x80131509
  Message=Late bound operations cannot be performed on fields with types for which Type.ContainsGenericParameters is true.
  Source=System.Private.CoreLib
  StackTrace:
   at System.Reflection.RtFieldInfo.InternalGetValue(Object obj, StackCrawlMark& stackMark)
   at System.Reflection.RtFieldInfo.GetValue(Object obj)
   at System.Diagnostics.EnhancedStackTrace.GetMethodDisplayString(MethodBase originMethod) in C:\GitHub\Ben.Demystifier\src\Ben.Demystifier\EnhancedStackTrace.Frames.cs:line 142
   at System.Diagnostics.EnhancedStackTrace.GetFrames(StackTrace stackTrace) in C:\GitHub\Ben.Demystifier\src\Ben.Demystifier\EnhancedStackTrace.Frames.cs:line 70
   at System.Diagnostics.EnhancedStackTrace..ctor(StackTrace stackTrace) in C:\GitHub\Ben.Demystifier\src\Ben.Demystifier\EnhancedStackTrace.cs:line 47
   at System.Diagnostics.EnhancedStackTrace.Current() in C:\GitHub\Ben.Demystifier\src\Ben.Demystifier\EnhancedStackTrace.cs:line 14
   at Sparrow.NativeAllocator`1.Initialize(NativeAllocator`1& allocator) in F:\ravendb-4.0\src\Sparrow\Allocators.Native.cs:line 106

The real stack trace is:

   at System.Environment.get_StackTrace()
   at System.Reflection.RtFieldInfo.InternalGetValue(Object obj, StackCrawlMark& stackMark)
   at System.Reflection.RtFieldInfo.GetValue(Object obj)
   at System.Diagnostics.EnhancedStackTrace.GetMethodDisplayString(MethodBase originMethod) in C:\GitHub\Ben.Demystifier\src\Ben.Demystifier\EnhancedStackTrace.Frames.cs:line 142
   at System.Diagnostics.EnhancedStackTrace.GetFrames(StackTrace stackTrace) in C:\GitHub\Ben.Demystifier\src\Ben.Demystifier\EnhancedStackTrace.Frames.cs:line 70
   at System.Diagnostics.EnhancedStackTrace..ctor(StackTrace stackTrace) in C:\GitHub\Ben.Demystifier\src\Ben.Demystifier\EnhancedStackTrace.cs:line 47
   at System.Diagnostics.EnhancedStackTrace.Current() in C:\GitHub\Ben.Demystifier\src\Ben.Demystifier\EnhancedStackTrace.cs:line 14
   at Sparrow.NativeAllocator`1.Initialize(NativeAllocator`1& allocator) in F:\ravendb-4.0\src\Sparrow\Allocators.Native.cs:line 106
   at Sparrow.ArenaAllocator`1.Initialize(ArenaAllocator`1& allocator) in F:\ravendb-4.0\src\Sparrow\Allocators.Arena.cs:line 126
   at Sparrow.Allocator`1.Initialize[TAllocatorOptions](TAllocatorOptions options) in F:\ravendb-4.0\src\Sparrow\Allocators.cs:line 129
   at Sparrow.Json.JsonOperationContext.Renew() in F:\ravendb-4.0\src\Sparrow\Json\JsonOperationContext.cs:line 970
   at Sparrow.Json.JsonContextPoolBase`1.TryReuseExistingContextFrom(ContextStack stack, T& context, IDisposable& disposable) in F:\ravendb-4.0\src\Sparrow\Json\JsonContextPoolBase.cs:line 173
   at Sparrow.Json.JsonContextPoolBase`1.AllocateOperationContext(T& context) in F:\ravendb-4.0\src\Sparrow\Json\JsonContextPoolBase.cs:line 138
   at Sparrow.Json.JsonOperationContext.ManagedPinnedBuffer.Clone[T](JsonContextPoolBase`1 pool) in F:\ravendb-4.0\src\Sparrow\Json\JsonOperationContext.cs:line 215
   at Raven.Server.Documents.Replication.IncomingReplicationHandler..ctor(TcpConnectionOptions options, ReplicationLatestEtagRequest replicatedLastEtag, ReplicationLoader parent, ManagedPinnedBuffer bufferToCopy) in F:\ravendb-4.0\src\Raven.Server\Documents\Replication\IncomingReplicationHandler.cs:line 75
   at Raven.Server.Documents.Replication.ReplicationLoader.AcceptIncomingConnection(TcpConnectionOptions tcpConnectionOptions, ManagedPinnedBuffer buffer) in F:\ravendb-4.0\src\Raven.Server\Documents\Replication\ReplicationLoader.cs:line 248
   at Raven.Server.RavenServer.DispatchDatabaseTcpConnection(TcpConnectionOptions tcp, TcpConnectionHeaderMessage header, ManagedPinnedBuffer bufferToCopy) in F:\ravendb-4.0\src\Raven.Server\RavenServer.cs:line 1469
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at Raven.Server.RavenServer.DispatchDatabaseTcpConnection(TcpConnectionOptions tcp, TcpConnectionHeaderMessage header, ManagedPinnedBuffer bufferToCopy)
   at Raven.Server.RavenServer.<>c__DisplayClass46_0.<<ListenToNewTcpConnection>b__0>d.MoveNext() in F:\ravendb-4.0\src\Raven.Server\RavenServer.cs:line 1289
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext()
   at System.Runtime.CompilerServices.TaskAwaiter.<>c.<OutputWaitEtwEvents>b__12_0(Action innerContinuation, Task innerTask)
   at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(Action action, Boolean allowInlining)
   at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
   at System.Threading.Tasks.Task`1.TrySetResult(TResult result)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(TResult result)
   at Sparrow.Json.JsonOperationContext.ParseToMemoryAsync(Stream stream, String documentId, UsageMode mode, ManagedPinnedBuffer bytes, Nullable`1 token, Int32 maxSize) in F:\ravendb-4.0\src\Sparrow\Json\JsonOperationContext.cs:line 942
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext()
   at System.Runtime.CompilerServices.TaskAwaiter.<>c.<OutputWaitEtwEvents>b__12_0(Action innerContinuation, Task innerTask)
   at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(Action action, Boolean allowInlining)
   at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
   at System.Threading.Tasks.Task`1.TrySetResult(TResult result)
   at System.Threading.Tasks.ValueTask`1.ValueTaskSourceAsTask.<>c.<.cctor>b__4_0(Object state)
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.InvokeContinuation(Action`1 continuation, Object state, Boolean forceAsync)
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.OnCompleted(SocketAsyncEventArgs _)
   at System.Net.Sockets.SocketAsyncEventArgs.FinishOperationAsyncSuccess(Int32 bytesTransferred, SocketFlags flags)
   at System.Net.Sockets.SocketAsyncEventArgs.<>c.<.cctor>b__177_0(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* nativeOverlapped)
   at System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* pOVERLAP)
benaadams commented 6 years ago

This is when capturing .Current() stack rather than an Exception stack?

ayende commented 6 years ago

Yes, this is what is failing for me:

            allocator._initializeStackTrace = EnhancedStackTrace.Current();
mattzink commented 6 years ago

We are also hitting this:

16:56:42     V1000.StorageSystems.RefreshNimble.GivenStorageSystemWithNameChangedOutOfBandWhenRefreshingThenNameIsUpdated [FAIL]
16:57:08       System.InvalidOperationException : Late bound operations cannot be performed on fields with types for which Type.ContainsGenericParameters is true.
16:57:08       Stack Trace:
16:57:08            at System.Reflection.RtFieldInfo.InternalGetValue(Object obj, StackCrawlMark& stackMark)
16:57:08            at System.Reflection.RtFieldInfo.GetValue(Object obj)
16:57:08         C:\GitHub\Ben.Demystifier\src\Ben.Demystifier\EnhancedStackTrace.Frames.cs(142,0): at System.Diagnostics.EnhancedStackTrace.GetMethodDisplayString(MethodBase originMethod)
16:57:08         C:\GitHub\Ben.Demystifier\src\Ben.Demystifier\EnhancedStackTrace.Frames.cs(70,0): at System.Diagnostics.EnhancedStackTrace.GetFrames(StackTrace stackTrace)
16:57:08         C:\GitHub\Ben.Demystifier\src\Ben.Demystifier\EnhancedStackTrace.cs(47,0): at System.Diagnostics.EnhancedStackTrace..ctor(StackTrace stackTrace)
TylerAP commented 5 years ago

Ditto. https://github.com/benaadams/Ben.Demystifier/blob/c3519f14c56e8099a8f359e2355e1da0f944cd9d/src/Ben.Demystifier/EnhancedStackTrace.Frames.cs#L142

field's declaring type is generic, IsConstructedGenericType is false. This means it will throw ...

System.InvalidOperationException: Late bound operations cannot be performed on fields with types for which Type.ContainsGenericParameters is true.
   at System.Reflection.RtFieldInfo.InternalGetValue(Object obj, StackCrawlMark& stackMark)
   at System.Reflection.RtFieldInfo.GetValue(Object obj)

Going to fork this and provide a work-around by skipping the field value evaluation if !IsConstructedGenericType and just checking the field name, but I think the type diagnosis for the generic type's parameters (to turn the GTD into a CGT) will be either impossible or require looking at previous stack frames or heaven forbid the this variable in the frame.

TylerAP commented 5 years ago

https://github.com/benaadams/Ben.Demystifier/pull/77

TylerAP commented 5 years ago

Since #77 is merged, this might be resolved. @ayende can you test with latest?

benaadams commented 5 years ago

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

benaadams commented 3 years ago

Going to close this ass assumed fixed