From 00a67378e54d633092817f9ad48f9e1bf4ce573d Mon Sep 17 00:00:00 2001 From: Onkel Andy Date: Thu, 26 Sep 2024 01:03:34 +0200 Subject: [PATCH] stateengine plugin: fix and improve logging --- stateengine/StateEngineAction.py | 19 +++++++++++-------- stateengine/StateEngineItem.py | 18 +++++++++++------- stateengine/StateEngineValue.py | 19 +++++++++++-------- 3 files changed, 33 insertions(+), 23 deletions(-) diff --git a/stateengine/StateEngineAction.py b/stateengine/StateEngineAction.py index 2cd578b44..69250609d 100755 --- a/stateengine/StateEngineAction.py +++ b/stateengine/StateEngineAction.py @@ -429,6 +429,8 @@ def execute(self, is_repeat: bool, allow_item_repeat: bool, state): # check if any conditiontype is met or not # condition: type of condition 'conditionset'/'previousconditionset'/'previousstate_conditionset'/'nextconditionset' def _check_condition(condition: str): + self._log_debug("Checking {}", condition) + self._log_increase_indent() _conditions_met_count = 0 _conditions_necessary_count = 0 _condition_to_meet = None @@ -451,23 +453,24 @@ def _check_condition(condition: str): _updated_current_condition = self._abitem.get_variable("next.conditionset_id") if _current_condition == '' else _current_condition _condition_to_meet = _condition_to_meet if isinstance(_condition_to_meet, list) else [_condition_to_meet] _condition_met = [] + self._log_decrease_indent() for cond in _condition_to_meet: - if cond is not None: + if cond is not None and condition not in _conditions_met_type: _conditions_necessary_count += 1 _orig_cond = cond try: - cond = re.compile(cond) _matching = cond.fullmatch(_updated_current_condition) if _matching: - self._log_debug("Given {} {} matches current one: {}", condition, _orig_cond, _updated_current_condition) + self._log_debug("Given {} '{}' matches current one: '{}'", condition, _orig_cond.pattern, _updated_current_condition) _condition_met.append(_updated_current_condition) _conditions_met_count += 1 + _conditions_met_type.append(condition) else: - self._log_debug("Given {} {} not matching current one: {}", condition, _orig_cond, _updated_current_condition) - self.update_webif_actionstatus(state, self._name, 'False', None, f"({condition} {_orig_cond} not met)") + self._log_debug("Given {} '{}' not matching current one: '{}'", condition, _orig_cond.pattern, _updated_current_condition) + self.update_webif_actionstatus(state, self._name, 'False', None, f"({condition} {_orig_cond.pattern} not met)") except Exception as ex: if cond is not None: - self._log_warning("Given {} {} is not a valid regex: {}", condition, _orig_cond, ex) + self._log_warning("Given {} '{}' is not a valid regex: {}", condition, _orig_cond.pattern, ex) return _condition_met, _conditions_met_count, _conditions_necessary_count # update web interface with delay info @@ -499,11 +502,9 @@ def _update_repeat_webif(value: bool): self._log_increase_indent() try: self._getitem_fromeval() - self._log_decrease_indent() _validitem = True except Exception: _validitem = False - self._log_decrease_indent() if not self._can_execute(state): self._log_decrease_indent() return @@ -513,6 +514,7 @@ def _update_repeat_webif(value: bool): previous_condition_met = None previousstate_condition_met = None next_condition_met = None + _conditions_met_type = [] if not self.conditionset.is_empty(): current_condition_met, cur_conditions_met, cur_condition_necessary = _check_condition('conditionset') conditions_met += cur_conditions_met @@ -529,6 +531,7 @@ def _update_repeat_webif(value: bool): next_condition_met, next_conditions_met, next_conditionset_necessary = _check_condition('nextconditionset') conditions_met += next_conditions_met condition_necessary += min(1, next_conditionset_necessary) + self._log_decrease_indent() self._log_develop("Action '{0}': conditions met: {1}, necessary {2}.", self._name, conditions_met, condition_necessary) if conditions_met < condition_necessary: self._log_info("Action '{0}': Skipping because not all conditions are met.", self._name) diff --git a/stateengine/StateEngineItem.py b/stateengine/StateEngineItem.py index f0d5b9a3c..407dba038 100755 --- a/stateengine/StateEngineItem.py +++ b/stateengine/StateEngineItem.py @@ -223,18 +223,17 @@ def __init__(self, smarthome, item, se_plugin): self.__name = str(self.__item) self.__itemClass = Item # initialize logging - + self.__logger.log_level_as_num = 2 self.__log_level = StateEngineValue.SeValue(self, "Log Level", False, "num") _default_log_level = self.__logger.default_log_level.get() _returnvalue, _returntype, _using_default, _issue, _ = self.__log_level.set_from_attr(self.__item, "se_log_level", - _default_log_level) + default_value=_default_log_level) self.__using_default_log_level = _using_default _returnvalue = self.__log_level.get() if isinstance(_returnvalue, list) and len(_returnvalue) == 1: _returnvalue = _returnvalue[0] - self.__logger.log_level_as_num = 2 _startup_log_level = self.__logger.startup_log_level.get() @@ -266,13 +265,13 @@ def __init__(self, smarthome, item, se_plugin): # get startup delay self.__startup_delay = StateEngineValue.SeValue(self, "Startup Delay", False, "num") - self.__startup_delay.set_from_attr(self.__item, "se_startup_delay", StateEngineDefaults.startup_delay) + self.__startup_delay.set_from_attr(self.__item, "se_startup_delay", default_value=StateEngineDefaults.startup_delay) self.__startup_delay_over = False # Init suspend settings self.__default_suspend_time = StateEngineDefaults.suspend_time.get() self.__suspend_time = StateEngineValue.SeValue(self, "Suspension time on manual changes", False, "num") - self.__suspend_time.set_from_attr(self.__item, "se_suspend_time", self.__default_suspend_time) + self.__suspend_time.set_from_attr(self.__item, "se_suspend_time", default_value=self.__default_suspend_time) # Init laststate and previousstate items/values self.__config_issues = {} @@ -459,7 +458,7 @@ def update_leave_action(self, default_instant_leaveaction): self.__default_instant_leaveaction = default_instant_leaveaction _returnvalue_leave, _returntype_leave, _using_default_leave, _issue, _ = self.__instant_leaveaction.set_from_attr( - self.__item, "se_instant_leaveaction", default_instant_leaveaction) + self.__item, "se_instant_leaveaction", default_value=default_instant_leaveaction) if len(_returnvalue_leave) > 1: self.__logger.warning("se_instant_leaveaction for item {} can not be defined as a list" @@ -2111,7 +2110,12 @@ def get_update_original_source(self): # return value of variable def get_variable(self, varname): - return self.__variables[varname] if varname in self.__variables else "(Unknown variable '{0}'!)".format(varname) + if varname not in self.__variables: + returnvalue = "(Unknown variable '{0}'!)".format(varname) + self.__logger.warning("Issue when getting variable {}".format(returnvalue)) + else: + returnvalue = self.__variables[varname] + return returnvalue # set value of variable def set_variable(self, varname, value): diff --git a/stateengine/StateEngineValue.py b/stateengine/StateEngineValue.py index 0e14b1296..b4ff3a3bb 100755 --- a/stateengine/StateEngineValue.py +++ b/stateengine/StateEngineValue.py @@ -115,7 +115,7 @@ def set_from_attr(self, item, attribute_name, default_value=None, reset=True, at value = default_value _using_default = True self._log_develop("Processing value from attribute name {0}, reset {1}, type {2}: using default value {3}", - attribute_name, reset, value, attr_type) + attribute_name, reset, attr_type, value) value_list = [] if value is not None and isinstance(value, list) and attr_type is not None: for i, entry in enumerate(value): @@ -475,6 +475,7 @@ def get_type(self): # Write condition to logger def write_to_logger(self): + returnvalues = [] if self.__template is not None: self._log_info("{0}: Using template(s) {1}", self.__name, self.__template) if self.__value is not None: @@ -484,7 +485,7 @@ def write_to_logger(self): self._log_debug("{0}: {1} ({2})", self.__name, i, type(i)) else: self._log_debug("{0}: {1} ({2})", self.__name, self.__value, type(self.__value)) - return self.__value + returnvalues.append(self.__value) if self.__regex is not None: if isinstance(self.__regex, list): for i in self.__regex: @@ -492,7 +493,7 @@ def write_to_logger(self): self._log_debug("{0} from regex: {1}", self.__name, i) else: self._log_debug("{0} from regex: {1}", self.__name, self.__regex) - return f"regex:{self.__regex}" + returnvalues.append(f"regex:{self.__regex}") if self.__struct is not None: if isinstance(self.__struct, list): for i in self.__struct: @@ -501,7 +502,7 @@ def write_to_logger(self): else: self._log_debug("{0} from struct: {1}", self.__name, self.__struct.property.path) - return self.__struct + returnvalues.append(self.__struct) if self.__item is not None: _original_listorder = self.__listorder.copy() items = [] @@ -517,14 +518,14 @@ def write_to_logger(self): items = self.__get_from_item() self._log_debug("Currently item results in {}", items) self.__listorder = _original_listorder - return items + returnvalues.append(items) if self.__eval is not None: self._log_debug("{0} from eval: {1}", self.__name, self.__eval) _original_listorder = self.__listorder.copy() eval_result = self.__get_eval() self._log_debug("Currently eval results in {}. ", eval_result) self.__listorder = _original_listorder - return eval_result + returnvalues.append(eval_result) if self.__varname is not None: if isinstance(self.__varname, list): for i in self.__varname: @@ -535,8 +536,10 @@ def write_to_logger(self): _original_listorder = self.__listorder.copy() var_result = self.__get_from_variable() self.__listorder = _original_listorder - return var_result - return None + returnvalues.append(var_result) + returnvalues = StateEngineTools.flatten_list(returnvalues) + returnvalues = returnvalues[0] if len(returnvalues) == 1 else None if len(returnvalues) == 0 else returnvalues + return returnvalues # Get Text (similar to logger text) # prefix: Prefix for text