Cleanup bus logs

src/Abc.Zebus.Tests/log4net.config

@@ -1,7 +1,7 @@
 <?xml version="1.0" encoding="utf-8"?>
 <log4net>
 
-  <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
+  <!--<appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
     <file value="logs/Abc.Testing.log" />
     <appendToFile value="true" />
     <rollingStyle value="Date" />
@@ -10,7 +10,7 @@
     <layout type="log4net.Layout.PatternLayout">
       <conversionPattern value="%date{HH:mm:ss.fff} - %-5level - %logger || %message%newline" />
     </layout>
-  </appender>
+  </appender>-->
 
   <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
     <layout type="log4net.Layout.PatternLayout">
@@ -19,8 +19,8 @@
   </appender>
 
   <root>
-    <level value="INFO" />
-    <appender-ref ref="RollingFileAppender" />
+    <level value="DEBUG" />
+    <!--<appender-ref ref="RollingFileAppender" />-->
     <appender-ref ref="ConsoleAppender" />
   </root>
 

src/Abc.Zebus/Core/Bus.cs

@@ -227,7 +227,7 @@ namespace Abc.Zebus.Core
                 HandleLocalMessage(message, null);
 
             var targetPeers = shouldBeHandledLocally ? peersHandlingMessage.Where(x => x.Id != PeerId).ToList() : peersHandlingMessage;
-            LogAndSendTransportMessage(message, targetPeers, true, shouldBeHandledLocally);
+            LogAndSendMessage(message, targetPeers, true, shouldBeHandledLocally);
         }
 
         public Task<CommandResult> Send(ICommand message)
@@ -277,7 +277,7 @@ namespace Abc.Zebus.Core
                 _messageIdToTaskCompletionSources.TryAdd(transportMessage.Id, taskCompletionSource);
 
                 var peers = new[] { peer };
-                LogMessageSend(message, peers, transportMessage);
+                _messageLogger.LogSendMessage(message, peers, transportMessage);
                 SendTransportMessage(transportMessage, peers);
             }
 
@@ -572,7 +572,7 @@ namespace Abc.Zebus.Core
                 return;
             }
 
-            _messageLogger.DebugFormat("RECV remote: {0} from {3} ({2} bytes). [{1}]", dispatch.Message, transportMessage.Id, transportMessage.Content.Length, transportMessage.Originator.SenderId);
+            _messageLogger.LogReceiveMessageRemote(dispatch.Message, transportMessage);
             _messageDispatcher.Dispatch(dispatch);
         }
 
@@ -589,7 +589,7 @@ namespace Abc.Zebus.Core
                 {
                     var messageExecutionCompleted = MessageExecutionCompleted.Create(dispatch.Context, dispatchResult, _serializer);
                     var shouldLogMessageExecutionCompleted = _messageLogger.IsInfoEnabled(dispatch.Message);
-                    LogAndSendTransportMessage(messageExecutionCompleted, new[] { dispatch.Context.GetSender() }, shouldLogMessageExecutionCompleted);
+                    LogAndSendMessage(messageExecutionCompleted, new[] { dispatch.Context.GetSender() }, shouldLogMessageExecutionCompleted);
                 }
 
                 AckTransportMessage(transportMessage);
@@ -653,7 +653,7 @@ namespace Abc.Zebus.Core
 
         protected virtual void HandleMessageExecutionCompleted(TransportMessage transportMessage, MessageExecutionCompleted message)
         {
-            _messageLogger.DebugFormat("RECV: {0}", message);
+            _messageLogger.LogReceiveMessageAck(message);
 
             if (!_messageIdToTaskCompletionSources.TryRemove(message.SourceCommandId, out var taskCompletionSource))
                 return;
@@ -666,7 +666,7 @@ namespace Abc.Zebus.Core
 
         protected virtual void HandleLocalMessage(IMessage message, TaskCompletionSource<CommandResult> taskCompletionSource)
         {
-            _messageLogger.DebugFormat("RECV local: {0}", message);
+            _messageLogger.LogReceiveMessageLocal(message);
 
             var context = MessageContext.CreateOverride(PeerId, EndPoint);
             var dispatch = new MessageDispatch(context, message, GetOnLocalMessageDispatchedContinuation(taskCompletionSource))
@@ -692,12 +692,12 @@ namespace Abc.Zebus.Core
             };
         }
 
