User Activity Logging, Telemetry (and Variables in Global Exception Handlers)

Question

Background:

I am dealing with a very old app that generates Exceptions quite rarely and very intermittently.

Current Practices:

Typically we programmers deal with rare unknowns using Global Exception handlers, wiring up something like this:

[STAThread]
[SecurityPermission(SecurityAction.Demand, Flags = SecurityPermissionFlag.ControlAppDomain)]
private static void Main()
{
    Application.ThreadException += new ThreadExceptionEventHandler(UIThreadException);
    Application.SetUnhandledExceptionMode(UnhandledExceptionMode.CatchException); 
    AppDomain.CurrentDomain.UnhandledException +=
        new UnhandledExceptionEventHandler(UnhandledException);

    Application.EnableVisualStyles();
    Application.SetCompatibleTextRenderingDefault(false);
    Application.Run(new OldAppWithLotsOfWierdExceptionsThatUsersAlwaysIgnore());
}

private static void UIThreadException(object sender, ThreadExceptionEventArgs t)
{
    //-------------------------------
    ReportToDevelopers("All the steps & variables you need to repro the problem are: " + 
    ShowMeStepsToReproduceAndDiagnoseProblem(t));
    //-------------------------------

    MessageToUser.Show("It’s not you, it’s us. This is our fault.\r\n Detailed information about this error has automatically been recorded and we have been notified.Yes, we do look at every error. We even try to fix some of them.")
}

private static void UnhandledException(object sender, UnhandledExceptionEventArgs e)
{
    //...
}

Problem Domain:

Its hard to get the repro steps from users and because of the varied amount of issues being reported I dont want to go down (the Second Chance Exception) WinDBG or CDB troubleshooting paths just yet. I want some metrics and hopefully some recent System.Diagnostic love first.

Research/Understanding:

A long time ago I read a book Debugging Microsoft .NET 2.0 Applications and it discusses a cool tool that John Robbins (a.k.a The BugSlayer) wrote SuperAssert.Net

The only downside to this tool is (in order to work out problems) the size of the memory dumps are huge and of course debugging them is almost as much of an art, as it is a science.

Question:

I am hoping someone can tell me a way I can dump out variables in this program, well at least the one's in the last step of the applications Exception.StackTrace.

Is this at all possible these days? Its easy enough for me to map the StackTrace back to user actions to work out the steps.. I just need the variables!

Update

Turned out to be a faulty router.

Allier

That's way too late. The information no longer exists, quite likely. The stack has been unwound, and possibly changed along the way. And that's just the stack - a lot of the stuff will be on the heap, which is even more "violent" - things are moved around and collected all the time. Instead, set your debugger to break on every exception - this allows you to see the whole context immediately, including all the variables etc., because it's not yet out of scope. Not to mention that some arguments might not have ever been passed, and some might have been passed through registers. – Mastery

These rare and extremely hard to reproduce problems that don't happen in DEV with a debugger attached (remote debugging is out of the question too as they're so rare). That's my main the problem. Otherwise the story would be much brighter, I would have at least found some and fixed them. I appreciate your suggestion, I have thought about using an AOP library like PostSharp to record state before the stack is unwound but there must be something in this day an age (apart from a gigantic .dmp file or AOP Try-Catching every method) to track what was last in memory... – Allier

Memory is much more complicated than it used to be in the olden days :)) procdump can be used to create the full memory dump in case the unhandled exception occurs, but that would mean your users would have to run the application through procdump, and the app would have to crash when this exception occurs - hardly ideal. The cool point is that you can then just load that dmp into visual studio and see it as if it happened on your computer (mostly), which makes debugging it a lot easier, but the cost isn't trivial. – Mastery

Something like PostSharp is probably your best bet. Of course, it will still really only be able to give you the arguments, not the variables. You could also write your own debugger, but that's somewhat complicated. – Mastery

Answer 1

The Open Source Project is now on GitHub: https://github.com/MeaningOfLights/UserActionLog

