Wed, 17 Aug 2011

Lightweight Tracing to Windows Azure Tables

I wrote a blog post last year called “Printf(‘HERE’) in the Cloud,” and I find it’s one of the posts I reference most frequently when helping people to debug their code in Windows Azure. The technique described in that post is useful because it’s just about the simplest form of logging you can implement. It’s easy to drop the code into a project and to immediately see the output. However, it has the drawback of making it hard to view all the logs together. (Each message logged goes into its own blob.)

To address that, I’ve implemented a custom TraceListener called smarx.TableTraceListener that logs messages immediately to table storage using a simple schema. This is meant to be used for lightweight tracing during the development phase of your project. For serious production logging, you’ll want to invest the time to understand and implement Windows Azure Diagnostics, which is more robust and cost-effective (fewer storage transactions due to batching) but is also harder to configure and introduces a delay between when you log something and when you can see it.

Usage

[UPDATE 8/17/2011] This is now a NuGet package, so you can just do install-package smarx.TableTraceListener. That will add the assembly to your project and register the listener in web.config or app.config.

To use the TraceListener in your project, just download and reference smarx.TableTraceListener.dll. (Yes, I should make it into a NuGet package. I simply haven’t learned how to do that yet.) Then add the trace listener in your web.config or app.config:

<system.diagnostics>
  <trace>
    <listeners>
      <add name="TableTraceListener"
           type="smarx.TableTraceListener.TableTraceListener, smarx.TableTraceListener"
           connectionStringName="LogConnectionString" />
    </listeners>
  </trace>
</system.diagnostics>

Note the connectionStringName attribute. That specifies which connection string to use for logging. It defaults to “DataConnectionString,” which is probably what you’re using in your application already, but if you want to log to a different storage account, you can control that.

Once you’ve configured the TraceListener, you can just use normal tracing methods like System.Diagnostics.Trace.WriteLine(…) in your code, and everything will be logged to a table called “log” in your storage account. To view the logs, I usually just fire up ClumsyLeaf TableXplorer. (Remember, this is supposed to be lightweight!) If you prefer, you can write your own code to query the logs. Here’s an ASP.NET MVC 3 controller action that grabs the top twenty log messages (for the current deployment ID) and sends them to a view:

public ActionResult Index()
{
    return View(CloudStorageAccount.Parse(RoleEnvironment.GetConfigurationSettingValue("LogConnectionString"))
        .CreateCloudTableClient().GetDataServiceContext().CreateQuery<LogMessage>("log")
        .Where(l => l.PartitionKey == RoleEnvironment.DeploymentId).Take(20));
}

Here’s the corresponding view, which just puts the messages into a list:

@using smarx.TableTraceListener;
@model IEnumerable<LogMessage>

<ul>
    @foreach (var message in Model)
    {
        <li>@message.Time: [@message.InstanceId] (@(message.Category ?? "none")) @message.Message</li>
    }
</ul>

Source

The code for the TraceListener is short enough that I can share it all here. I first created a class to represent log messages:

public class LogMessage : TableServiceEntity
{
    public DateTime Time { get; set; }
    public string Message { get; set; }
    public string InstanceId { get; set; }
    public string Category { get; set; }

    public LogMessage() { }
    public LogMessage(string message, string category)
    {
        Message = message;
        Category = category;
        Time = DateTime.UtcNow;
        InstanceId = RoleEnvironment.CurrentRoleInstance.Id;
        PartitionKey = RoleEnvironment.DeploymentId;
        RowKey = (DateTime.MaxValue.Ticks - Time.Ticks).ToString("d19");
    }
}

Each message includes a timestamp, the ID of the instance that generated the message, and the message itself (with an optional category). The partition key is the app’s deployment ID so it’s easy to find the messages from a specific deployment. (Otherwise messages from a staging deployment and a production deployment get intermixed, possibly even with messages from other applications sharing the same storage account.) The row key is the typical reverse timestamp to make sure new log messages appear on top.

The TraceListener itself is as follows:

public class TableTraceListener : TraceListener
{
    private TableServiceContext _context = null;
    private TableServiceContext context
    {
        get
        {
            if (_context == null)
            {
                var tables = CloudStorageAccount
                    .Parse(RoleEnvironment.GetConfigurationSettingValue(
                        Attributes["connectionStringName"] ?? "DataConnectionString"))
                    .CreateCloudTableClient();
                tables.CreateTableIfNotExist("log");
                _context = tables.GetDataServiceContext();
                _context.MergeOption = MergeOption.NoTracking;
            }
            return _context;
        }
    }

    protected override string[] GetSupportedAttributes() { return new[] { "connectionStringName" }; }

    public override void Write(string message, string category)
    {
        context.AddObject("log", new LogMessage(message, category));
        context.SaveChangesWithRetries();
    }

    public override void WriteLine(string message, string category) { Write(message + "\n", category); }
    public override void Write(string message) { Write(message, null); }
    public override void WriteLine(string message) { Write(message + "\n"); }
}

The actual work is done in the surprisingly short Write method, which creates a new LogMessage object and adds it to the table. The rest is setup (getting the connection string and ensuring the “log” table exists) and various overloaded methods. That’s it!

Downloads

I hope you find this useful, and be sure to check out this Friday’s episode of Cloud Cover, where we’ll talk about this and other logging techniques.