Implementing SLAB in an Azure service

In my previous post,  I talked about design considerations when using SLAB, and presented a class to be changed from regular trace logging to semantic logging using SLAB. In this post, I’m going to show you how to set up the event logging with SLAB, how to write the entries to Windows Azure Table Storage, and how to implement the design to change the class to use SLAB instead of regular trace logging.

To implement SLAB, first you need to download the NuGet package and install it. So in Visual Studio, you can click Solution / Tools / NuGet Package Manager / Manager Packages and search for “semantic logging application block”. You will get several entries – one for the EventSource analyzer, one for each sink, one for the out-of-process service, and one that is just the semantic logging application block. Select the last one and the Azure Sink, which will allow us to write our results to Table Storage.

Now we need to add a class that inherits from EventSource. I’m going to call it CustomerSvcEventSource. In the bare bones of the class, I will add a static method to call to Log events, a static field instance to provide access to an instance of the class, and a private constructor. Here’s the bare bones of the class.

public class CustomerSvcEventSource : EventSource
{        
  //create a static field instance that provides access to an instance of this class
  private static readonly Lazy<CustomerSvcEventSource> Instance
    = new Lazy<CustomerSvcEventSource>(() => new CustomerSvcEventSource());

  //create a static property called Log that returns the current value 
  //of the Instance field of the event source. This value is 
  //determined by the custom event methods called in the Customerservices application.
  private CustomerSvcEventSource() { }

  public static CustomerSvcEventSource Log
  {
    get { return Instance.Value; }
  }
}

The next thing we need to do is to set up the listener. This needs to start up when the application starts up, and close when the application closes. Since this is a WCF service, I’m going to put this in the Application_Start method and the Application_End method in Global.asax.cs.

I need these two using clauses:

using Microsoft.Practices.EnterpriseLibrary.SemanticLogging;
using Microsoft.WindowsAzure.ServiceRuntime;

I define the listener in the Global.asax.cs class:

public ObservableEventListener listener;

Now put the code to start up the listener in Application_Start. “CustomerSvc” is the name of the listener. The

“RoleEnvironment…” gets the connection string to the storage account I want to write the logs to. In EnableEvents, I provide the name of the Event Source log method, the logging level, and keywords. You can have your listener just write errors by changing the EventLevel, or just write specific Keywords. you can also set up multiple listeners and send the results of each to different tables. (You can specify the table name when instantiating the listener.)

//slab listener
listener = new ObservableEventListener();
listener.LogToWindowsAzureTable("CustomerSvc", 
  RoleEnvironment.GetConfigurationSettingValue("DataConnectionString"));
listener.EnableEvents(CustomerSvcEventSource.Log, EventLevel.LogAlways, Keywords.All);

Put the code to stop the listener in Application_End:

if (listener != null)
{
  listener.DisableEvents(CustomerSvcEventSource.Log);
  listener.Dispose();
}

Now we can go back and update our Event Source with keywords, tasks, opcodes, and then finally the actual events. Here are the results of our analysis in the previous post on what events we’d like to log, including the keywords, tasks, and logging levels:

• 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

Let’s set up the Keywords. You can have up to 64, and they have to be in a nested class in the EventSource class. Each keyword value is a 64-bit integer, which is treated as a bit array, so they all have to be powers of 2 – 1, 2, 4, 8, 16, 32, etc.

From the information above, we have 3 keywords. I’m adding this in to our EventSource class:

public class Keywords
{
  public const EventKeywords Database = (EventKeywords)1;
  public const EventKeywords ParameterError = (EventKeywords)2;
  public const EventKeywords EntryPoint = (EventKeywords)4;
}

Now let’s add the Tasks. We have three. These do not have to be a multiple of 2.

public class Tasks
{
  public const EventTask DatabaseRead = (EventTask)1;
  public const EventTask DatabaseWrite = (EventTask)2;
  public const EventTask DatabaseRetry = (EventTask)3;
}

What’s left? We didn’t use any OpCodes, but they are set up the same way as the tasks. We assign the event id’s and levels when we add the events to the EventSource class. So let’s go back to our bare bones Event Source class and start adding the methods for writing the events.

The first event I’m going to write is the EntryPoint. You put the event id in the attribute of the method, as well as the Message, Level, and Keywords. You call WriteEvent inside the method, passing the parameters passed in. WriteEvent will write a line to table storage. The message will be written, and the parameters in json format.

[Event(105, Message = "[GetCustomerFavorites] Called/entry point. FirstName = {0}, LastName = {1}", 
  Level = EventLevel.Informational, Keywords = Keywords.EntryPoint)]
