Posts Tagged

Nuget

When disaster strikes: the complete guide to Failover Appenders in Log4net

Log4Net is a cool, stable, fully featured, highly configurable, highly customizable and open source logging framework for .Net.

One of its powerful features is that it can be used to write logs to multiple targets, by using “Appenders”.
An Appender is a Log4Net component that handles log events; It receives a log event each time a new message is logged and it ‘handles’ the event. For example, a simple file appender will write the new log event to a local file.

Although there are a lot of Log4Net Appenders that are included in the Log4net framework, occasionally we won’t find one that fully satisfies our needs. During a project I was working on, I had to implement a failover mechanism for logging, where the app had to start logging to a remote service, and then failback to a local file system if that remote service wasn’t reachable anymore.

Fortunately, Log4Net allows us implement our own Custom Appenders.
The Appender had to start writing logs to a remote service, and fallback to a local disk file after the first failed attempt to send a log message to that service.

Implementing the Appender

To create a custom Appender we have to implement the IAppender interface. Although easy to implement, Log4Net makes it even simpler by providing the AppenderSkeleton abstract class, which implements IAppender and adds common functionalities on top of it.

public class FailoverAppender : AppenderSkeleton
{
    private AppenderSkeleton _primaryAppender;
    private AppenderSkeleton _failOverAppender;

    //Public setters are necessary for configuring
    //the appender using a config file
    public AppenderSkeleton PrimaryAppender 
    { 
        get { return _primaryAppender;} 
        set 
        { 
             _primaryAppender = value; 
             SetAppenderErrorHandler(value); 
        } 
    }

    public AppenderSkeleton FailOverAppender 
    { 
        get { return _failOverAppender; } 
        set 
        { 
            _failOverAppender = value; 
            SetAppenderErrorHandler(value); 
        } 
    }

    public IErrorHandler DefaultErrorHandler { get; set; }

    //Whether to use the failover Appender or not
    public bool LogToFailOverAppender { get; private set; }

    public FailoverAppender()
    {
        //The ErrorHandler property is defined in
        //AppenderSkeleton
        DefaultErrorHandler = ErrorHandler;
        ErrorHandler = new FailOverErrorHandler(this);
    }

    protected override void Append(LoggingEvent loggingEvent)
    {
        if (LogToFailOverAppender)
        {
            _failOverAppender?.DoAppend(loggingEvent);
        }
        else
        {
            try
            {
                _primaryAppender?.DoAppend(loggingEvent);
            }
            catch
            {
                ActivateFailOverMode();
                Append(loggingEvent);
            }
        }
    }

    private void SetAppenderErrorHandler(AppenderSkeleton appender)
        => appender.ErrorHandler = new PropogateErrorHandler();

    internal void ActivateFailOverMode()
    {
        ErrorHandler = DefaultErrorHandler;
        LogToFailOverAppender = true;
    }
}

The FailoverAppender above accepts two appenders; a primary appender and a failover appender.

By default it will propagate Log events only to the primary appender, but in case an exception is thrown from the primary appender during event logging , it will stop sending log events to that appender and instead it starts propagating log events only to the failover appender.

I’ve used AppenderSkeleton to reference both the primary and the failover appenders in order to utilize a functionality in the AppenderSkeleton class – in this case the ability to handle errors (a.k.a Exceptions) that were thrown during an appender attempt to log an event.
We can do so by assigning the ErrorHandler property defined in AppenderSkeleton an object.

I use the LogToFailOverAppender flag to determine whether we are in ‘normal’ mode or in ‘FailOver’ mode.

The actual logging logic exists in the overridden ‘Append’ method:

protected override void Append(LoggingEvent loggingEvent)
{
    if (LogToFailOverAppender)
    {
        _failOverAppender?.DoAppend(loggingEvent);
    }
    else
    {
        try
        {
            _primaryAppender?.DoAppend(loggingEvent);
        }
        catch
        {
            ActivateFailOverMode();
            Append(loggingEvent);
        }
    }
}

If the LogToFailOverAppender flag is active, it logs events using the failover appender, as it means an exception has been thrown already. Otherwise, it logs events using the primary appender, and it will activate the failover mode, if an exception is thrown during that time.

