Sunday, April 28, 2013

Writing your own Glimpse Plugin

As I wrote in my last post, Glimpse is a great tool to diagnose your web application. And there is already a lot of plugins available. But maybe you have the need to get some additional info, for which no plugin is available so far. In such a case it is quite easy to write your own plugin.
I will show it with a plugin for Log4Net. Before you ask, yes there is already a Glimpse.Log4Net plugin. Unfortunately this package is outdated. It was written for Glimpse 0.86, but with 1.x it doesn't work anymore.
UPDATE 15-Jun-2013: In between the Glimpse.Log4Net plugin has been updated to support Glimpse 1.x. But nevertheless the how to below should be interesting enough, since there is not a lot of documentation out there.

Log4Net and Trace

It is not absolute necessary to use a special Log4Net plugin. Instead it is possible to redirect the Log4Net output to the Tracing infrastructure. And for this, Glimpse provides already a tab.
All you need is a new appender:
<appender name="TraceAppender" type="log4net.Appender.TraceAppender">
  <category value="%level" /> 
  <layout type="log4net.Layout.PatternLayout"> 
    <conversionPattern value="%logger - %message" /> 
  </layout> 
</appender>
After connecting it to a logger, you will see all relevant log lines in the trace tab. With the specification of the category tag, the trace output will have the same level as the original Log4Net log line. Therefore some of the outputs are prefixed with the corresponding icons:
 

Log4Net Plugin

The implementation of the plugin is straightforward: first we need a Log4Net appender, which collects the messages to display in Glimpse. And we need an implementation for the tab in the Glimpse window. The rest in some infrastructure around it.
So let's have a look at the details.

Log4NetMessage

This is a simple container for the data transferred from the Log4Net appender to Glimpse. The only prerequisite is, it has to implement the interface Glimpse.Core.Message.IMessage:

public class Log4NetMessage : IMessage
{
  public Log4NetMessage()
  {
    Id = Guid.NewGuid();
  }

  public Guid Id { get; private set; }
  public TimeSpan FromFirst { get; set; }
  public TimeSpan FromLast { get; set; }
  public string ThreadName { get; set; }
  public string Level { get; set; }
  public string LoggerName { get; set; }
  public string Message { get; set; }
}

Log4NetInspector

Next we need some additional infrastructure. The appender sends the message to the tab via a Glimpse.Core.Extensibility.IMessageBroker. This must be set from outside.
Therefore I added an implementation of Glimpse.Core.Extensibility.IInspector, whose Setup method will be called at startup. It takes the needed properties from the Glimpse context and stores them in static properties of my appender:
public class Log4NetInspector : IInspector
{
  public void Setup(IInspectorContext context)
  {
    GlimpseAppender.Initialize(context.MessageBroker, context.TimerStrategy);
  }
}

GlimpseAppender

Now it's time for the real stuff, first the appender. The implementation is quite easy, a bigger part of the code is about the calculation of the elapsed time since the last call (this part could be also skipped).
public class GlimpseAppender : AppenderSkeleton
{
  private static IMessageBroker _messageBroker;
  private static Func<IExecutionTimer> _timerStrategy;

  private static Stopwatch fromLastWatch;

  public static void Initialize(IMessageBroker messageBroker, Func<IExecutionTimer> timerStrategy)
  {
    _messageBroker = messageBroker;
    _timerStrategy = timerStrategy;
  }

  protected override void Append(LoggingEvent loggingEvent)
  {
    if (_timerStrategy != null && _messageBroker != null)
    {
      IExecutionTimer timer = _timerStrategy();
      if (timer != null)
      {
        _messageBroker.Publish(new Log4NetMessage
          {
            ThreadName = loggingEvent.ThreadName,
            Level = loggingEvent.Level.DisplayName,
            LoggerName = loggingEvent.LoggerName,
            Message = loggingEvent.RenderedMessage,
            FromFirst = timer.Point().Offset,
            FromLast = CalculateFromLast(timer)
          });
      }
    }
  }

