Monitoring log files in real time

Debugging Windows services, especially in a test or production environment, can be tricky. In many cases you won't have access to the box. You certainly won't have the ability to step through the code.

Thus, you are usually forced to monitor log files, looking for an indication of where the problem occurred. The typical method is to start by opening the file in Notepad. Then, when you want to see more recent log entries, you close and reopen the file. This is mildly annoying when dealing with a single service. If your business workflow is split among multiple services, this becomes incredibly inefficient.

An easier solution is to use a log monitor app such as BareTail. For this little demo I am using the free version of the tool.

I have three separate services logging to files named "process1.log", "process2.log" and "process3.log." To keep it simple I am only logging the RequestID for each received request. Here I have loaded all three logs into BareTail.


When I send a new request to the system it should update each log file. BareTail monitors the logs and displays any updates. In the screenshot below, note the new Request ID #2918891. Note also that the document tabs for each file show a green arrow - this indicates an update was made.


As you view each tab, the green arrow will be cleared to visually show which files you have already reviewed.


Say you were trying to debug a request that fails to make it through the system. A quick glance at the document tabs will show you how far a request made it through the system. After reviewing each log (to clear the green markers) we submit another request. In the following screenshot, note that we have a green arrow for process1.log and process2.log, but none for process3.log. So either the second process failed to send the message on, or the third process failed to receive it.

Mmc load failure

After running our legacy installer we ran into yet another problem - the Computer Management administrative app quit working. Attempting to start it gave an error stating:

MMC cannot open the file C:\WINDOWS\system32\compmgmt.msc.

This may be because the file does not exist, is not an MMC console, or was created by a later version of MMC. This may also be because you do not have sufficient access rights to the file.

To debug this particular issue, we turn to Process Monitor. When we start up the app, the first item shown is a filter dialog. For this session, we need to add mmc.exe to the list of processes to monitor.


Though it's useful to see all activity for a given process, we are generally focused on errors. To make this easier, we want to highlight any log entries that do not have a Result of 'SUCCESS'


Once we have Process Monitor configured and running, we can start the Computer Management tool. The logs will quickly fill up with registry and filesystem events, many of which will be highlighted


In the above screenshot, notice the registry ReadOpenKey failures for various items under "HKCR\CLSID\{2933BF90-7B36-11d2-B20E-00C04F983E60}". I don't know off hand what those sub-items specify, but without them I do know you will be unable to load the associated COM object. To determine what dll was at fault, we went to another computer and looked for that section in the registry.


Note above the default value of "C:\WINDOWS\system32\msxml3.dll." For whatever reason, our installer was unregistering this system dll - definitely not a good thing. Fixing the problem on the broken box was as simple as running regsvr32 on msxml3.dll.

Runtime profiling a COM registration failure

As a continuation of my last post, we had another registration error with the same legacy installer. This time the problem was with mssoap30.dll. Loading the dll in Dependency Walker revealed a single error with dwmapi.dll.


With a bit of web searching we found that dwmapi.dll is only present on Vista and later machines. Since we weren't using that dll directly it shouldn't be the cause of our issue on Windows XP.

At this point it would appear we have all necessary dlls and that our problem must be elsewhere. The documentation on Dependency Walker, however, provides some useful information:

When a module is first opened by Dependency Walker, it is immediately scanned for all implicit, delay-load, and forwarded dependencies. Once all the modules have been scanned, the results are displayed. In addition to these known dependencies, modules are free to load other modules at run-time without any prior warning to the operating system. These types of dependencies are known as dynamic or explicit dependencies. There is really no way to detect dynamic dependencies without actually running the application and watching it to see what modules it loads at run-time.

Version 2.0 and later of Dependency Walker provides a Profile option from the menu. If you have a dll loaded, however, the item is disabled - you have to load an executable first.


For this to work, you need to load regsvr32.exe, which will enable the menu items. Once done, select Profile > Start Profiling to bring up the Profile Module dialog. The only necessary change is to add the dll being registered to the "Program arguments" setting.