The following are the IErrorHandlers that I defined and used

/*
This is important. 
By default the AppenderSkeleton's ErrorHandler doesn't
propagate exceptions
*/
class PropogateErrorHandler : IErrorHandler
{
    public void Error(string message, Exception e, ErrorCode errorCode)
    {
        throw new AggregateException(message, e);
    }

    public void Error(string message, Exception e)
    {
        throw new AggregateException(message, e);
    }

    public void Error(string message)
    {
        throw new LogException($"Error logging an event: {message}");
    }
}
/*
This is just in case something bad happens. It signals 
the FailoverAppender to use the failback appender.
*/
class FailOverErrorHandler : IErrorHandler
{
    public FailOverAppender FailOverAppender { get; set; }
        
    public FailOverErrorHandler(FailOverAppender failOverAppender)
    {
        FailOverAppender = failOverAppender;
    }

    public void Error(string message, Exception e, ErrorCode errorCode)
        => FailOverAppender.ActivateFailOverMode();

    public void Error(string message, Exception e)
        => FailOverAppender.ActivateFailOverMode();

    public void Error(string message)
        => FailOverAppender.ActivateFailOverMode();
}

Testing the Appender

I’ve created a config file you can use to test the appender. These are the important bits:

<!--This custom appender handles failovers. If the first appender fails, it'll delegate the message to the back appender-->
<appender name="FailoverAppender" type="MoreAppenders.FailoverAppender">
    <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger - %message%newline"/>
    </layout>

    <!--This is a custom test appender that will always throw an exception -->
    <!--The first and the default appender that will be used.-->
    <PrimaryAppender type="MoreAppenders.ExceptionThrowerAppender" >
        <ThrowExceptionForCount value="1" />
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%date [%thread] %-5level %logger - %message%newline"/>
        </layout>        
    </PrimaryAppender>

    <!--This appender will be used only if the PrimaryAppender has failed-->
    <FailOverAppender type="log4net.Appender.RollingFileAppender">
        <file value="log.txt"/>
        <rollingStyle value="Size"/>
        <maxSizeRollBackups value="10"/>
        <maximumFileSize value="100mb"/>
        <appendToFile value="true"/>
        <staticLogFileName value="true"/>
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%date [%thread] %-5level %logger - %message%newline"/>
        </layout>
    </FailOverAppender>
</appender>

In this post I’ll discuss the parts that are relevant to the appender. You can find the full config file here. The rest of the config file are a regular Log4Net configurations, which you can read more about here and here.

Log4Net has a feature that give us an ability to instantiate and assign values to public properties of appenders in the config file using XML. I’m using this feature to instantiate and assign values to both the PrimaryAppender and the FailOverAppender properties.

In this section I’m instantiating the PrimaryAppender:

<PrimaryAppender type="MoreAppenders.ExceptionThrowerAppender" >
    <ThrowExceptionForCount value="1" />
    <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger - %message%newline"/>
    </layout>        
</PrimaryAppender>

The type attribute’s value is the fully qualified name of the appender’s class.
For our example, I’ve created the ExceptionThrowerAppender appender for testing purposes. It can be configured to throw exceptions once per a certain amount of log events.

In a similar manner, in the following XML I’ve instantiated and configured the FailOverApppender to be a regular RollingFileAppender

<FailOverAppender type="log4net.Appender.RollingFileAppender">
    <file value="log.txt"/>
    <rollingStyle value="Size"/>
    <maxSizeRollBackups value="10"/>
    <maximumFileSize value="100mb"/>
    <appendToFile value="true"/>
    <staticLogFileName value="true"/>
    <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger - %message%newline"/>
    </layout>
</FailOverAppender>

I used the following code to create log events:

class Program
{
    static void Main(string[] args)
    {
        XmlConfigurator.Configure();

        var logger = LogManager.GetLogger(typeof(Program));

        for (var index = 0; index < int.MaxValue; ++index)
        {
            logger.Debug($"This is a debug message number {index}");
        }

        Console.ReadLine();
    }
}

I started the program in debug mode and placed a breakpoint inside the ‘Append’ method:

First logging message - goes to the primary appender

Notice how OzCode’s Predict the Future feature marks the if-statement with an X and with a red background, telling us that the condition is evaluated to false. That means an exception wasn’t thrown yet from the primary appender.

In order to make figuring out the loggingEvent message value easier, I’ve used OzCode’s Magic Glance feature to view the necessary information in every LoggingEvent object.

Selecting the properties to show

The result:

Magic Glance feature

By continuing the program, the primary appender will handle the logging event, and it will throw an exception

Exception is thrown.

After that exception is propagated by the ErrorHandler, it will be handled by the catch-clause, which activates the FailOverAppender mode (notice how the log event is sent to the FailOverAppender as well) which would send future logging events only to the FailOverAppender

FailOverAppender mode is active

This time the if-statement is marked by a green ‘V’ . This tell us that the condition is evaluated to be true and that it will execute the if-statement body (sends the logging-event to the failover appender).

You can view and download the code by visiting this GitHub Repository.

Summary

Log4Net is a well-known logging framework for .Net. The framework comes with a list of out-of-the-box Appenders that we can use in our programs.
Although these Appenders are usually sufficient for most of us, sometimes you’ll need Appenders that are more customized for your needs.

We saw how we can use Log4Net’s extensibility features to implement our own Log4Net custom Appenders. In this example, we have created a Fail-over mechanism for Appenders that we can use to change the active Appender when it is failing to append log messages.

Log4Net is highly extensible and it has many more extensibility features that I encourage you to explore.

Note: this post is published also at OzCode’s blog.

Code Generation Chronicles #1 – Using Fody to Inject KnownType attributes

Code Generation Chronicles

As part of my new year resolutions, I’ve decided to put more effort in learning code generation techniques.

This is the first blog post in a series exploring code generation. Although I won’t always dive into the internals, I do promise that I’ll show examples of what we can achieve with each technique and when it is better to use each one.

Fody

Fody is an open source library for IL weaving. It can generate and manipulate IL code during build time.
Getting Fody is easy – it is available as a Nuget Package and doesn’t require any installation/modification to the build system.

One of the benefits of using Fody is that there is no footprint – since the IL weaving is done during build time, there aren’t any Fody-related assemblies needed at runtime, which could be a good thing if you worried about your project dependencies or the number of assemblies you ship with your product.
And on top of that Fody is highly extensible and there is an active open source community around it.

One example for how Fody can save developer’s time is such extension: “PropertyChanged” which works by placing the ImplementPropertyChanged attribute it provides on a class, it will generate all of the code necessary to fully implement the INotifyPropertyChanged interface in that class.
More extensions can be found here.

Using Fody to add WCF’s KnownType attributes

At work we’ve used a client which was implemented using .Net Remoting as the communication model for it services. At some point, we wanted to exchange .Net Remoting with the more modern WCF. The problem was that a lot of the code base was unmaintainable legacy code, and we’ve wanted to perform as little changes as possible, and reuse as much of the existing architecture as we could.
One of the challenges resided in a WCF quirk, were by default it doesn’t allow passing a derived type of the DataContract type that is defined in the OperationContract.
The way to make derived classes work is done in WCF by adding a KnownType attribute on the base type for each derived type we use.
As an example, if we have a class A and two derived classes B and C, we would have to add two KnownType attributes over class A; one for Class B and one for Class C.

[KnownType(typeof(B))]
[KnownType(typeof(C))]
class A
{
}

class B : A
{
}

class C : A
{
}

Since this scenario was common in the current architecture, we were looking for a way to solve this issue without manually adding KnownType attributes, since it would be easy to miss some or to forget adding the attribute over new derived classes in the future.

In the end we’ve managed to save time and replace the communication layer easily by using Fody for automatically adding KnownType attributes for all derived types on their base classes during build time.

Implementing a Fody extension

If you want to write Fody extension start by cloning the BasicFodyAddin repository. This repository is maintained by the open source community and it simplifies both the implementation and the deployment of the extension as a Nuget Package.
BasicFodyAddin source code contains a Solution with four C# projects:

  1. BasicFodyAddin which will contain the extension
  2. Nuget which is for deploying a Nuget package
  3. Tests for writing unit tests
  4. AssemblyToProcess that is used as a target assembly for testing your mew Fody extension.