...

I did a HUGE amount of reseach into this*. In the end I just created a log of what the user does, its a fraction of the size of a memory dump and reliably gets me the steps to reproduce problems. It also serves another benefit, understanding how users use the application.

*I seriously could not find anything online that does this basic User Activity Logging. Everything I found was about AOP, Auto UI Testing Frameworks or 1/2 Gig memory dumps.

For your convenience here is the goodness!

---

ActionLogger Class:

public class ActionLogger
{
    private Type _frmType;
    private Form _frm;
    /// <summary>
    /// Ctor Lazy way of hooking up all form control events to listen for user actions.
    /// </summary>
    /// /// <param name="frm">The WinForm, WPF, Xamarin, etc Form.</param>
    public ActionLogger(Control frm)
    {
        _frmType = ((Form)frm).GetType();
        _frm = (Form)frm;
        ActionLoggerSetUp(frm);
    }

    /// <summary>
    /// Ctor Optimal way of hooking up control events to listen for user actions.
    /// </summary>
    public ActionLogger(Control[] ctrls)
    {
        ActionLoggerSetUp(ctrls);
    }

    /// <summary>
    /// Lazy way of hooking up all form control events to listen for user actions.
    /// </summary>
    /// /// <param name="frm">The WinForm, WPF, Xamarin, etc Form.</param>
    public void ActionLoggerSetUp(Control frm)
    {
        HookUpEvents(frm);  //First hook up this controls' events, then traversely Hook Up its children's
        foreach (Control ctrl in frm.Controls) {
            ActionLoggerSetUp(ctrl); //Recursively hook up control events via the *Form's* child->child->etc controls
        }
    }

    /// <summary>
    /// Optimal way of hooking up control events to listen for user actions.
    /// </summary>
    /// <param name="ctrls">The controls on the WinForm, WPF, Xamarin, etc Form.<param>
    public void ActionLoggerSetUp(Control[] ctrls)
    { 
        foreach (var ctrl in ctrls) {
            HookUpEvents(ctrl);
        }
    }

    /// <summary>
    /// Releases the hooked up events (avoiding memory leaks).
    /// </summary>      
    public void ActionLoggerTierDown(Control frm)
    {
        ReleaseEvents(frm);
    }

    /// <summary>
    /// Hooks up the event(s) needed to debug problems. Feel free to add more Controls like ListView for example subscribe LogAction() to more events.
    /// </summary>
    /// <param name="ctrl">The control whose events we're suspicious of causing problems.</param>
    private void HookUpEvents(Control ctrl)
    {
        if (ctrl is Form) {
            Form frm = ((Form)ctrl);
            frm.Load += LogAction;
            frm.FormClosed += LogAction;
            frm.ResizeBegin += LogAction;
            frm.ResizeEnd += LogAction;
        }
        else if (ctrl is TextBoxBase) {
            TextBoxBase txt = ((TextBoxBase)ctrl);
            txt.Enter += LogAction;
        }
        else if (ctrl is ListControl) { //ListControl stands for ComboBoxes and ListBoxes.
            ListControl lst = ((ListControl)ctrl);
            lst.SelectedValueChanged += LogAction;
        }
        else if (ctrl is ButtonBase) { //ButtonBase stands for Buttons, CheckBoxes and RadioButtons.
            ButtonBase btn = ((ButtonBase)ctrl);
            btn.Click += LogAction;
        }
        else if (ctrl is DateTimePicker) {
            DateTimePicker dtp = ((DateTimePicker)ctrl);
            dtp.Enter += LogAction;
            dtp.ValueChanged += LogAction;
        }
        else if (ctrl is DataGridView) {
            DataGridView dgv = ((DataGridView)ctrl);
            dgv.RowEnter += LogAction;
            dgv.CellBeginEdit += LogAction; 
            dgv.CellEndEdit += LogAction;
        }
    }