internal void GetCustomerFavoritesCalled(string firstName, string lastName)
{
  if (this.IsEnabled()) this.WriteEvent(105, firstName, lastName);
}

The event id is 105.  I’ve put if (this.IsEnabled()) in front of my WriteEvent in case the Event Source is not enabled. This will keep it from throwing an exception if for some reason the Event Source is not enabled.

So now we need to call this from the entry point in our class, the code for which is posted in the previous blog post. It will look like this:

CustomerSvcEventSource.Log.GetCustomerFavoritesCalled(firstName, lastName);

The next one I’m going to add is for the parameter errors. I’m going to make this one generic, and pass in the method name to be written as part of the payload. Then I can call this from anywhere.

[Event(104, Message = "Parameter error in method {0}, msg = {1}", Level = EventLevel.Error, 
  Keywords = Keywords.ParameterError)]
internal void ParameterError(string methodName, string errorMessage)
{
  if (this.IsEnabled()) this.WriteEvent(104, errorMessage);
}

Here is an example of calling this:

errorMessage = "First and last name are blank.";
CustomerSvcEventSource.Log.ParameterError("GetCustomerFavorites", errorMessage);

I’m calling this in the same places I’m calling the trace logging for the invalid parameters. (I’m going to post the entire class when I’m finished.)

One thing to note here – this shows the advantage of using this method of logging. You don’t have a whole bunch of trace statements that essentially do the same thing, which open you up to typos. You’re making the message once in the event definition and using it repeatedly. Of course, this means if you have a typo in the event definition, it will be displayed in every event message. But as a friend of mine once said about programming rules: Right or wrong, be consistent.

Here is a method for the case where I read the database and should find data, but I don’t. Note that this one has a Task attached to it, and the keyword is Database. (You could argue whether or not this should have the Database keyword, but we’ll leave it “as is” for an example.) 

[Event(102, Message = "Method {0}; no data found, but should be. Input Info = {1}.",
  Level = EventLevel.Warning, Keywords = Keywords.Database, Task = Tasks.DatabaseRead)]
internal void DatabaseRecordsNotFound(string methodName, string extraInfo, string errorMessage)
{
  if (this.IsEnabled()) this.WriteEvent(102, methodName, extraInfo, errorMessage);
}

And here’s what the call looks like:

CustomerSvcEventSource.Log.DatabaseRecordsNotFound("GetCustomerFavorites", 
  string.Format("FirstName = {0}, LastName = {1}", firstName, lastName),
  errorMessage);

Note – I’m consolidating a bit here. If you wanted to truly make this 100% SLAB-ified, you could make this less generic, and call it something like GetCustomersDataRNF and pass the first and last name in as parameters, and only use this for this one case. This goes for some of hte other methods you’re going to see below. You get to decide how much granularity you want to have.

Here is a method for database data conversion errors. Note that this one has a Task attached to it, and the keyword is Database. (Again, you could argue whether or not this should have the Database keyword, since it’s a coding error.)  This is called when trying to convert the parameters to local variables. This is an addition to the original design from the previous blog post. When working on this, flexibility is important. When you decide to implement your event source, you may find you want different information than originally decided.

[Event(108, Message = "Error converting the database fields to output parameters in method {0}. "
  + "ExtraInfo = {1}, ex = {2}",
  Level = EventLevel.Error, Keywords = Keywords.Database, Task = Tasks.DatabaseRead)]
internal void DatabaseFieldConversionError(string methodName, string extraInfo, string errorMessage)
{
  if (this.IsEnabled()) this.WriteEvent(108, methodName, extraInfo, errorMessage);
}

And here’s what the caller looks like: 

CustomerSvcEventSource.Log.DatabaseFieldConversionError("GetCustomerFavorites",
  string.Format("firstName = {0}, lastName = {1}", firstName, lastName),
  CustomerSvcEventSource.FormatException(ex));

I realized I am going to need to be able to log exceptions. I want all of them to have the same format, so I have added a FormatException method to my Event Source class that I can call from anywhere. You  might want to add the InnerException to it; this is just a basic example.

public static string FormatException(Exception exception)
{
  return exception.GetType().ToString() + Environment.NewLine + exception.Message;
}

I’m actually calling this when sending the information in to write the event. This way, if I want to format exceptions differently depending on where they are, I can just set up another FormatException type method and call that instead.