Press OK and wait for the application to run. Eventually you will see the usual registration error message box, which you can simply click to continue. Once finished, scrolling through the results shows a couple errors for mssoapr3.dll.


The first error states that the file path specified can't be found. Double-clicking the error shows that it is looking for the dll under "c:\temp\1033". The second states that it cannot find the file - this time in the same folder as the dll we tried to register. So it seems either location is valid for this particular dependency.

Once we add mssoapr3.dll to the same folder, mssoap30.dll registers without issue.

COM dll registration failure

Every shop has at least one legacy piece of software they have to support. Written in VB6. With lots of copy/paste code and sections that may or may not still be active. By a developer long since gone from the company. It's bad enough to have to deal with the code itself, but try and rebuild the equally-convoluted installer and you might just go mad.

Our problem wasn't in rebuilding the installer, per-se, but in getting it to run successfully afterward. One issue we ran into were COM dlls that failed to self register.


When we attempted to run regsvr32 on this particular dll, we were given an error dialog stating:

LoadLibrary("C:\WINDOWS\system32\pcmcom.dll") failed - The specified module could not be found.

This particular issue is often due to a missing dependency. To verify this we opened up Dependency Walker and loaded pcmcom.dll. In the screenshot below, you can see the yellow question mark symbol next to pcm.dll - our missing dependency. Once we found pcm.dll and its dependencies, pcmcom.dll registered without issue.

Debugging InstallUtil.exe

The project I'm currently working on contains a Windows service with a number of performance counters. To run the code on a dev machine, we prefer to do so without first running an msi. So to get the performance counters installed, we tried to run installutil on the service executable. Which of course returned a vague error message and rolled back the changes. Fortunately, this type of problem wasn't too difficult to debug.

To demonstrate, I've created a new application and added a class that inherits from Installer. I've overridden the OnBeforeInstall event as follows:

protected override void OnBeforeInstall(IDictionary savedState)

{

    base.OnBeforeInstall(savedState);

    string nullString = null;

    int invalidLength = nullString.Length;

}

If I attempt to run "InstallUtil MyApp.exe" I receive the following within the console output:

An exception occurred in the OnBeforeInstall event handler of MyApp.MyAppInstaller.
System.NullReferenceException: Object reference not set to an instance of an object.

For trivial code such as my above sample, tracking down the problem should take most developers all of five minutes. Once you have a non-trivial amount of code (which was the case at work) you need a little more information. If I call "InstallUtil /ShowCallStack MyApp.exe" I receive the exact line where the problem occurs:

An exception occurred during the Install phase.
System.InvalidOperationException: An exception occurred in the OnBeforeInstall e
vent handler of MyApp.MyAppInstaller.
at System.Configuration.Install.Installer.Install(IDictionary stateSaver)
at System.Configuration.Install.Installer.Install(IDictionary stateSaver)
at System.Configuration.Install.AssemblyInstaller.Install(IDictionary savedState)
at System.Configuration.Install.Installer.Install(IDictionary stateSaver)
at System.Configuration.Install.TransactedInstaller.Install(IDictionary savedState)
The inner exception System.NullReferenceException was thrown with the following
error message: Object reference not set to an instance of an object..
at InstalUtilDebugging.MyAppInstaller.OnBeforeInstall(IDictionary savedState)
in C:\source\temp\InstalUtilDebugging\MyAppInstaller.cs:line 23
at System.Configuration.Install.Installer.Install(IDictionary stateSaver)

In many cases, this will be enough to solve the problem. There may be cases, however, where you need to attach a debugger to the process and step through the code to see where a problem actually started. To do this I add the following line to the beginning of OnBeforeInstall:

System.Diagnostics.Debugger.Launch();

After I recompile and again run InstallUtil, I am given a JIT Debugger dialog which allow me to attach to the process.


I select the instance of VisualStudio that has my install code and click 'Yes' to begin debugging. You may be given a warning stating "There is no source code available for the current location." Click 'OK' and press F10 once - this will show the Debugger.Launch statement as the current line of code being executed. From here debugging works as in any application.

