Search This Blog

2011-10-05

log4net appender for Raven DB

Recently I have started to look at noSQL databases and Document-Oriented DBs particularly for the .NET platform to solve some issues within our solution. One of the brilliant examples of such databases is Raven DB by Ayende. IMHO, one of the benefits of Raven DB is easy to start way. It has almost all I need out of the box: simple deploy, native .NET client with Linq, Map/Reduces indexes, RESTful API and so on and so forth.
Raven DB itself uses NLog by default and our solution uses log4net like thousands of other ones. So I decided to experiment with custom log4net appender for our needs because one of the first steps of moving to noSQL direction might be logging, due to simple implementation. Such an approach is far more flexible than logging to text files and might significantly reduce load on SQL servers in case of using ADO.NET appender.
So let's start.
First we need to decide what we are going to store. Since logging event  is simple and independent document  we can just wrap LoggingEvent.
// The log entry document entity that will be stored to the database.
public class Log : INamedDocument
{
  ...

  public Log(LoggingEvent logEvent)
  {
    if (logEvent == null)
    {
    throw new ArgumentNullException("logEvent");
    }

    this.LoggerName = logEvent.LoggerName;
    this.Domain = logEvent.Domain;
    this.Identity = logEvent.Identity;
    this.ThreadName = logEvent.ThreadName;
    this.UserName = logEvent.UserName;
    this.MessageObject = logEvent.MessageObject;
    this.TimeStamp = logEvent.TimeStamp;
    this.Exception = logEvent.ExceptionObject;
    this.Message = logEvent.RenderedMessage;
    this.Fix = logEvent.Fix.ToString();

    ...

    // Raven doesn't serialize unknown types like log4net's PropertiesDictionary
    this.Properties = logEvent.Properties.GetKeys().ToDictionary(key => key, key => logEvent.Properties[key].ToString());
  }

  public string LoggerName { get; set; }
  public string Domain { get; set; }
  public string Identity { get; set; }
  public string ThreadName { get; set; }
  public string UserName { get; set; }
  public object MessageObject { get; set; }
  public DateTime TimeStamp { get; set; }
  public object Exception { get; set; }
  public string Message { get; set; }
  public string Fix { get; set; }
  public IDictionary Properties { get; set; }
  ....
}
Next step will be choosing which appender template we need and which additional settings Raven requires. I think using of buffering appender makes sense in order not to drive database connection up the wall. As for additional setting of appender we might need connection string (or connection string name) and Raven's settings about max number of request per document session.
So our ".config" file would have something like this:


  
Ok, we have all the prerequisites and we can write some code.
Implementation is simple: on SendBuffer method it adds log events to a document session and saves changes to a DB server. On ActivateOptions it will initialize DB connection, i.e. create document store instance.
  public class RavenAppender : BufferingAppenderSkeleton
  {
    private readonly object lockObject = new object();

    private IDocumentStore documentStore;

    private IDocumentSession documentSession;

    #region Appender configuration properties

    /// 
    /// Gets or sets the connection string.
    /// 
    /// 
    /// The connection string.
    /// 
    public string ConnectionString { get; set; }

    /// 
    /// Gets or sets the max number of requests per session.
    /// By default the number of remote calls to the server per session is limited to 30.
    /// 
    /// 
    /// The max number of requests per session.
    /// 
    public int MaxNumberOfRequestsPerSession { get; set; }

    #endregion

    /// 
    /// Initializes a new instance of the  class.
    /// 
    public RavenAppender() {}

    /// 
    /// Initializes a new instance of the  class. 
 /// Can be used for unit testing
    /// 
    /// 
The document store.
    public RavenAppender(IDocumentStore documentStore)
    {
      if (documentStore == null)
      {
        throw new ArgumentNullException("documentStore");
      }

      this.documentStore = documentStore;
    }

    protected override void SendBuffer(LoggingEvent[] events)
    {
      if (events == null || !events.Any())
      {
        return;
      }

      this.CheckSession();

      foreach (var entry in events.Where(e => e != null).Select(e => new Log(e)))
      {
        this.documentSession.Store(entry);
      }

      this.Commit();
    }

    public override void ActivateOptions()
    {
      try
      {
        this.InitServer();
      }
      catch (Exception exception)
      {
        ErrorHandler.Error("Exception while initializing Raven Appender", exception, ErrorCode.GenericFailure);
        // throw;
      }
    }

    protected override void OnClose()
    {
      this.Flush();
      this.Commit();

      try
      {
        if (this.documentSession != null)
        {
          this.documentSession.Dispose();
        }

        if (this.documentStore != null && !this.documentStore.WasDisposed)
        {
          this.documentStore.Dispose();
        }
      }
      catch (Exception e)
      {
        ErrorHandler.Error("Exception while closing Raven Appender", e, ErrorCode.GenericFailure);
      }

      base.OnClose();
    }

    protected virtual void Commit()
    {
      if (this.documentSession == null)
      {
        return;
      }

      try
      {
        this.documentSession.SaveChanges();
      }
      catch (Exception e)
      {
        ErrorHandler.Error("Exception while commiting to the Raven DB", e, ErrorCode.GenericFailure);
      }
    }

    private void CheckSession()
    {
      if (this.documentSession != null)
      {
        return;
      }

      lock (this.lockObject)
      {
        if (this.documentSession != null)
        {
          if (this.documentSession.Advanced.NumberOfRequests >= this.documentSession.Advanced.MaxNumberOfRequestsPerSession)
          {
            this.Commit();
            this.documentSession.Dispose();
          }
          else
          {
            return;
          }
        }

        this.documentSession = this.documentStore.OpenSession();
        this.documentSession.Advanced.UseOptimisticConcurrency = true;

        if (this.MaxNumberOfRequestsPerSession > 0)
        {
          this.documentSession.Advanced.MaxNumberOfRequestsPerSession = this.MaxNumberOfRequestsPerSession;
        }
      }
    }

    private void InitServer()
    {
      if (this.documentStore != null)
      {
        return;
      }

      if (string.IsNullOrEmpty(this.ConnectionString))
      {
        var exception = new InvalidOperationException("Connection string is not specified.");
        ErrorHandler.Error("Connection string is not specified.", exception, ErrorCode.GenericFailure);

        return;
      }

      this.documentStore = new DocumentStore
      {
        ConnectionStringName = this.ConnectionString
      };

      this.documentStore.Initialize();
    }
  }
