Use status events to log and analyze an application
Applications can get quite complex, with multiple components, assemblies, subsystems, etc. Understanding this complexity can be daunting.
An old but still very effective way of analyzing code is to modify the code to output a string whenever that section of code gets executed.
Remember the old Printf() from old C/C++ programs?
Perhaps that code could be #IFDEF’d out, or use the [Conditional("Debug")] attribute. Both of these require that the code be recompiled.
Sprinkling your application with code that outputs status that can be gated at runtime without recompilation can be very effective means of understanding how it works, and perhaps more importantly, how it fails. You could for example turn on logging remotely at a client’s location to diagnose a failure. Because it’s gated, the impact on application performance can be minimal.
Debugging a complex app can be very difficult: often code or variables are optimized away, the debug scenario may be extremely large (maybe it takes a long time to execute the prerequisites to the issue), the debugging must be available (imagine an app on a customer’s Phone)
The sample below includes a class called MyStatusEventClass that contains some methods and defines an event MyStatusEventClass.
Imagine the code being in a very large application with multiple components. The class is globally accessible, so multiple components can call MyStatusEventClass.UpdateStatus passing in a string and perhaps some parameters, indicating that particular code was being executed.
Some (0 or more) of the components can subscribe to the event, and do whatever they like. For example, a unit test assembly might listen to the output. A file logger could write to a file. A Windows Event can be raised as well (from managed code, see https://msdn.microsoft.com/en-us/library/system.diagnostics.eventlog.aspx)
In the sample below we just have a subscriber writing output to a TextBox.
There are multiple event sources: one is a timer that fires periodically on the main thread. Then there are multiple threads used to fire events.
The event hander can be called from multiple threads, so it needs to update the textbox UI on the UI thread, using the Textbox’s Dispatcher.
The btnClose event adds a status event, waits 2 seconds, then closes the form. Because the wait is a sleep, which doesn’t process messages, the last event doesn’t get put in the UI. So we synchronously invoke a do nothing task of low priority so the render messages get processed.
Start VS, File->New->Project->Windows->WPF Application. Replace MainWindow.Xaml.cs with the code below. You might need to adjust the namespace.
Hit F5 to run the code.
See also Create a logger for watching your test progress as it runs.
<code>
using System;
using System.Diagnostics;
using System.Threading;
using System.Windows;
using System.Windows.Controls;
using System.Windows.Media;
using System.Windows.Threading;
namespace WpfApplication1
{
/// <summary>
/// Interaction logic for MainWindow.xaml
/// </summary>
public partial class MainWindow : Window
{
Button _btnClose;
bool _closing = false;
TextBox _txtboxStatus;
public MainWindow()
{
InitializeComponent();
this.Height = 600;
this.Loaded += (o, e) =>
{
try
{
MyStatusEventClass.UpdateStatus(
@"This won't be logged:
there are no subscribers yet");
var sp = new StackPanel()
{
Orientation =
System.Windows.Controls.Orientation.Vertical
};
sp.Children.Add(
new TextBlock()
{
Text = "Your very complex application's UI",
Height = 40,
});
_btnClose = new Button()
{
Content = "_Quit",
Width = 200,
HorizontalAlignment =
System.Windows.HorizontalAlignment.Left
};
_btnClose.Click += btnClose_Click;
sp.Children.Add(_btnClose);
_txtboxStatus = new TextBox()
{
MaxLines = 20,
Background = Brushes.AliceBlue,
AcceptsReturn = true,
AcceptsTab = true,
IsReadOnly = true,
VerticalScrollBarVisibility = ScrollBarVisibility.Auto,
Text = "InitialText\r\n"
};
sp.Children.Add(_txtboxStatus);
this.Content = sp;
//some component, perhaps in a different assembly
// subscribes to the event
// and shows the status by updating the textbox
// there can be multiple subscribers, perhaps one
// to update the UI, another to write to a log file
// or yet another being a unit test
MyStatusEventClass.MyStatusEvent += MyStatusEventHandler;
// now we need a source of events
// sprinkle your code with calls like this:
MyStatusEventClass.UpdateStatus("Initial status");
// For sample event sources,
// lets use a timer that fires very N msecs.
var tmr = new DispatcherTimer()
{
Interval = TimeSpan.FromMilliseconds(200),
};
var cntTicks = 0;
tmr.Tick += (oTmr, eTmr) =>
{ // when the timer Ticks:
MyStatusEventClass.UpdateStatus(
"Timer tick {0}",
cntTicks++
);
};
tmr.Start();
// now create multiple threads that
// will update status
for (int i = 0; i < 8; i++)
{
ThreadPool.QueueUserWorkItem((oThread) =>
{// this code executes on a different thread
while (!_closing)
{
MyStatusEventClass.UpdateStatus("From diff thread");
Thread.Sleep(1000);
}
});
}
}
catch (Exception ex)
{
this.Content = ex.ToString();
}
};
}
//this event handler (subscriber)
// can be in a totally different
// assembly/component from the event raiser.
void MyStatusEventHandler(
object o,
MyStatusEventArgs ee)
{ // the subscriber can optionally, perhaps
// based on a config setting, output or
// log data. There can be levels of Verbosity
if (ee.MsgType == MyStatusEventType.Log)
{
// get the method name of the caller
// (in this sample, this is not very interesting, but
// a more complicatd app it could be very useful)
// GetFrame(0) is the current method,
// so we go up a couple frames
var stk = new StackTrace();
var methName1 = stk.GetFrame(3).GetMethod().Name;
var methName2 = stk.GetFrame(4).GetMethod().Name;
var msg = String.Format(
"{0:T} TID={1} '{2}/{3}' {4}", //like "11:52:37 PM"
ee.MsgTimeStamp,
Thread.CurrentThread.ManagedThreadId,
methName1,
methName2,
ee.Message);
// because this subscriber can be called from multiple
// threads, we ask the dispatcher of the txtbox to
// update the txtbox on the UI thread
_txtboxStatus.Dispatcher.
BeginInvoke(new Action<string>((p1) =>
{
_txtboxStatus.Text += p1 + "\r\n";
_txtboxStatus.ScrollToEnd();
}), msg);
}
}
void btnClose_Click(object o, EventArgs e)
{
MyStatusEventClass.UpdateStatus("Closing!!");
//if we do a Thead.Sleep, then the
//textbox won't render the last message
// try commenting out this Dispatcher call
// to see what happens
// we need to let the dispatcher synchronously
// update the UI by processing pending
// render messages by synchronously calling a
// low priority do nothing task
this.Dispatcher.Invoke(
DispatcherPriority.Background,
(Action)(() => { }));
_closing = true;
Thread.Sleep(2000); // so we can see the last msg
this.Close(); // end the program
}
}
/// <summary>
/// this class is accessible globally from
/// throughout a complex application and
/// has an event that gets raised
/// whenever anybody calls UpdateStatus
/// </summary>
public static class MyStatusEventClass
{
// declare an event that takes "MyStatusEventArgs"
public static event
EventHandler<MyStatusEventArgs> MyStatusEvent;
// allow user to pass in optional parms,
// and we'll call string.Format
public static void UpdateStatus(
string msg,
params object[] args
)
{
UpdateStatus(MyStatusEventType.Log, msg, args);
}
public static void UpdateStatus(
MyStatusEventType msgType,
string msg,
params object[] args)
{
var eventarg = new MyStatusEventArgs()
{
Message = string.Format(msg, args),
MsgType = msgType
};
if (MyStatusEvent != null)
{
MyStatusEvent.Invoke(null, eventarg);
}
}
}
public class MyStatusEventArgs : EventArgs
{
public MyStatusEventArgs()
{
MsgTimeStamp = DateTime.Now;
}
public string Message;
public MyStatusEventType MsgType;
public DateTime MsgTimeStamp;
public override string ToString()
{
return Message;
}
}
// some of these flags might be
// combined: use [Flags]
public enum MyStatusEventType
{
ShowMessageBox,
DebugMessage,
Warning,
Error,
StatusBarEntry,
Log
}
}
</code>