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.