Software Diagnostics Library

A typical trace is a detailed narrative. It is accompanied by a problem description that lists essential facts. Therefore the first task of any trace analysis is to check the presence of Basic Facts in the trace. If they are not visible or do not correspond then the trace was possibly not recorded during the problem or was taken from a different computer or under different conditions. Here is an example. A user “test01″ cannot connect to an application. We look at the trace and find this statement:

No   PID  TID  Date      Time         Statement
[...]
3903 3648 5436 4/29/2009 16:17:36.150 User Name: test01
[...]

At least we can be sure that this trace was taken for the user test01 especially when we expect this or similar trace statements. If we could not see this trace statement we can suppose that the trace was taken at the wrong time, for example, after the problem happened already.

- Dmitry Vostokov @ TraceAnalysis.org -

After coming back to engineering I decided to expand the domain of my research and start the new series of posts called Trace Analysis Patterns. In addition to Citrix CDF / Microsoft ETW traces I plan to cover other variants based on my extensive software engineering background in the past where I used tracing in software products ranging from soft multi-platform real-time systems to static code analysis tools. Connection with memory dump analysis will be covered too because sometimes the combination of static and dynamic data leads to interesting observations and helps to troubleshoot and resolve customer problems especially when not all data can be collected dynamically.

In fact, stack traces and their collections are specializations of the more general traces. Another example is historical information in memory dump files especially when it is somehow timestamped.  

In this part I start with the obvious and to some extent the trivial pattern called Periodic Error. This is an error or a status value that is observed periodically many times:

No     PID  TID   Date      Time         Statement
[...]
664957 1788 22504 4/23/2009 17:59:14.600 MyClass::Initialize: Cannot open connection “Client ID: 310″, status=5  
[…]
668834 1788 19868 4/23/2009 19:11:52.979 MyClass::Initialize: Cannot open connection “Client ID: 612″, status=5 
[…]

or 

No     PID  TID   Date      Time         Statement
[...] 
202314 1788 19128 4/21/2009 16:03:46.861 HandleDataLevel: Error 12005 Getting Mask
[…]
347653 1788 17812 4/22/2009 13:26:00.735 HandleDataLevel: Error 12005 Getting Mask
[…]

Here single trace entries can be isolated from the trace and studied in detail. 

Be aware though that some modules might report periodic errors that are false positive, in the sense, that they are expected as a part of implementation details, for example, when a function returns an error to indicate that bigger buffer is required or to estimate its size for a subsequent call. It merits its own pattern name and I come to it next time with more examples.

I also created a page where I’ll will be adding all tracing patterns:

Trace Analysis Patterns   

- Dmitry Vostokov @ TraceAnalysis.org -

Citrix CDF traces are based on ETW (Event Tracing for Windows) and therefore Citrix customers, their support personnel and developers can use MS TraceView tool for troubleshooting Citrix terminal service environments:

Viewing Common Diagnostics Facility (CDF) Traces Using TraceView

In cases with slow logon or slow process startup we can analyze process launch sequence to determine delays. In the output trace we can filter tzhook module messages which also contain session id (this is quite handy to differentiate between different sessions), for example: 

PID      TID      TIME          MESSAGE     
21864    21912    06:34:53.598  tzhook: Attach on process - cmd.exe session=51         
21620    20372    06:34:59.754  tzhook: Attach on process - acregl.exe session=51         
18668    21240    06:35:02.704  tzhook: Attach on process - cmstart.exe session=51         
18560    18832    06:35:02.735  tzhook: Attach on process - wfshell.exe session=51         
18204    20060    06:35:06.575  tzhook: Attach on process - icast.exe session=51         
20640    21104    06:35:07.717  tzhook: Attach on process - LOGON.EXE session=51         
21188    21032    06:35:07.938  tzhook: Attach on process - cscript.exe session=51         
21888    19592    06:35:11.157  tzhook: Attach on process - WScript.exe session=51         
20600    20732    06:35:11.780  tzhook: Attach on process - admin.exe session=51         
17976    20456    06:35:18.752  tzhook: Attach on process - winlogon.exe session=53         
21332    13156    06:35:51.625  tzhook: Attach on process - mpnotify.exe session=53         
10988    10732    06:35:57.043  tzhook: Attach on process - rundll32.exe session=53

Here is another process launch sequence for published Notepad application:

PID     TID     TIME            MESSAGE
15828   18720   15:34:02.637    tzhook: Attach on process - winlogon.exe session=2 
5300    18508   15:34:03.043    tzhook: Attach on process - mpnotify.exe session=2 
17948   19300   15:34:03.356    tzhook: Attach on process - userinit.exe session=2 
17956   19316   15:34:03.415    tzhook: Attach on process - cmd.exe session=2 
5384    5324    15:34:03.443    tzhook: Attach on process - cmd.exe session=2 
19432   19264   15:34:03.461    tzhook: Attach on process - SSONSVR.EXE session=2 
12480   7472    15:34:03.466    tzhook: Attach on process - cmd.exe session=2 
19448   19364   15:34:03.474    tzhook: Attach on process - net.exe session=2 
19416   19656   15:34:03.489    tzhook: Attach on process - acregl.exe session=2 
19480   19596   15:34:03.544    tzhook: Attach on process - cmstart.exe session=2 
664     19512   15:34:03.559    tzhook: Attach on process - wfshell.exe session=2 
19904   13140   15:34:03.610    tzhook: Attach on process - net.exe session=2 
6864    20036   15:34:03.746    tzhook: Attach on process - icast.exe session=2 
19540   20016   15:34:03.749    tzhook: Attach on process - ctfmon.exe session=2 
19944   19032   15:34:03.757    tzhook: Attach on process - net.exe session=2 
10232   18356   15:34:03.787    tzhook: Attach on process - notepad.exe session=2

Such sequences are also useful to determine a process upon which the session initialization or startup sequence hangs. In this case a user dump of that process might be useful.

Of course we can do all this with Process Monitor and other similar tools but here we get other Citrix related trace messages as well. All in one.

- Dmitry Vostokov @ DumpAnalysis.org -