Since update to 2.5M6 (from M4), rules are executed 16x if an update-trigger is used

[Euphi (Ian Hubbertz)]

Preamble: I solved the problem by changing trigger-type to “changed”. In my context this is not only a workaround, but also the better configuration. However, I still consider this as a bug, so that’s why I’m writing about it here.

Today I updated from 2.5M4 to 2.5M6.

Since the update, rules that are triggered by an update-trigger, are executed many times (16?) for each update:

20:59:12.735 [INFO ] [jsr223.jython.Thermostat             ] - Schalte Heizung für IaniZ ein.                                                                                                                                                
20:59:12.797 [DEBUG] [jsr223.jython.Thermostat             ] - Thermostat
20:59:12.863 [DEBUG] [jsr223.jython.Thermostat             ] - Getting item IaniZ_temp
20:59:12.990 [DEBUG] [jsr223.jython.Thermostat             ] - Heizungs-Mode: IaniZ_heizung updated to ON
20:59:13.006 [DEBUG] [jsr223.jython.Thermostat             ] - Getting item IaniZ_solltemp
20:59:13.054 [DEBUG] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Zustand: ON [Automatik: ON]
20:59:13.071 [DEBUG] [jsr223.jython.Thermostat             ] - Getting item IaniZ_heatauto
20:59:13.120 [DEBUG] [jsr223.jython.Thermostat             ] - Heizungs-Mode: IaniZ_heizung updated to ON
20:59:13.137 [DEBUG] [jsr223.jython.Thermostat             ] - Getting item IaniZ_heizung
20:59:13.177 [DEBUG] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Zustand: ON [Automatik: ON]
20:59:13.195 [INFO ] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Ist: 22.53 - Soll: 22.799999999999972 - Zustand: ON [Automatik: ON]
20:59:13.246 [DEBUG] [jsr223.jython.Thermostat             ] - Heizungs-Mode: IaniZ_heizung updated to ON
20:59:13.262 [DEBUG] [jsr223.jython.Thermostat             ] - Bereits eingeschaltet
20:59:13.292 [DEBUG] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Zustand: ON [Automatik: ON]
20:59:13.339 [DEBUG] [jsr223.jython.Thermostat             ] - Heizungs-Mode: IaniZ_heizung updated to ON
20:59:13.382 [DEBUG] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Zustand: ON [Automatik: ON]
20:59:13.430 [DEBUG] [jsr223.jython.Thermostat             ] - Heizungs-Mode: IaniZ_heizung updated to ON
20:59:13.472 [DEBUG] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Zustand: ON [Automatik: ON]
20:59:13.524 [DEBUG] [jsr223.jython.Thermostat             ] - Heizungs-Mode: IaniZ_heizung updated to ON
20:59:13.587 [DEBUG] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Zustand: ON [Automatik: ON]
20:59:13.649 [DEBUG] [jsr223.jython.Thermostat             ] - Heizungs-Mode: IaniZ_heizung updated to ON
20:59:13.696 [DEBUG] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Zustand: ON [Automatik: ON]
20:59:13.739 [DEBUG] [jsr223.jython.Thermostat             ] - Heizungs-Mode: IaniZ_heizung updated to ON
20:59:13.777 [DEBUG] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Zustand: ON [Automatik: ON]
20:59:13.821 [DEBUG] [jsr223.jython.Thermostat             ] - Heizungs-Mode: IaniZ_heizung updated to ON
20:59:13.859 [DEBUG] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Zustand: ON [Automatik: ON]
20:59:13.904 [DEBUG] [jsr223.jython.Thermostat             ] - Heizungs-Mode: IaniZ_heizung updated to ON
20:59:13.943 [DEBUG] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Zustand: ON [Automatik: ON]
20:59:13.998 [DEBUG] [jsr223.jython.Thermostat             ] - Heizungs-Mode: IaniZ_heizung updated to ON
20:59:14.036 [DEBUG] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Zustand: ON [Automatik: ON]
20:59:14.078 [DEBUG] [jsr223.jython.Thermostat             ] - Heizungs-Mode: IaniZ_heizung updated to ON
20:59:14.117 [DEBUG] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Zustand: ON [Automatik: ON]
20:59:14.165 [DEBUG] [jsr223.jython.Thermostat             ] - Heizungs-Mode: IaniZ_heizung updated to ON
20:59:14.208 [DEBUG] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Zustand: ON [Automatik: ON]
20:59:14.253 [DEBUG] [jsr223.jython.Thermostat             ] - Heizungs-Mode: IaniZ_heizung updated to ON
20:59:14.293 [DEBUG] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Zustand: ON [Automatik: ON]
20:59:14.338 [DEBUG] [jsr223.jython.Thermostat             ] - Heizungs-Mode: IaniZ_heizung updated to ON
20:59:14.383 [DEBUG] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Zustand: ON [Automatik: ON]
20:59:14.433 [DEBUG] [jsr223.jython.Thermostat             ] - Heizungs-Mode: IaniZ_heizung updated to ON
20:59:14.473 [DEBUG] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Zustand: ON [Automatik: ON]
20:59:14.515 [DEBUG] [jsr223.jython.Thermostat             ] - Heizungs-Mode: IaniZ_heizung updated to ON
20:59:14.556 [DEBUG] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Zustand: ON [Automatik: ON]

The rule looks like this:

@rule("Thermostat-Modus setzen")
@when("Member of gHeatAuto received update")
@when("Member of gHeater received update")
def therm_mode_changed(event):
    #plog = logging.getLogger("RULES.Heating.Mode")
    therm_temp_changed.log.debug("Heizungs-Mode: " + str(event))
    item = event.getItemName()
    prefix = item[:item.index("_")]
    item_mode = prefix+"_heatmode"
    item_switch = prefix+"_heizung"
    item_auto = prefix+"_heatauto"
    switch_state = itemRegistry.getItem(item_switch).getState()
    auto_mode = itemRegistry.getItem(item_auto).getState()
    therm_temp_changed.log.debug(u"Prefix %s: Zustand: %s [Automatik: %s]" % (prefix, unicode(switch_state), unicode(auto_mode)))
    newModeStr = "Auto_" if auto_mode==ON else "Manual_"
    newModeStr += "ON" if switch_state==ON else "OFF"
    events.sendCommand(item_mode, newModeStr)

Loading the rule shows, that a trigger is only generated once:

20:54:35.584 [DEBUG] [jsr223.jython.core.triggers          ] - when: target=[Member of gHeatAuto received update], target_type=Member of, trigger_target=gHeatAuto, trigger_type=received update, old_state=None, new_state=None
20:54:35.646 [DEBUG] [jsr223.jython.core.triggers          ] - when: target=[Member of gHeater received update], target_type=Member of, trigger_target=gHeater, trigger_type=received update, old_state=None, new_state=None
20:54:35.725 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-BadOG_heizung-received-update_66818eb0147411eaa9eb0281f4918d2c]
20:54:35.790 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-GrBad_heizung-received-update_668c1600147411eaa8f50281f4918d2c]
20:54:35.843 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-IaniZ_heizung-received-update_669564d1147411ea91020281f4918d2c]
20:54:35.935 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-Flur_heizung-received-update_669df04f147411eabf150281f4918d2c]
20:54:36.003 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-GZ_heizung-received-update_66ac482e147411eaaade0281f4918d2c]
20:54:36.055 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-AldoniZ_heizung-received-update_66b5e51e147411ea830b0281f4918d2c]
20:54:36.111 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-BadUG_heizung-received-update_66bdfb70147411ea83150281f4918d2c]
20:54:36.167 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-Kueche_heizung-received-update_66c6d50f147411ea95ef0281f4918d2c]
20:54:36.295 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-WZ_heizung-received-update_66ceeb5e147411ea9aba0281f4918d2c]
20:54:36.363 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-SZ_heizung-received-update_66e29a70147411eaa6fa0281f4918d2c]
20:54:36.420 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-GZ_heatauto-received-update_66ed21c0147411ea88750281f4918d2c]
20:54:36.484 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-IaniZ_heatauto-received-update_66f5d44f147411ea98be0281f4918d2c]
20:54:36.575 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-GrBad_heatauto-received-update_6703b700147411eab3590281f4918d2c]
20:54:36.633 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-Kueche_heatauto-received-update_670dc921147411ea9fed0281f4918d2c]
20:54:36.693 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-WZ_heatauto-received-update_671717f0147411eab45e0281f4918d2c]
20:54:36.749 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-AldoniZ_heatauto-received-update_671f5551147411eab3460281f4918d2c]
20:54:36.810 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-SZ_heatauto-received-update_6728a41e147411ea94300281f4918d2c]
20:54:36.878 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-BadUG_heatauto-received-update_67330461147411ea9b030281f4918d2c]
20:54:36.936 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-Flur_heatauto-received-update_673bde00147411eaaed50281f4918d2c]
20:54:36.992 [DEBUG] [jsr223.jython.core.triggers          ] - when: Created item_trigger: [Item-BadOG_heatauto-received-update_6744b79e147411eaaee60281f4918d2c]
20:54:37.039 [DEBUG] [jsr223.jython.core.rules             ] - Added rule [Thermostat-Modus setzen]

