Better Debug logging

GrumpyBusted · GrumpyBusted · commit f808152f4587 · 2018-02-04T11:13:49.000+01:00
diff --git a/Grumpy.MessageQueue.Msmq/MessageQueueManager.cs b/Grumpy.MessageQueue.Msmq/MessageQueueManager.cs
@@ -147,11 +147,11 @@ public Message Receive(System.Messaging.MessageQueue messageQueue, TimeSpan time
             }
             catch (Exception exception)
             {
-                _logger.Debug(exception, "Error Receiving Message from Message Queues");
-
                 if (exception is MessageQueueException messageQueueException && messageQueueException.MessageQueueErrorCode == MessageQueueErrorCode.IOTimeout)
                     return null;
 
+                _logger.Debug(exception, "Error Receiving Message from Message Queues");
+
                 throw new MessageQueueReceiveException(messageQueue, timeout, exception);
             }
         }
@@ -165,11 +165,11 @@ public Message ReceiveByCorrelationId(System.Messaging.MessageQueue messageQueue
             }
             catch (Exception exception)
             {
-                _logger.Debug(exception, "Error Receiving by Correlation Id Message from Message Queues");
-
                 if (exception is MessageQueueException messageQueueException && messageQueueException.MessageQueueErrorCode == MessageQueueErrorCode.IOTimeout)
                     return null;
 
+                _logger.Debug(exception, "Error Receiving by Correlation Id Message from Message Queues");
+
                 throw new MessageQueueReceiveException(messageQueue, correlationId, timeout, exception);
             }
         }
