Rename HANDLE to RECV and add an optional HANDLE log in the dispatch

src/Abc.Zebus/Core/Bus.cs

@@ -21,7 +21,7 @@ namespace Abc.Zebus.Core
         private readonly ConcurrentDictionary<MessageId, TaskCompletionSource<CommandResult>> _messageIdToTaskCompletionSources = new ConcurrentDictionary<MessageId, TaskCompletionSource<CommandResult>>();
         private CustomThreadPoolTaskScheduler _completionResultTaskScheduler;
         private readonly Dictionary<Subscription, int> _subscriptions = new Dictionary<Subscription, int>();
-        private readonly BusMessageLogger _messageLogger = new BusMessageLogger();
+        private readonly BusMessageLogger _messageLogger = BusMessageLogger.Get<Bus>();
         private readonly ILog _logger = LogManager.GetLogger(typeof(Bus));
         private readonly ITransport _transport;
         private readonly IPeerDirectory _directory;
@@ -151,7 +151,7 @@ namespace Abc.Zebus.Core
         {
             var peers = _directory.GetPeersHandlingMessage(message);
             if (peers.Count == 0)
-                throw new InvalidOperationException("Unable to find peer for specified command, " + _messageLogger.ToString(message) + ". Did you change the namespace?");
+                throw new InvalidOperationException("Unable to find peer for specified command, " + BusMessageLogger.ToString(message) + ". Did you change the namespace?");
 
             var self = peers.FirstOrDefault(x => x.Id == _peerId);
 
@@ -160,7 +160,7 @@ namespace Abc.Zebus.Core
 
             if (peers.Count > 1)
             {
-                var exceptionMessage = string.Format("{0} peers are handling {1}. Peers: {2}.", peers.Count, _messageLogger.ToString(message), string.Join(", ", peers.Select(p => p.ToString())));
+                var exceptionMessage = string.Format("{0} peers are handling {1}. Peers: {2}.", peers.Count, BusMessageLogger.ToString(message), string.Join(", ", peers.Select(p => p.ToString())));
                 throw new InvalidOperationException(exceptionMessage);
             }
 
@@ -346,7 +346,7 @@ namespace Abc.Zebus.Core
             if (dispatch == null)
                 return;
 
-            _messageLogger.LogFormat("HANDLE remote: {0} from {3} ({2} bytes). [{1}]", dispatch.Message, transportMessage.Id, transportMessage.MessageBytes.Length, transportMessage.Originator.SenderId);
+            _messageLogger.LogFormat("RECV remote: {0} from {3} ({2} bytes). [{1}]", dispatch.Message, transportMessage.Id, transportMessage.MessageBytes.Length, transportMessage.Originator.SenderId);
             _messageDispatcher.Dispatch(dispatch);
         }
 
