chore: add logging for current scenario searching

src/PepperDash.Essentials.Core/Room/Combining/EssentialsRoomCombiner.cs

@@ -1,11 +1,10 @@
-using System;
+using Crestron.SimplSharp;
+using PepperDash.Core;
+using PepperDash.Core.Logging;
+using Serilog.Events;
+using System;
 using System.Collections.Generic;
 using System.Linq;
-using Crestron.SimplSharp;
-
-using PepperDash.Core;
-using Serilog.Events;
-using Newtonsoft.Json;
 
 namespace PepperDash.Essentials.Core
 {
@@ -35,7 +34,7 @@ namespace PepperDash.Essentials.Core
             }
             set
             {
-                if(value == _isInAutoMode)
+                if (value == _isInAutoMode)
                 {
                     return;
                 }
@@ -93,7 +92,7 @@ namespace PepperDash.Essentials.Core
             });
         }
 
-        void CreateScenarios()
+        private void CreateScenarios()
         {
             foreach (var scenarioConfig in _propertiesConfig.Scenarios)
             {
@@ -102,21 +101,20 @@ namespace PepperDash.Essentials.Core
             }
         }
 
-        void SetRooms()
+        private void SetRooms()
         {
             _rooms = new List<IEssentialsRoom>();
 
             foreach (var roomKey in _propertiesConfig.RoomKeys)
             {
-                var room = DeviceManager.GetDeviceForKey(roomKey) as IEssentialsRoom;
+                if (DeviceManager.GetDeviceForKey(roomKey) is IEssentialsRoom room)
-                if (room != null)
                 {
                     _rooms.Add(room);
                 }
             }
         }
 
-        void SetupPartitionStateProviders()
+        private void SetupPartitionStateProviders()
         {
             foreach (var pConfig in _propertiesConfig.Partitions)
             {
@@ -130,18 +128,18 @@ namespace PepperDash.Essentials.Core
             }
         }
 
-        void PartitionPresentFeedback_OutputChange(object sender, FeedbackEventArgs e)
+        private void PartitionPresentFeedback_OutputChange(object sender, FeedbackEventArgs e)
         {
             StartDebounceTimer();
         }
 
