WCF Error Handling

For the last few posts I was focusing on logging from a Windows Azure Hosted Service. When implementing a WCF service, a common problem that I see is the lack of unhandled exception logging. This seems to be a feature that slips through the cracks until an application goes into production. I for one don’t blame the development teams for overlooking this because implementing this feature in WCF is no easy task.

So, here is a basic implementation of an error handling behaviour for WCF that can be re-used for multiple projects.

IErrorHandler

To start with, we will create a class that implements the IErrorHandler interface. This class will be in charge of sending the unhandled exceptions to log4net.

public class ErrorHandler : IErrorHandler
{
    private ILog _logger;
    public ErrorHandler()
    {
        _logger = LogManager.GetLogger(GetType());
    }

    public bool HandleError(Exception error)
    {
        _logger.Error(error.Message, error);
        return false;
    }

    public void ProvideFault(Exception error, MessageVersion version, ref Message fault)
    {
    }
}

The false return value indicates that WCF should abort the session, if true was returned the session would be kept alive.

ErrorHandlingBehavior

Once we have the error handler we need to attach it to the channel dispatcher. To accomplish this we need to write a behaviour. Note, this implementation inherits from Attribute so that this can be added to a service contract as an attribute. Later I will show how to configure the behaviour with the web.config file.

public class ErrorHandlingBehavior : Attribute, IServiceBehavior
{
    public void ApplyDispatchBehavior(ServiceDescription serviceDescription, System.ServiceModel.ServiceHostBase serviceHostBase)
    {
        var errorHandler = new ErrorHandler();
        foreach (ChannelDispatcher channelDispatcher in serviceHostBase.ChannelDispatchers)
        {
            channelDispatcher.ErrorHandlers.Add(errorHandler);
        }
    }

    public void Validate(ServiceDescription serviceDescription, System.ServiceModel.ServiceHostBase serviceHostBase)
    {
    }

    public void AddBindingParameters(ServiceDescription serviceDescription, System.ServiceModel.ServiceHostBase serviceHostBase, System.Collections.ObjectModel.Collection endpoints, System.ServiceModel.Channels.BindingParameterCollection bindingParameters)
    {
    }
}

Now if we stop the implementation here we can add this as an attribute to any service contract.

ErrorHandlingBehaviorExtension and web.config

The attribute may be a simple solution, however you may want to implement error handling on all the services without needing to modify each one. To accomplish this, you can use the default behaviour feature in .NET 4.0.

<system.serviceModel>   <extensions>     <behaviorExtensions>       <add name="ErrorLogging" type="WebService.ErrorLogging.ErrorHandlingBehaviorExtension, WebService" /> 
     </behaviorExtensions>   </extensions>   <behaviors>     <serviceBehaviors>       <behavior>         <!-- To avoid disclosing metadata information, set the value below to false and remove the metadata endpoint above before deployment -->         <serviceMetadata httpGetEnabled="true"/>         <!-- To receive exception details in faults for debugging purposes, set the value below to true.  Set to false before deployment to avoid disclosing exception information -->         <serviceDebug includeExceptionDetailInFaults="false"/>         <ErrorLogging />       </behavior>     </serviceBehaviors>   </behaviors>   <serviceHostingEnvironment multipleSiteBindingsEnabled="true" /> 
    </system.serviceModel>
namespace WebService.ErrorHandling
{
    public class ErrorHandlingBehaviorExtension : BehaviorExtensionElement
    {
        public override Type BehaviorType
        {
            get { return typeof(ErrorHandlingBehavior); }
        }

        protected override object CreateBehavior()
        {
            return new ErrorHandlingBehavior();
        }
    }
}

Well that should just about do it. Implementing these three classes will allow you to configure error logging for WCF services, including WCF HTTP services.

Thank you.

Logging in Azure: Part 3-Trace/Event Logs

This is the third and final entry on this series on logging from an Azure hosted service.

These topics included:

1. Synchronizing a log file to blob storage
2. Using a custom log4net appender to write directly to table storage
3. Logging to the Trace log and synchronizing to table storage

These solutions are in order of complexity (in my opinion). Each topic outlines the structure of the solution, how to implement it, and the pros/cons of the solution compared to the others.

3. Logging to the Trace log

I left this solution for last not because of ease-of-use, the setup for trace logging is fairly simple, to me this is the most complex because of the amount of components in place.

There are a number of features built into the Azure Diagnostics Module. The purpose of this module is to forward valuable diagnostic information to a storage account, there it can be reviewed manually or consumed by an application like System Center Operations Manager. Trace logs are included in the diagnostic data that can be managed by the Azure Diagnostics Module. This final solution involves setting up the diagnostics monitor, configuring a Trace Listener, and finally configuring log4net to write to the Trace Log. This includes a few steps so in summary this is the path of the log message.

