Collect .NET Applications Traces with sysinternals Tools

In this short post, I would like to show you how, with sysinternals tools, you may noninvasively trace .NET applications. This is especially useful in production environment where you can’t install your favorite debugger and hang whole IIS to diagnose an issue. We will work with three tools: dbgview, procdump and procmon. Let’s start with the first one.

DebugView (dbgview.exe)

According to its description on sysinternals site: “DebugView is an application that lets you monitor debug output on your local system, or any computer on the network that you can reach via TCP/IP.” DebugView captures text messages sent by OutputDebugString and DbgPrint Win32Api methods. Interestingly .NET’s DefaultTraceListener under the hood posts trace messages using the OutputDebugString method. So by enabling .NET trace sources, we could have a peak at how the application interacts with .NET Framework APIs. Some interesting trace source names are (based on http://msdn.microsoft.com/en-us/library/ty48b824.aspx):

• System.Net – traces from some public methods of the HttpWebRequest, HttpWebResponse, FtpWebRequest and FtpWebResponse classes, and SSL debug information (invalid certificates, missing issuers list and client certificate errors)
• System.Net.Sockets – traces from some public methods of the Socket, TcpListener, TcpClient, and Dns classes
• System.Net.HttpListener – traces from some public methods of the HttpListener, HttpListenerRequest and HttpListenerResponse
• System.Net.Cache – traces from some private and internal methods in System.Net.Cache
• System.Net.Http – traces from some public methods of the HttpClient, DelegatingHandler, HttpClientHandler, HttpMessageHandler, MessageProcessingHandler, and WebRequestHandler classes
• System.Net.WebSockets – traces from some public methods of the ClientWebSocket and WebSocket classes
• Microsoft.Owin – traces from Owin infrastructure in recent ASP.NET applications
• System.IdentityModel – Windows Identity Foundation traces
• System.Runtime.Serialization – runtime serializers logs
• System.ServiceModel – logs all stages of WCF processing, whenever configuration is read, a message is processed in transport, security processing, a message is dispatched in user code, and so on
• System.ServiceModel.MessageLogging – logs all messages that flow through the system
• System.ServiceModel.Activation – WCF activation logs

REMARK: I mentioned WCF traces above, but they have some specific switch settings which I won’t describe in this post – if you need to work with WCF traces, read this MSDN article.

We will see how to collect .NET traces by examining a sample erroneous situation I ran into in one of our applications. We implemented a Google authentication based on Microsoft.Owin.Security.Google. Unfortunately, on our test server, the application was not able to authenticate the user – only the external authentication cookie was set. I couldn’t run Fiddler on the server so I added the following lines to the application web.config file:

<system.diagnostics>
    <trace autoflush="true" />
    <sharedListeners>
    </sharedListeners>
    <sources>
        <source name="Thinktecture.IdentityModel" switchValue="Verbose">
        </source>
        <source name="System.IdentityModel" switchValue="Verbose">
        </source>
        <source name="Microsoft.Owin" switchValue="Verbose">
        </source>
        <source name="System.Net" switchValue="Verbose">
        </source>
    </sources>
</system.diagnostics>

Then I ran dbgview.exe as an administrator and select Capture Global Win32 from the Capture menu. When I tried to sign in with Google again traces started to appear. Below, you may find a snippet of the output (I used x to hide sensitive info):

00000005	0.01719604	[5280] System.Net Verbose: 0 :
00000006	0.01721783	[5280] [8136] Exiting HttpWebRequest#32103595::HttpWebRequest()
00000007	0.01734075	[5280] System.Net Verbose: 0 :
00000008	0.01738405	[5280] [8136] HttpWebRequest#32103595::HttpWebRequest
   (uri: 'https://accounts.google.com/o/oauth2/token', connectionGroupName: '9777040')
00000009	0.01745697	[5280] System.Net Verbose: 0 :
00000010	0.01747121	[5280] [8136] Exiting HttpWebRequest#32103595::HttpWebRequest()
00000011	0.03358723	[5280] System.Net Verbose: 0 :
00000012	0.03368026	[5280] [8136] HttpWebRequest#32103595::BeginGetRequestStream()
00000013	0.03388838	[5280] System.Net Verbose: 0 :
00000014	0.03393281	[5280] [8136] ServicePoint#40870089::ServicePoint(accounts.google.com:443)
00000015	0.03459155	[5280] System.Net Information: 0 :
00000016	0.03465440	[5280] [8136] Associating HttpWebRequest#32103595 with ServicePoint#40870089
00000017	0.03490024	[5280] System.Net Information: 0 :
00000018	0.03493740	[5280] [8136] Associating Connection#19415024 with HttpWebRequest#32103595
00000019	0.04254256	[5280] System.Net Verbose: 0 :
00000020	0.04256323	[5280] [8136] 
            Exiting HttpWebRequest#32103595::BeginGetRequestStream()  -> ContextAwareResult#40053370
00000021	0.06268339	[5280] System.Net Information: 0 :
00000022	0.06276719	[5280] [2988] 
             Connection#19415024 - Created connection from x.x.x.x:59905 to 173.194.70.84:443.
00000023	0.06294571	[5280] System.Net Information: 0 :
00000024	0.06302002	[5280] [2988] TlsStream#43170133::.ctor(host=accounts.google.com, #certs=0)
00000025	0.06314965	[5280] System.Net Information: 0 :
00000026	0.06323793	[5280] [2988] Associating HttpWebRequest#32103595 with ConnectStream#64411991
00000027	0.06338710	[5280] System.Net Information: 0 :
00000028	0.06345862	[5280] [2988] HttpWebRequest#32103595 - Request: POST /o/oauth2/token HTTP/1.1
00000029	0.06345862	[5280]
00000030	0.06362708	[5280] System.Net Information: 0 :
00000031	0.06370223	[5280] [2988] ConnectStream#64411991 - Sending headers
00000032	0.06370223	[5280] {
00000033	0.06370223	[5280] Content-Type: application/x-www-form-urlencoded
00000034	0.06370223	[5280] Host: accounts.google.com
00000035	0.06370223	[5280] Content-Length: 299
00000036	0.06370223	[5280] Expect: 100-continue
00000037	0.06370223	[5280] Connection: Keep-Alive
00000038	0.06370223	[5280] }.
...
0.65584564	[5280] [8136] ConnectStream#64411991::BeginWrite()
00000107	0.65595937	[5280] System.Net Verbose: 0 :
00000108	0.65602893	[5280] [8136] Data from ConnectStream#64411991::BeginWrite
00000109	0.65620744	[5280] System.Net Verbose: 0 :
00000110	0.65627921	[5280] [8136] 00000000 : 
            67 72 61 6E 74 5F 74 79-70 65 3D 61 75 74 68 6F : grant_type=autho
00000111	0.65640384	[5280] System.Net Verbose: 0 :
00000112	0.65647143	[5280] [8136] 00000010 : 
            72 69 7A 61 74 69 6F 6E-5F 63 6F 64 65 26 63 6F : rization_code&co
00000113	0.65660554	[5280] System.Net Verbose: 0 :
00000114	0.65667343	[5280] [8136] 00000020 : 
            64 65 XX XX XX XX XX XX-XX XX XX XX XX XX XX XX : de=xxxxxxxxxxxxx
00000115	0.65679383	[5280] System.Net Verbose: 0 :
00000122	0.65743381	[5280] [8136] 00000060 : 
            XX XX XX 26 72 65 64 69-72 65 63 74 5F 75 72 69 : xxx&redirect_uri
00000123	0.65756148	[5280] System.Net Verbose: 0 :
...
00000220	0.75980693	[5280] Microsoft.Owin.Security.Google.GoogleOAuth2AuthenticationMiddleware Error: 0 :
00000221	0.75987005	[5280] Authentication failed
00000222	0.75987005	[5280] System.Net.Http.HttpRequestException: 
                 Response status code does not indicate success: 400 (Bad Request).
...

As you can see, in verbose mode, whole HTTP requests are logged – with the trace from dbgview, it was easy to conclude that our application was sending an invalid redirect uri to Google when generating authentication token.

ProcDump and Process Monitor (procmon.exe)

Another great tool to diagnose applications on production is procdump. Its main purpose is to create dumps in different buggy situations, but today, I will focus only on its logging capabilities. You may not know but procdump has a special mode in which no dumps are collected but profiling messages are sent to procmon. You enable this mode with following switches: -f “” -e 1. I usually also add -l switch which makes procdump collect debug log output of our application (i.e., traces I described in the previous paragraph). Procdump is a bit more invasive than dbgview as it attaches itself (as a debugger) to the examined process, but it shouldn’t have a big impact on your application performance.

Let’s have a look at an example. Attach procdump to some buggy application:

PS windows> procdump -e 1 -f "" -l ExceptionTest.exe

Then, run procmon and make sure that you included events from: your application, procdump.exe and procdump64.exe (for x64 machines):

Procmon is itself an excellent diagnosing tool and exception logs from procdump make it even more usable. With these logs, you should be able to correlate exceptions in your application with system events (such as I/O, registry or network operations). I need to mention that procdump logs appear in procmon as Profiling Events so remember to enable them:

I hope hints presented in this post will help you in your own diagnosing battles. :) And if you know any .NET trace sources that I’ve forgotten in my list, please write them in the comments and I will add them.