One detail we should care about is max number of requests per session. RavenDB's default limitation is 30 requests per session. On the one hand we have moved this option to the config file on the other hand we just recreate a session when max number of requests is reached.
So this is it: simple but effective. With RavenDB indexes it is possible to have extra-analysis or statistics of logged events, for instance, number of error per day / per module, new errors or warnings, etc.
Sources are available on GitHub.
NuGet package: http://nuget.org/List/Packages/log4net.Raven

Update:
The screenshot of the test Log documents



23 comments:

  1. i've not found anyone who has gotten this to work. have you seen it work?

    ReplyDelete
    Replies
    1. What error do you have?
      I have just tried to run tests on real database and I can see log documents.

      Delete
    2. I had to use the following appender type to get this example to work.

      <appender name="RavenAppender" type="log4net.Raven.RavenAppender, log4net.Raven">
      ...
      </appender>

      Delete
    3. Oh yes, you are right! This is my fault, I was testing it directly from sources.
      Thanks! I will update Readme.

      Delete
  2. I have tried to get this working on my MVC 4 site, with no success.
    - Confirmed that log4net works using RollingFile appender
    - Confirmed that connection string to RavenDB works, RavenDB is running properly

    Yet when I set it up to use your appender, and try to log, nothing is sent to RavenDB. Any advice on how to diagnose the problem/debug?

    ReplyDelete
    Replies
    1. Well, I just tried with MVC4 (on VS11 Beta) and RavenDB Build 701 (which were setup as an IIS application), and it works!
      I just follow the ReadMe file:
      https://github.com/antonsamarsky/log4net.Raven/blob/master/README

      Maybe you should set the buffer size to 1:


      For testing your configuration you can write a simple test:

      [Test]
      public void TetsRavenAppender()
      {
      log4net.Config.XmlConfigurator.Configure();
      ILog logger = LogManager.GetLogger(this.GetType());
      logger.Error("Error");
      }

      It should write a document to database or show detailed error in the output.

      Delete
    2. Ran it as a unit test and it worked. Run it in the MVC project and it doesnt work.

      When running it in debugger in VS, I am see the following error message: https://gist.github.com/2028449. Based on this, it looks like there is an issue binding the assembly for log4net.Raven, specifically because your assembly uses log4net 1.2.11, while I had 2.0 installed based on another dependency. So some nuget style assembly-hell was the cause of this. To fix, I imported your project to my solution, upgraded log4net to 2.0, and now it works.

      Delete
    3. Thanks! I will update package.

      Delete
    4. Package has been updated.

      Id Version Range
      log4net (≥ 2.0.0)
      RavenDB (≥ 1.0.701)

      Delete
  3. Anton,

    Awesome work my brother! :D Just got the NuGet package and tried it in a Test method.

    Working like a charm...

    Keep doing great things. I'm sure they'll return to you!

    All the best,

    Leniel

    ReplyDelete
    Replies
    1. asa,

      It's not working anymore. Updated to Raven build 888 and now I get this error:

      Newtonsoft.Json.JsonReaderException: Unexpected character encountered while parsing value: . Line 0, position 0.

      Delete
    2. I have updated the package. Try it now.
      https://nuget.org/packages/log4net.Raven

      Sources are also updated on GitHub.

      Delete
    3. I think you're faster than Ayende! :D Congrats mate...

      Delete
  4. Anton,

    Do you consider to add it as ELMAH appender ?

    ReplyDelete
  5. Hi! now i encountred in query like this
    var resutl = (from query in session.Query() select query).ToList();
    above code snipped can not mapped to LoggingEvent. how can i resolve the problem?
    thanks

    ReplyDelete
  6. This is even better than log4net:
    http://www.kellermansoftware.com/p-14-net-logging-library.aspx

    ReplyDelete