[Bruce_Osborne]

@Euphi

I still consider this as a bug, so that’s why I’m writing about it here.

Please also open an issue on GitHub then.

[rossko57]

Interesting. I note that the triggers here are “Member of Group” which is likely connected. Also seems a relatively long time (50 - 90mS) between triggers.

[Bruce_Osborne]

@rossko57

I note that the triggers here are “Member of Group” which is likely connected.

Whenever I have sent a command to a group, it is followed up by commands sent to each individual member of the group. That is standard behavior.

[rossko57]

Just so. Such commands may or may not provoke state updates for each individual member, configuration dependent. With no events log, we cannot see what started all this.

[5iver (Scott Rushworth)]

@Euphi

def therm_mode_changed(event):

@Euphi

therm_temp_changed.log.debug("Heizungs-Mode: " + str(event))

You must have another rule function named “therm_temp_changed” or you’d be getting an error. This should be (also cleaner using format)…

therm_mode_changed.log.debug(“Heizungs-Mode: {}”.format(event))

@Euphi

item = event.getItemName()

Cleaner with attributes rather than method…

item = event.itemName

@Euphi

switch_state = itemRegistry.getItem(item_switch).getState()
auto_mode = itemRegistry.getItem(item_auto).getState()

Use the items object injected into the default script scope. It contains the states of all Items and can be accessed as a dictionary. But

switch_state = items[item_switch]
auto_mode = items[item_auto]

@Euphi

therm_temp_changed.log.debug(u"Prefix %s: Zustand: %s [Automatik: %s]" % (prefix, unicode(switch_state), unicode(auto_mode)))

Another log from the wrong rule function. And another opportunity to use format…

therm_mode_changed.log.debug(u"Prefix {}: Zustand: {} [Automatik: {}]".format(prefix, switch_state, auto_mode))

@Euphi

events.sendCommand(item_mode, newModeStr)

If you are sending commands to Items in gHeatAuto or gHeater, then the rule will retrigger itself in a loop. Or more likely, the “therm_temp_changed” rule is changing the Items that are triggering this rule. What is in this other rule? It looks like there is a mix of logs from both of the rules, so the rules look to be interacting with each other. It wold be a lot easier to tell the log entries apart if they weren’t all using the same logger (see above). It would also be helpful to see some example Item definitions.

I’m not aware fo any changes in automation between M4 and M6 that would have affected this. I don’t think this is a bug in OH, but a configuration issue.

@Bruce_Osborne

Please also open an issue on GitHub then.

Please wait until we can determine if this is a bug.

[Euphi (Ian Hubbertz)]

@5iver

@Euphi

therm_temp_changed.log.debug("Heizungs-Mode: " + str(event))

You must have another rule function named “therm_temp_changed” or you’d be getting an error. This should be (also cleaner using format)…

Thanks, I’ll fix this.
However, this is not related to the problem.

@5iver

therm_mode_changed.log.debug(“Heizungs-Mode: {}”.format(event))

@Euphi

item = event.getItemName()

Cleaner with attributes rather than method…

This rule is quite old, this was not possible when it was created.(Same for the dictionary in the script scope).

@5iver

@Euphi

events.sendCommand(item_mode, newModeStr)

If you are sending commands to Items in gHeatAuto or gHeater, then the rule will retrigger itself in a loop.

The item_mode is neither a member of gHeatAuto nor gHeater.

@5iver

Or more likely, the “therm_temp_changed” rule is changing the Items that are triggering this rule.

