Getting to grips with EasyNetQ – Part 2 – Logger


In part 1 of this series about EasyNetQ, I’ve provided an overview of what happens when we use the Publish and Subscribe methods as well as explaining the actual default behaviour. In part 2, I will experiment with the logger in EasyNetQ and is a logical continuation of part 1.

In this particular case, I will log to a file using NLog rather than logging to the console which is the default behaviour in EasyNetQ. So here is the code (source code available here) used:

Subscriber with logging

using EasyNetQ;
using PublishConsoleAppNamespace;

namespace SubscribeWithLoggerConsoleAppNamespace
{
    class Program
    {
        static void Main()
        {
            var logger = new MyLogger();
            logger.InfoWrite("In subscriber");
            var bus = RabbitHutch.CreateBus("host=Ubuntu-12", x => x.Register<IEasyNetQLogger>(_ => logger));

            bus.Subscribe<MyMessage>("SubscribeWithLoggerConsoleAppId"
                                     , msg => logger.InfoWrite(msg.Text));
        }
    }
}

MyLogger class

using System;
using EasyNetQ;
using NLog;

namespace SubscribeWithLoggerConsoleAppNamespace
{
    public class MyLogger:IEasyNetQLogger
    {
        private static readonly Logger Logger = LogManager.GetCurrentClassLogger();
        public void DebugWrite(string format, params object[] args)
        {
            Logger.Debug(format);
        }

        public void InfoWrite(string format, params object[] args)
        {
            Logger.Info(format);
        }

        public void ErrorWrite(string format, params object[] args)
        {
            Logger.Error(format);
        }

        public void ErrorWrite(Exception exception)
        {
            Logger.ErrorException("An exception has occurred", exception);
        }
    }
}

NLog configuration file

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">

  <!-- 
  See http://nlog-project.org/wiki/Configuration_file 
  for information on customizing logging rules and outputs.
   -->
  <targets>
    <!-- add your targets here -->

    <target xsi:type="File" name="f" fileName="${basedir}/logs/${shortdate}.log"
            layout="${longdate} ${uppercase:${level}} ${message}" />

  </targets>

  <rules>
    <!-- add your logging rules here -->

    <logger name="*" minlevel="Trace" writeTo="f" />

  </rules>
</nlog>

The code in the SubscribeWithLogger Console App is the one of interest and in particular:

var logger = new MyLogger();
logger.InfoWrite("In subscriber");
var bus = RabbitHutch.CreateBus("host=Ubuntu-12", x => x.Register<IEasyNetQLogger>(_ => logger));

bus.Subscribe<MyMessage>("SubscribeWithLoggerConsoleAppId"
                         , msg => logger.InfoWrite(msg.Text));

This is pretty much the code described in the logging section of  this page. So first, you should run this code on its own and when you do so, the console application will just remain there. That is due to the fact that we are not disposing the connection:

bus.Dispose();

The reason why I’m not disposing of the connection is due to the fact that I don’t want to encounter the issue described at the end of the post in the first post in this series.

In any case close the application and if you look at the RabbitMQ admin web page, you will see that a new queue has been added because I used a new id “SubscribeWithLoggerConsoleAppId”:

ENQ-Queue for loggerNote that this queue has been bound to the already existing exchange “PublishConsoleAppNamespace_MyMessage:PublishConsoleAppAssembly”.

Now run the PublishConsoleApp code, which is also provided in the first post, on its own. What actually surprised me in this case was the number of messages being queued:

ENQ-20000MsgsQueuedIn the first post when we ran this, we had 10,000 messages queued where as now we had twice that amount. In fact, if we look at the “Queues” page we see that each queue contains 10,000 messages.

ENQ-QueueBreakdownSo, the logical question is what messages are now on each queue and the answer lies in running each of the subscriber application in turn.

This is the output when the information is sent to the console window.

ENQ-SubscribeConsoleand this is an excerpt of the output when the information is sent to a log file:

2013-08-15 12:17:04.9033 INFO Hello Rabbit9992
2013-08-15 12:17:04.9033 DEBUG Received 
    RoutingKey: '{0}'
    CorrelationId: '{1}'
    ConsumerTag: '{2}'
2013-08-15 12:17:04.9033 INFO Hello Rabbit9993
2013-08-15 12:17:04.9203 DEBUG Received 
    RoutingKey: '{0}'
    CorrelationId: '{1}'
    ConsumerTag: '{2}'
2013-08-15 12:17:04.9203 INFO Hello Rabbit9994
2013-08-15 12:17:04.9203 DEBUG Received 
    RoutingKey: '{0}'
    CorrelationId: '{1}'
    ConsumerTag: '{2}'
2013-08-15 12:17:04.9333 INFO Hello Rabbit9995
2013-08-15 12:17:04.9333 DEBUG Received 
    RoutingKey: '{0}'
    CorrelationId: '{1}'
    ConsumerTag: '{2}'
2013-08-15 12:17:04.9333 INFO Hello Rabbit9996
2013-08-15 12:17:04.9333 DEBUG Received 
    RoutingKey: '{0}'
    CorrelationId: '{1}'
    ConsumerTag: '{2}'
2013-08-15 12:17:04.9333 INFO Hello Rabbit9997
2013-08-15 12:17:04.9533 DEBUG Received 
    RoutingKey: '{0}'
    CorrelationId: '{1}'
    ConsumerTag: '{2}'
2013-08-15 12:17:04.9533 INFO Hello Rabbit9998
2013-08-15 12:17:04.9533 DEBUG Received 
    RoutingKey: '{0}'
    CorrelationId: '{1}'
    ConsumerTag: '{2}'
2013-08-15 12:17:04.9663 INFO Hello Rabbit9999

Effectively, it would appear that both queues contained the same published data and although the exchange type is topic, it is behaving very much like a fanout exchange i.e. the messages published are sent to all bound queues.

When you look at the overview of these two operations, you will see that both operations were quite quick although the debug to console (1) was quicker:

ENQ-TimeTaken

Advertisements
Posted in .NET, ALT.NET, EasyNetQ, RabbitMQ

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: