Logging

This article describes "technical logging", i.e. logging intended as an aid in the development process, while code is being created and debugged by programmers. As such it would not be part of the product's requirements, as it is not concerned with "application-level logging" where mostly statistical information would be gathered about the application domain, nor "audit trailing" that may be required by some regulatory autorities.

In my view logging mainly means collecting single-line messages while a program runs, capturing what the program is doing, together with relevant data values, and whatever can be useful to verify the program is behaving as expected, but also to investigate things that go wrong occasionally.

Logging versus debugging

Modern debuggers are powerful tools; they support break points, single-stepping, watching intermediate values, etc., all at the spur of the moment. That turns out to be useful for solving problems, unfortunately it works best for rather simple problems, and less so for more complex situations, such as:

• concurrency, multi-threading and real-time problems: when interactions between threads, or specific timing sequences seem to fail, breakpoint and single-step techniques disrupt the timing behavior, and may completely hide any potential problem.
• intermittent problems: problems that occur only a couple of times a day; the probability of someone willing to spend the time and hitting the problem while inside the debugger, are slim.

Essential characteristics

Logging should be

• easy: each potential log line should require only a single statement.
• inexpensive: it does not make sense when it takes lots of computer resources to make it work.
• customizable: when looking for a specific problem, it should be easy to add or expand logging specifically tailored at the problem at hand.

Official solutions

There are a number of highly regarded log packages. I choose not to use them, as they are more expensive: they typically require more initialization, an additional DLL file, and more computer resources as they tend to implement a Swiss-knife approach, offering every feature anybody could dream of.

Writing your own will result in something lean-and-mean, that can easily be tailored to specific needs without the Swiss expense.

A simple example

A very simple example is given here:

class myClass {
	private static void log(string s) {
		Console.WriteLine(s);
	}
	
	public myClass() {
		log("myClass constructor begin");
		...
		for(int step=0; step<4; step++) {
			log("step = "+step);
			...
		}
		log("myClass constructor end");
	}
}

I tend to keep the log method static, as it should not rely on instance data, and having it available to static methods is a plus too.

A separate logging class

All classes should use the same log method; it makes perfect sense to have a separate static class holding the actual log method. On the other hand, we want to keep the log statement as simple as possible, so the recommended approach is this:

class LogClass {
	public static void Log(string s) {
		Console.WriteLine(s);
	}
}

class AnotherClass {
	protected static log(string s) {
		LogClass.Log("AnotherClass "+s);
	}
	
	public AnotherClass() {
		log("constructor begin");
		...
		log("constructor end");
	}
}

Having a local stub keeps the log statements simple; it also allows for an easy insertion of the class name in the log message; and it can be used to turn logging on or off for each class individually, e.g. by commenting the LogClass.Log() statement.

Logging more information

I consider it essential to include a time stamp. When using multiple threads, I also want to identify the active thread. It often results in this:

class LogClass {
	public static void Log(string s) {
		if (s.Length!=0) {
			int TID=Thread.GetCurrentThread().ManagedThreadId;
			s=DateTime.Now.ToString("HH:mm:ss.ff")+"  ["+TID.ToString("X2")+"]  "+s;
		}
		Console.WriteLine(s);
	}
}

If time stamps need millisecond accuracy, I combine DateTime.Now with a free-running Stopwatch to get the milliseconds right, as DateTime.Now itself only ticks once every 10 to 30 milliseconds (see my timers article for more on this).

Other and/or more logging channels

So far everything got logged towards a Console, which is either the Command Prompt window when running a Console application, or an explicitly created Console window when running a WinForms application.

It is often extremely useful to log to a file. I often want the file to be closed most of the time, which means each write operation basically consists of opening the file, appending one line, and closing it again. The reason I want this is because, when the application crashes, the last, i.e. most recent log lines are probably the most relevant ones. Hence, no buffering, and no open files. In other situations, when a lot of information is required, and a crash isn't going to happen, a scheme with a permanently open file may be preferred.

Logging to a file

Writing one line of text to a closed file is extremely easy; just add one line to the Log() method:

File.AppendAllText(logPath, s+Environment.NewLine);

where logPath is a static string in the LogClass, holding the path of the log file.

Suggestions:

• use a special folder to keep your log file(s);
• include time information in the log's filename, so you can easily keep a number of them;
• when creating a logfile, also consider including clean-up code that deletes your own stale log files; after all, you don't want your logging to cause a disk-full situation or an application crash.