Here is the SQL DB Retry error event method. By including the TryCount as a parameter, I can search my logs for entries where TryCount > 3, and find the places that didn’t work at all because it could not connect to the database within 3 retries.

[Event(101, Message = "DB Retry in method {0}, MiscInfo = {1}, TryCount = {2, "
  + "RetrySleepTime = {3}, ex = {4}",
  Level = EventLevel.Error, Keywords = Keywords.Database, Task = Tasks.DatabaseRead)]
internal void DatabaseRetry(string methodName, string miscInfo, int tryCount, int sleepTime, 
  string exceptionInfo)
{
  if (this.IsEnabled()) this.WriteEvent(101, methodName, miscInfo, tryCount, sleepTime, 
    exceptionInfo);
}

And this is the caller, which is in the catch for the SQL Exception:

CustomerSvcEventSource.Log.DatabaseRetry("GetCustomerFavorites",
  string.Format("FirstName = {0}, LastName = {1}", firstName, lastName),
  tryCount, GlobalStaticProperties.retrySleepTime[tryCount - 1], 
  CustomerSvcEventSource.FormatException(ex));

Again, I’ve genericized this so I can use it repeatedly, but you can make it specific to this method.

You should have the general idea by now. After finishing all the code in the class, here is the final EventSource class:

public class CustomerSvcEventSource : EventSource
{        
  //create a static field instance that provides access to an instance of this class
  private static readonly Lazy<CustomerSvcEventSource> Instance
    = new Lazy<CustomerSvcEventSource>(() => new CustomerSvcEventSource());

  //create a static property called Log that returns the current value 
  //of the Instance field of the event source. This value is 
  //determined by the custom event methods called in the Customerservices application.
  private CustomerSvcEventSource() { }

  public static CustomerSvcEventSource Log
  {
    get { return Instance.Value; }
  }

  public class Keywords
  {
    public const EventKeywords Database = (EventKeywords)1;
    public const EventKeywords ParameterError = (EventKeywords)2;
    public const EventKeywords EntryPoint = (EventKeywords)4;
  }

  public class Tasks
  {
    public const EventTask DatabaseRead = (EventTask)1;
    public const EventTask DatabaseWrite = (EventTask)2;
    public const EventTask DatabaseRetry = (EventTask)3;
  }

  [Event(101, Message = "DB Retry in method {0}, MiscInfo = {1}, TryCount = {2}, "
    + "RetrySleepTime = {3}, ex = {4}",
    Level = EventLevel.Error, Keywords = Keywords.Database, Task = Tasks.DatabaseRead)]
  internal void DatabaseRetry(string methodName, string miscInfo, int tryCount, int sleepTime, 
    string exceptionInfo)
  {
    if (this.IsEnabled()) this.WriteEvent(101, methodName, miscInfo, tryCount, sleepTime, 
      exceptionInfo);
  }

  [Event(102, Message = "Method {0}; no data found, but should be. Input Info = {1}.",
    Level = EventLevel.Warning, Keywords = Keywords.Database, Task = Tasks.DatabaseRead)]
  internal void DatabaseRecordsNotFound(string methodName, string extraInfo, string errorMessage)
  {
    if (this.IsEnabled()) this.WriteEvent(102, methodName, extraInfo, errorMessage);
  }

  [Event(103, Message = "Message from method {0} = {1}", Level = EventLevel.Informational,
    Keywords = Keywords.Database, Task = Tasks.DatabaseRead)]
  internal void WriteDBInfoMsg(string methodName, string infoMessage)
  {
    if (this.IsEnabled()) this.WriteEvent(103, methodName, infoMessage);
  }

  [Event(104, Message = "Parameter error in method {0}, msg = {1}", Level = EventLevel.Error,
    Keywords = Keywords.ParameterError)]
  internal void ParameterError(string methodName, string errorMessage)
  {
    if (this.IsEnabled()) this.WriteEvent(104, methodName, errorMessage);
  }

  [Event(105, Message = "[GetCustomerFavorites] Called/entry point. FirstName = {0}, LastName = {1}",
    Level = EventLevel.Informational, Keywords = Keywords.EntryPoint)]
  internal void GetCustomerFavoritesCalled(string firstName, string lastName)
  {
    if (this.IsEnabled()) this.WriteEvent(105, firstName, lastName);
  }

  [Event(106, Message = "Method {0}, output params = {1}", Level = EventLevel.Informational, 
    Task = Tasks.DatabaseRead)]
  internal void OutputParams(string methodName, string paramString)
  {
    if (this.IsEnabled()) this.WriteEvent(106, methodName, paramString);
  }

