SLAB design considerations

In my previous post, I talked about the features available in the Semantic Logging Application Block. In this post, I will show you a class with regular trace logging, and talk about things to consider when converting it to implement the Semantic Application Logging Block (SLAB) to create structured logging. You can just do a straight conversion and not think about your trace logging methodology, but this kind of goes against the whole point of using SLAB. You should put some thought into it so that what you end up with isn’t just trace logging, but is structured in a way that will allow you to search for patterns or do data mining.

Show me some code

Here is a class called CustomerFavorites that is similar to one you might use in a data access layer or a WCF service. Input parameters are first name and last name; output parameters are favorite movie and favorite language. I’ve written this in a way that allows me to put in a lot of trace logging, like validating that the input fields aren’t blank, and rolling my own SQL retry code. This displays regular unstructured trace logging.

internal class CustomerFavorites
{
  int maxNameLength = 50;

  internal string GetCustomerFavorites(out string favoriteMovie, out string favoriteLanguage,
    string firstName, string lastName)
  {
    Trace.TraceInformation("[GetCustomerFavorites] called. FirstName = {0}, LastName = {1}", 
      firstName, lastName);

    string errorMessage = string.Empty;
    favoriteMovie = string.Empty;
    favoriteLanguage = string.Empty;

    if (string.IsNullOrWhiteSpace(firstName) && string.IsNullOrWhiteSpace(lastName))
    {
      Trace.TraceError("[GetCustomerFavorites] called. First and last name are blank, "
          + "no data returned.");
        errorMessage = "Must provide name to get favorites.";
    }
    else if (string.IsNullOrWhiteSpace(firstName))
    {
      Trace.TraceError("[GetCustomerFavorites] called. First name is blank, no data returned."
        + " LastName = {0}", lastName);
      errorMessage = "First name is blank; both fields must be provided.";
    }
    else if (string.IsNullOrWhiteSpace(lastName))
    {
      Trace.TraceError("[GetCustomerFavorites] called. First name is blank, no data returned."
        + " LastName = {0}", lastName);
      errorMessage = "First name is blank; both fields must be provided.";
    }
    else if (firstName.Length > maxNameLength)
    {

      Trace.TraceError("[GetCustomerFavorites] called. First name is too long, no data " 
        + "returned. FirstName = {0}, LastName = {0}", firstName, lastName);
      errorMessage = string.Format("First name is too long. Can not be more than {0} "
        + "characters long.", maxNameLength);
    }
    else if (lastName.Length > maxNameLength)
    {
      Trace.TraceError("[GetCustomerFavorites] called. Last name is too long, no data "
        + "returned. FirstName = {0}, LastName = {0}", firstName, lastName);
      errorMessage = string.Format("Last name is too long. Can not be more than {0} "
        + "characters long.", maxNameLength);
    }

    int tryCount = 0;
    bool success = false;

    try
    {
      do
      {
        errorMessage = string.Empty; 
        tryCount++;
        try
        {
          using (SqlConnection cnx = 
            new SqlConnection(GlobalStaticProperties.dbConnectionString))
          {
            cnx.Open();
            using (SqlCommand cmd = new SqlCommand("Customer_GetByName", cnx))
            {
              cmd.CommandType = CommandType.StoredProcedure;

              SqlParameter prm = new SqlParameter("@FirstName", SqlDbType.NVarChar, 50);
              prm.Direction = ParameterDirection.Input;
              prm.Value = firstName;
              cmd.Parameters.Add(prm);

              prm = new SqlParameter("@LastName", SqlDbType.NVarChar, 50);
              prm.Direction = ParameterDirection.Input;
              prm.Value = lastName;
              cmd.Parameters.Add(prm);

              SqlDataAdapter da = new SqlDataAdapter(cmd);
              DataTable dt = new DataTable();
              da.Fill(dt);
              success = true;

              if (dt == null || dt.Rows.Count <= 0)
              {
                errorMessage = string.Format("Error retrieving favorites; record not found "
                  + "for first name '{0}', last name '{1}'.", firstName, lastName);
              }
              else
              {
                try
                {
                  DataRow dr = dt.Rows[0];
                  favoriteMovie = dr["FavoriteMovie"].ToString();
                  favoriteLanguage = dr["FavoriteLanguage"].ToString();
                  Trace.TraceInformation("[GetCustomerFavorites] FirstName = {0}, "
                    + "LastName = {1}, FavoriteMovie = {2}, FavoriteLanguage = {3}",
                      firstName, lastName, favoriteMovie, favoriteLanguage);
                }
                catch (Exception ex)
                {
                  Trace.TraceError("[GetCustomerFavorites] FirstName = {0}, LastName = {1}, "
                    + "Exception thrown trying to get favorites from SQL record = {2}", 
                    firstName, lastName, ex.ToString());
                  errorMessage = "Error retrieving customer favorites.";
                }
              }
            }//using SqlCommand
          } //using SqlConnection
        }
        catch (SqlException ex)
        {
          errorMessage = "Error retrieving customer favorites.";
          Trace.TraceError("[GetCustomerFavorites] firstName = {0}, lastName = {1}, "
            + "Try #{2}, will sleep {3}ms. SQL Exception = {4}",
              firstName, lastName, tryCount, 
              GlobalStaticProperties.retrySleepTime[tryCount - 1], ex.ToString());
          if (tryCount < GlobalStaticProperties.MaxTryCount && 
            GlobalStaticProperties.retrySleepTime[tryCount - 1] > 0)
              Thread.Sleep(GlobalStaticProperties.retrySleepTime[tryCount - 1]);
        }
      } while (tryCount < GlobalStaticProperties.MaxTryCount && !success);
    }
    catch (Exception ex)
    {
      Trace.TraceError("[GetCustomerFavorites] firstName = {0}, lastName = {1}, "
        + "Overall Exception thrown = {2}", firstName, lastName, ex.ToString());
        errorMessage = "Error getting customer favorites.";
    }
    return errorMessage;
  }
}

