Integrating System.Diagnostics: Logging

When debugging, before using an actual debugger, many programmers, myself included, use a method called printf debugging, after the function in the C standard library: You just print out a label identifying where in the program currently we currently are and possibly some of the program state.

When you do that professionally, it's called logging, and it is incredibly useful to determine which portion of your code probably contains the bug. Logging also implies that you do it more systematically, for instance by printing to a file. When you do that, you can also debug after the problem has already occurred, making reproduction of bugs a lot easier.

There's many logging frameworks out there, such as Apache log4net, but I'll be using the logging features of the .net framework, for two reasons:

1. I'd rather not add dependencies to my game without a good reason; and, somewhat related
2. since I'm already using MonoGame, I'd like to keep porting to platforms other than Windows as easy as possible. If I have to switch out my logging framework, that would make things harder.

Granted, there's a subset of log4net available that is compatible with both .NET and Mono, but both of these already come with System.Diagnostics, so why bother with subsets?

How does it work?

In principle, it's simple: there's this thing called a TraceSource, through which you append messages to your log. Before you can use one, you need to configure TraceListeners, which handle the messages and print them to different outputs, such as log files and the console. You also have to set up TraceFilters and TraceSwitches, which determine what messages get through to be actually logged.

Microsoft would like you to do that in App.config. Which isn't that bad an idea, really, it just doesn't suit my tastes really well, for a couple reasons:

1. I really only want multiple sources because I want different log channels to filter console output by. I still want all their output in the exact same log file. The XML to do that in App.config is incredibly verbose and thus doesn't lend itself to quick changes.
2. If two thematically related, but independent pieces of code should share the same channel, you either have to pass around the TraceSource object, introducing a dependency, or instantiate two of them. Neither sounds fun.
3. I don't see myself using App.config for anything else, and chugging around a config file for something that is neither changed by the user nor updated after deploy seems stupid to me.

Since setting up TraceSources in code is almost worse than in App.config (albeit more flexible), and I still had to solve problem no. 2, I decided to write...

The TracerCollection class

I originally wanted to object pool the TraceSources here, but, as it turns out, there is no way to set the Name property after initialization, so I'd still be reallocating and initializing new instances, defeating the point of the pool.
Since I won't be instantiating more than, like, 8 different sources anyway, I decided to simply wrap a Dictionary<string, TraceSource> instead. Upon initialization, it silently creates the two listeners and, when a TraceSource is requested (by name, obviously) that is not in the dictionary, one is created and the listeners added.

So we get lazy initialization of TraceSources without any setup work required on the user side, just by passing around an instance of this class.
However, there's still some problems with this:

1. You can't easily reconfigure what is logged to the console! At the moment, that involves changing the constructor of TracerCollection and recompiling. When we get to content management, we'll also deal with save games and user config, and then we'll also fix this.
2. The TextWriterTraceListener isn't particularly smart. If the log file already exists, it just appends to it, making it hard to differentiate between independent runs of the game. I considered using timestamps in the file name, so as to make a new file every run, but that clutters up the directory really fast, so I'd rather put them into a sub directory. That's not an option either, because the listener doesn't take relative paths, and figuring out the absolute path of the running executable is a pain, so I'd rather just deal with concatenated logs.

Seeing as I don't have a solution for either, all that's left to do for now is instrumenting the code, but I'd rather do the profiling facilities first and instrument the little code I have with both in one step.

So next time, we'll take a look at System.Diagnostics profiling. See you there!