We will focus on BasicFodyAddin.

In the BasicFodyAddin project there is a file called ModuleWeaver.cs Go ahead and replace it content with the following code:

using System;
using System.Linq;
using Mono.Cecil;
using Mono.Cecil.Rocks;

namespace KnownTypes.Fody
{
   public class ModuleWeaver
   {
      public ModuleDefinition ModuleDefinition { get; set; }
   
      public void Execute()
      {
      }

      void AddKnownTypeAttributes(ModuleDefinition module, TypeDefinition baseType)
      {
      }

      void RemoveKnowsDeriveTypesAttribute(TypeDefinition baseType)
      {
      }
   }
}

This is the class we will use to implement the extension. The ModuleDefinition property will be populated during build time by Fody and it will contain the target Module for the IL Weaving.
As you have probably noticed, the property is of type ModuleDefinition.
ModuleDefinition is a class representing a MSIL Module in Mono.Cecil which is a library Fody relies on to generate and manipulate IL code. In addition to ModuleDefinition we will use more types it defines such as TypeDefinition.

When using Fody your ModuleWeaver class must be implemented according the following:

  • Be public, instance and not abstract.
  • Have an empty constructor.
  • Have a ModuleDefinition property that will be populated during build.
  • Have an Execute method.

The KnownTypeAttributeWeaver class has three main methods:

  • Execute – Entry point. It calls other methods for performing the IL weaving.
  • AddKnownTypeAttributes – Decorates base types with KnownType attributes.
  • RemoveKnowsDeriveTypesAttribute – Removes KnowsDeriveTypes attributes from base types

Note: A few helper methods will be added down the road.

 

Now create another a new class called KnowsDeriveTypesAttribute.

[AttributeUsage(AttributeTargets.Class, Inherited = false)]
public class KnowsDeriveTypesAttribute : Attribute
{
}

This attribute is for explicitly specifying the base types we want to decorate with KnownType attributes. We could have added KnownType attributes over every base class in the assembly, but we wanted the extra control.

Implementing Execute

public void Execute()
{
   foreach (var type in ModuleDefinition.GetTypes().Where(HasKnownDeriveTypesAttribute))
   {
      AddKnownTypeAttributes(module, type);
      RemoveKnowsDeriveTypesAttribute(type);
   }
}

//A helper method 
//For filtering the types without the KnowsDeriveTypes Attribute.
bool HasKnownDeriveTypesAttribute(TypeDefinition type) => 
   type.CustomAttributes.Any(attr => attr.AttributeType.FullName == typeof(KnowsDerivativeTypesAttribute).FullName);

In Execute we locate all the types decorated with KnowsDeriveTypesAttribute, and we decorate them with KnownType attributes according to their sub types.
After that is done, we remove the KnowsDeriveTypesAttribute as it isn’t necessary anymore.

Implementing AddKnownTypeAttributes

void AddKnownTypeAttributes(ModuleDefinition module, TypeDefinition baseType)
{
   //Locate derived types
   var derivedTypes = GetDerivedTypes(module, baseType);

   //Gets a TypeDefinition representing the KnownTypeAttribute type.
   var knownTypeAttributeTypeDefinition = GetTypeDefinition(module, "System.Runtime.Serialization", "KnownTypeAttribute");

   //Gets the constructor for the KnownTypeAttribute type.
   var knownTypeConstrcutor = GetConstructorForKnownTypeAttribute(module, knownTypeAttributeTypeDefinition);

   //Adds KnownType attribute for each derive type
   foreach (var derivedType in derivedTypes)
   {
      var attribute = new CustomAttribute(constructorToUse);
      attribute.ConstructorArguments.Add(new CustomAttributeArgument(constructorToUse.Parameters.First().ParameterType, derivedType));

      baseType.CustomAttributes.Add(attribute);
   }
}

Let’s break it down.

//Locate derived types
var derivedTypes = GetDerivedTypes(module, baseType);