Yes, but only once. But it seems that this is related to the problem, because the problem did not occur, when the therm_mode_changed was initially triggered by the BasicUI.

@5iver

What is in this other rule? It looks like there is a mix of logs from both of the rules, so the rules look to be interacting with each other. It wold be a lot easier to tell the log entries apart if they weren’t all using the same logger (see above). It would also be helpful to see some example Item definitions.

Ok. I don’t have access to the sources right now, but I will post them this evening (CET).

However, from the log I see that the other rule is only triggered twice (the initial one that triggers the “therm_mode_changed” and then a second time where no more command is sent) (Line “Bereits eingeschaltet”).

@5iver

I’m not aware fo any changes in automation between M4 and M6 that would have affected this. I don’t think this is a bug in OH, but a configuration issue.

The problem was not there with M4 (Maybe it was executed twice - I’ll have a look at the logs again this evening).

Thanks for code review and your suggestions - the rule was implemented with on of the first versions of the helper library (still in Steve Bate’s repository) - and I’m more used to C++ format strings than to python

[Euphi (Ian Hubbertz)]

Ok. I tried again with “received update” triggers: This time the rule is executed only twice. Still strange, but I remember to had this behaviour also with M4.

If I use an “changed”-trigger, the rule is executed only once:

Log-File with “updated”-Trigger:

22:13:31.714 [DEBUG] [jsr223.jython.Thermostat             ] - Thermostat:IaniZ_temp updated to 22.58
22:13:31.752 [DEBUG] [jsr223.jython.Thermostat             ] - Getting item IaniZ_temp
22:13:31.787 [DEBUG] [jsr223.jython.Thermostat             ] - Getting item IaniZ_solltemp
22:13:31.822 [DEBUG] [jsr223.jython.Thermostat             ] - Getting item IaniZ_heatauto
22:13:31.856 [DEBUG] [jsr223.jython.Thermostat             ] - Getting item IaniZ_heizung
22:13:31.891 [INFO ] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Ist: 22.58 - Soll: 22.599999999999973 - Zustand: OFF [Automatik: ON]                                                                                       
22:13:31.926 [INFO ] [jsr223.jython.Thermostat             ] - Schalte Heizung für IaniZ ein.                       
22:13:32.124 [DEBUG] [jsr223.jython.Thermostat-Modus setzen] - Heizungs-Mode: IaniZ_heizung updated to ON
22:13:32.202 [DEBUG] [jsr223.jython.Thermostat-Modus setzen] - Prefix IaniZ: Zustand: ON [Automatik: ON]
22:13:32.267 [DEBUG] [jsr223.jython.Thermostat-Modus setzen] - Heizungs-Mode: IaniZ_heizung updated to ON
22:13:32.301 [DEBUG] [jsr223.jython.Thermostat-Modus setzen] - Prefix IaniZ: Zustand: ON [Automatik: ON]

Log-File with “changed”-trigger:

22:22:00.902 [DEBUG] [jsr223.jython.Thermostat             ] - Thermostat:IaniZ_solltemp changed from 22.59999999999
9973 to 22.799999999999972
22:22:01.025 [DEBUG] [jsr223.jython.Thermostat             ] - Getting item IaniZ_temp
22:22:01.157 [DEBUG] [jsr223.jython.Thermostat             ] - Getting item IaniZ_solltemp
22:22:01.217 [DEBUG] [jsr223.jython.Thermostat             ] - Getting item IaniZ_heatauto
22:22:01.284 [DEBUG] [jsr223.jython.Thermostat             ] - Getting item IaniZ_heizung
22:22:01.345 [INFO ] [jsr223.jython.Thermostat             ] - Prefix IaniZ: Ist: 22.61 - Soll: 22.799999999999972 -
Zustand: OFF [Automatik: ON]                                                                                        
22:22:01.416 [INFO ] [jsr223.jython.Thermostat             ] - Schalte Heizung für IaniZ ein.                        
22:22:01.997 [DEBUG] [jsr223.jython.Thermostat-Modus setzen] - Heizungs-Mode: IaniZ_heizung changed from OFF to ON   
22:22:02.152 [DEBUG] [jsr223.jython.Thermostat-Modus setzen] - Prefix IaniZ: Zustand: ON [Automatik: ON]