More logging, and some optimization

Author: patrick-dmxc

RDMSharp/RDM/AsyncRDMRequestHelper.cs

@@ -177,6 +177,11 @@ public async Task<RequestResult> RequestMessage(RDMMessage request, bool setTran
             Logger?.LogTrace($"Successful Request: {request?.ToString()} Response: {response?.ToString()} ElapsedTime: {bag2?.ElapsedTime}");
             return result;
         }
+        catch (TimeoutException)
+        {
+            Logger?.LogInformation($"Timeout Exception Request: {request}");
+            return new RequestResult(request, timeout: true);
+        }
         catch (Exception ex)
         {
             Logger?.LogError(ex);

RDMSharp/RDM/GlobalTimers.cs

@@ -1,10 +1,12 @@
-using System;
+using Microsoft.Extensions.Logging;
+using System;
 
 [assembly: System.Runtime.CompilerServices.InternalsVisibleTo("RDMSharp.Tests")]
 namespace RDMSharp;
 
 public class GlobalTimers
 {
+    private static readonly ILogger Logger = Logging.CreateLogger<GlobalTimers>();
     private static GlobalTimers instance = null;
     public static GlobalTimers Instance
     {
@@ -107,6 +109,7 @@ public event EventHandler PresentUpdateTimerElapsed
     }
     private void initializeParameterUpdateTimer()
     {
+        Logger?.LogInformation("InitializeParameterUpdateTimer");
         if (parameterUpdateTimer != null)
             return;
         parameterUpdateTimer = new System.Timers.Timer(ParameterUpdateTimerInterval);
@@ -115,6 +118,7 @@ private void initializeParameterUpdateTimer()
     }
     private void destroyParameterUpdateTimer()
     {
+        Logger?.LogCritical("DestroyParameterUpdateTimer");
         if (parameterUpdateTimer == null)
             return;
         parameterUpdateTimer.Enabled = false;
@@ -125,6 +129,7 @@ private void destroyParameterUpdateTimer()
 
     private void initializePresentUpdateTimer()
     {
+        Logger?.LogInformation("InitializePresentUpdateTimer");
         if (parameterUpdateTimer != null)
             return;
         presentUpdateTimer = new System.Timers.Timer(PresentUpdateTimerInterval);
@@ -133,6 +138,7 @@ private void initializePresentUpdateTimer()
     }
     private void destroyPresentUpdateTimer()
     {
+        Logger?.LogCritical("DestroyPresentUpdateTimer");
         if (parameterUpdateTimer == null)
             return;
         presentUpdateTimer.Enabled = false;
@@ -142,6 +148,7 @@ private void destroyPresentUpdateTimer()
     }
     public void ResetAllTimersToDefault()
     {
+        Logger?.LogCritical("ResetAllTimersToDefault");
         QueuedUpdateTime = DefaultQueuedUpdateTime;
         NonQueuedUpdateTime = DefaultNonQueuedUpdateTime;
         UpdateDelayBetweenRequests = DefaultUpdateDelayBetweenRequests;
@@ -172,37 +179,52 @@ internal void InternalAllTimersToTestSpeed()
 
     private void ParameterUpdateTimer_Elapsed(object sender, System.Timers.ElapsedEventArgs e)
     {
-        // Parallelisierung: Alle Handler parallel ausführen, falls mehrere abonniert sind
-        var handlers = parameterUpdateTimerElapsed?.GetInvocationList();
-        if (handlers != null)
+        try
         {
-            System.Threading.Tasks.Parallel.ForEach(handlers, handler =>
+            var handlers = parameterUpdateTimerElapsed?.GetInvocationList();
+            if (handlers != null)
             {
-                try
+                System.Threading.Tasks.Parallel.ForEach(handlers, handler =>
                 {
-                    ((EventHandler)handler)?.Invoke(sender, EventArgs.Empty);
-                }
-                catch
-                {
-                }
-            });
+                    try
+                    {
+                        ((EventHandler)handler)?.Invoke(sender, EventArgs.Empty);
+                    }
+                    catch (Exception ex)
+                    {
+                        Logger?.LogError(ex, "Error in ParameterUpdateTimerElapsed handler");
+                    }
+                });
+            }
+        }
+        catch (Exception ex)
+        {
+            Logger?.LogError(ex, "Error in ParameterUpdateTimer_Elapsed");
         }
     }
     private void PresentUpdateTimer_Elapsed(object sender, System.Timers.ElapsedEventArgs e)
     {
-        var handlers = presentUpdateTimerElapsed?.GetInvocationList();
-        if (handlers != null)
+        try
         {
-            System.Threading.Tasks.Parallel.ForEach(handlers, handler =>
+            var handlers = presentUpdateTimerElapsed?.GetInvocationList();
+            if (handlers != null)
             {
-                try
+                System.Threading.Tasks.Parallel.ForEach(handlers, handler =>
                 {
-                    ((EventHandler)handler)?.Invoke(sender, EventArgs.Empty);
-                }
-                catch
-                {
-                }
-            });
+                    try
+                    {
+                        ((EventHandler)handler)?.Invoke(sender, EventArgs.Empty);
+                    }
+                    catch (Exception ex)
+                    {
+                        Logger?.LogError(ex, "Error in PresentUpdateTimerElapsed handler");
+                    }
+                });
+            }
+        }
+        catch (Exception ex)
+        {
+            Logger?.LogError(ex, "Error in PresentUpdateTimer_Elapsed");
         }
     }
 }

RDMSharp/RDM/PeerToPeerProcess.cs

@@ -161,7 +161,15 @@ public async Task Run(AsyncRDMRequestHelper asyncRDMRequestHelper = null)
             int counter = 0;
             do
             {
-                await RDMSharp.Instance.lockTransaktion(UID).WaitAsync(TimeSpan.FromSeconds(7));
+                try
+                {
+                    await RDMSharp.Instance.lockTransaktion(UID, TimeSpan.FromSeconds(7));
+                }
+                catch (TimeoutException)
+                {
+
+                }
+
                 counter++;
                 if (response?.ResponseType == ERDM_ResponseType.ACK)
                     return;
@@ -285,6 +293,11 @@ public async Task Run(AsyncRDMRequestHelper asyncRDMRequestHelper = null)
             }
             while (!done && State == EPeerToPeerProcessState.Running);
         }
+        catch (TimeoutException te)
+        {
+            Logger?.LogInformation($"Timeout while running PeerToPeerProcess: {Command} UID: {UID} SubDevice: {SubDevice} Parameter: {ParameterBag.PID}");
+            State = EPeerToPeerProcessState.Failed;
+        }
         catch (Exception e)
         {
             Logger?.LogError(e);

RDMSharp/RDMSharp.cs

@@ -106,15 +106,24 @@ internal byte getTransactionCounter(UID uid)
             return 0;
         }
     }
-    internal Task lockTransaktion(UID uid)
+    internal Task lockTransaktion(UID uid, TimeSpan? timeout = null)
     {
         if (!transactionLock.TryGetValue(uid, out SemaphoreSlim semaphore))
         {
             semaphore = new SemaphoreSlim(1);
             transactionLock.TryAdd(uid, semaphore);
         }
 
-        return semaphore.WaitAsync();
+        if (timeout.HasValue)
+            try
+            {
+                return semaphore.WaitAsync(timeout.Value);
+            }
+            catch (TimeoutException) { }// Ignore Exception
+        else
+            return semaphore.WaitAsync();
+
+        return Task.CompletedTask;
     }
     internal void unlockTransaktion(UID uid)
     {