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 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-filters

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:

procmon

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 comments and I will add them.

2 thoughts on “Collect .NET applications traces with sysinternals tools

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s