  [Event(107, Message = "Unexpected exception in method {0}. Extra info = {1}. Ex = {2}", 
    Level = EventLevel.Error)]
  internal void UnexpectedException(string methodName, string miscInfo, string exceptionInfo)
  {
    if (this.IsEnabled()) this.WriteEvent(107, methodName, miscInfo, exceptionInfo);
  }

  [Event(108, Message = "Error converting the database fields to output parameters in method {0}. "
    + "ExtraInfo = {1}, ex = {2}",
    Level = EventLevel.Error, Keywords = Keywords.Database, Task = Tasks.DatabaseRead)]
  internal void DatabaseFieldConversionError(string methodName, string extraInfo, string errorMessage)
  {
    if (this.IsEnabled()) this.WriteEvent(108, methodName, extraInfo, errorMessage);
  }

  public static string FormatException(Exception exception)
  {
    return exception.GetType().ToString() + Environment.NewLine + exception.Message;
  }
}

And here is the final GetCustomerFavorites. I’ve left in the original trace logging, but commented out, so you can see how much cleaner the new calls are.

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);

    CustomerSvcEventSource.Log.GetCustomerFavoritesCalled(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 = "First and last name are blank.";

      CustomerSvcEventSource.Log.ParameterError("GetCustomerFavorites", errorMessage);
    }
    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.";

      CustomerSvcEventSource.Log.ParameterError("GetCustomerFavorites", errorMessage);
    }
    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.";

      CustomerSvcEventSource.Log.ParameterError("GetCustomerFavorites", errorMessage);
    }
    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);

      CustomerSvcEventSource.Log.ParameterError("GetCustomerFavorites", errorMessage);
    }
    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);

      CustomerSvcEventSource.Log.ParameterError("GetCustomerFavorites", errorMessage);
    }
    if (!string.IsNullOrWhiteSpace(errorMessage))
      return errorMessage;

    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);

                CustomerSvcEventSource.Log.DatabaseRecordsNotFound("GetCustomerFavorites", 
                  string.Format("FirstName = {0}, LastName = {1}", firstName, lastName),
                  errorMessage);
              }
              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);

                  string outputs = string.Format("favoriteMovie: {0}, favoriteLanguage: {1}", 
                    favoriteMovie, favoriteLanguage);
                  CustomerSvcEventSource.Log.OutputParams("GetCustomerFavorites", outputs);
                }
                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.";

                  CustomerSvcEventSource.Log.DatabaseFieldConversionError("GetCustomerFavorites",
                    string.Format("firstName = {0}, lastName = {1}", firstName, lastName),
                    CustomerSvcEventSource.FormatException(ex));
                }
              }
            }//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());

          CustomerSvcEventSource.Log.DatabaseRetry("GetCustomerFavorites",
            string.Format("FirstName = {0}, LastName = {1}", firstName, lastName),
            tryCount, GlobalStaticProperties.retrySleepTime[tryCount - 1], 
            CustomerSvcEventSource.FormatException(ex));

          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.";

        CustomerSvcEventSource.Log.UnexpectedException("GetCustomerFavorites", 
          String.Format("FirstName = {0}, LastName {1}", firstName, lastName), 
          CustomerSvcEventSource.FormatException(ex));
    }
    return errorMessage;
  }
}

I’ve run the service, and set it to have a bunch of errors, which were all logged to the default table for SLAB logging – SLABLogsTable. The table has a column for EventID, Keywords, Level, Message, Opscode, Task, Version, Payload, and then each parameter in the payload across all of the error messages: Payload_firstName, Payload_lastName, Payload_methodName, etc. I’ve exported the file to CSV and Excel if you want to take a look at them.

If you use the same field names, they will be put in the same column. So if I went back and changed this, I would change MiscInfo and ExtraInfo  and paramstring to all have the same names, they will all show up in the same column. This is not something you’re likely to search on, it’s just some extra information to identify the records being handled.

Finally, there re two things you want to be sure of:

• The id # in the attribute of the method used to write the event is the same as the id# in the WriteEvent call
• Don’t use the same id# more than once.

You can include the EventSourceAnalyzer in your project and write a unit test that will confirm your EventSource doesn’t have any configuration errors.

Summary

In this post, I showed how to set up an Event Source and a listener for it, and then take a class with trace logging and “SLAB-ify” it. This provided us with structured output and multiple fields we can query against directly, making it easier to get our data in a consistent format that we can later use for data mining.

Tags: Azure, Diagnostics, Logging, SLAB