  private static TimeSpan CalculateFromLast(IExecutionTimer timer)
  {
    if (fromLastWatch == null)
    {
      fromLastWatch = Stopwatch.StartNew();
      return TimeSpan.FromMilliseconds(0);
    }

    // Timer started before this request, reset it
    if (DateTime.Now - fromLastWatch.Elapsed < timer.RequestStart)
    {
      fromLastWatch = Stopwatch.StartNew();
      return TimeSpan.FromMilliseconds(0);
    }

    var result = fromLastWatch.Elapsed;
    fromLastWatch = Stopwatch.StartNew();
    return result;
  }
}

Log4NetTab

Now we are ready for the tab's implementation. It inherits from Glimpse.Core.Extensibility.TabBase, and implements the interfaces Glimpse.Core.Extensibility.ITabSetup, Glimpse.Core.Extensibility.IKey and Glimpse.Core.Extensibility.ITabLayout. As you see, the biggest part is the definition of the layout, how the data will be displayed on the tab.
public class Log4NetTab : TabBase, ITabSetup, IKey, ITabLayout
{
  private static readonly object layout = TabLayout.Create()
    .Row(r =>
    {
      r.Cell(0).WidthInPixels(80);
      r.Cell(1).WidthInPixels(80);
      r.Cell(2);
      r.Cell(3);
      r.Cell(4).WidthInPercent(15).Suffix(" ms").AlignRight().Prefix("T+ ").Class("mono");
      r.Cell(5).WidthInPercent(15).Suffix(" ms").AlignRight().Class("mono");
    }).Build();

  public override object GetData(ITabContext context)
  {
    return context.GetMessages<Log4NetMessage>().ToList();
  }

  public override string Name
  {
    get { return "Log4Net"; }
  }

  public void Setup(ITabSetupContext context)
  {
    context.PersistMessages<Log4NetMessage>();
  }

  public string Key
  {
    get { return "glimpse_log4net"; }
  }

  public object GetLayout()
  {
    return layout;
  }
}

Log4NetMessagesConverter

The final part is a converter, which knows how to display a Log4NetMessage in the layout of Log4NetTab:
public class Log4NetMessagesConverter : SerializationConverter<IEnumerable<Log4NetMessage>>
{
  public override object Convert(IEnumerable<Log4NetMessage> obj)
  {
    var root = new TabSection("Level", "ThreadName", "LoggerName", "Message", "From Request Start", "From Last");
    foreach (var item in obj)
    {
      root.AddRow().
        Column(item.Level).
        Column(item.ThreadName).
        Column(item.LoggerName).
        Column(item.Message).
        Column(item.FromFirst).
        Column(item.FromLast).
        Style(GetStyle(item.Level));
    }
      return root.Build();
  }

  private static string GetStyle(string levelDisplayName)
  {
    switch (levelDisplayName)
    {
      case "EMERGENCY":
      case "FATAL":
      case "ALERT":
        return FormattingKeywords.Fail;

      case "CRITICAL":
      case "SEVERE":
      case "ERROR":
        return FormattingKeywords.Error;

      case "WARN":
        return FormattingKeywords.Warn;

      case "NOTICE":
      case "INFO":
        return FormattingKeywords.Info;

      case "DEBUG":
      case "FINE":
      case "TRACE":
      case "FINER":
      case "VERBOSE":
      case "FINEST":
      case "ALL":
        return FormattingKeywords.Quiet;

      default:
        return FormattingKeywords.Quiet;
    }
  }
}

Result

Finally you have to add the GlimpseAppender to your Log4Net configuration. When you start now your application, you should have a new Log4Net tab in the Glimpse window. Its content is similar to the Trace tab above, but the data is better structured.
NOTE: Be sure to start the application really from scratch. E.g. stop an already running IISExpress before. Otherwise it could be the Glimpse setup is not working as expected.

You can find the source code at GitHub: https://github.com/Ritzlgrmft/GlimpseDemo.

1 comment:

  1. This was really useful! I could not get the "official" Glimpse.Log4Net extension to work, so getting a detailed walkthrough of how to do it yourself was extremely useful!
    Thank you!

    ReplyDelete