//Gets a TypeDefinition representing the KnownTypeAttribute type.
var knownTypeAttributeTypeDefinition = GetTypeDefinition(module, "System.Runtime.Serialization", "KnownTypeAttribute");

//Gets the constructor for the KnownTypeAttribute type.
var knownTypeConstrcutor = GetConstructorForKnownTypeAttribute(module, knownTypeAttributeTypeDefinition);

In the code above we are performing three steps:

  1. Finding and retrieving all derived types of the given base type.
  2. Creating a TypeDefinition instance for the KnownType attribute.
  3. Finding and retrieving a constructor for the KnownType attribute.

The first step is done using a helper method called GetDerivedTypes.

Given a module and a type it returns an array of TypeDefinitions, containing all of the types in the given module that derive from the given type

The second step is done using a helper method called GetTypeDefinition.

Given an assembly name and a type name, it returns a TypeDefinition for that type.

The third step is done using a helper method called GetConstructorForKnownTypeAttribute.

Given a ModuleDefinition and a TypeDefinition it returns a the first constructor for that type.

//A helper method. Given a module and a baes type:
//It returns all derived types of that base type.
TypeDefinition[] GetDerivedTypes(ModuleDefinition module, TypeDefinition baseType)
   => module.GetTypes()
         .Where(type => type.BaseType?.FullName == baseType.FullName)
         .ToArray();

//A helper method. Given an assembly and a type name:
//It returns a TypeDefinision for that type.
TypeDefinition GetTypeDefinition(ModuleDefinition module, string assemblyName, string typeName) 
   => module.AssemblyResolver
         .Resolve(assemblyName)
         .MainModule.Types.Single(type => type.Name == typeName);

//A helper method. Given a module and type definition for the KnownType Attribute:
//It returns the constructor for the attribute accepting a System.Type object.
MethodReference GetConstructorForKnownTypeAttribute(ModuleDefinition module, TypeDefinition knownTypeAttributeTypeDefinition)
{
   var constructorMethodToImport = knownTypeAttributeTypeDefinition
                                     .GetConstructors()
                                     .Single(ctor => 1 == ctor.Parameters.Count && "System.Type" == ctor.Parameters[0].ParameterType.FullName);

   return module.Import(constructorMethodToImport);
}

Let’s continue and break down the last part of AddKnownTypeAttributes.

//Adds KnownType attribute for each derive type
foreach (var derivedType in derivedTypes)
{
   var attribute = new CustomAttribute(constructorToUse);
   attribute.ConstructorArguments.Add(new CustomAttributeArgument(constructorToUse.Parameters.First().ParameterType, derivedType));

   baseType.CustomAttributes.Add(attribute);
}

In this part of the code we add a KnownType attribute to the base type for each derived type we previously found.
We are using the KnownType attribute’s constructor that expects the System.Type of the sub class.

Implementing RemoveKnowsDeriveTypesAttribute

This part is straight forward. We locate and then remove the KnowsDeriveTypes attribute from the base type.

void RemoveKnowsDeriveTypesAttribute(TypeDefinition baseType)
{
   var foundAttribute = baseType.CustomAttributes
         .Single(attribute => attribute.AttributeType.FullName == typeof(KnowsDeriveTypesAttribute).FullName);

   baseType.CustomAttributes.Remove(foundAttribute);
}

Unit Tests & Debugging

Unit Tests are always important, especially when writing Fody extensions. We had a good code coverage in the final product, but for this blog post I’ll use Unit Tests solely for debugging purposes, as I will be able to debug the extension by running the Unit Tests in debug mode.

For this post I’ve created two Unit Tests. One for testing the addition of the KnownType attributes and one for testing the removal of the KnowsDeriveTypes attribute. You can view the Unit Tests file here. I’ve also went ahead and added three classes to the AssemblyToProcess project for testing the IL Weaving process.

Even though Fody has a basic logging capability it isn’t always easy to find and view logs in the output window.
Fortunately, at debug time we can use OzCode’s Trace Points feature. I’ve added a trace point at the line which adds a KnownType attribute over base types.

//Trace point was added here in the AddKnownTypeAttributes method.
baseType.CustomAttributes.Add(attribute);

Read More