Introduction
Logging progresses/problems/states be a valuable part of software development for evaluating, testing and trouble-shooting purposes, this simple utility could bring quite some convenience to your coding by:
- Logging different messages of different levels without typing too much, just like Log.e, Log.w, Log.i, Log.d and Log.v for ERROR, WARN, INFO, DEBUG and VERBOSE familiar by JAVA deveopers.
- Writing these Log statements in the source codes once during your development, and extract different logs of any levels by simply adjusting the setting of the loggers.
- Generating styled messages automatically to distinguish between messages of different levels.
- Making multiple loggers working simultaneously.
- Keeping timestamps to evaluate the during of execution and multiple queues to calculate the intervals of any operations.
Background
This tools was originally developed to guage the performance of some intensive calculation by using one Stopwatch to tag timestamps to any operations identified by different strings.
Without typing boilerplate codes like Debug.WriteLine() or CW(Console.WriteLine), then commenting/un-commenting them out afterwards, with forms of Log.x(e/w/i/d/v, similar to android developers) to tag messages with different log levels and fully customizable behaviours, this small tools saved me a lot of typing. To make this tools more handy, the same line of logging triggering multiple loggers to work independently and this goal is not hard to achieve thanks to the mechanism behind of Events. Finally, as originally intended, with a single StopWatch, some lists identified by strings could be used to record time/interval information that would otherwise means quite some redundant codes.
This article tries to explain how to use this tools, and also explains some techniques used to implement these desirable functions.
General Infomation
There are only 3 files included in the toolkit library: LogLevel.cs, ILog.cs and Log.cs.
Just to follow the conventions in JAVA world, the ENUM LogLevel is defined as below:
[Flags]
public enum LogLevel
{
NONE = 0,
VERBOSE = 1,
DEBUG = 2,
INFO = 4,
WARN = 8,
ERROR = 16,
WARN_AND_ABOVE = WARN | ERROR,
INFO_AND_ABOVE = INFO | WARN_AND_ABOVE,
DEBUG_AND_ABOVE = DEBUG | INFO_AND_ABOVE,
ALL = VERBOSE | DEBUG_AND_ABOVE
}
Each logger has such a property ConcernedLogs to decide which levels of messages shall be logged: choosing predefined combinations of ALL/XXX_AND_ABOVE would achieve the effect of keeping only messages above a specific level. However, it is also possible to log only messages of specific levels. For example, by specifying ConcernedLogs as VERBOSE|ERROR, messages of DEBUG/INFO/WARN would be screened out.
The interface of ILog defines expected behaviors of the implementation as below:
public interface ILog
{
PerformLogging DoLogging { get; }
LogLevel ConcernedLogs { get; set; }
Func<LogLevel, string> BuildTag { get; }
Func<Exception, StackTrace, string> BuildStacktrace { get; }
Func<string, string, string> BuildFinalMessage { get; }
void v(string details);
void d(string details);
void i(string details);
void w(string details);
void e(string details);
void v(string tag, string details);
void d(string tag, string details);
void i(string tag, string details);
void w(string tag, string details);
void e(string tag, string details);
void e(Exception exception, LogLevel? stacktraceLevel = null);
}
The PerformLogging is actually an delegate defined below, it is a function delegate and also an Event Handler:
public delegate void PerformLogging(LogLevel logLevel, string message);
Unlike conventional ways depending on variables, function delegates are used to define the behaviours of the loggers. This is always my favorite to get maximum extends of flexibilities and details implementations would be covered later.
There are 3 sets of methods defined for each logger:
- logging functions with a single argument details: the details would be classified as some LogLevel (v(something) would be marked with VERBOSE, i(...) would be INFO, d()/w()/e() for DEBUG/WARN/ERROR respectively), then based on the ConcernedLogs, the delegates DoLogging, BuildTag and BuildFinalMessage would create tags and final output messages of correspondent LogLevel with some default template. Thus v("some message") would show differently from d("some message").
- For those who prefer defining some meaningful tags by themselves, the second set methods (such as void d(string tag, string details)) with two string arguments could be chosen.
- Exception might contain some information most useful for a developer and worth special treatment.With e(Exception exception, LogLevel? stacktraceLevel=null), the stacktrace of the exception would be converted to a string by Func<Exception, StackTrace, string> BuildStacktrace, and be saved as stacktraceLavel if it is not null.
These functions could be associated with instances only because the limitation of interface. Actaully, static methods with capital-formed names would unleash the power of this tools:
- V(string details), D(), I(), W() and E() would trigger v()/d()/i()/w()/e() of all loggers respectively.
- V(string format, params object[] args), D(...), I(...), W(...) and E(...) would have no intance counterparts, they are equal to V(string.Format(string format, params object[] args))... This might be confusing if you expect a static version of void d(string tag, string details), because that would introduce some conflictions and personally I believe incorporating string.Format() could be more helpful.
- static void E(Exception ex, LogLevel? stackTraceLevel = LogLevel.INFO) would trigger all loggers to log the exception with stacktrace with source codes output when stackTraceLevel is not null.
Implementations
Define a Log instance with delegates
Instead of keeping many descriptive information, for efficiency consideration, sometime I would keep behaviours directly as properties. In the Log.cs, the instance fields/properties are defined as below:
#region Properties and Hooks
public LogLevel ConcernedLogs { get; set; }
public PerformLogging DoLogging { get; protected set; }
public Func<LogLevel, string> BuildTag { get; protected set; }
public Func<string, string, string> BuildFinalMessage { get; protected set; }
public Func<Exception, StackTrace, string> BuildStacktrace { get; protected set; }
public string Descripiton { get; set; }
#endregion
The ConcernedLogs, as explained, is used as a filter on the level of a message by the unique execution method:
protected virtual void log(LogLevel logLevel, string details)
{
if (DoLogging != null && (logLevel & ConcernedLogs) != 0)
{
string tag = BuildTag(logLevel);
switch(logLevel)
{
case LogLevel.VERBOSE:
v(tag, details);
break;
case LogLevel.DEBUG:
d(tag, details);
break;
case LogLevel.INFO:
i(tag, details);
break;
case LogLevel.WARN:
w(tag, details);
break;
case LogLevel.ERROR:
e(tag, details);
break;
default:
throw new NotImplementedException();
}
}
}
v(tag, details) would simply stamp VERBOSE as LogLevel of the message composed by tag and details as below, so do d()...e():
public virtual void v(string tag, string details)
{
DoLogging(LogLevel.VERBOSE, BuildFinalMessage(tag, details));
}
Thus the three function delegates, BuildTag/BuildFinalMessage/DoLogging, define how tags are created, then attached with the details as final message before being saved/output respectively.
For Func<LogLevel, string> BuildTag, given a specific LogLevel, it would compose a string as Tag to mark the details with some special format. Some pre-defined static functions (FormattedTag, NoTag, ShortTag & FullTag) could be referred directly, ShortTag(LogLevel logLevel) would return "[V]"/"[D]"..."[E]" respectively for different LogLevel, while FormattedTag(LogLevel logLevel):
public static string FormattedTag(LogLevel logLevel)
{
switch (logLevel)
{
case LogLevel.VERBOSE:
case LogLevel.DEBUG:
return string.Format("{0}[{1}]", SpaceBeforeTag, logLevel.ToString().First());
case LogLevel.INFO:
return string.Format("[I:{0}]", ElapsedTimeString());
case LogLevel.WARN:
return string.Format("*[W:{0}]", ElapsedTimeString());
case LogLevel.ERROR:
return string.Format("***[ERROR:{0}@{1}]", ElapsedTimeString(), DateTime.Now.ToString("HH:mm:ss"));
default:
throw new NotImplementedException();
}
}
would show different messages with different leadings to enable locating messages of, for example ERRORs, quickly: you just need to see where are logs started with "***[ERROR:...".
For Func<string, string, string> BuildFinalMessage { get; protected set; }, it just provide a flexible way to compose tag and details together as the final message. The default implementation is shown below:
public static Func<string, string, string> DefaultFinalMessage =
(tag, details) => string.Format("{0}{1}{2}", tag, TagMessageConnector, details);
You can provide much richer features to include extra information like time/source/item# as you wish.
For PerformLogging DoLogging { get; protected set; }, its signature comes from below and hints it as an Event Handler:
public delegate void PerformLogging(LogLevel logLevel, string message);
Notice: the message can be regarded as Tag + Details.
It could be implemented as simple as the default one:
public static PerformLogging DefaultDoLogging = (level, msg) => Console.WriteLine(msg);
Or could be associated with a StringBuffer as the test sample following shows, or output in reverse order to a filestream with full access control and exception handling that cannot be described.
To put them together, with only LogLevel and DoLogging as mandatory arguments, a Log instance could be defined with this constructor:
public Log(LogLevel concernedLogs, PerformLogging doLogging,
Func<LogLevel, string> buildTag=null
, Func<Exception, StackTrace, string> buildStacktrace = null
, Func<string, string, string> buildMessage = null)
{
if (doLogging == null)
throw new ArgumentNullException("Logging means must be specified!");
this.ConcernedLogs = concernedLogs;
this.DoLogging = doLogging;
this.BuildTag = buildTag ?? DefaultTag;
this.BuildFinalMessage = buildMessage??DefaultFinalMessage;
this.BuildStacktrace = buildStacktrace??DefaultStacktrace;
this.Descripiton = description ?? string.Format("Log{0}", this.GetHashCode());
OnLoggingEvent += this.log;
OnExceptionEvent += this.logException;
}
Then the Log instance would have a quite sound set of behaviours to handle different messages. However, creating and referring these instances could hardly bring noticeable convenience to log messages, calling static methods to trigger logging of all created Log instances is my desirable approach, and its implementation is based on Event mechanism.
Event based logging
According to Microsoft Events Tutorial: Events provide a generally useful way for objects to signal state changes that may be useful to clients of that object. Events are an important building block for creating classes that can be reused in a large number of different programs.
The event to trigger message logging is defined as static one as below:
private static event PerformLogging onLoggingEvent;
public static event PerformLogging OnLoggingEvent
{
add
{
lock (DefaultDoLogging)
{
if (onLoggingEvent == null || !onLoggingEvent.GetInvocationList().Contains(value))
{
onLoggingEvent += value;
}
}
}
remove
{
lock (DefaultDoLogging)
{
if (value != null && onLoggingEvent != null && onLoggingEvent.GetInvocationList().Contains(value))
{
onLoggingEvent -= value;
}
}
}
}
The event can only be raised by calling either of the two private raiseEvent() methods:
private static void raiseEvent(LogLevel level, string details)
{
try
{
if (onLoggingEvent != null)
onLoggingEvent(level, details);
}
catch (Exception ex)
{
try
{
Instance.e(ex, LogLevel.INFO);
}
catch { }
}
}
private static void raiseEvent(LogLevel level, string format, params object[] args)
{
try
{
if (format == null)
throw new ArgumentNullException("format cannot be null!");
if (onLoggingEvent != null)
{
string details = string.Format(format, args);
onLoggingEvent(level, details);
}
}
catch (Exception ex)
{
try
{
Instance.e(ex, LogLevel.INFO);
}
catch { }
}
}
And they are called only by the capital named static methods, to log VERBOSE messages for example:
public static void V(string details)
{
raiseEvent(LogLevel.VERBOSE, details);
}
public static void V(string format, params object[] args)
{
raiseEvent(LogLevel.VERBOSE, format, args);
}
Because the constructor of the Log instance hook the this.log up to the static events:
OnLoggingEvent += this.log;
OnExceptionEvent += this.logException;
Using "Log.V(...)" or "Log.D(...)" would trigger the OnLoggingEvent and all registered log would then call the relavent "this.v()" and "this.d()" respectively. As a result, it is fully possible to define multiple Log instances and calling these static methods would make them working as if their instance methods are called recursively. When logging is no longer needed, just un-register the event handlers would leave the source codes untouched. (Although I have included codes to unhook these events when Log instance is disposed, there is no tests to validate that).
For example, define an extended Log class like this:
public class MemLog : Log
{
StringBuilder sb = new StringBuilder();
public MemLog(LogLevel minLogLevel,
Func<LogLevel, string> buildTag = null
, Func<Exception, StackTrace, string> buildStacktrace = null
, Func<string, string, string> buildMessage = null)
{
this.ConcernedLogs = minLogLevel;
this.DoLogging = (level, msg) => sb.Insert(0, msg + "\r\n");
this.BuildTag = buildTag ?? DefaultTag;
this.BuildFinalMessage = buildMessage ?? DefaultFinalMessage;
this.BuildStacktrace = buildStacktrace;
OnLoggingEvent += this.log;
OnExceptionEvent += this.logException;
}
public string GetLog()
{
return sb.ToString();
}
}
A simple test method:
[TestMethod]
public void TestMethod3()
{
Log.I("Change the DefaultLogLevel to " + Log.ChangeDefaultLogLevel(LogLevel.ALL));
var memLog = new MemLog(LogLevel.VERBOSE | LogLevel.WARN,
Log.FullTag,
Log.DebuggableStacktrace
);
t1(3);
Console.WriteLine("\r\n------------------------------------------");
Console.WriteLine("MemLog shows:");
Console.WriteLine(memLog.GetLog());
}
Would get output like this:
Result StandardOutput:
[I:038ms]: Change the DefaultLogLevel to DEBUG_AND_ABOVE
[D]: t1
[I:039ms]: v=3
[V]: verbose from t3
***[ERROR:039ms@23:07:10]: To throw Exception in t3
***[ERROR:040ms@23:07:10]: Exception of type 'System.Exception' was thrown.
*[W:040ms]: StackTrace
t3: d:\Trial\EasyLogger\EasyLoggerTest\UnitTest1.cs, line 55
t2: d:\Trial\EasyLogger\EasyLoggerTest\UnitTest1.cs, line 45
t1: d:\Trial\EasyLogger\EasyLoggerTest\UnitTest1.cs, line 34
TestMethod3: d:\Trial\EasyLogger\EasyLoggerTest\UnitTest1.cs, line 110
[V]: t1 done!
------------------------------------------
MemLog shows:
[VERBOSE]: t1 done!
[WARN]: StackTrace
t3: d:\Trial\EasyLogger\EasyLoggerTest\UnitTest1.cs, line 55
t2: d:\Trial\EasyLogger\EasyLoggerTest\UnitTest1.cs, line 45
t1: d:\Trial\EasyLogger\EasyLoggerTest\UnitTest1.cs, line 34
TestMethod3: d:\Trial\EasyLogger\EasyLoggerTest\UnitTest1.cs, line 110
[VERBOSE]: verbose from t3
The Memlog would keep only VERBOSE and WARN messages in reversed order of the default Log.
Logging of Exceptions
Exceptions could be the most valuable source to trouble-shooting problems, thus in addition to log messages as ERROR level with Log.E() or somelog.e(), the ILog interface declares a method to handle Exception:
public virtual void e(Exception exception, LogLevel? stacktraceLevel = null)
{
logException(exception, new StackTrace(true), stacktraceLevel);
}
Similar to this.log(), the logException() method would do some pre-processing before calling log():
protected virtual void logException(Exception exception, StackTrace stacktrace, LogLevel? stacktraceLevel = null)
{
if(exception == null || DoLogging == null)
return;
log(LogLevel.ERROR, exception.Message);
if (!stacktraceLevel.HasValue || BuildStacktrace == null)
return;
LogLevel level = stacktraceLevel.Value;
if ((level & ConcernedLogs) == 0)
return;
string stacktraceString = BuildStacktrace(exception, stacktrace);
log(level, "StackTrace\r\n" + stacktraceString);
}
The Func<Exception, StackTrace, string> BuildStacktrace { get; protected set; } means to extract Stacktrace information from the Exception being thrown, the given Stacktrace as a string to be output as LogLevel specified by stacktraceLevel. Uncomfortable with the Microsoft default stacktrace information that might invloves dozens of calling to underlying library, the following method would be used as default to logging only debuggable codes as the output of previous example demonstrated.
public static string DebuggableStacktrace(Exception exception, StackTrace stacktrace)
{
if (stacktrace == null)
throw new ArgumentNullException();
StringBuilder sb = new StringBuilder();
StackFrame[] frames = stacktrace.GetFrames();
int i = 0;
foreach(StackFrame frame in frames)
{
string fileName = frame.GetFileName();
if (fileName == logClassFilename)
continue;
int lineNumber = frame.GetFileLineNumber();
if(lineNumber > 0)
{
sb.AppendFormat("{0}{1}: {2}, line {3}\r\n", new string(' ', (++i)*2), frame.GetMethod().Name, fileName, lineNumber);
}
}
return sb.ToString();
}
The logClassFilename is used to keep the filename of the Log class in the static constructor:
protected static string logClassFilename = null;
static Log()
{
RestartStopwatch();
StackTrace stackTrace = new StackTrace(true);
StackFrame thisFrame = stackTrace.GetFrame(0);
logClassFilename = thisFrame.GetFileName();
}
To support Event based Exception logging, a similar set of delegate, event and static method are defined as below:
public delegate void PeformExceptionLogging(Exception exception, StackTrace stacktrace, LogLevel? stacktraceLevel = null);
private static event PeformExceptionLogging onExceptionEvent;
public static event PeformExceptionLogging OnExceptionEvent {add{...} remove{...}}
private static void raiseEvent(Exception exception, StackTrace stacktrace, LogLevel? stacktraceLevel = null)
{
try
{
if (onExceptionEvent != null)
{
onExceptionEvent(exception, stacktrace, stacktraceLevel);
}
}
catch (Exception ex)
{
try
{
Instance.e(ex, LogLevel.INFO);
}
catch { }
}
}
public static void E(Exception ex, LogLevel? stackTraceLevel = LogLevel.INFO)
{
raiseEvent(ex, new StackTrace(true), stackTraceLevel);
}
Stopwatch for Everything
As mentioned earlier, this tools was developed to keep and measure time elaspsed when I tried to use a single Stopwatch instance to masure multiple operations by keeping the ticks into a list of longs referred by a string key.
private static Stopwatch stopwatch = new Stopwatch();
protected static long createMoment = DateTime.Now.Ticks;
protected static Dictionary<string, List<long>> MomentsRepository = new Dictionary<string, List<long>>();
public static ICollection<string> GetMomentIds()
{
return MomentsRepository.Keys;
}
public static int MarkMoment(string momentId = null)
{
if (momentId == null)
{
StackTrace stacktrace = new StackTrace(true);
StackFrame callerFrame = stacktrace.GetFrames().FirstOrDefault(frame =>
frame.GetFileName() != logClassFilename && frame.GetFileLineNumber() != 0);
momentId = callerFrame == null ? "Unknown"
: string.Format("{0}: {1}_L{2}", callerFrame.GetFileName(), callerFrame.GetMethod().Name, callerFrame.GetFileLineNumber());
}
if (!MomentsRepository.ContainsKey(momentId))
{
MomentsRepository.Add(momentId, new List<long>());
}
long ticks = DateTime.Now.Ticks;
List<long> moments = MomentsRepository[momentId];
moments.Add(ticks);
return moments.Count;
}
Then it is convenient to get the logged moment and the elapsed time between these moments as below:
public static long[] GetMoments(string momentId, IEnumerable<int> indexes=null)
{
if (momentId == null)
throw new ArgumentNullException("momentId cannot be null to retrieve the concerned moments.");
if (!MomentsRepository.ContainsKey(momentId))
return new long[0];
if (indexes == null)
return MomentsRepository[momentId].ToArray();
var moments = MomentsRepository[momentId];
List<int> qualifiedIndexes = indexes.Where(i => i >= 0 && i < moments.Count).ToList();
var result = qualifiedIndexes.Select(i => moments[i]).ToArray();
return result;
}
public static long[] GetIntervals(string momentId, IEnumerable<int> indexes=null)
{
if (momentId == null)
throw new ArgumentNullException("momentId cannot be null to retrieve the concerned moments.");
if (!MomentsRepository.ContainsKey(momentId))
return new long[0];
var moments = MomentsRepository[momentId];
if (indexes == null)
{
var intervals = moments.Skip(1).Select((v, index) => v - moments[index-1]).ToArray();
return intervals;
}
List<int> qualifiedIndexes = indexes.Where(i => i > 0 && i < moments.Count).ToList();
long[] selectedIntervals = qualifiedIndexes.Select(i => moments[i] - moments[i-1]).ToArray();
return selectedIntervals;
}
Alternatively, logging the entry and exit moments as two lists with two string keys might be easier for post-processing.
Using the code
There is a test project attached with the source codes to show how to use this tools.
For example, the MemLog.cs shows an extension of the Log class as below:
public class MemLog : Log
{
StringBuilder sb = new StringBuilder();
public MemLog(LogLevel minLogLevel,
Func<LogLevel, string> buildTag = null
, Func<Exception, StackTrace, string> buildStacktrace = null
, Func<string, string, string> buildMessage = null)
{
this.ConcernedLogs = minLogLevel;
this.DoLogging = (level, msg) => sb.Insert(0, msg + "\r\n");
this.BuildTag = buildTag ?? DefaultTag;
this.BuildFinalMessage = buildMessage ?? DefaultFinalMessage;
this.BuildStacktrace = buildStacktrace;
OnLoggingEvent += this.log;
OnExceptionEvent += this.logException;
}
public string GetLog()
{
return sb.ToString();
}
}
Then the test method declare one instance and all calling to the static methods of Log.cs would leave VERBOSE and WARN messages in the StringBuild in reversed order:
[TestMethod]
public void TestMethod3()
{
Log.I("Change the DefaultLogLevel to " + Log.ChangeDefaultLogLevel(LogLevel.ALL));
var memLog = new MemLog(LogLevel.VERBOSE | LogLevel.WARN,
Log.FullTag,
Log.DebuggableStacktrace
);
t1(3);
Console.WriteLine("\r\n------------------------------------------");
Console.WriteLine("MemLog shows:");
Console.WriteLine(memLog.GetLog());
}
And the output of the test would be:
Test Name: TestMethod3
Test Outcome: Passed
Result StandardOutput:
[I:000ms]: Restart stopwatch at 12/14/2015 11:59:08 PM, with time elapsed of 000ms
[I:006ms]: Change the DefaultLogLevel to DEBUG_AND_ABOVE
[D]: t1
[I:007ms]: v=3
[V]: verbose from t3
***[ERROR:008ms@23:59:08]: To throw Exception in t3
***[ERROR:009ms@23:59:08]: Exception of type 'System.Exception' was thrown.
*[W:009ms]: StackTrace
t3: d:\Trial\EasyLogger\EasyLoggerTest\UnitTest1.cs, line 55
t2: d:\Trial\EasyLogger\EasyLoggerTest\UnitTest1.cs, line 45
t1: d:\Trial\EasyLogger\EasyLoggerTest\UnitTest1.cs, line 34
TestMethod3: d:\Trial\EasyLogger\EasyLoggerTest\UnitTest1.cs, line 110
[V]: t1 done!
------------------------------------------
MemLog shows:
[VERBOSE]: t1 done!
[WARN]: StackTrace
t3: d:\Trial\EasyLogger\EasyLoggerTest\UnitTest1.cs, line 55
t2: d:\Trial\EasyLogger\EasyLoggerTest\UnitTest1.cs, line 45
t1: d:\Trial\EasyLogger\EasyLoggerTest\UnitTest1.cs, line 34
TestMethod3: d:\Trial\EasyLogger\EasyLoggerTest\UnitTest1.cs, line 110
[VERBOSE]: verbose from t3
It is easy to see how convenient it could be to log messages in another form without much modification on the source codes.
The latest source codes, if there is any update, could also be found from https://github.com/Cruisoring/EasyLog/tree/master/EasyLogger.
History
15/12/2015: First release.