    /// <summary>
    /// Releases the hooked up events (avoiding memory leaks).
    /// </summary>
    /// <param name="ctrl"></param>
    private void ReleaseEvents(Control ctrl)
    {
        if (ctrl is Form) {
            Form frm = ((Form)ctrl);
            frm.Load -= LogAction;
            frm.FormClosed -= LogAction;
            frm.ResizeBegin -= LogAction;
            frm.ResizeEnd -= LogAction;
        }
        else if (ctrl is TextBoxBase) {
            TextBoxBase txt = ((TextBoxBase)ctrl);
            txt.Enter -= LogAction;
        }
        else if (ctrl is ListControl) {
            ListControl lst = ((ListControl)ctrl);
            lst.SelectedValueChanged -= LogAction;
        }
        else if (ctrl is DateTimePicker) {
            DateTimePicker dtp = ((DateTimePicker)ctrl); 
            dtp.Enter -= LogAction;
            dtp.ValueChanged -= LogAction;
        }
        else if (ctrl is ButtonBase) {
            ButtonBase btn = ((ButtonBase)ctrl);
            btn.Click -= LogAction; 
        }
        else if (ctrl is DataGridView) {
            DataGridView dgv = ((DataGridView)ctrl);
            dgv.RowEnter -= LogAction;
            dgv.CellBeginEdit -= LogAction; 
            dgv.CellEndEdit -= LogAction;
        }
    }

    /// <summary>
    /// Log the Control that made the call and its value
    /// </summary>
    /// <param name="sender"></param>
    /// <param name="e"></param>
    public void LogAction(object sender, EventArgs e)
    {
        if (!(sender is Form || sender is ButtonBase || sender is DataGridView)) //Tailor this line to suit your needs
        {   //dont log control events if its a Maintenance Form and its not in Edit mode
            if (_frmType.BaseType.ToString().Contains("frmMaint")) {//This is strictly specific to my project - you will need to rewrite this line and possible the line above too. That's all though...
                PropertyInfo pi = _frmType.GetProperty("IsEditing");
                bool isEditing = (bool)pi.GetValue(_frm, null);
                if (!isEditing) return;
            }
        }
        StackTrace stackTrace = new StackTrace();      
        StackFrame[] stackFrames = stackTrace.GetFrames();
        var eventType = stackFrames[2].GetMethod().Name;//This depends usually its the 1st Frame but in this particular framework (CSLA) its 2
        ActionLog.LogAction(_frm.Name, ((Control)sender).Name, eventType, GetSendingCtrlValue(((Control)sender), eventType));
    }

    private string GetSendingCtrlValue(Control ctrl, string eventType)
    {
        if (ctrl is TextBoxBase) {
            return ((TextBoxBase)ctrl).Text;
        }
        //else if (ctrl is CheckBox || ctrl is RadioButton) {
        //  return  ((ButtonBase)ctrl).Text;
        //}
        else if (ctrl is ListControl) {
            return ((ListControl)ctrl).Text.ToString();
        }
        else if (ctrl is DateTimePicker) {
            return ((DateTimePicker)ctrl).Text;
        }
        else if (ctrl is DataGridView && eventType == "OnRowEnter")
        {
            if (((DataGridView)ctrl).SelectedRows.Count > 0) {
                return ((DataGridView)ctrl).SelectedRows[0].Cells[0].Value.ToString();
            }
            else {
                return string.Empty;
            }
        }
        else if (ctrl is DataGridView) {
            DataGridViewCell cell = (((DataGridView)ctrl).CurrentCell);
            if (cell == null) return string.Empty;
            if (cell.Value == null) return string.Empty;
            return cell.Value.ToString();
        }
        return string.Empty;
    }
}

ActionLog Class:

public static class ActionLog
{
    const string ACTIONLOGFILEIDENTIFIER = "ActionLog_"; 
    private static int _numberOfDaily = 0;
    private static int _maxNumerOfLogsInMemory = 512;
    private static List<string> _TheUserActions = new List<string>();
    private static string _actionLoggerDirectory = string.Empty;