log4net >> Trace Log >> Diagnostics Listener >> Diagnostics Monitor >> Table Storage

A similar solution can be configured with Event Logs which has the following flow.

log4net >> Event Log >> Diagnostic Monitor >> Table Storage

Setup

This example will mainly use the app.config file for the Trace Listener configuration but this could also be done programmatically with the Trace static class.

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
  </configSections>
  <log4net>
    <appender name="TraceAppender" type="log4net.Appender.TraceAppender">
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline" />
      </layout>
    </appender>
    <root>
      <level value="INFO" />
      <appender-ref ref="TraceAppender" />
    </root>
  </log4net>
  <system.diagnostics>
    <trace>
      <listeners>
        <add type="Microsoft.WindowsAzure.Diagnostics.DiagnosticMonitorTraceListener, Microsoft.WindowsAzure.Diagnostics, Version=1.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35"
          name="AzureDiagnostics">
          <filter type="" />
        </add>
      </listeners>
    </trace>
  </system.diagnostics>
</configuration>

Once the Diagnostic Monitor Trace Listener is setup the trace messages will be sent to the diagnostic monitor. The following code will setup and start the monitor.

public override bool OnStart()
{
    var diagnostics = DiagnosticMonitor.GetDefaultInitialConfiguration();

    diagnostics.Logs.ScheduledTransferLogLevelFilter = LogLevel.Verbose;
    diagnostics.Logs.ScheduledTransferPeriod = TimeSpan.FromMinutes(1);

    CloudStorageAccount account = CloudStorageAccount.Parse(
        RoleEnvironment.GetConfigurationSettingValue(
            "Microsoft.WindowsAzure.Plugins.Diagnostics.ConnectionString"));

    DiagnosticMonitor.Start(account, diagnostics);

    return base.OnStart();
}

Setting the Verbose level allows the log4net appender and filters to set logging level, this will allow all messages through to the logger. The Logs property configures the Trace logs, to setup the event logs use the .WindowsEventLogs property. Finally to configure log4net and write messages use the following code. This is the same code in all the solutions.

private ILog _logger;

public override void Run()
{
    XmlConfigurator.Configure();

    _logger = LogManager.GetLogger(GetType());

    _logger.Info("Starting Worker Role");

    while (true)
    {
        Thread.Sleep(10000);
        _logger.Info("Waiting 10 Seconds");
    }
}

Pros / Cons

Pros: This solution requires very little setup and can be done with mainly configuration. The log messages are stored in Table Storage, the message rows contain lots of information about the logging level, process and other Azure hosted service information. The biggest pro for this solution is that the log messages can be consumed by System Center Operations Manager. Also, the log tables can be managed with the PowerShell cmdlets.

Cons: If not configured correctly this solution can be difficult to debug, mainly due to the amount of components involved. Compared to Part 2 (straight to Table Storage) you have no control over the columns which makes querying for trends very difficult, even impossible since Table Storage does not support a “contains” clause.

Like all of the solutions the need to be combined with a log management system to archive or truncate the log messages. This is more important with Azure storage because you are charged per GB of storage.

Summary

I hope this series has given you some information on logging from an Azure Hosted Service. I know writing them has helped me work through some of the subtle differences in the logging mechanisms.

There are a variety of solutions for logging and diagnostics in Azure, the most common are the three presented. If you have any questions about the solutions please leave a comment or contact me on Twitter @tyler_gd.

As always, thank you for reading.

Logging in Azure: Part 2–Table Storage

This entry is part 2 in a series outlining different solutions for writing logs from an Azure hosted service.

So far the solutions include (subject to change):

1. Synchronizing a log file to blob storage
2. Using a custom log4net appender to write directly to table storage
3. Logging to the Trace log and synchronizing to table storage

These solutions are in order of complexity (in my opinion). Each topic will outline the structure of the solution, how to implement it, and the pros/cons of the solution compared to the others.

2. Using a custom appender to write to Table Storage

Compared to the previous solution this has fewer components, but requires more to setup. In Part 1 the Diagnostics Module did most of the work, the only requirement was a location that contained log files. There were 2 main phases, writing to a file then synchronizing the file to blobs. There was no dependency between the mechanism creating the file (log4net) and the sync process (Diagnostics Module).

In this solution we will create a log4net appender which takes logging events and persists them directly to table storage. Here we will have a direct dependency between log4net and Azure Table Storage. Even with that dependency this solution can be configured into an existing application because the code itself only interacts with the log4net API.