diff --git a/Grumpy.MessageQueue.Msmq/Queue.cs b/Grumpy.MessageQueue.Msmq/Queue.cs
@@ -337,7 +337,7 @@ public async Task<ITransactionalMessage> ReceiveAsync(int millisecondsTimeout, C
             {
                 if (exception is TaskCanceledException taskCanceledException)
                 {
-                    Logger.Warning(taskCanceledException, "Receive canceled {@Queue}", this);
+                    Logger.Debug(taskCanceledException, "Receive canceled {@Queue}", this);
 
                     return new TransactionalMessage();
                 }
diff --git a/Grumpy.MessageQueue/QueueHandler.cs b/Grumpy.MessageQueue/QueueHandler.cs
@@ -149,12 +149,9 @@ private void Process()
         {
             try
             {
-                _heartRateMonitor?.Start();
-
                 while (!(_cancellationTokenSource?.Token.IsCancellationRequested ?? true))
                 {
-                    if (_heartRateMonitor != null && _numberOfException == 0 && _heartRateMonitor.ElapsedMilliseconds > _heartRateMilliseconds)
-                        Heartbeat();
+                    Heartbeat();
 
                     var message = ReceiveMessage();
 
@@ -240,7 +237,7 @@ private void ErrorHandler(ITransactionalMessage message, Exception exception)
                 else
                     message.NAck();
             }
-            catch(Exception ex)
+            catch (Exception ex)
             {
                 _logger.Information(ex, "Exception in Error Handler {QueueName} {@Message} {@Exception}", _queueName, message, exception);
 
@@ -263,13 +260,26 @@ private bool CallErrorHandler(object message, Exception exception)
 
         private void Heartbeat()
         {
+            if (_heartbeatHandler == null)
+                return;
+
+            if (!_heartRateMonitor.IsRunning)
+            {
+                _heartRateMonitor.Start();
+
+                return;
+            }
+
+            if (_numberOfException > 0 || _heartRateMonitor?.ElapsedMilliseconds < _heartRateMilliseconds)
+                return;
+
             _logger.Debug("Heartbeat Handler called {QueueName}", _queueName);
 
             try
             {
-                _heartbeatHandler?.Invoke();
+                _heartbeatHandler.Invoke();
             }
-            catch(Exception exception)
+            catch (Exception exception)
             {
                 _logger.Warning(exception, "Error in Heartbeat Handler {QueueName}", _queueName);
             }
@@ -306,21 +316,24 @@ private void CleanUpTasks()
         {
             if (_numberOfException == 0)
             {
-                _logger.Debug("Cleaning up dead tasks {QueueName}", _queueName);
-
                 try
                 {
-                    foreach (var task in _workTasks.Where(t => t.IsCompleted || t.IsFaulted))
+                    if (_workTasks.Any())
                     {
-                        if (task.IsFaulted)
-                            CallErrorHandler(task.AsyncState, task.Exception);
+                        _logger.Debug("Cleaning up dead tasks {QueueName}", _queueName);
 
-                        task.Dispose();
-                    }
+                        foreach (var task in _workTasks.Where(t => t.IsCompleted || t.IsFaulted))
+                        {
+                            if (task.IsFaulted)
+                                CallErrorHandler(task.AsyncState, task.Exception);
+
+                            task.Dispose();
+                        }
 
-                    _workTasks.RemoveAll(t => t.IsCompleted || t.IsFaulted);
+                        _workTasks.RemoveAll(t => t.IsCompleted || t.IsFaulted);
+                    }
                 }
-                catch(Exception exception)
+                catch (Exception exception)
                 {
                     _logger.Information(exception, "Error in cleaning up dead tasks {QueueName}", _queueName);
                 }

Original file line number	Diff line number	Diff line change
`@@ -147,11 +147,11 @@ public Message Receive(System.Messaging.MessageQueue messageQueue, TimeSpan time`
`147`	`147`	`}`
`148`	`148`	`catch (Exception exception)`
`149`	`149`	`{`
`150`		`- _logger.Debug(exception, "Error Receiving Message from Message Queues");`
`151`		`-`
`152`	`150`	`if (exception is MessageQueueException messageQueueException && messageQueueException.MessageQueueErrorCode == MessageQueueErrorCode.IOTimeout)`
`153`	`151`	`return null;`
`154`	`152`
	`153`	`+ _logger.Debug(exception, "Error Receiving Message from Message Queues");`
	`154`	`+`
`155`	`155`	`throw new MessageQueueReceiveException(messageQueue, timeout, exception);`
`156`	`156`	`}`
`157`	`157`	`}`
`@@ -165,11 +165,11 @@ public Message ReceiveByCorrelationId(System.Messaging.MessageQueue messageQueue`
`165`	`165`	`}`
`166`	`166`	`catch (Exception exception)`
`167`	`167`	`{`
`168`		`- _logger.Debug(exception, "Error Receiving by Correlation Id Message from Message Queues");`
`169`		`-`
`170`	`168`	`if (exception is MessageQueueException messageQueueException && messageQueueException.MessageQueueErrorCode == MessageQueueErrorCode.IOTimeout)`
`171`	`169`	`return null;`
`172`	`170`
	`171`	`+ _logger.Debug(exception, "Error Receiving by Correlation Id Message from Message Queues");`
	`172`	`+`
`173`	`173`	`throw new MessageQueueReceiveException(messageQueue, correlationId, timeout, exception);`
`174`	`174`	`}`
`175`	`175`	`}`
Original file line number	Diff line number	Diff line change
`@@ -337,7 +337,7 @@ public async Task<ITransactionalMessage> ReceiveAsync(int millisecondsTimeout, C`
`337`	`337`	`{`
`338`	`338`	`if (exception is TaskCanceledException taskCanceledException)`
`339`	`339`	`{`
`340`		`- Logger.Warning(taskCanceledException, "Receive canceled {@Queue}", this);`
	`340`	`+ Logger.Debug(taskCanceledException, "Receive canceled {@Queue}", this);`
`341`	`341`
`342`	`342`	`return new TransactionalMessage();`
`343`	`343`	`}`
Original file line number	Diff line number	Diff line change
`@@ -149,12 +149,9 @@ private void Process()`
`149`	`149`	`{`
`150`	`150`	`try`
`151`	`151`	`{`
`152`		`- _heartRateMonitor?.Start();`
`153`		`-`
`154`	`152`	`while (!(_cancellationTokenSource?.Token.IsCancellationRequested ?? true))`
`155`	`153`	`{`
`156`		`- if (_heartRateMonitor != null && _numberOfException == 0 && _heartRateMonitor.ElapsedMilliseconds > _heartRateMilliseconds)`
`157`		`- Heartbeat();`
	`154`	`+ Heartbeat();`
`158`	`155`
`159`	`156`	`var message = ReceiveMessage();`
`160`	`157`
`@@ -240,7 +237,7 @@ private void ErrorHandler(ITransactionalMessage message, Exception exception)`
`240`	`237`	`else`
`241`	`238`	`message.NAck();`
`242`	`239`	`}`
`243`		`- catch(Exception ex)`
	`240`	`+ catch (Exception ex)`
`244`	`241`	`{`
`245`	`242`	`_logger.Information(ex, "Exception in Error Handler {QueueName} {@Message} {@Exception}", _queueName, message, exception);`
`246`	`243`
`@@ -263,13 +260,26 @@ private bool CallErrorHandler(object message, Exception exception)`
`263`	`260`
`264`	`261`	`private void Heartbeat()`
`265`	`262`	`{`
	`263`	`+ if (_heartbeatHandler == null)`
	`264`	`+ return;`
	`265`	`+`
	`266`	`+ if (!_heartRateMonitor.IsRunning)`
	`267`	`+ {`
	`268`	`+ _heartRateMonitor.Start();`
	`269`	`+`
	`270`	`+ return;`
	`271`	`+ }`
	`272`	`+`
	`273`	`+ if (_numberOfException > 0 \|\| _heartRateMonitor?.ElapsedMilliseconds < _heartRateMilliseconds)`
	`274`	`+ return;`
	`275`	`+`
`266`	`276`	`_logger.Debug("Heartbeat Handler called {QueueName}", _queueName);`
`267`	`277`
`268`	`278`	`try`
`269`	`279`	`{`
`270`		`- _heartbeatHandler?.Invoke();`
	`280`	`+ _heartbeatHandler.Invoke();`
`271`	`281`	`}`
`272`		`- catch(Exception exception)`
	`282`	`+ catch (Exception exception)`
`273`	`283`	`{`
`274`	`284`	`_logger.Warning(exception, "Error in Heartbeat Handler {QueueName}", _queueName);`
`275`	`285`	`}`
`@@ -306,21 +316,24 @@ private void CleanUpTasks()`
`306`	`316`	`{`
`307`	`317`	`if (_numberOfException == 0)`
`308`	`318`	`{`
`309`		`- _logger.Debug("Cleaning up dead tasks {QueueName}", _queueName);`
`310`		`-`
`311`	`319`	`try`
`312`	`320`	`{`
`313`		`- foreach (var task in _workTasks.Where(t => t.IsCompleted \|\| t.IsFaulted))`
	`321`	`+ if (_workTasks.Any())`
`314`	`322`	`{`
`315`		`- if (task.IsFaulted)`
`316`		`- CallErrorHandler(task.AsyncState, task.Exception);`
	`323`	`+ _logger.Debug("Cleaning up dead tasks {QueueName}", _queueName);`
`317`	`324`
`318`		`- task.Dispose();`
`319`		`- }`
	`325`	`+ foreach (var task in _workTasks.Where(t => t.IsCompleted \|\| t.IsFaulted))`
	`326`	`+ {`
	`327`	`+ if (task.IsFaulted)`
	`328`	`+ CallErrorHandler(task.AsyncState, task.Exception);`
	`329`	`+`
	`330`	`+ task.Dispose();`
	`331`	`+ }`
`320`	`332`
`321`		`- _workTasks.RemoveAll(t => t.IsCompleted \|\| t.IsFaulted);`
	`333`	`+ _workTasks.RemoveAll(t => t.IsCompleted \|\| t.IsFaulted);`
	`334`	`+ }`
`322`	`335`	`}`
`323`		`- catch(Exception exception)`
	`336`	`+ catch (Exception exception)`
`324`	`337`	`{`
`325`	`338`	`_logger.Information(exception, "Error in cleaning up dead tasks {QueueName}", _queueName);`
`326`	`339`	`}`