Wednesday, January 20, 2010

Log4Net: log.Debug(String.Format()) versus log.DebugFormat()

Log4net is one of the most popular opensource logging frameworks available in the .NET world. I've been using this framework for over a year now, and today I discovered something new.

I often use string.Format() to format my log messages. Earlier this morning I made a typo formatting my message and an Exception was thrown in the beginning of my method which caused the application flow to break. You can avoid this by using the DebugFormat() method. If you mistype here, no Exception will be thrown, but a WARN message will be logged.

Example using log.Debug(String.Format())

   1:  try
   2:  {
   3:      if (log.IsDebugEnabled)
   4:      {
   5:          log.Debug("Starting to insert item ABC_1.");
   6:          //Insert item ABC_1
   7:          log.Debug(string.Format("Item {0} inserted with success. Started inserting item {1}.", "ABC_1"));
   8:          log.Debug("Starting to insert item ABC_2.");
   9:          //Insert item ABC_2
  10:          log.Debug(string.Format("Inserted item {0}.", "ABC_2"));
  11:      }
  12:  }
  13:  catch (Exception ex)
  14:  {
  15:      log.Error("Woops", ex);
  16:  }


As expected this throws a "System.FormatException: Index (zero based) must be greater than or equal to zero and less than the size of the argument list."

Example using log.DebugFormat()

   1:  try
   2:  {
   3:      if (log.IsDebugEnabled)
   4:      {
   5:          log.Debug("Starting to insert item ABC_1.");
   6:          //Insert item ABC_1
   7:          log.DebugFormat("Item {0} inserted with success. Started inserting item {1}.", "ABC_1");
   8:          log.Debug("Starting to insert item ABC_2.");
   9:          //Insert item ABC_2
  10:          log.Debug(string.Format("Inserted item {0}.", "ABC_2"));
  11:      }
  12:  }
  13:  catch (Exception ex)
  14:  {
  15:      log.Error("Woops", ex);
  16:  }

Using DebugFormat() the logger logs a WARN message, but it doesn't break the application flow.

   1:  WARN StringFormat: Exception while rendering format [Item {0} inserted with
   2:  success. Started inserting item {1}.]


So to avoid logging breaking your application, you should use the DebugFormat(), WarningFormat(), InfoFormat(), ErrorFormat() methods instead of String.Format() to format your log message. This should be a best practice.

6 comments:

  1. This is even better than log4net:
    http://www.kellermansoftware.com/p-14-net-logging-library.aspx

    ReplyDelete
    Replies
    1. I'd prefer a stable good enough OSS library over that any day.

      Delete
  2. For non-US users, note that a date being logged using InfoFormat, DebugFormat etc will be in US forrmat. In my simple test, log.InfoFormat(...) gave a US date whereas log.Info(String.Format(...)) produced the windows default date format.

    ReplyDelete
  3. Anonymous, you are right! Log.XXXFormat() uses String.Format but not takes into account the current culture.

    ReplyDelete
  4. Why would you say this is best practice? If you didn't do it the Exception throwing way to start with you would have a much lower chance of finding and correcting your typo and hence fixing that part of your code. A broken logging statement is still a broken piece of code that is going to make its way through to production and I'd argue that hiding these items under xxxFormat is actually bad practice.

    ReplyDelete
  5. @Ryan: It's a best practice, but not for the reason cited in the post.

    Imagine you have a lot of log.Debug(string.Format("{}{}{}{}{}", a, b, c, d, e)) calls in a tight loop in your code. It's helpful to have them in the source when debugging, but of course you don't want to incur the overhead of calling string.Format(...), which calls ToString() on each one of the arguments you pass in. This is overhead you don't want to incur unless you're going to use the output.

    If you use logger.DebugFormat("{}{}{}{}{}", etc.), the first thing the logger's method does is check to see if the appropriate log level is enabled. If not, it returns right away and you don't incur the formatting overhead. It only does the string formatting if the result will actually be logged. This is a nontrivial optimization and is the reason you should use the *Format(...) methods.

    ReplyDelete