Add logging to your applications. NLog for beginners.

One of the most important aspects of your applications and scripts (beside their actual purpose)  is to log information about the currently running actions. On daily usage it might be useful to just verify if everything is working OK, or to have some kind of reporting based on this (logparser is quite helpful for such tasks). But as soon as a problem arises, this information is of huge importance to troubleshoot the current problem. So actually you can’t log to much, only to less.

Logging in MDT

The Microsoft Deployment Toolkit has one of the simplest and most effective logging engines I have seen so far for scripting. And you are doing good at making extensive use of those logging capabilities if you are creating your own scripts used for Deployments (Well actually you could make use of it for any scripts). You mainly have to reference the ZTIUtility.vbs file and can then log entries using the oLogging object with something like

They will then typically end up in a log file with the same name as the script and also be added to the BDD.log. To view those log files, I highly recommend Trace32 that is part of the ConfigMgr 2007 Toolkit which can be downloaded from Microsoft for free (details.aspx-FamilyID=948e477e-fd3b-4a09-9015-141683c7ad5f&DisplayLang=en). See a recent post with some more information (Testing your wizard files, gather steps, customsettings.ini ….).

Logging for managed code

Anyway, this was mainly for scripting. But how about managed code? While being spoilt by the nice implementation of the MDT Framework it was hard for me to find a competing Framework for VB.Net/C#. Sure, there are dozens of solutions out there but I wanted to have it as simple as referencing it in a single line and then just log information at different levels. Ideally, being able to manage the logging level during runtime.

So I evaluated a couple different options like the .Net Framework built-in Tracing provider, Log4Net, the Microsoft Enterprise Library and finally ended up at NLog. I’ve used the internal tracing so far but it’s hard getting a nice output. The enterprise library was simply to complicated and takes to much code for “just” some logging. Far away from being intuitive, at least for me. Log4Net and NLog are quite similar in their approach. While I found NLog fitting a bit better to what I requested. Especially as I wanted to implement it into an ASP.Net MVC project I was simply unable to get Log4Net running while NLog did with a one-liner. Probably my fault so I’m not blaming Log4Net for anything, might have been Murphy who decided what framework to take 😉

Implementing NLog

So let’s jump directly into the implementation. Get the files from the NLog Download page. I’m currently using Version 1.0. Version 2.0 is still in preview. If you download the …setup.exe file and execute it, it will also integrate itself into an existing installation of Visual Studio (2005 – 2010 including the free Express Editions!). That brings some additional benefit. The first benefit will be visible if we want to add NLog to a project In Visual Studio (Express). To do this, just right click on your project, choose “Add New Item”. You should now find three default configuration templates for NLog in the “MyTemplates” section. Let’s choose the “Typical NLog Configuration File” for now. This will write the log entries to a text file.

This will now add a new NLog.config file to your project and at the same time also add a reference to the LNog.dll (How nice is that? 😉 ).

This default config file is enough to already write log entries. But let’s have a quick look on it first

First, make sure that you change the “Copy to Output Directory” to “Copy always” in the File properties of the new config file. Otherwise this file won’t show up when you build your project. Then you see two sections. One for Targets and one for Rules.

Targets defines where to write and how the log entry should look like (it can be a file, Database, event, and a whole lot other target types) and how to write (We will have a look on some formats later).

The Rules define what level of information to log and what target(s) shall be used. Both sections have a full load of possibilities to configure and customize them. You can have several targets and several rules for different situations etc.

Our first log entry

To keep it simple and just start somewhere, we now want to log a bit. With the integration of NLog into Visual Studio you also get an additional code snippet. All you have to do to be able start logging is to type “nlogger” at the beginning of your class/module and press Tab. This will add a private object called “logger” that we now can use to log information. In C# it will be a static object, so you can also make it shared in VB.Net if you want.

So let’s have a look on a very (very, very) simplified module and log the well known “Hello World”

If we now run our project it will write a new log entry into the log.txt

As you can see, on default it will log the date and time, the level, the class/module and the message itself. NLog has 6 different levels for logging. Trace, Debug, Info, Warn, Error, and Fatal. Typically a more detailed level includes also all less detailed levels if e.g. limited by a rule. So if you have a rule for all “Info” messages, it will also log Warn, Error and Fatal on default (which can also be tweaked)

Some more entries

While you are able to have different levels of logging and define during runtime what levels to really write to a file (or database, or …) you can also make use of the built-in possibility to use a parameterized string. As String formatting is quite expensive, the cool thing about this way is, that it will only be evaluated  if there is at least one rule that logs entries of the current (or above) level. Let’s see some more examples (Yes it makes sense to use variables for the parameters I just hardcoded it to keep it short 😉 ):

I guess you got the point.

Additional configuration/customization

So to finish this post, let’s have a quick look on early nlog.config file for the Deployment Webservice. Might not the best one and will most probably change during time but should give you some ideas.

First, I set the property “autoReload” to true. This has the advantage, that NLog will re-read the configuration if a change to the file has happened. So you can implement changes really at runtime. Switch to tracing detail for a single webservice call and then switch back to Info level. etc. Then you see a couple of entries looking like “${…}”. These are Layout Renderer that you can use to customize names and also the entry itself. If storing in a database you could use a Layout Renderer per column so really log a whole bunch of useful information. Have a look in the official documentation of NLog in the Layout Renderer section to see the full list of the roughly 50 built-in renderers. And if those aren’t enough it’s a piece of cake writing your own and integrating it into your logging. I will show an example for a Trace32 kind of logging in a future article.

As mentioned before, you can have multiple Rules logging to different targets. You can limit each rule to certain log levels only or even to the namespace of the class you would like to log to e.g. enable tracing for something you have just added or need to troubleshoot without getting overwhelmed by thousands of entries from the rest of the project.

Same for the targets. You can have different targets at the same time, each can have a different layout for the information to log. Tracing might be more detailed then info messages, etc.

Another interesting thing is, that you can group targets to apply the same behavior. These groups are called wrappers here. They don’t do any kind of log operation itself, they just define some additional behavior. In the example above you see the property async=”true”. That’s a short form of the following:

It simply allows NLog to write the entries without stopping the current process. This might make more sense on Database operation as you don’t want to have a slow application just because it tries to write log entries to a currently slow database. There are a couple more options on this wrapper, to e.g. log only in chunks, let say collecting 10 entries before sending to the database. There are also a couple other wrappers you can use like Buffering, Retrying, Impersonating, etc. See https://github.com/nlog/nlog/wiki/Tutorial#wrappers for more information on these wrappers.

While giving you very fast an easy solution to just start logging, it can easily be extended and customized to all your needs. And that often without any change to your existing code later on. You just add the necessary logging to your application at the beginning and decide later what and how this information shall be used. And to make it even more easy, NLog comes with a great online documentation and it has IntelliSense in the code itself but also in the config file!

There is a whole lot more to say about this solution. But this hopefully gave you an idea on what it can do and how easy it is to implement. It even comes with a COM API so you could use it within scripts.

Anyway, the idea of this post was to give you a start. The Deployment Webservice has already been updated with this logging Framework (while not published yet) and the MDT Web Front End is under a re-write to add this as well. So with the next versions you will be able to define what you would like to see.

You would like to track who executes what webservice function? You have a strange issue that happens only in certain situations? You need to have some more extensive logging due to internal regulations?  No problem, all this is built-in already. The information is there and it’s just up to you to decide what you want 😉