Example:

class LogClass {
	private static string CompanyName="myCompany";
	private static string AppName="myApplication";
	private static string logPath;
	
	public static void Log(string s) {
		if (s.Length!=0) {
			int TID=Thread.GetCurrentThread().ManagedThreadId;
			s=DateTime.Now.ToString("HH:mm:ss.ff")+"  ["+TID.TiString("X2")+"]  "+s;
		}
		Console.WriteLine(s);
		if (logPath==null) CreateLogFile();
		File.AppendAllText(logPath, s+Environment.NewLine);
		AppendToListBox(s);   // see next chapter
	}
	
	private static void CreateLogFile() {
		string folder=Environment.GetFolderPath(Environment.SpecialFolder.ApplicationData)+@"\"+
			CompanyName+@"\"+AppName+@"\";
		Directory.CreateDirectory(folder);
		string[] oldLogs=File.GetFiles(folder, "log*.txt");
		foreach(string f in oldLogs) { // check age and try-delete if old }
		DateTime now=DateTime.Now;
		logPath=folder+"log_"+now.ToString("yyyyMMdd")+".txt";
		File.WriteAllText(logPath, "Started at "+now.ToString());
	}
}

Logging to a Form

The ideal Control for accepting log messages is the System.Windows.Forms.ListBox as it is line-oriented and does not suffer from degrading performance when thousands of messages get added.

As soon as multiple threads (or asynchronous handlers) are involved, one must take measures to get the ListBox accesses limited to the GUI thread (see this cross-thread article), as the code below does:

private void AppendToListBox(string s) {
	if (myListBox.InvokeRequired) {
		myListBox.Invoke(new Action<string>(AppendToListBox), new object[] {s} );
	} else {
		myListBox.Items.Add(s);
		if (Control.MouseButtons==0) myListBox.TopIndex=myListBox.Items.Count-1;
	}
}

The TopIndex statement implements a little feature where the ListBox scrolls up, unless you press a mouse button (maybe because you want to scroll manually in the very same ListBox). As scrolling eats CPU cycles, you may consider skipping it all together.

Time-related warning: I use Invoke rather than BeginInvoke, as this best preserves the chronology of the log messages; but even that will not be perfect, it is possible some messages get stalled in the input queue of the GUI thread. Also note that, in all code shown, the time stamp is added early on, so it, rather than the relative order of the log messages should be taken into account.

Conditional logging

Sometimes one does not want to obtain the output of all available log statements, and some build-time or even run-time control over the logging is wanted. Build-time control could be as easy as commenting/ uncommenting a line in the local log() method of the relevant classes.

Run-time control could be quite elaborate. My largest applications offer a control panel, where different categories can be enabled and disabled while the application is running.

One rather easy scheme for run-time control involves assigning each log statement to a particular category, and passing the category as a parameter or use separate methods. Here is an example:

class AnotherClass {
	protected static error(string s) {
		if (logErrror) LogClass.Log("error: AnotherClass "+s);
	}
	
	protected static info(string s) {
		if (logInfo) LogClass.Log("info: AnotherClass "+s);
	}
	
	public AnotherClass() {
		info("constructor begin");
		...
		info("constructor end");
	}
}

Whatever scheme you implement, I strongly advise against ever removing a log statement: if you don't want it, make it disappear from the program flow (using a comment, or an if statement), but don't throw away the result of earlier efforts, instead keep it around until you want it again.

Logging variable data

When logging statements become more complex and a lot of them will not execute because of log conditions, a lot of string manipulations tend to become useless. If so, one could consider implementing a number of log methods, each taking a different number of parameters, that only get merged into the final log message once it has been established the log will pass the log conditions.

Example:

class AnotherClass {
	protected static log(string s, int arg0, int arg1, int arg2) {
		if (logCondition) {
			s=string.Format(s, arg0, arg1, arg2);
			LogClass.Log("AnotherClass "+s);
		}
	}
		
	public AnotherClass() {
		log("constructor minimum={0} maximum={1} value={2}", min, max, val);
		...
	}
}

Read more

The Art of Logging, an excellent article by Colin Eberhardt, is available on CodeProject.

Conclusion

There is no limit to what one can include in a logging mechanism. The advantage of doing it yourself is, it only takes a small amount of code and can easily be tailored for a good balance between functionality and performance.

History

• Version 1.0 (03-Jun-2010): Original version
• Version 1.1 (07-Jun-2016): Added a link to a Colin Eberhardt article