Logging with Dynamic Objects in .NET 4.0 (part 2-n) - User Interaction Logging

In my previous blog post, you were able to see the starting point of a logging solution I am trying to build. In this blog post, we will step into logging the user interaction of the end-user. Sometimes, it’s hard to discover how the end-user was able to produce a certain situation/bug. You walk to the desk of the end-user to ask what they did, but they are unable to reproduce their steps. They lost their work, and you want to do something to stop that from happening again.

In this blog post, we will look at the basic concept I created for logging the interaction of the end-user with our application. It still needs some polishing, but I just want to get the idea out, and later on improve it, to become a better solution.

I created a very basic application, with 4 buttons and 2 list boxes. The end-user is able to press any of the buttons and drag and drop items from the left list box to the right list box. The submit button will submit it somewhere. The case: there is a weird kind of bug on our application, but we are unable to get our hands on it. It feels like something that happens at random, and we want to solve the issue. Each time the end-users reports back a list of steps to reproduce the bug, it's almost equal, but still different each time, and each time we are unable to reproduce it.

The application:

The XAML of the main window is as given below:

<Grid>
    <StackPanel Name="stack">
        <Button>TestA</Button>
        <Button Name="btnTestB">TestB</Button>
        <Button Click="Button_Click2" Name="btnTestC">TestC</Button>
        <StackPanel Orientation="Horizontal" Height="220">
            <ListBox Name="lstboxSource"
                        PreviewMouseLeftButtonDown=
			"lstboxSource_PreviewMouseLeftButtonDown" 
                        Margin="12" Width="215"
                        DisplayMemberPath="Name"
                        ScrollViewer.VerticalScrollBarVisibility="Visible" />
            <ListBox Name="lstboxDest" 
                        Drop="lstboxDest_Drop" 
                        AllowDrop="True" 
                        Margin="12" Width="215"
                        DisplayMemberPath="Name"
                        ScrollViewer.VerticalScrollBarVisibility="Visible"/>
        </StackPanel>
        <Button Name="btnSubmit">Submit</Button>
    </StackPanel>
</Grid>

Let’s start: To discover what the user did, we want to log the following interaction:

• Clicking button TestA, TestB, or TestC
• Dropping of items in the right list box

We can do this by adding logging code to all these controls, but that solution isn’t great. If this would be a bigger application, then that might take a few hours or more to do. After we are done solving the issue, it would take ages to remove it again. So I want some way to do this, with the minimal amount of effort.

To get to a solution quickly, I just (for now) assume your application only has one window that you want to trace user interactions on. If you got multiple windows, then you need to implement the same process multiple times. Next to that, I assume you are using a WPF application (The current solution can, but for now will not, work in a Windows Forms or web application).

Ok, let’s start. What we want is an easy way to listen to the interaction of the end user within the application. Most of the interactions done by the end-user are performed by interaction with the controls (button, list box, etc.), which fire events. So we need some way to easily attach to those events.

With this idea, I first created the basic structure of how I wanted to define the logging. Below is the example of this:

When the MainWindow is loaded, I want to get all its child objects recursive, and add a logging action to the Click event of all of the child objects that are of the type Button. If there is a child object with the name btnSubmit, then I want to also listen to the Click event with the handler actionClearLog.

I don’t really like the BindAllOf<ListBox, DragEventArgs> method, because it’s less fluent, but for now it’s the most generic way to define different event handler arguments.

void MainWindow_Loaded(object sender, RoutedEventArgs e)
{
    GetAllChildrenRecursive(this)
        .BindAllOf<Button>("Click", actionLogClick)
        .BindAllOf<ListBox, DragEventArgs>("Drop", actionLogDrop)
        .Bind("btnSubmit", "Click", actionClearLog);
}

The first thing to do is get all child objects (recursive), this is done with an inline function:

// Find all the child dependency objects recursive
Func> GetAllChildrenRecursive = null;
GetAllChildrenRecursive = @do =>
{
    List doList = new List();
    doList.Add(@do);
    for (int i = 0; i < VisualTreeHelper.GetChildrenCount(@do); i++)
    {
        doList.AddRange(GetAllChildrenRecursive(VisualTreeHelper.GetChild(@do, i)));
    }
    return doList;
};

The BindAllOf<Type> and Bind() methods are extension methods on the IEnumerable<DependencyObject>, to keep the syntax as fluent as possible. I like this more than adding a list of custom objects as filter or definition. The downside is that it will cost more resources to walk the list for each definition.

The extension methods walk the list of DependencyObjects and add the given action as event handler for the given event.

