In this post I wanted to explore the options around building a Windows Azure Service Bus appender for log4net (sample download). This would allow me to publish logging events outside of my application to an internet scale messaging system which can then provide opportunities to centrally store or process messages from all of my applications. This article is part of a few articles I will write while playing with the architectural idea of the centralized logging based on Azure Service Bus but in this case specifically focusing on a log4net appender that can be used by custom applications.
At this point I am going to assume you have some familiarity with log4net and Windows Azure Service Bus but only a basic level should be required.
To begin with in this article I want to start by writing an appender which I will plug into log4net. This will allow me to have a custom widget which I can use to process logging events from log4net and where I can decide what I want to do with them. This is the normal log4net approach and when you configure a logger through your .net configuration file you would normally specify a set of appenders which will process any log events your application creates. By default log4net comes with a set of appenders which you can configure out of the box but also I can write my own by deriving from the AppenderSkeleton class in log4net. This means that I can declare some properties to receive configuration data for my appender and then override a few methods and have quite an easy way to implement my appender.
Once I have written my appender I just need to make sure that the dll containing my appender is in the application bin directory and my configuration file references my appender then I should be good to go.
Below is an example of the appender configuration you would use for the ServiceBusAppender in your log4net configuration file.
There are a couple of key properties here:
This property is a string which points to a connection string you have declared in the config file. The connection string you have declared will be a connection string for a Windows Azure Service Bus Namespace
This is the name of a queue or topic in the Windows Azure Service bus which you would like to publish the message to
The application name property will be used to indicate on the log message which application published the message.
The event type is used to indicate what type of event it is. An example of where you might use this is if you have multiple loggers using different instances of the appender which are configured differently, then you might use this to indicate the types of events being published. An example might be publishing audit events and standard logging events.
Normally as you process flows across components you would include in this flow some context to relate execution in different places. An example of how you might do this would be to create a unique id when the user first clicks a button and then flow this through a web service call and into another component. From here you would usually use the log4net ThreadContext to set these variables to be available to each component as they begin executing. In this case the correlation id is a useful property to allow us to relate log messages from different components. In the configuration the CorrelationIdPropertyName allows you to specify the name of the log4net property that holds the CorrelationId in this component. This correlation id is then used as a specific element on the published log event.
The synchronous property allows you to control if an event is published on a background thread or not. There is a performance gain in publishing on a background thread but the trade of is you can't as easily respond to errors. For normal logging events you're probably happy to swallow the error and continue, but perhaps for audit events you might not want to do this.
In addition to the specific configuration properties the rest of the normal log4net stuff pretty much applies. As an example you can use the Appender filtering mechanism to control which messages are processed by the appender.
What happens inside the appender?
Inside the appender the code will start by creating an instance of the AzureLoggingEvent which is a type which will encapsulate the data I want to publish and setup the data as appropriate. The appender will then decide if you want to publish synchronously or asynchronously and then call the Internal Append method. In the internal append method we will serialize the AzureLoggingEvent to a JSON string to be the body of the published message. We will then setup the following context properties on the Azure Service Bus Brokered Message:
These properties will allow you to do some routing if you have published the message to a topic. Examples of routing uses could include:
- Creating a higher processing priority for certain messages (perhaps Errors need to be processed quicker)
- Routing for specific messages to also go to an operator who is looking for activity for a specific user
I'm sure you can think of other examples.
The Appender will then create a MessageingFactory, MessageSender and the other Azure Service Bus objects as required and will send the message. A quick point to note is Ill probably have a look at some point to include the transient error handling block but for now I have just included a basic retry mechanism (very basic).
Using the Appender
To illustrate the user of the log4net appender I've included a sample to show you how it can be used. In this sample I want to create three log4net loggers:
The application logger is a basic logger which will just use the console appender and event log appender to record information locally. This is just application diagnostic info.
The global logger is intended to be used when the application needs to publish information to the Azure Service Bus for general log events. This logger will process log events asynchronously
The audit logger will send out audit events using the Azure Service Bus appender but will do it synchronously.
The configuration for setting up the appender looks like the below example:
Step 1 - Loggers
The configuration to setup the loggers is below
There are 3 loggers as described above with the GlobalLogger and AuditLogger being the ones which will send messages to Azure Service Bus.
Step 2 - Appenders
The configuration for the appenders is below:
In the appenders you can see how the settings indicate each appender will send to different queues/topics in Azure Service Bus.
Step 3 Initialize Log4net
In the sample code when the console application starts I begin by setting up my loggers:
ApplicationLogger = log4net.LogManager.GetLogger(typeof(Program));
AuditLogger = log4net.LogManager.GetLogger("AuditLogger");
GlobalLogger = log4net.LogManager.GetLogger("GlobalLogger");
Step 4 Setup my Correlation ID
I then setup my correlation id property using the below example. Note that in this sample it's a really basic implementation but if you were flowing the correlation id across components then this would be a little more involved.
log4net.ThreadContext.Properties["CorrelationId"] = Guid.NewGuid();
Step 5 Adding the Application Code
After this I will execute some code to log different messages to different loggers in my application.
for (int i = 0; i <= 1000; i++)
ApplicationLogger.Info("This is info");
GlobalLogger.Info("The application has started");
//lots of code.....
ApplicationLogger.Debug("Ive done something");
ApplicationLogger.Debug("About to audit");
AuditLogger.Info("About to do something important");
//.... doing some work
ApplicationException("This is an error");
//... log error locally
ApplicationLogger.Error("There was an error", ex);
//... send error to central error system
GlobalLogger.Error("There was an error", ex);
This results in a bunch of messages going to log4net. Some of them will be filtered out because the log4net configuration says we aren't interested in them and some will be sent to Windows Azure Service Bus.
Step 6 Configuring Azure Service Bus
The key thing here is that you can configure it however you like. As long as it matches the configuration of the MessageEntity and Connection string in the log4net configuration it will work fine. For this demo I have created the following queue setup:
There is an audit message queue which all events from the audit logger will be sent to. There is also a logging topic for the general logging events. On the loggingtopic I have created some subscriptions to demonstrate how you could filter messages. The first subscription is an all events subscription using the 1=1 routing rule so that it will get all messages. The Just Errors subscription has a rule of Level='Error' so that it will only get errors. You can create filter rules based on any of the properties we earlier published as context properties on the service bus message.
You can see that at this point its quite easy to configure a flexible routing of events depending on what you want to do with the events once they reach service bus.
You are now ready to run the sample and publish logging messages.
What does the message look like?
After running the demo you will see that the queue or subscription will have a lot of messages on it. You can use Service Bus Explorer to take a look at the details. The below picture shows you an example of one message.
You can see here that there are the context properties I described on the message in the Message Custom Properties box. These are what you can filter on. The message text is also the JSON string I mentioned earlier. It will look something like the below:
"ExceptionMessage":"This is an error",
"RenderedMessage":"There was an error",
"ExceptionString":"System.ApplicationException: This is an error\r\n at MyLog4net.Program.Main(String args) in c:\\Users\\Michael\\Documents\\Visual Studio 2013\\Projects\\MyLog4net\\MyLog4net\\Program.cs:line 37",
"FileName":"c:\\Users\\Michael\\Documents\\Visual Studio 2013\\Projects\\MyLog4net\\MyLog4net\\Program.cs",
"FullInfo":"MyLog4net.Program.Main(c:\\Users\\Michael\\Documents\\Visual Studio 2013\\Projects\\MyLog4net\\MyLog4net\\Program.cs:44)",
We now have the capability to have some fairly useful logging information centrally published with the ability to process it.
What might I do with this now?
Now that we have messages on Azure Service Bus queues the most obvious thing to do with them might be to have a Worker Role or similar which polls the messages and then saves them to a database for operational analysis. I'll probably talk about that in a future post but for now the messages are somewhere safe and somewhere you can do some interesting stuff with them.
The sample can be downloaded from the following location:
As you can see it was really easy to implement this appender. Feel free to get the sample and give it a try or modify it if you choose. The one caveat is that this was only some R&D so I haven't really tried this in a production setup to see how it performs.