Viewing & Organizing Log Files

Phil has developed software for over 20 years in the defense, publishing, database, and financial industries. He can be contacted at [email protected].

Developers charged with supporting mission-critical applications need to be alerted to problems when they arise in the production environment. Once a problem is identified, it is essential that you can browse and/or search application log files for clues as to the nature and cause of the problem. Only then can the implications of the problem be assessed and resolved as quickly as possible.

Today's applications are highly distributed. Clients interact with server processes asynchronously. As a result, logged events reflecting user activity are intermixed in the strictly chronological log files with events reflecting numerous types of notifications from server processes.

Diagnosing production problems is a form of forensic analysis. Typically, on being alerted to an application error, the first step is to open the log file in a text viewer such as Notepad and search or browse the file for the exceptional event and other events that may have contributed to it. This can be a tedious process. Relevant clues can be missed. In addition, third-party tools maintain log files in their own formats. A generic approach to viewing and organizing log file contents is highly valuable in such an environment. In this article, I present LogChipper—one solution to this problem for the .NET platform.

Figure 1 is LogChipper's user interface. It uses two ListView controls to present the original view and the sorted and filtered view of events. Note the radio buttons for toggling between them. Also note the checkboxes for enabling autoscroll and dynamic load and pausing the loading process. The column chooser lets users select the desired columns and rearrange them.