Debugging XSL Transformations in VisualStudio 2005

I've been doing a bit of work lately with XSL transforms. While searching for a good transform debugging tool, I found that I had a decent one already installed - VisualStudio. To demonstrate, I pulled sample xml and xslt from the W3Schools site. (Click on each image to see a larger version.)


With the xsl template loaded in VS, right-click anywhere on the xslt and choose Properties. In the Properties window, set the Input value to point to the sample xml file (cdcatalog.xml in this case.)


At this point you can run the transform to view the output. Choose "XML" > "Debug XSLT" from the menu.


Nothing terribly interesting so far. The real fun doesn't start until you realize you can set breakpoints within the xslt. This is done the same as with other types of code files (by clicking the grey strip on the left or pressing F9.) Now, when you start the debugger, processing stops at the specified line. As expected, hovering the mouse over a variable or expression gives you a tooltip with the value.


Several of the other debug windows are also usable in this mode, such as the Locals and Immediate window.

Customizing DataTips

A convenient debugging tool in Visual Studio is the ability to hover the mouse over an object and see the information currently stored there. This is referred to as a DataTip.


If the class is derived from a base class, or contains other objects within, you can drill down to see those values as well. Depending on the complexity of the object however, this can become tedious. This is especially true if there are a couple values that you always want to see when debugging.

To quickly see one or more properties on a class, you can do so using the DebuggerDisplay attribute in System.Diagnostics. If I add the following to MyBaseClass, I can view the value of X without expanding the DataTip. (The property to display is placed in braces.)

[DebuggerDisplay("The value of X is: {X}")]

If I derive a new class from MyBaseClass, I can set a DebuggerDisplay attribute that accesses values both from this class and the base.

[DebuggerDisplay("{X}, {Y}")]
class MyDerivedClass : MyBaseClass
{
    private int _y;
    public int Y
    {
        get { return _y; }
        set { _y = value; }
    }
}

Quick and dirty debugging - DebugView and Trace.WriteLine

Here's another debug scenario for you. After taking great effort in testing your application you hand it off to QA. They throw it back with some interesting bug. Using the exact same steps, you're unable to reproduce on your machine. You have a general idea of where the app is failing, but can't be sure precisely what the issue is.

At this point one usually resorts to some sort of logging. These logging statements are placed in strategic locations through the suspect code (at every other line.) If the bug is in the UI, the common method is MessageBox.Show. If the problem is in an underlying assembly, you must resort to writing output to a text file. The downside is that lots of message boxes wear you out, and it's always a pain tracking down the necessary code to write files.

An easier option is to call Trace.WriteLine (located in System.Diagnostics.) In my sample application (MyApp) I have a single button. Inside the Click event, I add the following line

 Trace.WriteLine("Button1 was clicked");

The event then calls a method in a separate library. In this library method, I've added the following line ('x' was the parameter passed into the method)

 Trace.WriteLine("SomeMethod - Parameter x: " + x.ToString());

When I run the application from VisualStudio and click the button, the Output window contains the trace messages


That's fine if you're running VS, but what about on a QA box? For that I'm using DebugView. After starting up the utility, I fire up the sample application. Click the button (which again calls Trace.Writeline) and DebugView displays the messages previously seen in Visual Studio.

Debugging with the Fusion logger

If you've spent much time developing, you've probably run into this scenario. You're working along coding a new application. Everything runs on your machine. Then you hand it off to someone to test (that, or load it on the production server - let the users tell you what's wrong.) Unfortunately, the app crashes as soon as you attempt to start it. Looking in the Event Logs, you see generic .Net errors, but nothing that appears to help. Short of installing VisualStudio on the box in question, how do you track down the issue?

One place to start is the Fusion logs. For this demo, I've created a class library (MyClassLib) and a command-line app (MyConsoleApp.) The app makes a single method call into the library and then exits. Nothing interesting to see when everything works. If I delete MyClassLib.dll and run the application, I witness a rather unpleasant dialog