@@ -416,7 +416,7 @@ namespace Abc.Zebus.Core
 
         protected virtual void HandleLocalMessage(IMessage message, TaskCompletionSource<CommandResult> taskCompletionSource)
         {
-            _messageLogger.LogFormat("HANDLE local: {0}", message);
+            _messageLogger.LogFormat("RECV local: {0}", message);
 
             var context = MessageContext.CreateOverride(PeerId, EndPoint);
             var dispatch = new MessageDispatch(context, message, GetOnLocalMessageDispatchedContinuation(taskCompletionSource));

src/Abc.Zebus/Core/BusMessageLogger.cs

@@ -4,14 +4,27 @@ using System.Collections.Generic;
 using System.Reflection;
 using Abc.Zebus.Util.Annotations;
 using Abc.Zebus.Util.Extensions;
-using log4net;
-
+using log4net;
+using log4net.Core;
+
 namespace Abc.Zebus.Core
 {
     public class BusMessageLogger
-    {
-        private readonly ConcurrentDictionary<Type, MessageTypeLogInfo> _logInfos = new ConcurrentDictionary<Type, MessageTypeLogInfo>();
-        private readonly ILog _logger = LogManager.GetLogger(typeof(Bus));
+    {
+        private readonly Type _loggerType;
+        private static readonly ConcurrentDictionary<Type, MessageTypeLogInfo> _logInfos = new ConcurrentDictionary<Type, MessageTypeLogInfo>();
+        private readonly ILog _logger;
+
+        private BusMessageLogger(Type loggerType)
+        {
+            _loggerType = loggerType;
+            _logger = LogManager.GetLogger(loggerType);
+        }
+
+        public static BusMessageLogger Get<T>()
+        {
+            return Instance<T>.Value;
+        }
 
         public bool IsLogEnabled(IMessage message)
         {
@@ -20,18 +33,18 @@ namespace Abc.Zebus.Core
         }
 
         [StringFormatMethod("format")]
-        public void LogFormat(string format, IMessage message, MessageId? messageId = null, int messageSize = 0, PeerId peerId = default(PeerId))
+        public void LogFormat(string format, IMessage message, MessageId? messageId = null, int messageSize = 0, PeerId peerId = default(PeerId), Level logLevel = null)
         {
             var logInfo = _logInfos.GetOrAdd(message.GetType(), CreateLogger);
             if (!logInfo.Logger.IsInfoEnabled)
                 return;
 
-            var messageText = logInfo.GetMessageText(message);
-            _logger.InfoFormat(format, messageText, messageId, messageSize, peerId);
+            var messageText = logInfo.GetMessageText(message);
+            _logger.Logger.Log(_loggerType, logLevel ?? Level.Info, string.Format(format, messageText, messageId, messageSize, peerId), null);
         }
 
         [StringFormatMethod("format")]
-        public void LogFormat(string format, IMessage message, MessageId messageId, int messageSize, IList<Peer> peers)
+        public void LogFormat(string format, IMessage message, MessageId messageId, int messageSize, IList<Peer> peers, Level logLevel = null)
         {
             if (peers.Count == 0)
             {
@@ -51,13 +64,13 @@ namespace Abc.Zebus.Core
             var messageText = logInfo.GetMessageText(message);
             var otherPeersCount = peers.Count - 1;
             var peerIdText = otherPeersCount > 1
-                ? peers[0].Id + " and " + otherPeersCount + " other peers"
-                : peers[0].Id + " and " + otherPeersCount + " other peer";
-
-            _logger.InfoFormat(format, messageText, messageId, messageSize, peerIdText);
+                ? peers[0].Id + " and " + otherPeersCount + " other peers"
+                : peers[0].Id + " and " + otherPeersCount + " other peer";
+
+            _logger.Logger.Log(_loggerType, logLevel ?? Level.Info, string.Format(format, messageText, messageId, messageSize, peerIdText), null);
         }
 
-        public string ToString(IMessage message)
+        public static string ToString(IMessage message)
         {
             var logInfo = _logInfos.GetOrAdd(message.GetType(), CreateLogger);
             return logInfo.GetMessageText(message);
@@ -94,6 +107,11 @@ namespace Abc.Zebus.Core
             {
                 return _hasToStringOverride ? string.Format("{0} {{{1}}}", _messageTypeName, message) : string.Format("{0}", _messageTypeName);
             }
+        }
+
+        private static class Instance<T>
+        {
+            public static readonly BusMessageLogger Value = new BusMessageLogger(typeof(T));
         }
     }
 }

src/Abc.Zebus/Scan/Pipes/PipeInvocation.cs

@@ -1,9 +1,11 @@
 using System;
 using System.Collections.Generic;
-using System.Threading.Tasks;
+using System.Threading.Tasks;
+using Abc.Zebus.Core;
 using Abc.Zebus.Dispatch;
-using Abc.Zebus.Util.Extensions;
-
+using Abc.Zebus.Util.Extensions;
+using log4net.Core;
+
 namespace Abc.Zebus.Scan.Pipes
 {
     public class PipeInvocation : IMessageHandlerInvocation
@@ -12,7 +14,8 @@ namespace Abc.Zebus.Scan.Pipes
         private readonly IMessageHandlerInvoker _invoker;
         private readonly IMessage _message;
         private readonly MessageContext _messageContext;
-        private readonly IList<IPipe> _pipes;
+        private readonly IList<IPipe> _pipes;
+        private readonly BusMessageLogger _messageLogger = BusMessageLogger.Get<PipeInvocation>();
         
         private object[] _pipeStates;
 
@@ -49,8 +52,9 @@ namespace Abc.Zebus.Scan.Pipes
             _handlerMutations.Add(action);
         }
 
-        protected internal virtual void Run()
-        {
+        protected internal virtual void Run()
+        {
+            _messageLogger.LogFormat("HANDLE : {0} [{1}]", _message, _messageContext.MessageId, logLevel: Level.Debug);
             _pipeStates = BeforeInvoke();
 
             try
@@ -92,7 +96,8 @@ namespace Abc.Zebus.Scan.Pipes
         }
 
         protected internal virtual Task RunAsync()
-        {
+        {
+            _messageLogger.LogFormat("HANDLE : {0} [{1}]", _message, _messageContext.MessageId, logLevel: Level.Debug);
             var runTask = _invoker.InvokeMessageHandlerAsync(this);
             runTask.ContinueWith(task => AfterInvoke(_pipeStates, task.IsFaulted, task.Exception), TaskContinuationOptions.ExecuteSynchronously);