User Activity Logging, Telemetry (and Variables in Global Exception Handlers)
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.
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://stackoverflow.com/a/1163770/495455
_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