In this article, I will explain how you can track class activities like function calls, parameters and return values by simply inheriting one class which I named "Spy". The "Spy" class encapsulates the tracking and logging relates the complexities . This class can be used for debugging function call sequence, state change of objects & parameters on the way of nested function calls and their return steps.
How it works?
The Spy class adds small spy properties at the time of object creation with each method to intercept their activity. As your class is inherited from Spy class, all methods of your class will also be logged in the same way. Now, the question is, "How Spy class do this!". The Spy class is inherited from ContextBoundObject and has a custom attribute called AttributeSpy. Although there are some performance issues for inheriting the ContextBoundObject but it gives the cool feature - a context bound with the object. A context carries the properties and rules of the object. The cool thing is that these properties travel with the object and can be accessed by sinks. Now, The attribute AttributeSpy does the important task. It checks if spy property is already added for any particular method otherwise adds that. Before going to detail, lets see the object initialization process first.
What happens when user creates an object?
When the user creates an instance of a new client-activated object by calling new or Activator.CreateInstance and before the thread returns to the user code, a IConstructionCallMessage is sent to the remote application. When the construction message arrives at the remote application, it is processed by a remoting activator (either the default one, or one that is specified in the Activator property) and a new object is created. The remoting application then returns a IConstructionReturnMessage to the local application. The IConstructionReturnMessage contains an instance of ObjRef, which packages information about the remote object. The remoting infrastructure converts the ObjRef instance into a proxy to the remote object, which is returned to the user code.
Now, briefly, here is the workflow for any class which inherits from Spy class:
The Spy class is just few lines. It has the custom attribute AttributeSpy with the name in parameter and it is inherited from ContextBoundObject.
[AttributeSpy("Spy")]
class Spy : ContextBoundObject
{
}
The AttributeSpy class is inherited from ContextAttribute and overrides the IsContextOK() method which checks whether our PropertySpy (I will explain it shortly) is in ContextProperties list. By returning false, another override method GetPropertiesForNewContext() is invoked, where we are adding the PropertySpy in ContextProperties list.
[AttributeUsage(AttributeTargets.Class)]
class AttributeSpy : ContextAttribute{
private string _name = string.Empty;
public AttributeSpy(string name)
: base(name)
{
_name = name;
}
public override void GetPropertiesForNewContext(System.Runtime.Remoting.Activation.IConstructionCallMessage ctorMsg)
{
ctorMsg.ContextProperties.Add(new PropertySpy(_name));
}
public override bool IsContextOK(Context ctx, System.Runtime.Remoting.Activation.IConstructionCallMessage ctorMsg)
{
PropertySpy spy = ctx.GetProperty(_name) as PropertySpy;
if (spy == null)
return false;
return true;
}
}
The PropertySpy class implements IContextProperty and IContributeObjectSink interface. The IContributeObjectSink interface is implemented to get the GetObjectSink() method which is called during the method invocation and the parameter nextSink ( type of IMessageSink) contains the detail information of method. Here we created our own MessageSinkSpy class inheriting from IMessageSink and added to the spying code in Synchronous and Asynchronous methods for SyncProcessMessage and AsyncProcessMessage and returned it GetObjectSink(). When any method gets invoked, these methods keep the logs in a text file.
class MessageSinkSpy : IMessageSink
{ ...
...
IMessageCtrl IMessageSink.AsyncProcessMessage(IMessage msg, IMessageSink replySink)
{
if (msg is IMethodCallMessage)
{
IMethodCallMessage callingMessage = msg as IMethodCallMessage;
LogHelper.LogMethodCall(callingMessage);
}
return _nextSync.AsyncProcessMessage(msg, replySink);
}
IMessage IMessageSink.SyncProcessMessage(IMessage msg)
{
IMethodCallMessage callingMessage = msg as IMethodCallMessage;
LogHelper.LogMethodCall(callingMessage);
IMethodReturnMessage returnMessage = _nextSync.SyncProcessMessage(msg) as IMethodReturnMessage;
LogHelper.LogMethodReturn(returnMessage);
return returnMessage;
} ...
...
}
Writing custom objects in log:
Writing simple primitive datatypes (int, char, bool...) is easy but writing custom objects in log in a meaningful way needs some extra work.
private static string GetObjectDetail(Object obj, string padding)
{
if (obj == null)
return "Object is NULL";
StringBuilder objDescription = new StringBuilder();
//Object type
objDescription.Append(padding);
objDescription.Append("(" + obj.GetType() + ")");
//Object detail
objDescription.Append(":");
if (IsPrimptiveDataType(obj))
{
//int, string, bool
objDescription.Append(" " + obj.ToString());
}
else if (IsArray(obj))
{
if (obj is Array)
//Array[]
foreach (object o in (Array)obj)
GetObjectDetail(o, padding + DEFAULT_PADDING);
else
//IList
foreach (object o in (IList)obj)
GetObjectDetail(o, padding + DEFAULT_PADDING);
}
else
{
// Collect object properties
PropertyInfo[] infos = obj.GetType().GetProperties();
// Log object details
foreach (PropertyInfo info in infos)
{
object value = info.GetValue(obj, (object[])null);
objDescription.Append(DEFAULT_PADDING + info.Name + GetObjectDetail(value, padding + DEFAULT_PADDING));
}
// New line
objDescription.Append(Environment.NewLine);
}
return objDescription.ToString();
}
To keep it simple, I used regular .net class - StreamWriter. But for any large size application you should use optimized logging application like log4net or EnterpriseLibrary - Logging Application Block.
Source code & sample project