-        void StartDebounceTimer()
+        private void StartDebounceTimer()
         {
             // default to 500ms for manual mode
             var time = 500;
 
             // if in auto mode, debounce the scenario change
-            if(IsInAutoMode) time = _scenarioChangeDebounceTimeSeconds * 1000;
+            if (IsInAutoMode) time = _scenarioChangeDebounceTimeSeconds * 1000;
 
             if (_scenarioChangeDebounceTimer == null)
             {
@@ -156,7 +154,7 @@ namespace PepperDash.Essentials.Core
         /// <summary>
         /// Determines the current room combination scenario based on the state of the partition sensors
         /// </summary>
-        void DetermineRoomCombinationScenario()
+        private void DetermineRoomCombinationScenario()
         {
             if (_scenarioChangeDebounceTimer != null)
             {
@@ -164,14 +162,20 @@ namespace PepperDash.Essentials.Core
                 _scenarioChangeDebounceTimer = null;
             }
 
+            this.LogInformation("Determining Combination Scenario");
+
             var currentScenario = RoomCombinationScenarios.FirstOrDefault((s) =>
             {
+                this.LogDebug("Checking scenario {scenarioKey}", s.Key);
                 // iterate the partition states
                 foreach (var partitionState in s.PartitionStates)
                 {
+                    this.LogDebug("checking PartitionState {partitionStateKey}", partitionState.PartitionKey);
                     // get the partition by key
                     var partition = Partitions.FirstOrDefault((p) => p.Key.Equals(partitionState.PartitionKey));
 
+                    this.LogDebug("Expected State: {partitionPresent} Actual State: {partitionState}", partitionState.PartitionPresent, partition.PartitionPresentFeedback.BoolValue);
+
                     if (partition != null && partitionState.PartitionPresent != partition.PartitionPresentFeedback.BoolValue)
                     {
                         // the partition can't be found or the state doesn't match
@@ -184,6 +188,7 @@ namespace PepperDash.Essentials.Core
 
             if (currentScenario != null)
             {
+                this.LogInformation("Found combination Scenario {scenarioKey}", currentScenario.Key);
                 CurrentScenario = currentScenario;
             }
         }
@@ -253,7 +258,7 @@ namespace PepperDash.Essentials.Core
 
         public void ToggleMode()
         {
-            if(IsInAutoMode)
+            if (IsInAutoMode)
             {
                 SetManualMode();
             }

src/PepperDash.Essentials.Core/Room/Combining/RoomCombinationScenario.cs

@@ -1,22 +1,15 @@
-
+using Newtonsoft.Json;
-
-using System;
-using System.Collections.Generic;
-using System.Linq;
-using System.Text;
-using Crestron.SimplSharp;
-
 using PepperDash.Core;
-
+using PepperDash.Core.Logging;
-using Newtonsoft.Json;
 using Serilog.Events;
+using System.Collections.Generic;
 
 namespace PepperDash.Essentials.Core
 {
     /// <summary>
     /// Represents a room combination scenario
     /// </summary>
-    public class RoomCombinationScenario: IRoomCombinationScenario, IKeyName
+    public class RoomCombinationScenario : IRoomCombinationScenario, IKeyName
     {
         private RoomCombinationScenarioConfig _config;
 
@@ -40,7 +33,7 @@ namespace PepperDash.Essentials.Core
             get { return _isActive; }
             set
             {
-                if(value == _isActive)
+                if (value == _isActive)
                 {
                     return;
                 }
@@ -78,12 +71,13 @@ namespace PepperDash.Essentials.Core
 
         public void Activate()
         {
-            Debug.LogMessage(LogEventLevel.Debug, "Activating Scenario: '{0}' with {1} action(s) defined", Name, activationActions.Count);   
+            Debug.LogMessage(LogEventLevel.Debug, "Activating Scenario: '{name}' with {activationActionCount} action(s) defined", this, Name, activationActions.Count);
 
             if (activationActions != null)
             {
                 foreach (var action in activationActions)
                 {
+                    this.LogDebug("Running Activation action {@action}", action);
                     DeviceJsonApi.DoDeviceAction(action);
                 }
             }
@@ -93,12 +87,13 @@ namespace PepperDash.Essentials.Core
 
         public void Deactivate()
         {
-            Debug.LogMessage(LogEventLevel.Debug, "Deactivating Scenario: '{0}' with {1} action(s) defined", Name, deactivationActions.Count);
+            Debug.LogMessage(LogEventLevel.Debug, "Deactivating Scenario: '{name}' with {deactivationActionCount} action(s) defined", this, Name, deactivationActions.Count);
 
             if (deactivationActions != null)
             {
                 foreach (var action in deactivationActions)
                 {
+                    this.LogDebug("Running deactivation action {@action}", action);
                     DeviceJsonApi.DoDeviceAction(action);
                 }
             }

src/PepperDash.Essentials.Core/Routing/Extensions.cs

@@ -1,8 +1,10 @@
-using PepperDash.Core;
+using Serilog.Events;
-using Serilog.Events;
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.Linq;
+using System.Runtime.CompilerServices;
+using Debug = PepperDash.Core.Debug;
 
 
 namespace PepperDash.Essentials.Core
@@ -21,8 +23,13 @@ namespace PepperDash.Essentials.Core
         /// and then attempts a new Route and if sucessful, stores that RouteDescriptor
         /// in RouteDescriptorCollection.DefaultCollection
         /// </summary>
+        [MethodImpl(MethodImplOptions.NoInlining)] // REMOVE ME
         public static void ReleaseAndMakeRoute(this IRoutingInputs destination, IRoutingOutputs source, eRoutingSignalType signalType, string destinationPortKey = "", string sourcePortKey = "")
         {
+            // Remove this line before committing!!!!!
+            var frame = new StackFrame(1, true);
+            Debug.LogMessage(LogEventLevel.Information, "ReleaseAndMakeRoute Called from {method} with params {destinationKey}:{sourceKey}:{signalType}:{destinationPortKey}:{sourcePortKey}", frame.GetMethod().Name, destination.Key, source.Key, signalType.ToString(), destinationPortKey, sourcePortKey);
+
             var inputPort = string.IsNullOrEmpty(destinationPortKey) ? null : destination.InputPorts.FirstOrDefault(p => p.Key == destinationPortKey);
             var outputPort = string.IsNullOrEmpty(sourcePortKey) ? null : source.OutputPorts.FirstOrDefault(p => p.Key == sourcePortKey);
 
@@ -33,8 +40,8 @@ namespace PepperDash.Essentials.Core
         {
             if (destination == null) throw new ArgumentNullException(nameof(destination));
             if (source == null) throw new ArgumentNullException(nameof(source));
-            if (destinationPort == null) Debug.LogMessage(LogEventLevel.Verbose, "Destination port is null");
+            if (destinationPort == null) Debug.LogMessage(LogEventLevel.Information, "Destination port is null");
-            if (sourcePort == null) Debug.LogMessage(LogEventLevel.Verbose, "Source port is null");
+            if (sourcePort == null) Debug.LogMessage(LogEventLevel.Information, "Source port is null");
 
             var routeRequest = new RouteRequest
             {
@@ -57,7 +64,7 @@ namespace PepperDash.Essentials.Core
 
                 RouteRequests[destination.Key] = routeRequest;
 
-                Debug.LogMessage(LogEventLevel.Verbose, "Device: {0} is cooling down and already has a routing request stored.  Storing new route request to route to source key: {1}", null, destination.Key, routeRequest.Source.Key);
+                Debug.LogMessage(LogEventLevel.Information, "Device: {destination} is cooling down and already has a routing request stored.  Storing new route request to route to source key: {sourceKey}", null, destination.Key, routeRequest.Source.Key);
 
                 return;
             }
@@ -71,14 +78,14 @@ namespace PepperDash.Essentials.Core
 
                 RouteRequests.Add(destination.Key, routeRequest);
 
-                Debug.LogMessage(LogEventLevel.Verbose, "Device: {0} is cooling down.  Storing route request to route to source key: {1}", null, destination.Key, routeRequest.Source.Key);
+                Debug.LogMessage(LogEventLevel.Information, "Device: {destination} is cooling down.  Storing route request to route to source key: {sourceKey}", null, destination.Key, routeRequest.Source.Key);
                 return;
             }
 
             if (RouteRequests.ContainsKey(destination.Key) && coolingDevice != null && coolingDevice.IsCoolingDownFeedback.BoolValue == false)
             {
                 RouteRequests.Remove(destination.Key);
-                Debug.LogMessage(LogEventLevel.Verbose, "Device: {0} is NOT cooling down.  Removing stored route request and routing to source key: {1}", null, destination.Key, routeRequest.Source.Key);
+                Debug.LogMessage(LogEventLevel.Information, "Device: {destination} is NOT cooling down.  Removing stored route request and routing to source key: {sourceKey}", null, destination.Key, routeRequest.Source.Key);
             }
 
             destination.ReleaseRoute();

src/PepperDash.Essentials.Core/Routing/RouteRequest.cs

@@ -1,4 +1,7 @@
-namespace PepperDash.Essentials.Core
+using PepperDash.Core;
+using Serilog.Events;
+
+namespace PepperDash.Essentials.Core
 {
     public class RouteRequest
     {
@@ -11,10 +14,13 @@
 
         public void HandleCooldown(object sender, FeedbackEventArgs args)
         {
+            Debug.LogMessage(LogEventLevel.Information, "Handling cooldown route request: {destination}:{destinationPort} -> {source}:{sourcePort} {type}", null, Destination.Key, DestinationPort.Key, Source.Key, SourcePort.Key, SignalType.ToString());
+
             var coolingDevice = sender as IWarmingCooling;
 
             if (args.BoolValue == false)
             {
+                Debug.LogMessage(LogEventLevel.Information, "Cooldown complete. Making route from {destination} to {source}", Destination.Key, Source.Key);
                 Destination.ReleaseAndMakeRoute(Source, SignalType);
 
                 if (sender == null) return;