When an app closes in a violent manner, the first place to look is the computer's event logs. Unfortunately, the only entry for the app looks something like:

"Faulting application myconsoleapp.exe, version 1.0.0.0, stamp 47293d14, faulting module kernel32.dll, version 5.1.2600.3119, stamp 46239bd5, debug? 0, fault address 0x00012a5b."

So now we turn to the Fusion logs. The first step is to copy the Assembly Binding Log Viewer (fuslogvw.exe) from any machine with VS2005. Start it up; it looks something like this:


Click on the Settings button. In the dialog, select "Log bind failures to disk." Check the box to "Enable custom log path" and specify an already-existing folder (the app won't create it for you.)


Note: According to official documentation, you should be able to use the default log directory. In my experience, that never seemed to work.

With the logger set up I again attempt to run the application. Which again crashes. Going back to the Fusion log viewer, click Refresh. I now have a single entry


Clicking on the entry loads the details in Internet Explorer (shown below.) If you look halfway down the log, you'll see the reference to MyClassLib. Near the end, you'll see the various locations it searched for the file. Now it's a simple matter of finding a copy of my dll and placing in the search path.

---

*** Assembly Binder Log Entry (10/31/2007 @ 10:14:45 PM) ***

The operation failed.
Bind result: hr = 0x80070002. The system cannot find the file specified.

Assembly manager loaded from: C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\mscorwks.dll
Running under executable C:\temp\testcode\MyConsoleApp\bin\Release\MyConsoleApp.exe
--- A detailed error log follows.

=== Pre-bind state information ===
LOG: User = SH\pgoins
LOG: DisplayName = MyClassLib, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
(Fully-specified)
LOG: Appbase = file:///C:/temp/testcode/MyConsoleApp/bin/Release/
LOG: Initial PrivatePath = NULL
LOG: Dynamic Base = NULL
LOG: Cache Base = NULL
LOG: AppName = MyConsoleApp.exe
Calling assembly : MyConsoleApp, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null.
===
LOG: This bind starts in default load context.
LOG: No application configuration file found.
LOG: Using machine configuration file from C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\config\machine.config.
LOG: Policy not being applied to reference at this time (private, custom, partial, or location-based assembly bind).
LOG: Attempting download of new URL file:///C:/temp/testcode/MyConsoleApp/bin/Release/MyClassLib.DLL.
LOG: Attempting download of new URL file:///C:/temp/testcode/MyConsoleApp/bin/Release/MyClassLib/MyClassLib.DLL.
LOG: Attempting download of new URL file:///C:/temp/testcode/MyConsoleApp/bin/Release/MyClassLib.EXE.
LOG: Attempting download of new URL file:///C:/temp/testcode/MyConsoleApp/bin/Release/MyClassLib/MyClassLib.EXE.
LOG: All probing URLs attempted and failed.

Debugging with Exception Breakpoints

How many times has this happened to you? You're working on code that's not quite functioning correctly. You suspect there's an exception being thrown somewhere, but it's being caught and ignored. Maybe this was intentional, or maybe it was poorly written code. Either way, you need to locate the problem. Visual Studio 2005 has a handy little tool to help - Exception Breakpoints.

Say you have code that looks like this:

    try
    {
        int a = 2;
        int b = 0;
        int c = a / b;  // does not compute
    }
    catch
    {
        // Do nothing
    }

If you were to run this code, you'd never know that there was a problem (well, not until you tried to use the value of 'c' elsewhere.) What we want to do is have the debugger break as soon as an exception is thrown. To do this, open the Exceptions dialog, either through the menu (Debug > Exceptions) or the keyboard shortcut (Ctrl+D followed by E).



Under the Thrown column, check the box next to the Common Language Runtime Exceptions. Now, when an exception is thrown, VS immediately breaks at the offending line of code. One word of warning - Depending on the size of the code, you may find far more exceptions being thrown than you had expected.