I’ve restarted my OH container and now, when I save the mqtt.items file, then no action is executed… That’s why I think, there will be a problem in the OH as the behavior is not consistent. :S
Okay, some more information. It seems, the behavior I see is somehow related to last commands. After the OH server restart, when saving the items file, nothing happened. Then I clicked a button on one of my Tradfri remotes, which was switching my external lamp on, then I pushed another button, which was turning off my lamp. The lamp is turned on/off through a rule, which is executed, when the button on the remote it pushed.
2022-03-15 16:55:51.257 [INFO ] [enhab.core.model.script.scenes.rules] - Main door remote >> State: brightness_down_click; Command:
2022-03-15 16:55:51.258 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Rmt_EntryDoor_Action' changed from brightness_up_click to brightness_down_click
2022-03-15 16:55:51.262 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'Switch_ExtLamp_OnOff' received command OFF
2022-03-15 16:55:51.264 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Switch_ExtLamp_OnOff' predicted to become OFF
2022-03-15 16:55:51.268 [INFO ] [hab.event.GroupItemStateChangedEvent] - Item 'gLampsOutoor' changed from ON to OFF through Switch_ExtLamp_OnOff
2022-03-15 16:55:51.269 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Switch_ExtLamp_OnOff' changed from ON to OFF
Now, when I re-save my mqtt file, then it is re-sending the Tradfri remote comand.
2022-03-15 16:59:15.716 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mqtt.items'
2022-03-15 16:59:15.946 [INFO ] [enhab.core.model.script.scenes.rules] - Main door remote >> State: brightness_down_click; Command:
2022-03-15 16:59:15.954 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'Switch_ExtLamp_OnOff' received command OFF
2022-03-15 16:59:15.967 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Switch_ExtLamp_OnOff' predicted to become OFF
Again, consider how likely that only you see this special openHAB behavior.
I expect you saved the items file because you made changes.
Some bindings are not very good about dealing with changes in-flight, especially when using old style items and things files, and a restart of binding or system will be required.
Exactly what might happen is very dependent on the change and on the binding.
What actions? I don’t see any activity on those Items (or are they trigger channels?) in the events.log provided.
I can see your rules producing some log messages. I cannot see how those rules are triggered.
Is the offending Item linked to MQTT channel by definition in the items file? (most likely)
Is the remote device publishing it’s MQTT messages with a ‘retained’ tag?
What do we think might happen if an Item is reinitialised and an associated MQTT topic is retained? (I don’t know the answer to that, but you might be finding out)
I was not changing the items directly I just added a space to the end of the items file. But okay, I can understand and live with that fact. In the last weeks I was not seeing these “strange” things too frequently, but are still there (mainly in the last week) and are very dangerous. So, what I did yesterday, I’ve removed most of my groups and left only for the status items (temp sensors, etc.). Non of the current groups have subgroups nor parent groups. I’m trying to eliminate the complexity.
This is a very good question! I was not aware of that, and it could answer some observations. The Tradfri devices are proxied to MQTT through the Zigbee2mqtt library. It was not clear from the documentation if these messages are then proxied as persisted or not, but from the behaviors I saw seems to be as persistent. So now, I’ve explicitly disabled the persistence for all messages.
I’ve a couple of tasmota flashed switches, where the power retain was also enabled. So I’ll disable these as well.
What I also did, I’ve enabled the logging on the mosquitto broker. The reason was to see, who is triggering these unwanted actions. Yesterday I was analyzing another strange thing, and I did not see, any special message from MQTT side, so it was not the one, which was triggering the “unexpected” command. So it really seems, it is coming from OH.
What is hard, I cannot constantly repo any of these things, everything happens randomly and every time something else happens. I do not see any connection between them 
Summary till now:
- I’ve added logs to every rule, to see, if the rule is not the one which is triggering, but non of the analyzed issue was containing a rule log.
- I’ve closed HabPanel for a week, the issues were still happening.
- I’ve minimized the groups and removed the group relationships, so I think this factor is eliminated. - that was only yesterday, so will see
- I’ve removed the Tradfri rule code as it was very often making issues - the isses are still happening. The Tradfri issues could be caused by the message retain, what I have explicitly disabled now in zigbee2mqtt - will see
- I’ve enabled MQTT logging to see, if the “unwanted” action is not triggered by a device - I was not seeing it in the logs, so I think not.
What would be nice if I could enable a logging for the mobile apps. AFAIK, these are comunicating with OH through the REST API. Am I right? If yes, then is it possible to turn on logging there as well? I want to eliminate, that not the mobile app is the one who is changing something.
I can’t see any reson to implicate Group usage from what you have shared so far. Group involvement in commands when recieved is merely to pass them along to all members. Both Group and members would log such shared commands. Rules or GUI may issue commands to Groups, so you’d already be looking at that source.
I don’t know how you trap everything recieved by REST, but not sure it helps. You already know when commands are recieved because they are logged, regardless of source. You’re telling us you have put tell-tale logging in rules that could issue commands? By elimination then, from REST. Assuming affected Items are not configured by binding to recieve command (e.g. postCommand=true in MQTT, other bindings possible too).
I have no other idea, that’s why I’m trying to eliminate everything, which could cause issues. The groups were created at the beginning of my OH life to tag the items based on rooms, functionality, etc. Then these groups were put into hierarchy (outdoor → garage, house → rooms → room1 …). This hierarchy was then never used. So, this is not bad, nothing is limited, I’ve just cleaned them up 
Yes, every rule start with a log line.
This is not true, as I see only a command (coming from an unknown source), which is then causing some other action. What I wanted to really know, from which source is the command coming. What was triggering it? A mobile app? Or … I don’t really have an idea, what else
Hmm, the Tradfri controllers have the postCommand value set to true. But only those.
We’re going back to about post 2 here. This isn’t going to be random. Get a clear grasp of what you see as Items unexpectedly commamded. What is this subset of Items representing? What is it linked to, bindings wise? Remember we don’t have any idea what your “Tradfri controllers” are or how you have configured them to act.
Pick one culprit, follow it through in detail.
For elimination purposes, are you using “follow” link profile anywhere? This would NOT produce command logs, but could cause unexpected target device actions.
On this subject; “it” here is worth understanding properly.
My theory is that re-saving Item re-initialises it … leading to resubscribe via MQTT … leading to retrieval of a retained message … leading, because postCommand=true, to an openHAB command.
Note that MQTT retain is set per message. Even if you have now set the device not to send messages with 'retain" instruction, the broker will keep the last retained message indefinitely.
You have to take positive action to flush those out of the broker.
Okay, I know it’s complicated. As I see now, there are at least two different cases, what I’m solving here.
The first is the Tradfri remote (TRÅDFRI Remote control - IKEA), which is receiving an update when the items file is saved. This is most probably a by design issue, but would be good to understand what is going on under the hood. I stopped at this topic because at the beginning I though it is the same “random” thing. Now I think it is different.
The second thing are the random commands which are affecting not only the tradfri controllers by some other ones as well. This second case is the most important as randomly closing garage gates and front gates with little kids is really dangerous.
I’ll describe both cases in a separate post then.
So the first one:
I have 2 Tradfri remote controllers configured. It is communicating with zigbee. I’ve a zigbee stick (slaesh), which is then proxied by the zigbee2mqtt (GitHub - Koenkk/zigbee2mqtt: Zigbee 🐝 to MQTT bridge 🌉, get rid of your proprietary Zigbee bridges 🔨) to a mosquitto MQTT server. My OH is then connected to the mosquitto MQTT server.
The trandfri is using the following binding:
Thing topic tradfri_rmt_1 "Tradfri Remote 01"
{
Channels:
Type string : Action "Action" [ stateTopic="zigbee2mqtt/tradfri_rmt_1/action" ]
Type number : Battery "Battery" [ stateTopic="zigbee2mqtt/tradfri_rmt_1/battery" ]
Type number : Linkquality "Link quality" [ stateTopic="zigbee2mqtt/tradfri_rmt_1/linkquality" ]
}
The pressed button action is received in a string.
The items definition is the following:
String Rmt_EntryDoor_Action "Entry door remote [%s]" <button> {channel="mqtt:topic:myMQTTBroker:tradfri_rmt_1:Action"}
Number Rmt_EntryDoor_Battery "Entry door remote [%.1f %%]" <battery> (gBattery) {channel="mqtt:topic:myMQTTBroker:tradfri_rmt_1:Battery"}
Number Rmt_EntryDoor_Signal "Entry door remote [%d]" {channel="mqtt:topic:myMQTTBroker:tradfri_rmt_1:Linkquality"}
and finally the rule:
rule "External remote"
when
Item Rmt_External_Action received update
then
var currentState = Rmt_External_Action.state.toString
logInfo("scenes.rules", "External remote >> State: " + currentState)
// turn on-off the lights
if(currentState == 'toggle'){
if(Switch_WaterPump_OnOff.state == ON){
sendCommand(Switch_WaterPump_OnOff, OFF)
Echo_Terasse_Announcement.sendCommand('{ "sound": true, "speak":"Water pump is disabled.", "title": "Action", "body": "Hello", "volume": 40}')
} else {
sendCommand(Switch_WaterPump_OnOff, ON)
Echo_Terasse_Announcement.sendCommand('{ "sound": true, "speak":"Water pump is enabled.", "title": "Action", "body": "Hello", "volume": 40}')
}
}
else if(currentState == 'arrow_right_click'){
// front gate
Switch_FrontGate_OnOff_Toggle.sendCommand('ON')
}
else if(currentState == 'arrow_left_click'){
// garage
Switch_GarageGate_OnOff.sendCommand('ON')
}
else if(currentState == 'brightness_up_click'){
sendCommand(Switch_GarageLight2_OnOff, ON)
}
else if(currentState == 'brightness_up_hold'){
sendCommand(Switch_ExtLamp_OnOff, ON)
sendCommand(Switch_GarageLight2_OnOff, ON)
}
else if(currentState == 'brightness_down_click'){
sendCommand(Switch_GarageLight2_OnOff, OFF)
}
else if(currentState == 'brightness_down_hold'){
sendCommand(Switch_ExtLamp_OnOff, OFF)
sendCommand(Switch_GarageLight2_OnOff, OFF)
}
end
I think, here the “received update” is the tricky stuff, but non of the other events were working correctly. The item changed is not a deal, as I can press the same button multiple times, the rule should react to it.
What happens:
I’ve clicked the “up” button last time on the remote:
Mosquitto log:
2022-04-14T20:38:04: Sending PUBLISH to myMQTTClient (d0, q0, r0, m0, 'zigbee2mqtt/tradfri_rmt_1/action', ... (19 bytes))
OH log
2022-04-14 22:38:04.011 [INFO ] [enhab.core.model.script.scenes.rules] - Main door remote >> State: brightness_up_click
In the mosquitto log, the r0 parameter means, it is not preserved (retain=0) (based on this commit: U src/handle_publish.c,conf.c,lib/mosquitto.h: · yurenchen000/mosquitto@a339556 · GitHub)
Then, when I put a space to the end of my items file, the following happens:
OH log:
2022-04-14 22:54:46.604 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mqtt.items'
2022-04-14 22:54:46.779 [INFO ] [enhab.core.model.script.scenes.rules] - Main door remote >> State: brightness_up_click
Mosquitto log:
2022-04-14T20:54:40: Received PINGREQ from otatest
2022-04-14T20:54:40: Sending PINGRESP to otatest
2022-04-14T20:54:41: Received PINGREQ from frontgatectrl
2022-04-14T20:54:41: Sending PINGRESP to frontgatectrl
2022-04-14T20:54:41: Received PUBLISH from tasmota_POW02 (d0, q0, r0, m0, 'tele/tasmota_POW02/STATE', ... (294 bytes))
2022-04-14T20:54:41: Sending PUBLISH to myMQTTClient (d0, q0, r0, m0, 'tele/tasmota_POW02/STATE', ... (294 bytes))
2022-04-14T20:54:41: Received PUBLISH from tasmota_POW02 (d0, q0, r0, m0, 'tele/tasmota_POW02/SENSOR', ... (231 bytes))
2022-04-14T20:54:41: Sending PUBLISH to myMQTTClient (d0, q0, r0, m0, 'tele/tasmota_POW02/SENSOR', ... (231 bytes))
2022-04-14T20:54:44: Received PINGREQ from tasmota_SBS02
2022-04-14T20:54:44: Sending PINGRESP to tasmota_SBS02
2022-04-14T20:54:44: Received PINGREQ from mqttjs_9aae8bb9
2022-04-14T20:54:44: Sending PINGRESP to mqttjs_9aae8bb9
-> ??? nothing sent/received at that time
2022-04-14T20:54:50: Received PINGREQ from tasmota_POW02
2022-04-14T20:54:50: Sending PINGRESP to tasmota_POW02
2022-04-14T20:54:50: Received PUBLISH from frontgatectrl (d0, q0, r0, m0, 'stat/frontgatectrl/gate', ... (6 bytes))
2022-04-14T20:54:50: Sending PUBLISH to myMQTTClient (d0, q0, r0, m0, 'stat/frontgatectrl/gate', ... (6 bytes))
2022-04-14T20:54:51: Received PINGREQ from myMQTTClient
2022-04-14T20:54:51: Sending PINGRESP to myMQTTClient
So based on these logs, it seems to me, that OH is triggering the “received update” channel by using the last set value. I’m not sure, when else it could trigger (for example on device or binding disconnect/reconnect), but this is also dangerous as it can also open/close some gates. If you have any idea, how to make the rule part safe, how can I make sure, the action was really a button press and not just a reinitialize.
The second case:
This is more complicated as it could not be constantly reproduced and multiple items are affected. I’ve tracked yesterday down one issue, which is quite easy as there are not so many dependencies.
What happened:
My wife was using OH mobile app (android) to open and then close the front gate. This is one switch button in the app. The opening was fine, but when she closed the gate, suddenly the rollershutters went down. The rollershutters can be triggered from the following places:
- When the sun is down (Channel ‘astro:sun:local:set#event’ triggered END) → the rule sets IsDarkOutside.sendCommand(ON) → logged
- Through alexa command → logged
- Manually from the mobile app/habpanel
Sunset rule:
rule "Sunset Rule"
when
Channel 'astro:sun:local:set#event' triggered END
then
logInfo("scenes.rules", "SUNSET triggered")
if(IsDarkOutside.state != ON){
IsDarkOutside.sendCommand(ON)
}
end
When sunset happens:
rule "Turn on external lights when main door opens"
when
Item IsDarkOutside changed
then
logInfo("scenes.rules", "Is dark outside triggered: " + IsDarkOutside.state.toString)
// close the shaders in the kitchen
if(IsDarkOutside.state == ON){
sendCommand(Rs_AllRoom, DOWN)
}
end
Alexa rule:
rule "Alexa rollershutters"
when
Item Shader_Alexa_Ctrl received command
then
var currentState = Shader_Alexa_Ctrl.state.toString
var cmd = receivedCommand.toString
logInfo("scenes.rules", "Shader_Alexa_Ctrl >> State: " + currentState + "; Command: " + cmd)
if(cmd == 'Up'){
Rs_AllRoom.sendCommand('UP')
}
if(cmd == 'Down'){
Rs_AllRoom.sendCommand('DOWN')
}
end
And the logs:
In OH log, nothing is indicating, that the rollershutters are triggered, only by the incorrect status update. This is caused by the wrong implementation on the nodeMCU, as it is trying to return the state “opened”, “closed”, which is not allowed by the rollershutter item. So you can ignore the error, I’ll correct it.
2022-04-12 18:38:07.244 [INFO ] [enhab.core.model.script.xiaomi.rules] - FrontGate managed state: OFF
2022-04-12 18:38:07.247 [INFO ] [enhab.core.model.script.xiaomi.rules] - FrontGate contact state: OPEN
2022-04-12 18:38:09.251 [INFO ] [enhab.core.model.script.xiaomi.rules] - Sending update to managed state: ON
2022-04-12 18:38:14.469 [INFO ] [enhab.core.model.script.scenes.rules] - Open front gate - managed >> ReqState: ON
2022-04-12 18:38:14.472 [INFO ] [enhab.core.model.script.scenes.rules] - Open front gate - managed >> CurrState: OPEN
2022-04-12 18:38:59.205 [WARN ] [ab.binding.mqtt.generic.ChannelState] - Command 'closed' from channel 'mqtt:topic:myMQTTBroker:nodemcu_SRC_Thing:AllRoom' not supported by type 'RollershutterValue': Cannot call update() with closed
Mosquitto log (the command is going to front gate, but then also to rollershutters)
2022-04-12T16:38:52: Received PINGREQ from otatest
2022-04-12T16:38:52: Sending PINGRESP to otatest
2022-04-12T16:38:53: Received PUBLISH from myMQTTClient (d0, q0, r0, m0, 'cmnd/frontgatectrl/gate', ... (3 bytes))
2022-04-12T16:38:53: Sending PUBLISH to frontgatectrl (d0, q0, r0, m0, 'cmnd/frontgatectrl/gate', ... (3 bytes))
-> The message is sent to controller
2022-04-12T16:38:54: Received PUBLISH from myMQTTClient (d0, q0, r0, m0, 'cmnd/somfyctl/roomAll', ... (1 bytes))
2022-04-12T16:38:54: Sending PUBLISH to somfy-remote (d0, q0, r0, m0, 'cmnd/somfyctl/roomAll', ... (1 bytes))
2022-04-12T16:38:59: Received PUBLISH from somfy-remote (d0, q0, r0, m0, 'stat/somfyctl/ack', ... (15 bytes))
2022-04-12T16:38:59: Received PINGREQ from mqttjs_d1e94687
2022-04-12T16:38:59: Sending PINGRESP to mqttjs_d1e94687
-> The ACK is published by the controller
2022-04-12T16:38:59: Received PUBLISH from somfy-remote (d0, q0, r1, m0, 'stat/somfyctl/roomAll', ... (6 bytes))
2022-04-12T16:38:59: Sending PUBLISH to myMQTTClient (d0, q0, r0, m0, 'stat/somfyctl/roomAll', ... (6 bytes))
2022-04-12T16:39:01: Received PUBLISH from tasmota_POW02 (d0, q0, r0, m0, 'tele/tasmota_POW02/STATE', ... (294 bytes))
2022-04-12T16:39:01: Sending PUBLISH to myMQTTClient (d0, q0, r0, m0, 'tele/tasmota_POW02/STATE', ... (294 bytes))
2022-04-12T16:39:01: Received PUBLISH from tasmota_POW02 (d0, q0, r0, m0, 'tele/tasmota_POW02/SENSOR', ... (231 bytes))
2022-04-12T16:39:01: Sending PUBLISH to myMQTTClient (d0, q0, r0, m0, 'tele/tasmota_POW02/SENSOR', ... (231 bytes))
2022-04-12T16:39:04: Received PINGREQ from frontgatectrl
2022-04-12T16:39:04: Sending PINGRESP to frontgatectrl
This is only one of the mysteries.
For this case, remember this rule knows nothing about channels. It responds to updates of the Item state.
You’ve just reloaded the xxx.items file defining this Item, essentially re-defining it. I’m not surprised if that triggers an Item update event. I think you’re chasing a red herring here.
Although I still have doubts as well, that you may have a retained message associated with this in your broker. We would get exactly the same effects if ‘rebooting’ the Item caused it to issue a REFRESH to any linked channels. That would cause the MQTT binding in turn to go fetch any retained message from the broker, I think. And you may have one lurking there …
“the device” from the broker’s viewpoint is the zigbee2mqtt service.
Understood. It’s an unwanted consequence of representing button-push events in the form of an Item steady-state, it’s just not a good fit.
In ye olden days, there was no other choice. It could be improved by having an “un-push” event as well - if the device does not offer one, we can automate a simulated un-push via rule or expire. Then the Item state more usefully represents pushed and not-pushed. Still pants if you look for long or double presses etc.
A better solution is to treat the button push event as an event, not as a state.
openHAB already has internal events - Item commands - that are a good logical fit.
Unlikely as it seems here, a better approach is to set postCommand=true in your MQTT button channel.
Now, when the button is pushed, a command is issued to the Item. It’s a discrete event, we can send as many as we like of the same command in succession. Every MQTT message produces a new command.
In this situation the Item steady state is completely irrelevant and not used. You’d have to overhaul your rules to use command not state.
A variation on this approach is to use the trigger=true option on the MQTT channel. Don’t link any Item to it all, no Item is required. When MQTT message received, the binding will put a channel trigger event on the openHAB bus. You’ll see that in the log.
There’s not much you can do with that apart from directly trigger a rule, but if that’s all you need to do then it takes away lots of confusion with Item states and commands.
Oh man, that’s amazing! I was not aware of this possibility. I’ve converted my tradfri rule to use the channel trigger and also removed the associated item. Now, I cannot repro the unwanted trigger even if I restart the zigbee2mqtt or OH. I’ll watch it for a longer time, but based on the facts you have shared it seems to be a correct final solution.
Do you have any idea for the second case?
You have to be explicit. None of the messages are labelled “front gate” or “rollershutters”.
I think this is the one you didn’t expect?
And I guess MQTT client “myMQTTClient” is openHAB?
We can be very sure openHAB is not publishing random commands to random topics that just happen to target a particular device, so we can be sure this about something deliberately configured.
Step one - look through all your MQTT channels to see which have commandTopic cmnd/somfyctl/roomAll There may be more than one.
Then find out what these channels are linked to. Usually some Item, or possibly multiple Items for any given channel.
But as hinted at earlier, if you use any ‘follow’ profiles on channel links these also offer a backdoor for commands, check for that too.
Then you look in your events.log to see which Item got a command at 18:38:54.
Note that your MQTT broker seems to be using a clock two hours different from your openHAB service, just take care about log timestamps.
Yes and yes.
I have only one command on one channel, with topic ‘cmnd/somfyctl/roomAll’.
However there are two rules, which are directly publishing this topic. The reason is, that a in the past different command (payload) was sent to my rollershutter controller to go fully up and I was not able to pass that command through the item.
Both rules are starting with a log message, what I do not see in the OH log, so I assume, the topic was not published by them.
Type rollershutter : AllRoom [ stateTopic="stat/somfyctl/roomAll" , commandTopic="cmnd/somfyctl/roomAll", on="u", off="d", stop="s" ]
rule "Alexa morning routine"
when
Item Switch_Alexa_morning_routine changed to ON
then
logInfo("dev.rules", "Alexa morning routine exec ...")
val mqttActions=getActions("mqtt","mqtt:broker:myMQTTBroker")
// open all shaders
mqttActions.publishMQTT("cmnd/somfyctl/roomAll", "u")
end
There is only 1 item is linked:
I’m not using this feature, I was also not aware of it :). I’ve searched through the item definitions and nothing was found.
2022-04-12 18:38:04.199 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'Switch_FrontGate_OnOff2' received command ON
2022-04-12 18:38:04.209 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Switch_FrontGate_OnOff2' predicted to become ON
2022-04-12 18:38:04.220 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Switch_FrontGate_OnOff2' changed from OFF to ON
2022-04-12 18:38:05.738 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Contact_FrontGate_Status2' changed from CLOSED to OPEN
2022-04-12 18:38:05.747 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Notification_Setting_FrontGate' changed from OFF to ON
2022-04-12 18:38:08.138 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Switch_POW01_Voltage' changed from 240 to 239
2022-04-12 18:38:09.256 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Switch_FrontGate_OnOff_Managed2' changed from OFF to ON
2022-04-12 18:38:38.148 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Switch_POW01_Voltage' changed from 239 to 238
2022-04-12 18:38:52.096 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Date' changed from 2022-04-12T18:37:52.118+0200 to 2022-04-12T18:38:52.119+0200
2022-04-12 18:38:53.714 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'Switch_FrontGate_OnOff2' received command OFF
2022-04-12 18:38:53.723 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Switch_FrontGate_OnOff2' predicted to become OFF
2022-04-12 18:38:53.734 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Switch_FrontGate_OnOff2' changed from ON to OFF
2022-04-12 18:38:54.456 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'Rs_AllRoom' received command DOWN
2022-04-12 18:38:54.468 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Rs_AllRoom' predicted to become DOWN
2022-04-12 18:39:07.929 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Switch_POW01_Voltage' changed from 238 to 240
2022-04-12 18:39:11.746 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Contact_FrontGate_Status2' changed from OPEN to CLOSED
2022-04-12 18:39:11.754 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Notification_Setting_FrontGate' changed from ON to OFF
2022-04-12 18:39:12.559 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SWeather_Outdoor_temperature' changed from 20.27 °C to 19.76 °C
Okay, so the rollershutter call was published from the linked OH item “Item ‘Rs_AllRoom’ received command DOWN”. The Rs_AllRoom is set from 5 rules (4 from 5 are executed by Amazon Alexa). All rules start with a log.
NOTE: I have persistence enabled on my MQTT broker (however based on the docu, it should not affect Q0 messages).
Yes, it is using UTC, most probably I did not configured the timezone for the container. Will fix this.
Alright, so everything worked exactly as configured after that. No point looking at MQTT further, the openHAB command is the culprit. Where did this command come from? We have to infer from a limited list.
Not surprised you do not use ‘follow’ profile, but seeing this command event completes the ruling out. The “command like” happenings produced by ‘follow’ do not get logged as Item events. Cross one off.
Is this Item a member of any Groups? Remember, Groups cascade commands to member Items. However we would expect any commands to the parent Group to be visible in the events.log just a few milliseconds prior. No sign of that, cross that one off.
Some bindings can issue commands, e.g. KNX, and MQTT when using postCommand option. That should have been evident from your look at that already.
GUIs send user pokings to openHAB as Item commands. Only you know how likely that s to have happened.
Hackers, bogeymen, and carefully built external scripts and devices can use the REST API to issue commands to Items. Again, only you can judge how likely it is that a bogeyman has gained access to your system but only places carefully targeted nuisance commands.
Some deliberately set up external script or service is more likely, but you should remember setting that up.
The ‘expire’ option on an Item can be configured to send commands to itself. That would be a result of some long-ago event, so such commands would look like “spontaneous” in the events.log. Simple look at Item detail should/has rule that out, it only works on this Item itself.
Talk of delayed action has I hope triggered thoughts of delayed rule-initiated action … rules can create timers that carry out actions in the future, like sending commands. Unless you put tell-tale logs inside such timer blocks, you can’t see when they run. Any tell-tale from the spawning rule could be long ago.
It still all feels like an overlooked effect in a rule to me. This supposedly spontaneous command happens within a second of other deliberate expected actions.
Remember searching rules for Item names is not enough - rules can address Items indirectly, deriving a target from say a Group membership or associated name conventions, e.g.
sendcommand(someString, someVariable)
where someString has been constructed as the Item name elsewhere in the rule. Or constructs like
triggeringItem.sendCommand(xx)
No, this is the definition of it. Last time I’ve removed most of my groups to near down the possible factors.
Rollershutter Rs_AllRoom "All" <rollershutter> { channel="mqtt:topic:myMQTTBroker:nodemcu_SRC_Thing:AllRoom"}
The postcommand is only used only for the tradfri link. Here is the channel definition:
Type rollershutter : AllRoom [ stateTopic="stat/somfyctl/roomAll" , commandTopic="cmnd/somfyctl/roomAll", on="u", off="d", stop="s" ]
Yes, this is also one of my biggest question. It would be very good to have a log somewhere is an item update is triggered from any app. Not sure, if that is possible and also I’m not sure if all the apps are using the same API.
My OH installation is behind an OpnSense firewall, the only port allowed from outside is the VPN (using cert authentication). My OH is connected to the OH cloud, so the external systems (Alexa) are connected through OH cloud. The second thign, why I do not think it is triggered externally is the fact, that some other action is always triggered before (garage door open, …). An the happenings are not predictable or constantly reproducable. This is also the question, if it would be a rule, then why not the same happens always?
I’m not using the expire binding. I’ve also search through my item definitions.
I’m using couple of timers, but none of them is working with the rollershutters. Also, each delegate is writing a log.
I’ve searched for sendCommand in all my rules. Non of these calls are using a string variable for a target. Everywhere the items is specified as a fixed string, or the item object is used directly. I’ve also searched again for the Rs_AllRoom and all rules, where this item is a target has a log.
There is no tracing for events that are placed on the event bus. But there are some things you can know. The UI will never send an update. They only send commands. All of the UIs use the same REST API.
Expire isn’t a binding. It’s built into OH. It’d be worth a quick grep through the metadata jsondb file to confirm there is no Expire metadata defined on any Items.
I’ve not fully followed the whole thread but with what I know right now, I would try to totally eliminate MQTT as the source of the commands by either disabling the MQTT Broker Thing or unlinking the Items in question from the MQTT Channels. If the commands keep happening we know for certain that it’s OH really generating these commands or if it’s something happening with MQTT.
One avenue I’ve not seen explored here (I apologize if I missed it) is whether the MQTT topics involved are using retained messages. What could happen is something publishes a message that results in a command with retained set to true. The next time that OH connects to the MQTT Broker that retained message gets sent back to OH even if it’s received that message before; even if that message was sent days ago.
So if your connection to the MQTT broker is a little flakey you could be receiving these messages over and over, each time OH reconnects to the MQTT broker. Depending on how the topics and messages are configured to be interpreted, they could result in a command.
Note that a non-retained message sent to the topic does not clear out the old retained message. You have to send an empty retained message to clear out an old retained message. So if there has ever been a retained message sent to one of these topics by any publisher, it’s still there until you explicitly clear it out.
You should be able to tell if there are retained messages on a topic in MQTT Explorer (you can even clear them out from there). Or you can take MQTT out of the picture entirely and see if the problem persists.
Hi Rich,
Thanks for your response here on hunting the ghost :).
This is exactly my case, something is calling unexpected actions.
I know, there is not Expire binding anymore, just used the wrong terminology (again :(). I’ve searched through the jsonDB, as suggested, only for the googletts was found the “expire” keyword, but that is of the oauth token.
Unfortunately I cannot disable the MQTT as all my action items are using MQTT. Some of the sensors are using other bindings. BUT, we have already neared down from the logs, that the action is coming from OH and not from MQTT. Here is one log:
Mosquitto log:
2022-04-12T16:38:54: Received PUBLISH from myMQTTClient (d0, q0, r0, m0, ‘cmnd/somfyctl/roomAll’
OH log:
2022-04-12 18:38:54.456 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'Rs_AllRoom' received command DOWN
myMQTTClient is the OH MQTT client.
From the above Mosquitto log, you can see, that the message is not retained (second parameter: q0)
Hmm, okay I did not know that, but as we have found out above, the issue is not triggered by the MQTT, but by OH.
What is new and happened in the last two days, is that my wife uses her phone to open the front gate, and again the roller shutters were going down and the external lamp was turned on. The same behavior happened yesterday and today. So that’s why it would be very good to somehow trace down, from where the action is coming. She is using the Android OH app, while I’m using the iOS one. I’ll try to repro it with her cell. Other that that I’m not having any other idea, what else I could check
That message isn’t retained but has there ever been a retained message on that topic. Once published, a retained message is kept forever, even when non-retained messages are published afterward. And if OH disconnects from the broker and reconnects it will receive those retained messages again and again, every time it reconnects. And if those messages become commands, it will look like your devices are being commanded from out of nowhere.
From what I’ve seen, you’ve determined that the messages are not actively being published to MQTT, but if you’ve a retained message on the topic that’s been there for months… Your tests thus far, as far as I can tell, have not eliminated that possibility.