The Format menu is populated by the plug-in parser with items for selecting custom features offered by the plug-in. The plug-in in Figure 1 parses logs of a popular FIX engine, a protocol used in the financial industry to send buy and sell orders to the exchanges, and communicate about events on these orders (see http://www.fixprotocol.org/).

Plug-In Architecture

LogChipper is designed as a plug-in framework. Such a framework has three key ingredients.

• The interface is one ingredient. LogChipper is a WinForms application designed as several assemblies; see Figure 2. The assembly named "LogView" contains the application's host executable. "LogViewCommon" contains definitions of some common enumeration types. "LogViewInterfaces" is the assembly that exposes the definition of the plug-in parser interface. "LogViewPlugin_FIX" contains a specific implementation of the interface for FIX engine logs. One assembly houses a definition of the plug-in interface and the other implements that interface. The plug-in interface ILogViewParser is defined in Listing One. Any parser must implement ILogViewParser. In so doing, it must be responsible for processing events into fields of information, assigning the corresponding values to grid columns, and exploiting metadata (such as data type, identifying tag, and column heading).
• Dynamic activation is another key ingredient. To be effective, the application needs to be able to instantiate any parser that implements ILogViewParser at will. In the .NET Framework, the Activator class makes this possible. Listing Two demonstrates what happens when users select a plug-in parser. Note the use of the Activator class method CreateInstance. There are several overloads, but the one that takes the assembly file name, and the name of the type to be instantiated serves the current purpose best. CreateInstance constructs an instance of the requested type and returns a System.Runtime.Remoting.ObjectHandle. Calling Unwrap on this handle reconstitutes the object. Casting this object to the requisite interface type completes the process, equivalent to calling CoCreateInstance in COM, but without GUIDs or registry accesses.
• The third key ingredient of a plug-in framework is the ability to insert its custom features into the host application. Recall from Listing One that ILogViewParser defines the method GetPluginMenuItems. The plug-in implements this method by returning an array of objects of type MenuItem, defined in the System.Windows.Forms namespace. A plug-in typically constructs the MenuItem array and linked MenuItem arrays (if any) representing cascading submenus during its initialization.

Continuing in Listing Two, after instantiating the plug-in parser object, the host application calls GetPluginMenuItems on the interface and populates the Format menu.

The plug-in parser constructs the menus as in Listing Three(a). The menu items allow for three modes of column heading display:

• Events in the FIX protocol consist of tag-value pairs, where the tags are numeric.
• The parser maintains a mapping between the numeric tags and alphabetic equivalent headings.
• The modes of display provided by this parser are numeric, alphabetic equivalent, and a blend of the two.

Listing Three(b) illustrates one of the Format menu handlers.

You need a way of determining which parser assemblies are available to users. You could iterate over the DLLs in the application directory using CreateInstance to determine which DLLs are .NET assemblies that implement ILogViewParser. This solution offers dynamic discovery, but can be expensive. Instead, I decided to list the available parsers in the application configuration file (Listing Four). This way, users can choose from a collection of parsers by familiar format names, while the application instantiates the parser based on the assembly DLL filename.

Multithreaded Design

To let users browse, sort, and filter logs while they are being loaded, the file I/O for loading and parsing the events is placed in its own thread. This requires some thread synchronization; for instance, to ensure that new rows are not being inserted into a grid while new sort or filter criteria are being applied.

Listing Five(a) contains a portion of the handler for opening a log file. After restoring the user's settings for this file, it constructs a new thread to perform the file I/O and parsing. The member variable m_thPopulateList is of type Thread, defined in the System.Threading namespace.

Creating the thread is a matter of constructing a Thread object, passing a ThreadStart delegate to its constructor. Delegate is a .NET type representing a callback method with a specified signature. A ThreadStart delegate represents a callback method that takes no arguments and returns void. A ThreadStart delegate is created by passing its constructor a reference to a method that has the proper signature and is designed to perform the work of the thread. In this case, that method is PopulateListThreadFunc.

Listing Five(b) contains a portion of PopulateListThreadFunc demonstrating thread synchronization and indirect communication with the main thread. First, note the use of m_SortParseMutex, a member variable of type Mutex, defined in the System.Threading namespace.

Mutex offers a way to ensure that an operation that affects the state of a shared resource from one thread will not conflict with one in progress on another thread. A Mutex instance representing a Win32 mutex kernel object is created for each shared resource. All threads call the WaitOne method on the applicable Mutex instance before beginning an operation that affects the shared resource's state. WaitOne blocks if another thread holds the mutex, returning only when Release has been called on it. In this case, the ListView controls must be protected from concurrent manipulation by the user and the file I/O thread. To prevent such a change from occurring while a new row is being inserted in its proper sequence into the sorted ListView control, changes to the sort sequence are synchronized via a call to WaitOne on m_SortParseMutex.

"Tailing" the File

Returning to Listing Five(b), note the references to various Boolean flags—variables m_bInitialLoadInProgress, m_bDynamicUpdate, m_bLoadPaused, and m_bStopRequested. To load new events from the log file as they are written, the I/O loop is continuous. If set to True, the variable m_bInitialLoadInProgress indicates that the end of the file has not yet been reached. Once the end of file is reached, new events (if any) are read from the file after putting the file I/O thread to sleep briefly so as not to hog the CPU when the bulk of the I/O task is finished.

Again, the UI thread communicates indirectly with the file I/O thread. The checkbox labeled "Dynamic Update" is initially checked. The variable m_bDynamicUpdate alternates between True and False as users uncheck/recheck the checkbox. While False, "tailing" the file is disabled.

Similarly, the variable m_bLoadPaused is synchronized with the state of the Pause Load checkbox. While False, file loading is disabled. Also, when a user selects Close, Exit, or Open from the File menu and clicks OK on the confirmation prompt, the variable m_bStopRequested is set to True. On detecting that the user has confirmed closing the current file, PopulateListThreadFunc returns.

Multicolumn Sorting

The .NET Framework defines the IComparer interface in the Systems.Collections namespace. It is used to specify how pairs of objects are compared for sorting and searching purposes. For instance, IComparer is used by the static methods Sort and BinarySearch of the .NET Framework class Array.

The default sort behavior of the ListView class is case sensitive based on item text, the text displayed in the left-most column of the grid. By creating a class that implements the IComparer interface, it is possible to alter this behavior. Listing Six contains the ListViewItemComparer class, which derives from IComparer. Note that it has a custom constructor that takes an array of sort columns, a corresponding array of sort orders, and a reference to the plug-in parser interface. Its implementation of the interface method Compare iterates over the sort columns starting with the most dominant sort column, using the sort order and data type of each, to determine which ListViewItem is greater.

The data type of a field determines how to properly compare two items on that field. The parser holds the attributes of all of the fields and exposes them via the plug-in parser interface. Hence, the call to the interface method GetSortDataType is needed.

Conclusion

Among other improvements over MFC and other older frameworks, .NET represents a consistent programming model that hides the details of Win32 API programming and offers a rich class library. Although the details of filtering and parsing were beyond the scope of this article, there are many ways to present a UI for filtering the rows of a grid and to perform the filtering task. Likewise, there are numerous techniques for parsing events in a log file. Each format imposes constraints that emphasize one technique over others. The classes in the .NET namespace System.Text.RegularExpressions unleash the power of regular expressions. They can be applied wherever a pattern can be identified in the text. It can be advantageous to have several related log files open at the same time for browsing/searching. A multidocument extension is a planned enhancement for LogChipper.

DDJ

Listing One

/********************************************************
This file is part of the LogChipper(tm) software product.
Copyright (C) 2004 Ivden Technologies, Inc. All rights reserved.
********************************************************/

public interface ILogViewParser
{
   void Initialize(string sFileName, Mutex sortParseMutex);
   void SetListViewColumnInfo(ref ListViewColumnInfo lvColumnInfo);
   int FormatGridColumns(ListView listViewMain,ListView listViewSort);
   bool ParseLineIntoGrid(string line, ListView listViewMain, 
      ListView listViewSort,SortOrder order,ref int nNewRow);
   void GetAllHeadings(string[] sHeadings);
   SortDataType GetSortDataType(int iCol);
   string GetColumnHeading(int iCol);
   int GetColumnWidth(int iCol);
   void DisplayHeading(ListView listView,int iCol,string adornedValue);
   void GetPluginMenuItems(MenuItem[] menuItems);
}

/********************************************************
This file is part of the LogChipper(tm) software product.
Copyright (C) 2004 Ivden Technologies, Inc. All rights reserved.
********************************************************/

System.Runtime.Remoting.ObjectHandle handle =   
  Activator.CreateInstanceFrom(sPluginFile + ".dll", "LogViewPlugin.Parser"); 
m_LogViewParser = (LogViewInterfaces.ILogViewParser)handle.Unwrap();
m_LogViewParser.Initialize(sFormatFile + ".xml", m_SortParseMutex);
m_nColumns = m_LogViewParser.FormatGridColumns(listViewMain, listViewSort);
m_lvColumnInfo = new ListViewColumnInfo();
m_lvColumnInfo.SetSortColumns(m_anSortCols);
m_lvColumnInfo.SetSortOrders(m_anSortOrders);
m_LogViewParser.SetListViewColumnInfo(ref m_lvColumnInfo);

if (m_nColumns >= 1)
{
    m_sFormatFileName = sFormatFile;
    menuFormat.MenuItems.Clear();
    MenuItem[] menuItems = null;
    m_LogViewParser.GetPluginMenuItems(ref menuItems);
    int nMenuItems = menuItems.Length;
    for (int iItem = 0; iItem < nMenuItems; iItem++)
    {
        menuFormat.MenuItems.Add(iItem, menuItems[iItem]);
    }
}

/********************************************************
This file is part of the LogChipper(tm) software product.
Copyright (C) 2004 Ivden Technologies, Inc. All rights reserved.
********************************************************/

m_HeaderMenuItems = new MenuItem[3];

m_HeaderMenuItems[0] = new MenuItem("&Numeric Tags", new System.EventHandler(
                                         HeaderMenu_NumericTags_OnClick));
m_HeaderMenuItems[1] = new MenuItem("&Alphabetic Labels",
                  new System.EventHandler(HeaderMenu_AlphaLabels_OnClick));
m_HeaderMenuItems[2] = new MenuItem("&Both", 
                  new System.EventHandler(HeaderMenu_Both_OnClick));
m_MenuItems = new MenuItem[1];
m_MenuItems[0] = new MenuItem("&Header Format", m_HeaderMenuItems);

private void
HeaderMenu_AlphaLabels_OnClick(object sender, System.EventArgs e)
{
    if (m_headerFormat != HeaderFormat.Alpha)
    {
        m_headerFormat = HeaderFormat.Alpha;
        UpdateColumnHeadings(m_asColLabels);
    }
}

/********************************************************
This file is part of the LogChipper(tm) software product.
Copyright (C) 2004 Ivden Technologies, Inc. All rights reserved.
********************************************************/

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
    <appSettings>
        <add key="PluginAssembly_1" value="LogViewPlugin_FIX_4_1" />
        <add key="PluginFormatFile_1" value="Fix_4_1_LogFormat" />
        <add key="UserDataRootFolder" value="c:\Temp" />
    </appSettings>
</configuration>

/********************************************************
This file is part of the LogChipper(tm) software product.
Copyright (C) 2004 Ivden Technologies, Inc. All rights reserved.
********************************************************/

// Restore selected columns, their widths and order
// and selected sort columns and their sort order.
RestoreViewSettings();

// Populate list view.
m_bInitialLoadInProgress = true;
m_bLoadInProgress = true;
m_thPopulateList = new Thread(new ThreadStart(PopulateListThreadFunc));
m_thPopulateList.Priority = ThreadPriority.Lowest;
m_thPopulateList.Start();

while (!m_bStopRequested)
{
    int nNewRow = -1;
    while (((line = sr.ReadLine()) != null) &&
        !m_bStopRequested &&
        (m_bInitialLoadInProgress || m_bDynamicUpdate))
    {
        if (m_bStopRequested)
        {
            m_bStopRequested = false;
            m_bLoadInProgress = false;
            return;
        }
        while (m_bLoadPaused)
        {
            Thread.Sleep(100);
            if (m_bStopRequested)
            {
                m_bStopRequested = false;
                m_bLoadInProgress = false;
                return;
            }
        }
        m_SortParseMutex.WaitOne();
        nNewRow = -1;
        if (m_bAutoScroll)
        {
            listViewMain.BeginUpdate();
        }
        bool bParse = m_LogViewParser.ParseLineIntoGrid(line,
            listViewMain, listViewSort, listViewSort.Sorting, ref nNewRow);
        if (m_bAutoScroll)
        {
            listViewMain.EndUpdate();
        }
        if (!bParse)
        {
            m_SortParseMutex.ReleaseMutex();
            break;
        }
        if (m_bAutoScroll && (nNewRow >= 0))

       {
            listViewMain.EnsureVisible(nNewRow);
        }
        m_SortParseMutex.ReleaseMutex();
    }
}

/********************************************************
This file is part of the LogChipper(tm) software product.
Copyright (C) 2004 Ivden Technologies, Inc. All rights reserved.
********************************************************/

class ListViewItemComparer : IComparer
{
    private int m_nSortColumns;
    private ArrayList m_anSortCols;
    private ArrayList m_anSortOrders;
    private LogViewInterfaces.ILogViewParser m_LogViewParser;
    public ListViewItemComparer() 
    {
    }
    public ListViewItemComparer(ArrayList anSortCol,ArrayList anSortOrder,
                               LogViewInterfaces.ILogViewParser logViewParser)
    {
        m_nSortColumns  = anSortCol.Count;
        m_anSortCols    = anSortCol;
        m_anSortOrders  = anSortOrder;
        m_LogViewParser = logViewParser;
    }
    public int Compare(object x, object y) 
    {
        int nRet = 0;
        for (int iCol = 0; iCol < m_nSortColumns; iCol++)
        {
            nRet = CompareSingleColumn(x,y,(int)m_anSortCols[iCol],
                                             (SortOrder)m_anSortOrders[iCol]);
            if (nRet != 0)
            {
                break;
            }
        }
        return nRet;
    }
    public int CompareSingleColumn(object x, object y, 
                                                   int iCol, SortOrder order)
    {
        int nRet = 0;
        string s1, s2;
        SortDataType type = m_LogViewParser.GetSortDataType(iCol);
        switch (type)
        {
            case    SortDataType.AlphaNoCase:
                nRet = String.Compare(
                   ((ListViewItem)x).SubItems[iCol].Text,
                    ((ListViewItem)y).SubItems[iCol].Text, true);
                break;
            case    SortDataType.AlphaCase:
                nRet = String.Compare(
                    ((ListViewItem)x).SubItems[iCol].Text,
                    ((ListViewItem)y).SubItems[iCol].Text);
                break;
            case    SortDataType.Date:
            case    SortDataType.Time:
                s1 = ((ListViewItem)x).SubItems[iCol].Text;
                s2 = ((ListViewItem)y).SubItems[iCol].Text;
                if ((s1.Length == 0) || (s2.Length == 0))
                {
                    nRet = String.Compare(s1, s2);
                    break;
                }
                try
                {
                    DateTime dt1 = DateTime.Parse(s1);
                    DateTime dt2 = DateTime.Parse(s2);
                    nRet = DateTime.Compare(dt1, dt2);
                }
                // If neither object has valid date format, compare as strings.
                catch 
                {
                    // Compare the two items as a string.
                    nRet = String.Compare(s1, s2);
                }
                break;
            case    SortDataType.Number:
                double d1 = 0;
                double d2 = 0;
                s1 = ((ListViewItem)x).SubItems[iCol].Text;
                s2 = ((ListViewItem)y).SubItems[iCol].Text;
                if ((s1 != null) && (s1.Length > 0))
                {
                    d1 = Convert.ToSingle(s1);
                }
                if ((s2 != null) && (s2.Length > 0))
                {
                    d2 = Convert.ToSingle(s2);
                }
                nRet = (d1 < d2) ? -1 : 1;
                break;
        }
        if(order == SortOrder.Descending)
        {
            nRet *= -1;
        }
        return nRet;
    }
}