I’ve spent most of my professional career working on Enterprise Applications (mostly web based). Sometimes you release your code and everything goes smoothly (this is where praise is warranted by rarely given). However, there are times when code has been in place for many days, weeks, months without any issues and all of a sudden – all hell breaks loose and it stops (this is where harsh comments are never wanted but always received).

So, what do we do when that happens? If we cannot see what’s going on, we’re pretty much hosed. Sure we could start doing some knee-jerk reactions, do code changes to try trapping for situations, but come on… knee-jerk reactions are bad. Say it with me: “BAD”.

So this is where application logging comes in.  Below are 2 lists. The first list contains some things you just should not do… though everyone has probably done these. We learn through making mistakes, others and school (… yea), so the list below is mostly mistakes I’ve made in my career so hopefully some can learn from them.

What Not To do.

There are many ways to “log” what happens in an application. What I want to do here is list some of the ones I’ve encountered that really don’t give much info.

Rely on just Exception Logs

There is something to be said about logging exceptions, however, relying on just exception logs is a mistake. Exceptions are raised either when a code error, system exception, user exception or when a user manually throws it. However there are cases where there’s an error with your system, and it’s not throwing an exception.

Write out every action to the Hard Disk

I love this one. I’ve seen a system log over 100Mb an HOUR to the hard disk based on actions happening on it. Sure, it could be useful… if you had a hard disk that had a crap load of room on it. But come on, you let it run for a month un-checked. 100 * 24… um * 30… dot the i…  … that’s around 72GB of logging. Yes, some of it “might” be useful but who would want the daunting task of looking through that mess when we could doing real work.

Use a single log file

Whenever you log information to the system – split it up into files. One file per day, or one file per hour. If you have a log file that’s massive (look above) and you’re reading it every time you log something, you’ll be overloading your system in no time on read/writes. What i do is:    name files like:

• BicNet.Enfora_LOG_19_FEB_2008_0800.log
• BicNet.Enfora_LOG_19_FEB_2008_0900.log
• BicNet.BlueTree_LOG_19_FEB_2008_0800.log
• BicNet.AI.NinjaRevengePlan2000_LOG_59_SEPTEBURARY_2108_0800.log

If an error occurs at 8:30AM with some customers sending in GPS Data through an Enfora Modem, it’s pretty self-explanatory where I need to look.

Do nothing

YES! Awesome!… die… well actually this is better than the next one.

Log useless information

Have you ever seen a log file that looks like:

>Awesome function just called. Woo I rock. Go Canucks go!

>Another Awesome function was just called. It’s now 12:34PM. GO CANADA GO!

>WOO I ROCK!

>… Stupid user did an error. Message is “Object reference not set to an instance of an object”. COME ON!

>ANOTHER ERROR!? Gah button1 was clicked. Check the code to see why I was written. DO IT! DO IT NOW!

If you looked through some of my college programs you might find some error logs like this.

What to do

Honestly, don’t do any of the above and you’re better off already. There’s an example of a logging system I have in place that writes logs out.

Don’t bloat your logs

When doing logs – I rarely use XML. Wha!? NO XML!? HERESY! Yes yes it formats nicely, and yes it’s well it’s XML. However, there’s an overhead on using it. Only use it if you need to. If you can get by with writing logs in plain text, do it. XML can be used when you have complex object you need to write out, or if you nave a lot of data, however, for simple logging – use plain text.

Log raw information coming into the system

Whenever you have a system that needs it’s information logged, log the incoming data. If you don’t log that data, it could be transformed or corrupted at the time you do log it. If you log it when it’s coming in you can later on run tests against that function with the correct data if there’s an error. For web services, there’s ways of tapping into the raw SOAP data (using ASP.NET) before it hits your web-service. This allows you to log/trace that information to your disk before your web-service gets the data, very useful.

Example – UDP / TCP Listener

I have a service running on our servers that listens on TCP and UDP Ports. Whenever a device connects to our servers, my listener service picks it up and processes the information.  Every time I get a connection on our server, I log who connected, the message received, and the time (I don’t write anything out at this time). Every time I send something to a user, I log the IP, the message and the time. Every 10 minutes I’ll stream the output to one file, and the input to another file. If an exception is raised, I write out all the information, as well as the exception to an exception log file. Every hour I create a new file so they’re never too large.

I don’t log every function, I don’t log simple operations, I don’t need to because if they ever throw an exception, I already have it. If there is bad data coming in which is compromising the integrity of my system, I have it already logged with the date/time. This gives us all the information we need to perform tests to see what has gone wrong, and it catches exceptions. It also allows me to quickly count the # of connections coming in, to debug connectivity issues.

Code Example – Generic Log Entry Method

Here’s a sample “Logging” method I use to fill my StringBuilder with the data I need to log out:

   1:   private void LogEntry(string message, string customer, int reportID)

   2:          {

   3:              string sReportID = null;

   4:              char c = ' ';

   5:   

   6:              System.Diagnostics.Debug.WriteLine(message);

   7:   

   8:              if (_sbLog == null)

   9:                  _sbLog = new StringBuilder();

  10:   

  11:              if (reportID > -1)

  12:                  sReportID = reportID.ToString();

  13:   

  14:              if (customer != null && customer.Length > 25)

  15:                  customer = customer.Substring(0, 25);

  16:   

  17:              if (sReportID != null && sReportID.Length > 9)

  18:                  sReportID = "XX" + sReportID.Substring(2, 7);

  19:   

  20:              if (message.ToLower().IndexOf("exception") > -1)

  21:              {

  22:                  _sbLog.AppendLine(

  23:                      DateTime.Now

  24:                      + " - "

  25:                      + (customer == null ? new string(c, 25) : customer + new string(c, 25 - customer.Length))

  26:                      + " - "

  27:                      + (sReportID == null ? new string(c, 9) : sReportID + new string(c, 9 - sReportID.Length))

  28:                      + " - "

  29:                      + "Exception occured.");

  30:   

  31:                  _sbLog.AppendLine(message);

  32:              }

  33:              else

  34:              {

  35:                  _sbLog.AppendLine(

  36:                      DateTime.Now

  37:                      + " - "

  38:                      + (customer == null ? new string(c, 25) : customer + new string(c, 25 - customer.Length))

  39:                      + " - "

  40:                      + (sReportID == null ? new string(c, 9) : sReportID + new string(c, 9 - sReportID.Length))

  41:                      + " - "

  42:                      + message);

  43:              }

  44:          }

From here, you just have to tell it to write this out whenever you need.