    public static void LogActionSetUp(int maxNumerOfLogsInMemory = 512,string actionLoggerDirectory = "")
    {  
        if (string.IsNullOrEmpty(actionLoggerDirectory)) actionLoggerDirectory = Environment.GetFolderPath(Environment.SpecialFolder.UserProfile) + "\\Documents\\ProjectNameMgtFolder\\";
        if (!Directory.Exists(actionLoggerDirectory)) Directory.CreateDirectory(actionLoggerDirectory);

        _actionLoggerDirectory = actionLoggerDirectory;

        LogAction("MDI_Form", "APPLICATION", "STARTUP", string.Empty);
    }

    public static void LogAction(string frmName, string ctrlName, string eventName, string value)
    {
        if (value.Length > 10) value = value.Substring(0, 10);
        LogAction(DateTime.Now, frmName,ctrlName, eventName, value);
    }

    public static void LogAction(DateTime timeStamp, string frmName, string ctrlName, string eventName, string value)
    {
        _TheUserActions.Add(string.Format("{0}\t{1}\t{2}\t{3}\t{4}", timeStamp.ToShortTimeString(), frmName, ctrlName, eventName, value));
        if (_TheUserActions.Count > _maxNumerOfLogsInMemory) WriteLogActionsToFile();
    }

    public static string GetLogFileName()
    {
        //Check if the current file is > 1 MB and create another
        string[] existingFileList = System.IO.Directory.GetFiles(_actionLoggerDirectory, ACTIONLOGFILEIDENTIFIER +  DateTime.Now.ToString("yyyyMMdd") + "*.log");

        string filePath = _actionLoggerDirectory + ACTIONLOGFILEIDENTIFIER + DateTime.Now.ToString("yyyyMMdd") + "-0.log";
        if (existingFileList.Count() > 0)
        {
            filePath = _actionLoggerDirectory + ACTIONLOGFILEIDENTIFIER + DateTime.Now.ToString("yyyyMMdd") + "-" + (existingFileList.Count() - 1).ToString() + ".log";
            FileInfo fi = new FileInfo(filePath);
            if (fi.Length / 1024 > 1000) //Over a MB (ie > 1000 KBs)
            {
                filePath = _actionLoggerDirectory + ACTIONLOGFILEIDENTIFIER + DateTime.Now.ToString("yyyyMMdd") + "-" + existingFileList.Count().ToString() + ".log";
            }
        }
        return filePath;
    }

    public static string[] GetTodaysLogFileNames()
    {
        string[] existingFileList = System.IO.Directory.GetFiles(_actionLoggerDirectory, ACTIONLOGFILEIDENTIFIER + DateTime.Now.ToString("yyyyMMdd") + "*.log");
        return existingFileList;
    }

    public static void WriteLogActionsToFile()
    {
        string logFilePath = GetLogFileName();
        if (File.Exists(logFilePath)) {
            File.AppendAllLines(logFilePath,_TheUserActions);
        }
        else {
            File.WriteAllLines(logFilePath,_TheUserActions);
        }
        _TheUserActions = new List<string>();
    }
}

Note: The LogAction method will most likely fire 2nd (eg for a Button click, it will be invoked after the Button_Click event has been called). So while you may think you need to insert these LogAction events to fire first for example by reversing the event invocation order that is not good practice and is not required. The trick is in the stacktrace, the last call(s) in the stack will tell you the last user action. The Log of Actions tells you how to get the program in the state before the unhandled exception occurred. Once you get it to that point you need to follow the StackTrace to fault the application.

Putting it in action - for example a MDI Form Load event:

UserActionLog.ActionLog.LogActionSetUp();

In the MDI Forms Close event:

UserActionLog.ActionLog.WriteLogActionsToFile();

In a Child Form Constructor:

_logger = New UserActionLog.ActionLogger(this);

In a Child Form Closed Event:

