Get .NET call stack when files are written with WinDbg

I was interested in learning how Neuron ESB performed logging internally.

(To see if it would be relevant to use the same classes and methods for logging in custom C# process steps and possibly other situations)

 

At first I used Process Monitor.

I found a WriteFile event, where a log file was updated.

Neuron_ESB_WriteFile_Process_Monitor_Event

I checked the stack under event properties.

Neuron_ESB_WriteFile_Process_Monitor_Event_Properties_Stack

The native stack trace didn’t tell me which .NET classes or methods that were in use, but it did give me an idea:

Perhaps I could use WinDbg to get the .NET call stack for each call to WriteFile in kernel32.dll

 

Indeed this was possible by:

1. Starting WinDbg (x64) as Administrator.

2. Attaching to the ESBService.exe process.

3. Loading the SOS extension with:

.loadby sos clr

4. Setting a breakpoint with a command to show the .NET call stack and continue execution with:

bp kernel32!WriteFile "!clrstack; g"

5. Continuing execution with:

g

 

This showed the .NET call stack every time files were written.

Most WriteFile calls were for logging (as expected).

An example:

OS Thread Id: 0x2354 (35)
Child SP               IP Call Site
000000001836e028 00000000775a1fa0 [InlinedCallFrame: 000000001836e028] Microsoft.Win32.Win32Native.WriteFile(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte*, Int32, Int32 ByRef, IntPtr)
000000001836e028 000007feea284cf4 [InlinedCallFrame: 000000001836e028] Microsoft.Win32.Win32Native.WriteFile(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte*, Int32, Int32 ByRef, IntPtr)
000000001836dff0 000007feea284cf4 DomainNeutralILStubClass.IL_STUB_PInvoke(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte*, Int32, Int32 ByRef, IntPtr)
000000001836e0d0 000007feea265984 System.IO.FileStream.WriteFileNative(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte[], Int32, Int32, System.Threading.NativeOverlapped*, Int32 ByRef)
000000001836e130 000007feea2658d2 System.IO.FileStream.WriteCore(Byte[], Int32, Int32)
000000001836e1a0 000007feea265847 System.IO.FileStream.FlushInternalBuffer()
000000001836e1e0 000007feea2657d4 System.IO.FileStream.Flush(Boolean)
000000001836e220 000007feea27128c System.IO.StreamWriter.Flush(Boolean, Boolean)
000000001836e280 000007fec064f2f7 Microsoft.VisualBasic.Logging.FileLogTraceListener+ReferencedStream.Flush()
000000001836e2d0 000007fec064e065 Microsoft.VisualBasic.Logging.FileLogTraceListener.Flush()
000000001836e300 000007fee92e0859 System.Diagnostics.TraceInternal.WriteLine(System.String)
000000001836e370 000007fe8bcc780d Neuron.Esb.ESBMasterService.Trace(System.Diagnostics.TraceListener, System.String)
000000001836e3c0 000007fe8bcc7bec Neuron.Esb.ESBMasterService.TraceInfo(System.Diagnostics.TraceSwitch, System.String, System.Diagnostics.TraceListener)
000000001836e420 000007fe8bfa72a9 Neuron.Esb.ESBMasterService.TraceInfo(System.Diagnostics.TraceSwitch, System.String)
000000001836e460 000007fe8c1c831e Neuron.Esb.EsbService.AmqpService.Trace(System.String, System.Object[])
000000001836e4a0 000007fe8cbbbc2e Neuron.Esb.EsbService.AmqpService.UpdateServiceStatus(Neuron.Esb.EsbService.ServiceState, Newtonsoft.Json.Linq.JToken)
000000001836e530 000007fe8c8baa0b Neuron.Esb.EsbService.AmqpService.UpdateExchangeStatus(System.Object, System.Timers.ElapsedEventArgs)
000000001836e5d0 000007fee9802586 System.Timers.Timer.MyTimerCallback(System.Object)
000000001836e650 000007feea1c2490 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000001836e720 000007feea1c2327 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000001836e750 000007feea1f0b9b System.Threading.TimerQueueTimer.CallCallback()
000000001836e7b0 000007feea1f0998 System.Threading.TimerQueueTimer.Fire()
000000001836e800 000007feea281a9f System.Threading.TimerQueue.FireNextTimers()
000000001836ed08 000007feeb303753 [DebuggerU2MCatchHandlerFrame: 000000001836ed08]
000000001836ee98 000007feeb303753 [ContextTransitionFrame: 000000001836ee98]
000000001836f0b8 000007feeb303753 [DebuggerU2MCatchHandlerFrame: 000000001836f0b8]

 

Having years of experience with log4net, I decided to use and recommend that.

Neuron ESB service may hang due to RabbitMQ service

I recently experienced a situation where the Neuron ESB service would hang when restarting.

ESBService.exe was stuck at Stopping and didn’t finish within 5 minutes, so it seemed to be permanently stuck.

Troubleshooting

Resource Monitor’s “Analyze Wait Chain” feature showed that 3 threads were waiting to finish network I/O.

ESBService_Analyze_Wait_Chain_waiting_to_finish_network_IO

 

I took 5 memory dumps using procdump:

procdump -ma EsbService.exe

 

WinDbg showed similar call stacks for the waiting threads:

0:060> !clrstack
OS Thread Id: 0x4e58 (60)
Child SP IP Call Site
000000001cd6dd88 000000007757d3fa [InlinedCallFrame: 000000001cd6dd88] System.Net.UnsafeNclNativeMethods+OSSOCK.recv(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
000000001cd6dd88 000007fee9217e61 [InlinedCallFrame: 000000001cd6dd88] System.Net.UnsafeNclNativeMethods+OSSOCK.recv(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
000000001cd6dd60 000007fee9217e61 DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
000000001cd6de10 000007fee919c501 System.Net.Sockets.Socket.Receive(Byte[], Int32, Int32, System.Net.Sockets.SocketFlags, System.Net.Sockets.SocketError ByRef)
000000001cd6de90 000007fee919c3b8 System.Net.Sockets.Socket.Receive(Byte[], Int32, Int32, System.Net.Sockets.SocketFlags)
000000001cd6def0 000007fee919c132 System.Net.Sockets.NetworkStream.Read(Byte[], Int32, Int32)
000000001cd6df50 000007feea1479bf System.IO.BufferedStream.ReadByte()
000000001cd6df90 000007feea13444f System.IO.BinaryReader.ReadByte()
000000001cd6dfc0 000007fe8c0ad406 RabbitMQ.Client.Impl.Frame.ReadFrom(RabbitMQ.Util.NetworkBinaryReader)
000000001cd6e020 000007fe8c0ad374 RabbitMQ.Client.Impl.SocketFrameHandler_0_9.ReadFrame()
000000001cd6e070 000007fe8c0ad27c RabbitMQ.Client.Impl.ConnectionBase.MainLoopIteration()
000000001cd6e0b0 000007fe8c0acfe2 RabbitMQ.Client.Impl.ConnectionBase.MainLoop()
000000001cd6e110 000007feea0c2490 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000001cd6e1e0 000007feea0c2327 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000001cd6e210 000007feea0c22e2 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
000000001cd6e260 000007feea162362 System.Threading.ThreadHelper.ThreadStart()
000000001cd6e548 000007feeb203753 [GCFrame: 000000001cd6e548]
000000001cd6e898 000007feeb203753 [DebuggerU2MCatchHandlerFrame: 000000001cd6e898]
000000001cd6ea28 000007feeb203753 [ContextTransitionFrame: 000000001cd6ea28]
000000001cd6ec48 000007feeb203753 [DebuggerU2MCatchHandlerFrame: 000000001cd6ec48]

 

The call stacks indicated that the problem was related to RabbitMQ.

 

I decided to forcefully stop the ESBService.exe process.

 

When starting ESBService.exe it was still trying to communicate with RabbitMQ and hanging.

I noticed this error in the Neuron ESB Event Log:

Event Info: An error occurred trying to update the status for RabbitMQ exchange "DEFAULT.Enterprise.FileContent": This request operation sent to net.tcp://localhost:50004/MasterControl/ did not receive a reply within the configured timeout (00:01:00). The time allotted to this operation may have been a portion of a longer timeout. This may be because the service is still processing the operation or because the service was unable to send a reply message. Please consider increasing the operation timeout (by casting the channel/proxy to IContextChannel and setting the OperationTimeout property) and ensure that the service is able to connect to the client.. Attempted to Query 'localhost' on port '15672'.

 

I decided to restart the RabbitMQ service, which solved the problem.

After this the Neuron ESBService.exe was able to start and work normally.

 

If the problem occurs again, I will take and examine memory dumps of the RabbitMQ service, in an attempt to learn the cause of the problem.

This occured with Neuron ESB version 3.5.3.411 and RabbitMQ version 3.2.2 (bundled with Neuron ESB).

 

I notice that the latest RabbitMQ version is currently 3.6.1:

https://www.rabbitmq.com/changelog.html

It seems relevant to update RabbitMQ, but compatibility with the current Neuron ESB version is currently unknown.

Avoid storing multiple versions of custom adapters in Neuron ESB search path

While testing a custom adapter for Neuron ESB I encountered this error:

Neuron_could_not_load_type

System.TypeLoadException: Could not load type 'Neuron.Esb.Adapters.AdapterEncodingTypeConverter' from assembly 'Neuron.Esb.Adapters.FlatFileAdapter, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null'.

This seemed pretty odd because namespace and name were correct, at least in the DLL stored under:

C:\Program Files\Neudesic\Neuron ESB v3\DEFAULT\Adapters\

Troubleshooting

Using Process Monitor I discovered that I had mistakenly copied an earlier version of Neuron.Esb.Adapters.FlatFileAdapter.dll to:

C:\Program Files\Neudesic\Neuron ESB v3\DEFAULT\

NeuronExplorer_accessing_wrong_adapter_version

(This version actually didn’t have the type/class needed, but Neuron Explorer seemed to prefer using it…)

The problem was resolved by:

1. Shutting down NeuronExplorer.exe and ESBService.exe (because they lock assemblies in use while running)

2. Removing the old and unwanted DLL.

3. Starting ESBService.exe and NeuronExplorer.exe

Conclusion

Avoid storing multiple versions of custom adapters in Neuron ESB’s search path to avoid potential problems like this.