Logging with dynamic objects in .NET 4.0 (part 1-n)

Often, you reach the point where you need a way to monitor your applications once they are deployed to a production server or to the end user. This can be done by using one of the many logging frameworks, or just by using the build-in trace class in the System.Diagnostics namespace. While most of these frameworks work perfectly fine, they do add an extra dependency on external code that you don't have control over. If you ever want to swap out the framework with a different framework because you don't like the direction it goes, then you might be stuck with a lot of specific method calls or code that doesn't work well with the new framework.

I have been playing around with the idea of creating something that will abstract away these dependencies and return to a dependency on my own code, which I can control. I came up with the interface below, which is as close to the basics as I could get it and still allows the more advanced scenarios. If my application is only dependent on the interface below, then the logging framework is abstracted away and I can easily switch logging frameworks by just changing the class that implements the ILogger interface. This class can then for example be injected into the objects by using dependency injection. The interface contracts below define what my logger should do. It might be that a framework I pick does less, and for example if I need to throw away the category information or find a different way of logging the categories (by reformatting the message to contain the category).

This interface defines 5 methods, where each method requires a category, message, and an optional set of objects named values. This array of objects allows you to send extra data to the logger, which I will cover later on.

The implementation for now:

The Logger class contains a static property named Log that contains the instance that implements the interface ILogger that I will use. I am using a container around my dependency injection framework, so the “IoC.Container.Get<ILogger>()” will return back the instance that I bound to the interface ILogger during initialization of the application (If you don't know anything about dependency injection, just read it as “_logger = new Logger()” for now, that’s ok). I will just implement the logging container in the logger class, because I currently have no intent to extend it to multiple ways of logging and this keeps it simple.

For this example, I've just implemented it to write messages to console.out:

So when in code I use:

It will write to the console prompt:

DEBUG (system): Starting up the application at 12:12:12

Sending debug and trace messages is often not enough. While at first you might think, yes I got it, the process hangs here and that’s because this value is negative or something like that. While testing this on your machine, it might be that it will never be negative, because the end user performs certain tasks that you don't or the production server has another setup. So only having trace messages, mostly means that you don't have enough information to actually do something about the problem. One option is to write out the missing information, but I don't want to write a zillion log messages to get each property visible that I think I might need. This will cost a lot of time to write and will just generate a lot of clutter in the log.

The optional objects array solves this, by allowing you to log the state of objects during the sending of the trace messages. Be aware that this will costs extra resources of the environment, so only place it on objects that you assume to help you out. Now you are able to store the state of the objects that are relevant to the trace message on the local machine of the user or send them out to a database and reference them back to the trace message. This works quite perfectly, but sadly it doesn't work that great when we got objects that are not XML serializable, because you want some way to send or store them.

To solve this issue, I needed some other way of casting the objects to a readable format that can be processed in some way, I don't want to look at 400 files, because there might be something different in the property of a certain object. While XML serialization is good for this, I don't actually need it, because I don't really care about the de-serialization of the XML. I can just run XPath queries against the plain XML, that’s fine.

After playing for a while, I figured out a solution that uses the DynamicObject that is new in .NET 4.0. When you inherit this class, you get a dynamic instance that allows you to do fun things. Below is the example of how this works.

First of all, I've created the trace message method. It’s just writing its output all to the console prompt, just to keep this example simple as shown below:

The above allows me to send objects and get them printed out to the console prompt. This way, I don't have to worry about how it’s stored for now and I can just see everything quickly in the console prompt. While this is not handy later on, for now it is okay, because I will only have a few logging messages.

So let’s start writing an console prompt test application, I start the console application by just writing the current time to the debug log.

Then I request some user input and we will create an object from that.

In this case a timespan, this was just for testing, because a timespan cannot be XML serialized ;-)

So now we have the timespan object and want to perform some logging. In this case, this might be a little odd, but just imagine a more complex scenario. It’s time to check if we need to send a trace message. Let’s check if the total hours is less than a day (No one can walk that fast). And if so, create an instance of the class I wrote that inherits from the DynamicObject named DynamicClone.

When calling the constructor, you supply an object to clone. The DynamicClone object will take care of cloning all the properties on the supplied object. This will mean you will end up with the following object:

Ok, let’s start the fun. If you enter you can walk around the world in a day, then I assume you are drunk. So I want some way to store that, without sending another log message. Instead of assuming the end user is drunk, just imagine you want to store some extra data to the object.

For example: if it’s an object accessing a file, you might want to store if the file is still accessible at the time of writing the log message, the file size, or something else. So I've just going to add my own property to the object named Message, with the following code:

As you might see in the above image, the property “Message” doesn't exist yet! It will be created as soon as I set it, sort of on the fly.

I've also added some example code that creates an array and stores the user input, just to demonstrate it. The WhatDrinksDidTheUserOrder gets filled with a list of the logical drives that exist on the machine, so for example: “C:\”, “D:\”.

At this time, we have the properties of the TimeStamp and the properties Message, UserMessage, and the collection WhatDrinksDidTheUserOrder. Once again to remind you, those properties didn't need to be defined in the class, since this is a dynamic object.

It’s time to send the message to the trace log:

The first part is just the category and message string, while the second part converts the dynamic object to XML.

I don't know if this is the most understandable syntax, but it looks the most fancy ;-).

Maybe, just a method call is clearer, but I wanted to play around a bit. The current syntax makes it look more like the DOS prompt “dir > dirlisting.txt”. I didn't use the single > because that might be confused with the well-known greater than comparison sign.

Let’s look at the command prompt to see what happens:

So currently, you get a mix of the actual application and the logging information. Just to remove any confusion, if the logging was done to a file, the console should have only said:

As you can see in the highlights the debug messages were displayed on the screen, and the XML data was displayed containing all the properties of the Timespan object, the object that is normally not XML serializable, extended with the Message, UserMessage and WhatDrinksDidTheUserOrder properties that were added later on and didn't belong to the Timespan object.

Below is the XML formatted and better readable:

If this doesn't sound any useful at all, then it might help to say that we now used the Timespan object, but could have also used the current http context or something like that, which is a lot bigger.

This is the end of my first blog post and I hope you enjoyed it.

Now it’s time to cleanup code and improve the XML serialization of more complex objects, resolve circular references, and more.

In the following posts of this series, I will cover those and at the end when it’s done, share the code somewhere.

Have fun!

CodeProject