_logger.ActionLoggerTierDown(this);

In the UIThreadException and CurrentDomain_UnhandledException events call WriteLogActionsToFile(); then attach the logs to the email sent to support with a screenshot...

---

Here's a quick example on how to get log files emailed to support:

string _errMsg = new System.Text.StringBuilder();
string _caseNumber = IO.Path.GetRandomFileName.Substring(0, 5).ToUpper();
string _errorType;
string _screenshotPath;
List<string> _emailAttachments = new List<string>();
string _userName;

private static void UIThreadException(object sender, ThreadExceptionEventArgs t)
{
 _errorType = "UI Thread Exception"

 ....

//HTML table containing the Exception details for the body of the support email
_errMsg.Append("<table><tr><td colSpan=1><b>User:</b></td><td colSpan=2>" & _userName & "</td></tr>");
_errMsg.Append("<tr><td><b>Time:</b></td><td>" & _errorDateTime.ToShortTimeString & "</td></tr><tr></tr>");
_errMsg.Append("<tr><td><b>Exception Type:</b></td><td>" & _errorType.ToString & "</td></tr><tr></tr>");

if (exception != null) {
    _errMsg.Append("<tr><td><b>Message:</b></td><td>" & exception.Message.Replace(" at ", " at <br>") & "</td></tr><tr></tr>");
    if (exception.InnerException != null) _errMsg.Append("<tr><td><b>Inner Exception:</b></td><td>" & exception.InnerException.Message & "</td></tr>");
    _errMsg.Append("<tr><td><b>Stacktrace:</b></td><td>" & exception.StackTrace & "</td></tr></table>");
}

....

//Write out the logs in memory to file
UserActionLog.ActionLog.WriteLogActionsToFile();

//Get list of today's log files
_emailAttachments.AddRange(UserActionLog.ActionLog.GetTodaysLogFileNames());

//Adding a screenshot of the broken window for support is a good touch
//https://mcmap.net/q/126540/-capture-screenshot-of-active-window
_emailAttachments.Add(_screenshotPath);

....


Email emailSystem = New Email(); //(using Microsoft.Exchange.WebServices.Data)
emailSystem.SendEmail(ConfigMgr.AppSettings.GetSetting("EmailSupport"),  "PROJECT_NAME - PROBLEM CASE ID: " & _caseNumber, _errMsg.ToString(), _emailAttachments.ToArray());

After the email is sent show users a window explaining a problem happened, with a nice picture... StackExchange websites have great example, this is my favorite: https://serverfault.com/error

Allier

+1 This is pretty cool, but I would probably throw away the ActionLog class and simply use a known logging library like log4net (or, wrap log4net inside ActionLog, whatever). It is highly configurable, performant, already does file rollover, and can log events to numerous different targets based on their type/level. – Flieger

Yeah, I agree. I'm thinking I'll put the code up as a GitHub/Codeplex or whatever community project and let others contribute their 2 cents. There are some things I need to clean up.... You wouldn't believe the trouble I had finding code online that does this User Activity Logging - I seriously could not find anything!! Everything I found was about AOP, Auto UI Testing Frameworks or 1/2 Gig memory dumps. – Allier

This is simple and very effective. I like it and think you should publish this, I'm personally combining it with elmah and pushing the logs to an aspnet server. – Merat

Hi @rolls thanks for your kind words, is it possible to email me the ASP.net version you made with Elmah? I will make the Logging an Interface to accept both log4net or Elmah. I think I'll spend this weekend putting it up on GitHub. [email protected] – Allier

The project is quite large so I'll do my best to extract it and reply back when done – Merat

It is two projects btw, an aspnet azure Web api coupled with a website and a desktop application. It might be a bit too much work to give you a working project however I could definitely email you snippets and the core classes if that is useful? I implemented my own basic http auth filter and a lot of other stuff to make the api work. – Merat

Yeah mate, it doesn't have to compile, just a few bits and bobs will do the trick, thanks heaps – Allier