public static IEnumerable BindAllOf(
    this IEnumerable doList, 
    string eventName, 
    Action action)
{
    return BindAllOf(doList, eventName, action);
}

public static IEnumerable BindAllOf(
    this IEnumerable doList, 
    string eventName, 
    Action action)
{
    foreach (var item in doList)
    {
        if (item.GetType() != typeof(Type))
        {
            continue;
        }

        foreach (var @event in item.GetType().GetEvents(
                BindingFlags.Instance |
                BindingFlags.Static |
                BindingFlags.Public |
                BindingFlags.FlattenHierarchy))
        {
            if (@event.Name.ToLowerInvariant() == eventName.ToLowerInvariant())
            {
                @event.AddEventHandler(item, Delegate.CreateDelegate
				(@event.EventHandlerType, action.Method));
            }
        }
    }

    return doList;
}

The bind method for the Submit button, is almost the same, only compares on the name of the element:

public static IEnumerable Bind(
    this IEnumerable doList, 
    string instanceName, 
    string eventName, 
    Action action)
{
    foreach (var item in doList)
    {
        var obj = item as FrameworkElement;
        if (obj == null || obj.Name.ToLowerInvariant() != 
				instanceName.ToLowerInvariant())
        {
            continue;
        }

        foreach (var @event in item.GetType().GetEvents(
                BindingFlags.Instance |
                BindingFlags.Static |
                BindingFlags.Public |
                BindingFlags.FlattenHierarchy))
        {
            if (@event.Name.ToLowerInvariant() == eventName.ToLowerInvariant())
            {
                @event.AddEventHandler(item, Delegate.CreateDelegate
				(@event.EventHandlerType, action.Method));
            }
        }
    }
    return doList;
}

Now we got everything in place, let’s look again at the syntax:

void MainWindow_Loaded(object sender, RoutedEventArgs e)
{
    GetAllChildrenRecursive(this)
        .BindAllOf<Button>("Click", actionLogClick)
        .BindAllOf<ListBox, DragEventArgs>("Drop", actionLogDrop)
        .Bind("btnSubmit", "Click", actionClearLog);
}

At this point, we are still missing the action parameters. These are the handler functions to handle the logging actions. In this application, the btnSubmit will submit the settings to somewhere, and when that is done, I want to clear out the reproducing steps. I just assume that process returns to its initial state and that it’s time to clear the list of steps to reproduce. I don’t want to see all the things the user did that day (for now). Next to that, I want to log the dropping of items on the list boxes, because I assume there is something wrong there. So let’s take a look at the actions:

// The logging actions
Action actionLogClick = (snd, args) =>
{
    Logger.Log.TraceMessage("user interaction", 
        string.Format("{0}The event '{1}' fired on type {2} with the name: {3}",
            DateTime.Now.ToString("hh:mm:ss.fff tt"),
            args.RoutedEvent.Name,
            snd.GetType().Name,
            (snd as FrameworkElement).Name));
};
Action actionLogDrop = (snd, args) =>
{
    dynamic clonedObject = new DynamicClone(args.Data.GetData(typeof(Product)));
    Logger.Log.TraceMessage("user interaction", 
            string.Format(
                "{0} Dropped the a object on the {1} with the name: {2}",
                DateTime.Now.ToString("hh:mm:ss.fff tt"),
                snd.GetType().Name,
                (snd as FrameworkElement).Name),
            clonedObject >> ToFormat.Xml);
};
Action actionClearLog = (snd, args) =>
{
    Console.WriteLine("+-- Clear log --+");
}; 

I am using the logger and DynamicClone object from my previous blog post. The actions are pretty simple and just log information. The Drop action will get the object Product (the list box is bound to a collection of Product objects) and transform it to XML, because we want to know what the properties of the object are that the user dropped on the list box. For now, the actionClearLog will just output the clear log text to my console. (The Logger is still outputting logging information to the console prompt.)

At this point, we should have setup the actions and bound them to all the events and they should write out logging information to the console prompt, let’s see if it works :). I will launch the application and click and drag around:

What we can see from the log now, is:

• I clicked a Button that didn’t have a name set (see XAML above, button had no name!)
• I clicked a Button with the name btnTestC
• I clicked a Button with the name btnTestB
• I dragged the product with the name ‘cc’ from the left to the right box
• And pressed the Submit button

Yeah! Everything seems to work! :)

Now it’s time to polish this concept and I think I need to improve it, to easily replay the actions of the end-users, because as a developer I don’t like to follow an endless list of steps to reproduce each time. On one of my next blog posts, I will dive deeper into this.

Read the previous part of this series over here:

• Logging with dynamic objects in .NET 4.0 (Part 1-n)

CodeProject