Thursday, April 9, 2009

Logging – how to do it effectively

Whoa, I've been off-blog for 4 months... Mainly because I was too busy doing actual programming...
Hopefully I won't delay the next post too much.

Lately I was part of a team implementing new logging technique.

These are the summarized points of interest when starting the "logs".

First, make sure you have defined the levels of logging. It was hell of a time to look for every log-line and re-level it. We had a problem with the definitions so I did those remakes a few times, to tell the truth I don't know what's the results are.

Second thing to do is find / build a suitable logger (NLog is a good choice for an open source logger). We chose it for our "win services," it's definitely a good choice. It supports 6 levels of logging, multiple logs and writes to the event log.

Third thing is merge the logger levels with the levels you defined. This "trivial task" requires about 2 hours of the team; otherwise it requires a complete re-write of the code every time a fly lands on your screen. We had the chance to bypass this idea, luckily for us we got hold of ourselves quickly enough so only a week worth of code had to be re-written for the job.

Once everything is in place, working and appears rock stable comes the "funny part". Actually we found strange behaviors in some old apps (probably auto-rewritten from the VB6 source into the .NET C#.) Some parts had unused methods q sections. Others on the other hand became useless; did you know "Biztalk doesn't compile empty expressions, it throws an error." Other parts hadn't got enough logging in the first run; usually it means add a few lines of code.

As a rule of a thumb, make sure that every variable, message, program is logged with its value when you're using the highest log level.

Another important issue is conventions when writing. We had to write down "failed XMLs", in order to find "who's the developer which needs to fix the bug," we had to open them and read the values. It took only a day for us to realize that marking the module's ID is by far more important for the initial handling than the ID or type of the XML.

One last note – never, but never run stress test when logging in the highest level. The results are usually funny (well for anyone except the poor programmer who can't understand WTF went wrong)