-        private void LogAndSendTransportMessage(IMessage message, IList<Peer> peers, bool logEnabled, bool locallyHandled = false)
+        private void LogAndSendMessage(IMessage message, IList<Peer> peers, bool logEnabled, bool locallyHandled = false)
         {
             if (peers.Count == 0)
             {
                 if (!locallyHandled && logEnabled)
-                    _messageLogger.InfoFormat("SEND: {0} to {1}", message, peers, default, default);
+                    _messageLogger.LogSendMessage(message, peers);
 
                 return;
             }
@@ -705,7 +705,7 @@ namespace Abc.Zebus.Core
             var transportMessage = ToTransportMessage(message);
 
             if (logEnabled)
-                LogMessageSend(message, peers, transportMessage);
+                _messageLogger.LogSendMessage(message, peers, transportMessage);
 
             SendTransportMessage(transportMessage, peers);
         }
@@ -713,9 +713,6 @@ namespace Abc.Zebus.Core
         protected void SendTransportMessage(TransportMessage transportMessage, IList<Peer> peers)
             => _transport.Send(transportMessage, peers, new SendContext());
 
-        private static void LogMessageSend(IMessage message, IList<Peer> peers, TransportMessage transportMessage)
-            => _messageLogger.InfoFormat("SEND: {0} to {1} ({3} bytes) [{2}]", message, peers, transportMessage.Id, transportMessage.Content.Length);
-
         protected void AckTransportMessage(TransportMessage transportMessage)
             => _transport.AckMessage(transportMessage);
 

src/Abc.Zebus/Core/BusMessageLogger.cs

@@ -3,35 +3,32 @@ using System.Collections.Concurrent;
 using System.Collections.Generic;
 using System.Reflection;
 using Abc.Zebus.Scan;
-using JetBrains.Annotations;
+using Abc.Zebus.Transport;
 using Abc.Zebus.Util.Extensions;
 using log4net;
