I’m having some very strange and critical problem which occurs for a longer time but more and more often. I started with OH 2.5 where some of my basic sensors and controls were in place. With OH 2.5 everything was OK (I should also say, at that time I had only few action items/switches). Then I’ve updated to 3.0/3.1/3.2/3.3 and I started to experience some very strange issues. In some special circumstances, when an update happens (an update is triggered), then another item is also getting an update. This means, I’m opening my garage gate and suddenly the lights are turned off in the house. What is strange, this issue is not constantly happening and also the triggered item is different. Sometimes the the rollershutters are closed or the front gate is opened.
The issue also occurs randomly, there are sometimes days or a week and everything is OK, then suddenly happens this.
Originally in OH 3.0 I experienced this issue only ones a month, now I’m running on 3.3M1 and I experience it every day or second day.
In the log, I do not see anything strange, suddenly an item gets an update. The only point what is common, there is always a trigger (another item update) before/after this happens, which is triggered by a user or an automation.
A sample log:
2022-02-23 10:16:45.709 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZM_Monitor1_Image' changed from raw type (image/jpeg): 167877 bytes to raw type (image/jpeg): 180873 bytes
2022-02-23 10:16:52.300 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'Switch_FrontGate_OnOff2' received command OFF
2022-02-23 10:16:52.311 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Switch_FrontGate_OnOff2' predicted to become OFF
2022-02-23 10:16:52.315 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Switch_FrontGate_OnOff2' changed from ON to OFF
2022-02-23 10:16:53.039 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'Switch_LampsIndoorAll' received command OFF
2022-02-23 10:16:53.043 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Switch_LampsIndoorAll' changed from ON to OFF
2022-02-23 10:16:55.923 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZM_Monitor1_Image' changed from raw type (image/jpeg): 180873 bytes to raw type (image/jpeg): 175058 bytes
2022-02-23 10:16:59.983 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'Switch_LampsL1_OnOff' received command OFF
2022-02-23 10:16:59.985 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Switch_LampsL1_OnOff' predicted to become OFF
2022-02-23 10:16:59.995 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'Switch_LampsL2_OnOff' received command OFF
2022-02-23 10:16:59.996 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Switch_LampsL1_OnOff' changed from ON to OFF
2022-02-23 10:16:59.997 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Switch_LampsL2_OnOff' predicted to become OFF
2022-02-23 10:17:00.015 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Switch_LampsL2_OnOff' changed from ON to OFF
2022-02-23 10:17:00.017 [INFO ] [hab.event.GroupItemStateChangedEvent] - Item 'gLampsIndoor' changed from ON to OFF through Switch_LampsL2_OnOff
2022-02-23 10:17:00.019 [INFO ] [hab.event.GroupItemStateChangedEvent] - Item 'gLamps' changed from ON to OFF through gLampsIndoor
The expected item update was ‘Switch_FrontGate_OnOff2’ → OFF
The unexpected item update was ‘Switch_LampsL1_OnOff’ → OFF
An additional information: most of my action items as communicating through MQTT (Sonoff switches, custom nodemcu implementation, tradfri buttons, …). When such update happens, I do not see any incoming message in MQTT explorer, so the event is not coming from the device.
Any help is appreciated, how can I find out, what the hell is going on here …
Does that happen to be a member of a Group, 'Switch_LampsIndoorAll', or is that an Item associated with it in some way ?
It will be important in your investigation to distinguish between commands and updates at the openHAB end, these are different events with different possible sources and different effects.
Yes, I have rules. 90% percent of my rules start with a log messages, what I do not see in the log. I just walked through all rules now and added message to every.
This virtual switch is used to turn on/off multiple real switches, but not trough a group operation. Below you can see the relations and also the only rule which is reacting to ‘Switch_LampsIndoorAll’.
I mean that in your original post, you talked a lot about updates. But the events.log (and well done for including it) shows that the unwanted actions are really commands. These are different things in openHAB, like cause and effect.
Already made my suggestion to find out what can issue commands to Switch_LampsIndoorAll, likely that will be rules, or GUI.
I’ve searched through all my rule files (luckily I’m writing the rules in files), and the only place where the ‘Switch_LampsIndoorAll’ was found is that rule, I’ve posted earlier, but this is also just reading but not writing the item.
When searching the whole OH strucuture, here are the results:
rules\scenes.rules - Found in that only rule, mentioned above
sitemaps\watch.sitemap - There is a switch item defined
sitemaps\ _quickaccess.sitemap - There is a switch item defined
items\scenes.items - Definition of the item
Alright, then that leaves any GUI as suspects for issuing commands. What was open at the time? Includes phone apps and MainUI in a browser window at the back.
Searching for this special item-name is not enough! The item is member of group in more then one level. Do you have rules that act upon changes to those groups, possibly sending commands to members of the group? That way the item-name would not show in the rule!
It’s really unlikely that you would have the only OH server in the world that spontaneously issues commands to non-random devices.
Get yourself a good idea of what Items exactly are affected. As @opus points out, “parent” Group hierarchies are meant to pass commands down the line.
We should see commands to Groups in your events.log, no sign in the sample shown, but do keep it in mind.
Check in your MainUI that your Item has no unexpected links - Items defined from file with no links may later be given links from UI. This is an unlikely source of commands, though.
Sorry for the long quiet here, I did not have much time for OH. In the meanwhile, I’ve removed the hierarchies for groups as these were not used for anything and could complicate the life.
I’ve also checked the group rules, but did not find anything yet.
Yes, I know and most probably you are right, but the facts, that these strange things does not happen every time and always some other switch is getting an action lead me to this conclusion. If there would be a rule which is wrongly implemented, then always the same would happen. But this is not true.
Never mind, I’ll check all the group actions and items to see, if there is no duplicate assignments and will give here a feedback.
An update here! I was able to see a very similar issue, when I save my item file, which holds all my MQTT items. In such case some of my items are receiving a command. What is strange, that not all items are receiving a command. Do you have any answer what the hell is going one?
Here is the result of one save on the mqtt.items file:
2022-03-15 12:01:16.588 [INFO ][el.core.internal.ModelRepositoryImpl] - Loading model 'mqtt.items'
==> /var/log/openhab/events.log <==
2022-03-15 12:01:18.279 [INFO ][openhab.event.ItemCommandEvent ] - Item 'Switch_LampsIndoorAll' received commandOFF
2022-03-15 12:01:18.282 [INFO ][openhab.event.ItemStateChangedEvent ] - Item 'Switch_LampsIndoorAll' changed from ON to OFF
2022-03-15 12:01:18.295 [INFO ][openhab.event.ItemCommandEvent ] - Item 'Switch_LampsL1_OnOff' received commandOFF
2022-03-15 12:01:18.302 [INFO ][openhab.event.ItemCommandEvent ] - Item 'Switch_LampsL2_OnOff' received commandOFF
2022-03-15 12:01:18.304 [INFO ][penhab.event.ItemStatePredictedEvent] - Item 'Switch_LampsL1_OnOff' predicted to become OFF
2022-03-15 12:01:18.311 [INFO ][penhab.event.ItemStatePredictedEvent] - Item 'Switch_LampsL2_OnOff' predicted to become OFF
2022-03-15 12:01:18.321 [INFO ][openhab.event.ItemCommandEvent ] - Item 'Switch_GarageLight2_OnOff' received commandON
2022-03-15 12:01:18.323 [INFO ][openhab.event.ItemStateChangedEvent ] - Item 'Switch_LampsL1_OnOff' changed from ON to OFF
2022-03-15 12:01:18.324 [INFO ][openhab.event.ItemStateChangedEvent ] - Item 'Switch_LampsL2_OnOff' changed from ON to OFF
2022-03-15 12:01:18.326 [INFO ][hab.event.GroupItemStateChangedEvent] - Item 'gLampsIndoor' changed from ON to OFF through Switch_LampsL2_OnOff
2022-03-15 12:01:18.328 [INFO ][penhab.event.ItemStatePredictedEvent] - Item 'Switch_GarageLight2_OnOff' predicted to become ON
==> /var/log/openhab/openhab.log <==
2022-03-15 12:01:18.274 [INFO ][enhab.core.model.script.scenes.rules] - Main door remote >> State: toggle; Command:
2022-03-15 12:01:18.284 [INFO ][enhab.core.model.script.scenes.rules] - All lights on-off triggered OFF
2022-03-15 12:01:18.299 [INFO ][enhab.core.model.script.scenes.rules] - External remote >> State: brightness_up_click; Command:
I would guess that is likely the work of rules.
When you reload an xxx.items file, it reinitializes the changed Items, as it should. They will get NULL state as a consequence.
A while later, a remote device might check in with a routine status report or similar, and Item will get updated to a sensible value. The delay of some minutes from items file load would support that theory, and also tend to rule out buggy GUI widgets.
Note, that will be a state change event, and will trigger any rules listening for Item changes.
You will not see the reinitialize to NULL in your events.log, but if the theory is correct you would see the later NULL-to-whatever changes. Have a closer look in your log before the time of the snippet shared.
The standard initialization process you mentioned above is known also by me, I’ve seen that couple of times in the log when the OH server was restarted, but I did not see when a file item file was re-saved. I’ve checked the event log and I do not see initialization to null before the save event (BTW: the snippet I’ve shared above start with the save event → loading model ‘mqtt.item’).
For example ‘Switch_LampsIndoorAll’ is a virtual switch, it is not connected to a physical device.
The “Main door remote” and “External remote” are IKEA Tradfri remotes. Why are these receiving actions (which is a button press on the device)? Also if you see, both are receiving different commands. I think these were the last actions from these remotes.
String Rmt_EntryDoor_Action "Entry door remote [%s]" <button> (gHouse) {channel="mqtt:topic:myMQTTBroker:tradfri_rmt_1:Action"}
Thing topic tradfri_rmt_1 "Tradfri Remote 01"
{
Channels:
Type string : Action "Action" [ stateTopic="zigbee2mqtt/tradfri_rmt_1/action", postCommand=false ]
Type number : Battery "Battery" [ stateTopic="zigbee2mqtt/tradfri_rmt_1/battery" ]
Type number : Linkquality "Link quality" [ stateTopic="zigbee2mqtt/tradfri_rmt_1/linkquality" ]
}
Another anomaly is, why only these items are getting updates? In the mqtt.items file I have more than 40 items defined.
NOTE: I’ve a persistence service enabled, which is restoring some items states, but these items are not a part of it.
