stateengine plugin: improve logging

stateengine/StateEngineAction.py

@@ -149,6 +149,9 @@ def set_source(self, current_condition, previous_condition, previousstate_condit
     # state: state item that triggered the action
     def execute(self, is_repeat: bool, allow_item_repeat: bool, state):
         self._state = state
+        self._log_decrease_indent(50)
+        self._log_increase_indent()
+        self._log_info("Action '{0}': Preparing", self._name)
         if not self._can_execute():
             return
         conditions_met = 0
@@ -219,8 +222,6 @@ def execute(self, is_repeat: bool, allow_item_repeat: bool, state):
         if conditions_met < condition_necessary:
             self._log_info("Action '{0}': Skipping because not all conditions are met.", self._name)
             return
-        else:
-            self._log_info("Action '{0}': Running.", self._name)
 
         if is_repeat:
             _key1 = ['{}'.format(state.id), 'actions_stay', '{}'.format(self._name), 'repeat']
@@ -250,13 +251,15 @@ def execute(self, is_repeat: bool, allow_item_repeat: bool, state):
                 return
         else:
             repeat_text = ""
-
+        self._log_increase_indent()
         try:
             self._getitem_fromeval()
+            self._log_decrease_indent()
             _validitem = True
         except Exception as ex:
             _validitem = False
             self._log_error("Action '{0}': Ignored because {1}", self._name, ex)
+            self._log_decrease_indent()
         if _validitem:
             plan_next = self._se_plugin.scheduler_return_next(self._scheduler_name)
             if plan_next is not None and plan_next > self.shtime.now():
@@ -272,10 +275,14 @@ def execute(self, is_repeat: bool, allow_item_repeat: bool, state):
                 delay, self._scheduler_name)
             _delay_info = 0
             if delay is None:
+                self._log_increase_indent()
                 self._log_warning("Action '{0}': Ignored because of errors while determining the delay!", self._name)
+                self._log_decrease_indent()
                 _delay_info = -1
             elif delay < 0:
+                self._log_increase_indent()
                 self._log_warning("Action '{0}': Ignored because delay is negative!", self._name)
+                self._log_decrease_indent()
                 _delay_info = -1
             else:
                 self._waitforexecute(actionname, self._name, repeat_text, delay, current_condition_met, previous_condition_met, previousstate_condition_met)
@@ -325,7 +332,7 @@ def _waitforexecute(self, actionname: str, namevar: str = "", repeat_text: str =
         self._log_decrease_indent(50)
         self._log_increase_indent()
         if delay == 0:
-            self._log_info("Running action '{}'.", namevar)
+            self._log_info("Action '{}': Running.", namevar)
             self.real_execute(actionname, namevar, repeat_text, None, False, current_condition, previous_condition, previousstate_condition)
         else:
             instanteval = None if self.__instanteval is None else self.__instanteval.get()
@@ -484,11 +491,15 @@ def write_to_logger(self, log_level=StateEngineDefaults.log_level):
     # Check if execution is possible
     def _can_execute(self):
         if self.__item is None:
-            self._log_info("Action '{0}': No item defined. Ignoring.", self._name)
+            self._log_increase_indent()
+            self._log_warning("Action '{0}': No item defined. Ignoring.", self._name)
+            self._log_decrease_indent()
             return False
 
         if self.__value.is_empty():
-            self._log_info("Action '{0}': No value defined. Ignoring.", self._name)
+            self._log_increase_indent()
+            self._log_warning("Action '{0}': No value for item {1} defined. Ignoring.", self._name, self.__item)
+            self._log_decrease_indent()
             return False
 
         return True
@@ -843,11 +854,15 @@ def write_to_logger(self, log_level=StateEngineDefaults.log_level):
     # Check if execution is possible
     def _can_execute(self):
         if self.__item is None:
-            self._log_info("Action '{0}': No item defined. Ignoring.", self._name)
+            self._log_increase_indent()
+            self._log_warning("Action '{0}': No item defined. Ignoring.", self._name)
+            self._log_decrease_indent()
             return False
 
         if self.__value.is_empty():
-            self._log_info("Action '{0}': No value defined. Ignoring.", self._name)
+            self._log_increase_indent()
+            self._log_warning("Action '{0}': No value defined for item {1}. Ignoring.", self._name, self.__item)
+            self._log_decrease_indent()
             return False
 
         return True