One word about the SQL retry code: There is an array loaded in a global static variable called retrySleepTime that provides the retry information – how many seconds to wait before retrying. This is usually an increasing number; I think mine are 0, 2.5, 5, and 7.5. When it fails the first time, it retries immediately. The second time, it waits 2.5 seconds and then retries, etc. This kind of retry is necessary because the Azure SQL Database occasionally has connection problems, depending on a number of things. The best practice is not to roll your own retry code, but to use the Transient Fault Handling Application block from the Azure CAT team and the Microsoft Patterns and Practices team. This is part of Enterprise Library 6, which also contains the Semantic Logging Application Block.

Design considerations

Looking at the code above, we have the following kinds of messages we want to log:

• Entry point, which also traces the input and output variables.
• Input errors (variables or blank or too long)
• No matching records found in the database and there should be
• Exception converting the DataRow parameters to real numbers
• SQL Exception with retry code
• Unexpected exception

If you have a big WCF service, you might have lots of methods that look very similar to this, but with different database actions and different variables.

A note about keywords: When you set up your listener, you can filter the logging by the keywords and the Message Level. For example, you can turn off all but DatabaseError, or all but Errors. If you have something you’re going to be logging 1000 times per second, add a keyword for it, so you can turn it off if needed.

How would you gather this data? How are you going to look at the resulting logs?? When you set up your event source class, you can assign values to the following:

• Event ID
  • This is an arbitrary number provided by you.
• Keyword (defined by you) (limited to 64)
  • When you set up your listener, you can filter the logging by the keywords. For example, you can turn off logging for a specific keyword. If you have something you’re going to be logging 1000 times per second, add a keyword for it, so you can turn it off if needed.
• EventOpcode (1-10 are taken up by .NET, opcodes 11 and above are defined by you)
  • You can filter the results by EventOpcode.
• Task (defined by you)
  • You can filter the results by task.
• Message
  • This is your message that uses the parameters sent in to be used when writing the event log; it’s the “pretty” format. So you might send in method name, and your message might be “Entry point for {0}.” The parameters make up the payload, and if writing to Azure Table Storage, you can query on the parameters individually.
• Message Level (Informational, Critical, Error, etc)
  • You can filter the results by the message level; you can also turn the logging on/off. For example, you could turn off all of the information-only logging.

So here’s some of the kinds of events you might want to be able to query from this class and others like it:

• Database retry errors
• Database messages that are errors/exceptions
• Database messages that are informational
• Errors with the input parameters
• GetCustomerFavorites Entry Point (with params in)
• Output parameters (i.e. results)
• General exception

Looking at this list, how would you assign event id’s, keywords, opcodes, and tasks?

• You can only have up to 64 keywords, so you want to be careful about using them. You could set up keywords for Database, ParameterError, and EntryPoint.
• You could set up tasks for DatabaseRead, DatabaseUpdate, DatabaseRetry.
• You can tell error/exception from information by the event level.

So let’s look at that list again and categorize our events for this class. Each event has a different event id that you assign arbitrariliy.

• Database retry errors
  • Event id 101, Keyword=Database, Task=DatabaseRetry, Level = Error
• Database messages that are errors/exceptions
  • Event id 102, Keyword=Database, Task=[DatabaseRead or DatabaseWrite], Level = Error
• Database messages that are informational
  • Event id 103, Keyword=Database, Level = Informational
• Errors with the input parameters
  • Event id 104, Keyword = ParameterError, Level = Warning
• GetCustomerFavorites Entry Point (with params in)
  • Event id 105, Keyword = EntryPoint, Level = Informational
• Output parameters (i.e. results)
  • Event id 106, Level = Informational
• General exception
  • Event id 107, Level = Error

You get the general idea. Note that the parameters passed in when writing the event get written as separate key/value pairs, and can be queried on if you’re writing to Azure Table Storage. So if you pass in the method name, you will be able to query for all events having that method name.

Notice how quickly the event id’s add up. You might want to consider putting them in partial classes and grouping them that way so they are easier to maintain. Of course, you could always use regions, which people either love or hate. If you do this, find out which way your boss feels before deciding whether or not to use them. ;-)  (I had a lead once who removed all comments I put in my code. She said “it makes it look untidy.” So you never know what’s going to make someone happy.) (Yes, this drove me nuts.)

Summary

In this post, I showed an example of a class with trace logging, and discussed design considerations for converting this to semantic logging. In my next post, I will show you how to implement our design.

Tags: Azure, Azure Table Storage, Diagnostics, Logging, SLAB