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.

Windows Update stuck at Preparing to install

Windows Update problems on new Windows Server 2012 (R2) machines are fairly common.

 

Common advice is to clear: C:\Windows\SoftwareDistribution

This usually works, but unfortunately it also resets parts of the Windows Update history.

In some cases it’s not necessary to clear the SoftwareDistribution folder.

 

If Windows Update is stuck at Preparing to install for a long time (hours), the problem may be resolved simply by restarting the Windows Update service.

From an elevated command prompt run:

net stop wuauserv

Usually the Windows Update service will be started automatically.

In case it isn’t, start it with:

net start wuauserv

 

This simple procedure solved the Windows Update problem I experienced today. Afterwards it was no longer stuck, but installed updates normally.

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.

Update Fit-PC3 to latest BIOS before installing 4xLAN FACE module

I recently decided to repurpose a Fit-PC3 as a pfSense firewall.

To do this I needed more ethernet ports, so I bought a 4xLAN FACE module.

After installing the 4xLAN FACE module, the Fit-PC3 would not boot or display anything.

USB ports had power, but other than that it did nothing.

Troubleshooting

Checked the 4xLAN FACE module for damage or other obvious problems, but found none.

Tried reseating the 4xLAN FACE module, which had no effect.

Removed the FACE module and noticed that the machine started normally.

Mounted the original 4xUSB FACE module and the machine also started normally.

Reseated the 4xLAN FACE module multiple times, but the Fit-PC3 still didn’t work.

Removed the FACE module again.

Examined the BIOS version, which was 2.1.0.333_7

Checked the latest BIOS version and noticed a long list of changes.

Upgraded to BIOS version 2.1.0.333_14

Mounted the 4xLAN FACE module and the Fit-PC3 could now boot and display normally!

Conclusion

It’s unknown to me which BIOS version fixed the problem, but one of them did.

The latest BIOS versions add a lot of options, so that alone makes it relevant to update.

The bottom line is: Update a Fit-PC3 to the latest BIOS version before installing a FACE module to avoid potential problems.