Before I start the implementation, this code is based off a blog post and source code by Vidar Kongsli.

Table Storage Entity

An Entity object is required to store data to Table Storage. This can contain as much or as little data as needed.

public sealed class LogEventEntity : TableServiceEntity
{
    public LogEventEntity()
    {
        var now = DateTime.UtcNow;
        PartitionKey = string.Format("{0:yyyy-MM}", now);
        RowKey = string.Format("{0:dd HH:mm:ss.fff}-{1}",
                                now, Guid.NewGuid());
    }

    public string Identity { get; set; }
    public string ThreadName { get; set; }
    public string LoggerName { get; set; }
    public string Level { get; set; }
    public string Message { get; set; }
    public string Domain { get; set; }
    public string RoleInstance { get; set; }
    public string DeploymentId { get; set; }
}

Some other implementations implement a subclass of Table Service Context but, as I mentioned in a previous post, I don’t think that is necessary.

log4net Appender Implementation

To implement a log4net appender just inherit from AppenderSkeleton. When this appender is activated we need to setup the table storage configuration and create a new table data context instance. For the purposes of this article I’ll assume that this appender will only be used in an Azure hosted service context and use the configuration from the Role Environment. Table Storage can be used from anywhere so to make this implementation more portable just add more configuration.

public class TableStorageAppender : AppenderSkeleton
{
    private string _connectionStringKey =
        "Microsoft.WindowsAzure.Plugins.Diagnostics.ConnectionString";
    private string _tableName = "LogEntities";
    private TableServiceContext _dataContext;

    public string ConnectionStringKey
    {
        get { return _connectionStringKey; }
        set { _connectionStringKey = value; }
    }

    public string TableName
    {
        get { return _tableName; }
        set { _tableName = value; }
    }

    public override void ActivateOptions()
    {
        base.ActivateOptions();

        var connectionString = RoleEnvironment.GetConfigurationSettingValue(ConnectionStringKey);
        var account = CloudStorageAccount.Parse(connectionString);

        var tableClient = account.CreateCloudTableClient();
        tableClient.CreateTableIfNotExist(TableName);

        _dataContext = tableClient.GetDataServiceContext();
    }

    protected override void Append(LoggingEvent loggingEvent)
    {
        try
        {
            var entity = new LogEventEntity
                                {
                                    RoleInstance = RoleEnvironment.CurrentRoleInstance.Id,
                                    DeploymentId = RoleEnvironment.DeploymentId,
                                    Message = loggingEvent.RenderedMessage,
                                    Level = loggingEvent.Level.Name,
                                    LoggerName = loggingEvent.LoggerName,
                                    Domain = loggingEvent.Domain,
                                    ThreadName = loggingEvent.ThreadName,
                                    Identity = loggingEvent.Identity
                                };

            _dataContext.AddObject(TableName, entity);
            _dataContext.SaveChanges();
        }
        catch (DataServiceRequestException drex )
        {
            ErrorHandler.Error("Could not write log entry", drex);
        }
    }
}

Notice that 2 properties were added, for the configuration key the only reason that the diagnostics string is being used is out of convenience. This solution does not depend on the diagnostics module.

Configuration

Now that we have the storage entity and the appender the final step is to setup the appender in our log4net configuration section. When adding this implementation as a reference note that 3 other assemblies are needed:

Microsoft.WindowsAzure.ServiceRuntime

Microsoft.WindowsAzure.StorageClient

System.Data.Services.Client

To add this appender with no changes to the default configuration add the following to the app.config file

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configsections>
    <section type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" name="log4net" />
  </configsections>
  <log4net>
    <appender type="AzureLogAppender.TableStorageAppender, AzureLogAppender" name="TableStorageAppender">
    </appender>
    <root>
      <level value="INFO" />
      <appender-ref ref="TableStorageAppender" />
    </root>
  </log4net>
</configuration>

In this example I used a separate assembly for the appender (AzureLogAppender.dll) and referenced the assembly in the role project.

Pros / Cons

Pros: This solution requires some code but gives you full control over the logging component. Compared to the log files and trace logging, there are fewer components and less dependencies. With table storage the log messages can be easily queried for errors or trends.

Cons: The appender is less slightly slower then the out-of-the-box file appenders. Also, if left unmanaged the log table will continue to grow. These issues can be overcome with some thread management and a log truncating process.

So that is the table storage logging solution. The next solution involves a combination of the log4net configuration and diagnostic module to wrote to the Windows Azure Diagnostic Trace logs.

Thank you.