-using log4net.Core;
 
 namespace Abc.Zebus.Core
 {
     public class BusMessageLogger
     {
-        private static readonly ConcurrentDictionary<Type, MessageTypeLogInfo> _logInfos = new ConcurrentDictionary<Type, MessageTypeLogInfo>();
-        private static readonly Func<Type, MessageTypeLogInfo> _logInfoFactory = CreateLogger;
-        private readonly Type _loggerType;
+        private static readonly ConcurrentDictionary<Type, MessageTypeLogHelper> _logHelpers = new ConcurrentDictionary<Type, MessageTypeLogHelper>();
         private readonly ILog _logger;
         private bool _logDebugEnabled;
         private bool _logInfoEnabled;
 
         public BusMessageLogger(Type loggerType)
-            : this(loggerType, loggerType.FullName)
+            : this(loggerType.FullName)
         {
         }
 
-        public BusMessageLogger(Type loggerType, string loggerFullName)
+        public BusMessageLogger(string loggerFullName)
         {
-            _loggerType = loggerType;
             _logger = LogManager.GetLogger(typeof(BusMessageLogger).Assembly, loggerFullName);
 
             // Instances of BusMessageLogger are static, no need to unsubscribe from these events
             _logger.Logger.Repository.ConfigurationChanged += (sender, args) => UpdateLogConfig();
             _logger.Logger.Repository.ConfigurationReset += (sender, args) => UpdateLogConfig();
+
             UpdateLogConfig();
 
             void UpdateLogConfig()
@@ -42,84 +39,126 @@ namespace Abc.Zebus.Core
         }
 
         public bool IsInfoEnabled(IMessage message)
-            => _logInfoEnabled && GetLogInfo(message).Logger.IsInfoEnabled;
+            => _logInfoEnabled && GetLogHelper(message).Logger.IsInfoEnabled;
 
-        [StringFormatMethod("format")]
-        public void InfoFormat(string format, IMessage message, string dispatchQueueName, MessageId? messageId = null, long messageSize = 0, PeerId peerId = default(PeerId))
+        public void LogHandleMessage(IList<IMessage> messages, string dispatchQueueName, MessageId? messageId)
         {
-            if (!_logInfoEnabled)
-                return;
+            var message = messages[0];
 
-            var logInfo = GetLogInfo(message);
-            if (!logInfo.Logger.IsInfoEnabled)
+            if (!TryGetLogHelperForInfo(message, out var logHelper))
                 return;
 
-            var messageText = logInfo.GetMessageText(message);
-            dispatchQueueName = string.IsNullOrEmpty(dispatchQueueName) || dispatchQueueName == DispatchQueueNameScanner.DefaultQueueName ? string.Empty : $" [{dispatchQueueName}]";
+            var messageText = logHelper.GetMessageText(message);
+            var dispatchQueueNameText = HasCustomDispatchQueue() ? $" [{dispatchQueueName}]" : "";
+            var batchText = messages.Count > 1 ? $" Count: {messages.Count}" : "";
 
-            _logger.InfoFormat(format, messageText, dispatchQueueName, messageId, messageSize, peerId);
+            _logger.Info($"HANDLE{dispatchQueueNameText}: {messageText}{batchText} [{messageId}]");
+
+            bool HasCustomDispatchQueue() => !string.IsNullOrEmpty(dispatchQueueName) && dispatchQueueName != DispatchQueueNameScanner.DefaultQueueName;
         }
 
-        [StringFormatMethod("format")]
-        public void DebugFormat(string format, IMessage message, MessageId? messageId = null, long messageSize = 0, PeerId peerId = default(PeerId))
+        public void LogReceiveMessageAck(MessageExecutionCompleted messageAck)
         {
-            if (!_logDebugEnabled)
+            if (!TryGetLogHelperForDebug(messageAck, out _))
                 return;
 
-            var logInfo = GetLogInfo(message);
-            if (!logInfo.Logger.IsDebugEnabled)
+            _logger.Debug($"RECV ACK {{{messageAck}}}");
+        }
+
+        public void LogReceiveMessageLocal(IMessage message)
+        {
+            if (!TryGetLogHelperForDebug(message, out var logHelper))
                 return;
 
-            var messageText = logInfo.GetMessageText(message);
-            _logger.DebugFormat(format, messageText, messageId, messageSize, peerId);
+            var messageText = logHelper.GetMessageText(message);
+            _logger.Debug($"RECV local: {messageText}");
         }
 
-        [StringFormatMethod("format")]
-        public void InfoFormat(string format, IMessage message, IList<Peer> peers, MessageId messageId, long messageSize)
+        public void LogReceiveMessageRemote(IMessage message, TransportMessage transportMessage)
         {
-            if (!_logInfoEnabled)
+            if (!TryGetLogHelperForDebug(message, out var logHelper))
                 return;
 
-            var logInfo = GetLogInfo(message);
-            if (!logInfo.Logger.IsInfoEnabled)
+            var messageText = logHelper.GetMessageText(message);
+            _logger.Debug($"RECV remote: {messageText} from {transportMessage.SenderId} ({transportMessage.Content.Length} bytes). [{transportMessage.Id}]");
+        }
+
+        public void LogSendMessage(IMessage message, IList<Peer> peers)
+        {
+            if (!TryGetLogHelperForInfo(message, out var logHelper))
+                return;
+
+            var messageText = logHelper.GetMessageText(message);
+            var targetPeersText = GetTargetPeersText(peers);
+
+            _logger.Info($"SEND: {messageText} to {targetPeersText}");
+        }
+
+        public void LogSendMessage(IMessage message, IList<Peer> peers, TransportMessage transportMessage)
+        {
+            if (!TryGetLogHelperForInfo(message, out var logHelper))
                 return;
 
-            var messageText = logInfo.GetMessageText(message);
-            var targetPeersText = GetTargetPeersText();
+            var messageText = logHelper.GetMessageText(message);
+            var targetPeersText = GetTargetPeersText(peers);
 
-            _logger.InfoFormat(format, messageText, targetPeersText, messageId, messageSize);
+            _logger.Info($"SEND: {messageText} to {targetPeersText} ({transportMessage.Content.Length} bytes) [{transportMessage.Id}]");
+        }
 
-            string GetTargetPeersText()
+        private static string GetTargetPeersText(IList<Peer> peers)
+        {
+            switch (peers.Count)
             {
-                switch (peers.Count)
-                {
-                    case 0:
-                        return "no target peer";
-
-                    case 1:
-                        return peers[0].Id.ToString();
-
-                    default:
-                        var otherPeersCount = peers.Count - 1;
-                        return otherPeersCount > 1
-                            ? peers[0].Id + " and " + otherPeersCount + " other peers"
-                            : peers[0].Id + " and " + otherPeersCount + " other peer";
-                }
+                case 0:
+                    return "no target peer";
+
+                case 1:
+                    return peers[0].Id.ToString();
+
+                default:
+                    var otherPeersCount = peers.Count - 1;
+                    return otherPeersCount > 1
+                        ? peers[0].Id + " and " + otherPeersCount + " other peers"
+                        : peers[0].Id + " and " + otherPeersCount + " other peer";
             }
         }
 
         public static string ToString(IMessage message)
-            => GetLogInfo(message).GetMessageText(message);
+            => GetLogHelper(message).GetMessageText(message);
 
-        private static MessageTypeLogInfo GetLogInfo(IMessage message)
-            => _logInfos.GetOrAdd(message.GetType(), _logInfoFactory);
+        private static MessageTypeLogHelper GetLogHelper(IMessage message)
+            => _logHelpers.GetOrAdd(message.GetType(), type => CreateLogger(type));
 
-        private static MessageTypeLogInfo CreateLogger(Type messageType)
+        private static MessageTypeLogHelper CreateLogger(Type messageType)
         {
             var logger = LogManager.GetLogger(messageType);
             var hasToStringOverride = HasToStringOverride(messageType);
 
-            return new MessageTypeLogInfo(logger, hasToStringOverride, messageType.GetPrettyName());
+            return new MessageTypeLogHelper(logger, hasToStringOverride, messageType.GetPrettyName());
+        }
+
+        private bool TryGetLogHelperForInfo(IMessage message, out MessageTypeLogHelper logHelper)
+        {
+            if (!_logInfoEnabled)
+            {
+                logHelper = null;
+                return false;
+            }
+
+            logHelper = GetLogHelper(message);
+            return logHelper.Logger.IsInfoEnabled;
+        }
+
+        private bool TryGetLogHelperForDebug(IMessage message, out MessageTypeLogHelper logHelper)
+        {
+            if (!_logDebugEnabled)
+            {
+                logHelper = null;
+                return false;
+            }
+
+            logHelper = GetLogHelper(message);
+            return logHelper.Logger.IsDebugEnabled;
         }
 
         private static bool HasToStringOverride(Type messageType)
@@ -128,13 +167,13 @@ namespace Abc.Zebus.Core
             return methodInfo != null;
         }
 
-        private class MessageTypeLogInfo
+        private class MessageTypeLogHelper
         {
             public readonly ILog Logger;
             private readonly bool _hasToStringOverride;
             private readonly string _messageTypeName;
 
-            public MessageTypeLogInfo(ILog logger, bool hasToStringOverride, string messageTypeName)
+            public MessageTypeLogHelper(ILog logger, bool hasToStringOverride, string messageTypeName)
             {
                 Logger = logger;
                 _hasToStringOverride = hasToStringOverride;

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

@@ -8,7 +8,7 @@ namespace Abc.Zebus.Dispatch.Pipes
 {
     public class PipeInvocation : IMessageHandlerInvocation
     {
-        private static readonly BusMessageLogger _messageLogger = new BusMessageLogger(typeof(PipeInvocation), "Abc.Zebus.Dispatch");
+        private static readonly BusMessageLogger _messageLogger = new BusMessageLogger("Abc.Zebus.Dispatch");
 
         private readonly List<Action<object>> _handlerMutations = new List<Action<object>>();
         private readonly IMessageHandlerInvoker _invoker;
@@ -99,14 +99,14 @@ namespace Abc.Zebus.Dispatch.Pipes
 
         IDisposable IMessageHandlerInvocation.SetupForInvocation()
         {
-            _messageLogger.InfoFormat("HANDLE{1}: {0} [{2}]", _messages[0], _invoker.DispatchQueueName, _messageContext.MessageId);
+            _messageLogger.LogHandleMessage(_messages, _invoker.DispatchQueueName, _messageContext.MessageId);
 
             return MessageContext.SetCurrent(_messageContext);
         }
 
         IDisposable IMessageHandlerInvocation.SetupForInvocation(object messageHandler)
         {
-            _messageLogger.InfoFormat("HANDLE{1}: {0} [{2}]", _messages[0], _invoker.DispatchQueueName, _messageContext.MessageId);
+            _messageLogger.LogHandleMessage(_messages, _invoker.DispatchQueueName, _messageContext.MessageId);
 
             ApplyMutations(messageHandler);
 

src/Abc.Zebus/Transport/TransportMessage.cs

@@ -41,6 +41,9 @@ namespace Abc.Zebus.Transport
         [JsonIgnore]
         public bool IsPersistTransportMessage => PersistentPeerIds != null && PersistentPeerIds.Count != 0;
 
+        [JsonIgnore]
+        public PeerId SenderId => Originator.SenderId;
+
         public TransportMessage(MessageTypeId messageTypeId, Stream content, Peer sender)
             : this(messageTypeId, content, sender.Id, sender.EndPoint)
         {