Zwave Switches - turned ON by "Ghosts"

@norbert_jordan Are those 4 switches part of a group switch item? I realized my issue appears to be related to group switches. All my rules are setup for dimmer value based changes to/from 0 and the group switch sends an “OFF” command which is confusing my rules and sending them jumping around between “OFF” and dim values.

Hi, and thanks for the input.

No - all of them are part of a SwitchBOX group, but there are arround 10 other plugs in the same group - which are not reacting at all to my “ghost-requests”

Have you looked at the logs? Eg the zwave log? I’m pretty sure that the binding won’t be sending these by itself, but if you want to confirm this, then I’d suggest to check the debug logs as this will log the commands received by the binding.

hi chris, thanks…is there a dedicated zwave log or you mean zwave messages in debug mode for openhab/events.log.

As Rich suggested, will kill my manual setup and switch to apt first to see if there is a difference…

Normally, there’s no dedicated zwave log unless you’ve set one up (some people do, but most probably don’t). However, it’s not the events.log that is of any use - it’s the openhab.log file that is needed (with the binding in debug mode).

@chris - I’m now starting to think my duplicate mqtt messages may be zwave related. Here is my mqtt log showing the flurry of duplicate messages to my Master Bath Main Light:

12-Sep-2017 17:50:13.623 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathMainLight
12-Sep-2017 17:50:13.651 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
12-Sep-2017 17:50:13.660 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathMainLight
12-Sep-2017 17:50:13.677 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathBathLight
12-Sep-2017 17:50:13.720 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathNorthSinkLight
12-Sep-2017 17:50:13.740 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathMainLight
12-Sep-2017 17:50:13.753 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathBathLight
12-Sep-2017 17:50:14.736 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathMainLight
12-Sep-2017 17:50:14.953 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 100 to home/livingRoom/livingRoomFan
12-Sep-2017 17:50:15.120 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 100 to home/livingRoom/livingRoomFan
12-Sep-2017 17:50:15.140 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 100 to home/livingRoom/livingRoomFan
12-Sep-2017 17:50:15.165 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 100 to home/livingRoom/livingRoomFan
12-Sep-2017 17:50:15.357 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 100 to home/livingRoom/livingRoomFan
12-Sep-2017 17:50:15.410 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 100 to home/livingRoom/livingRoomFan
12-Sep-2017 17:50:16.057 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 100 to home/livingRoom/livingRoomFan
12-Sep-2017 17:50:17.037 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathMainLight
12-Sep-2017 17:50:17.066 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathMainLight
12-Sep-2017 17:50:17.110 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathMainLight
12-Sep-2017 17:50:18.146 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathMainLight
12-Sep-2017 17:50:18.719 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathMainLight
12-Sep-2017 17:50:18.915 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathMainLight
12-Sep-2017 17:50:19.470 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 100 to home/livingRoom/livingRoomFan
12-Sep-2017 17:50:19.620 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 100 to home/livingRoom/livingRoomFan
12-Sep-2017 17:50:19.736 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathMainLight
12-Sep-2017 17:50:20.124 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathMainLight
12-Sep-2017 17:50:20.429 [DEBUG] [org.openhab.binding.mqtt.internal.MqttItemBinding ] - Publishing state 0 to home/masterBathroom/masterbathMainLight

And here is a Z Wave debug log for that same time window showing (if I’m reading it right) Zwave polling the node (Node 16) multiple times and getting the same value:

https://drive.google.com/open?id=0B77VHtwPft8eRG44U1A4LVlCOFE

Any thoughts on why these bursts of polling are occuring?

I’ll take a look - possibly there’s an issue with the timers not being cancelled. This could occur if you make changes to configuration or something.

I don’t think it’s related to the discussion in this thread though as it’s only polling that can occur like this.

Chris, i have another observation that never happened before. I know you rightly will insist on logs and i will turn them on tonight and wait for another occurrence.
Maybe you already have seen this before.
I have a Fibaro Eye motion sensor that shows last presence time (alarm switch turned ON) in classic UI. Now in OH1 it always provided reasonable values - so if nobody at home the last time seen is the time the last person left home…

Now it happens several times within a week that during the day in a normal room (no direct sun, or reflections) an alarm was triggered…even if nobody is at home or hovering roboter or pets in the house…today we all slept until 6:30am but an alarm was regocnized at 5:37…which is impossible. I already put the Eye in the wrong direction, so it looks to the wall for days now…in order to not have reflections,…

Again, will start detailed logging now to see whom to “blame”…

You really have something strange going on :grinning:

Again, I can only tell you my experience with a Fibaro “eye”: no ghost alarms, everything works like expected. This is true for openHAB1 (used for two years) and openHAB2 (using since about a year now).

Did you ever check karaf and bundle:list to see if you have any old remains in your setup?
You should only see some “Resolved” states for the “GUI Fragments” and “Active” states for all your bindings and the dependencies. There normally should be no “Installed” or “Uninstalled” states present …

How are you generating the time? The binding does not do this, so I guess you have a rule? Does it update the time on the last ON, or for any update?

Thanks. I don’t have any rules within OH anymore (I run them all through Node-RED). In trying to troubleshoot in the other discussion thread I opened thinking it was a system issue, I did test it with Node-RED offline and still saw the same behaviour. It occurs on a frequent, but random baisis and I haven’t been able to tie it to any specific time or activity.

:confused: I’m not really sure what your point is?

I had assumed when you were talking about timers above that you meant rule-based timers. I’m guessing now that you meant system timers.

Ah - ok, understood. No - it’s not related to rules or anything…

Let me know any additional testing I can do on my end to help. Thanks

@Chris - did you get a chance to take a further look at this? Thanks

There’s nothing obvious. The only thing I can see is it’s possible there’s a thread sync issue, although I’m not sure why two threads would be starting polling at the same time. In any case, I’ll add some synchronisation and we can see if it helps.

Thanks. Let me know when it’s ready to test and I’ll see if that helps.

Edit: I’m using the test binding :wink:

hi, sorry for the delay. was busy the last 2 weeks and moved backward to OH1. Again all was way smoother and all problems gone i had with OH2…even though i of course enjoyed the changes that came with OH2…

Today i had an interesting observation…OH1…my old setup running for few days now…and suddenly the same ghost behaviour i had with OH2. AND again…its all coming immediately after sunset is coming…so for me its definitely related to ASTRO binding. My question if there is anything i can do/try to proof this…

2017-09-22 19:09:00 - MySunset_Event state updated to ON
2017-09-22 19:09:00 - MySunset_Event state updated to OFF
2017-09-22 19:09:00 - HouseNr_Switch received command ON This one should go on
2017-09-22 19:09:00 - HouseNr_Switch state updated to ON
2017-09-22 19:09:00 - Axis_Power state updated to 0
2017-09-22 19:09:00 - Sonnenkraft_Power state updated to 0
2017-09-22 19:09:01 - Router_Power state updated to 7
2017-09-22 19:09:01 - FGS223_Switch1 state updated to ON GHOST
2017-09-22 19:09:01 - FGS223_Switch1 state updated to ON
2017-09-22 19:09:04 - PowerTotal received command 122.4
2017-09-22 19:09:05 - Hofer_OGwater state updated to 979
2017-09-22 19:09:07 - HomeOffice_Switch state updated to ON GHOST
2017-09-22 19:09:08 - HomeOffice_Power state updated to 1.1
2017-09-22 19:09:09 - Sonnenkraft_Switch state updated to ON GHOST
2017-09-22 19:09:09 - PVng5mono_Power state updated to 0
2017-09-22 19:09:09 - pvmeter state updated to 0.3
2017-09-22 19:09:09 - PVng5mono_Switch state updated to ON
2017-09-22 19:09:09 - PVng5poly_Power state updated to 0.4
2017-09-22 19:09:09 - pvmeter state updated to 0.4
2017-09-22 19:09:09 - PVng5poly_Switch state updated to ON
2017-09-22 19:09:09 - Sonnenkraft_Power state updated to 2.5
2017-09-22 19:09:09 - FGS223_Switch1 state updated to ON
2017-09-22 19:09:10 - HomeOffice_Power state updated to 1.4
2017-09-22 19:09:11 - HomeOffice_Power state updated to 0.6
2017-09-22 19:09:12 - HomeOffice_Power state updated to 0.4
2017-09-22 19:09:13 - PVng4_Power state updated to 0.7
2017-09-22 19:09:13 - HomeOffice_Switch state updated to ON
2017-09-22 19:09:13 - Axis_Switch state updated to ON GHOST
2017-09-22 19:09:13 - PVng4_Switch state updated to ON GHOST
2017-09-22 19:09:14 - Axis_Power state updated to 0.5
2017-09-22 19:09:14 - PVng5mono_Switch state updated to ON
2017-09-22 19:09:14 - PVng4_Power state updated to 0.9
2017-09-22 19:09:14 - PVng5poly_Power state updated to 0.4
2017-09-22 19:09:14 - PVng5poly_Switch state updated to ON
2017-09-22 19:09:14 - PVng5mono_Power state updated to 0.3
2017-09-22 19:09:14 - PVng5mono_Switch state updated to ON
2017-09-22 19:09:14 - pvmeter state updated to 0.7
2017-09-22 19:09:15 - FGS223_Switch1 state updated to ON
2017-09-22 19:09:15 - HomeOffice_Power state updated to 0.3
2017-09-22 19:09:15 - Axis_Power state updated to 0.7
2017-09-22 19:09:16 - PVng5mono_Power state updated to 0.3
2017-09-22 19:09:16 - Fristar_Power state updated to 123.1
2017-09-22 19:09:16 - Axis_Power state updated to 0.9
2017-09-22 19:09:17 - FGS223_Switch1 state updated to ON
2017-09-22 19:09:17 - HomeOffice_Power state updated to 0.4
2017-09-22 19:09:17 - Axis_Power state updated to 1.2
2017-09-22 19:09:18 - Fristar_Power state updated to 82.4
2017-09-22 19:09:18 - HomeOffice_Power state updated to 0.3
2017-09-22 19:09:19 - LivingRoom_Power state updated to 0
2017-09-22 19:09:19 - Fristar_Power state updated to 46.8
2017-09-22 19:09:19 - PowerTotal received command 121.1
2017-09-22 19:09:20 - Fristar_Power state updated to 36.5
2017-09-22 19:09:20 - HomeOffice_Power state updated to 0.4
2017-09-22 19:09:21 - Fristar_Power state updated to 77.3
2017-09-22 19:09:21 - HomeOffice_Power state updated to 0.3
2017-09-22 19:09:22 - CPU_combined state updated to 3.46555768820644072292225246201269328594207763671875
2017-09-22 19:09:22 - HomeOffice_Switch state updated to ON
2017-09-22 19:09:22 - Axis_Power state updated to 1.4
2017-09-22 19:09:23 - PVng4_Power state updated to 0.9
2017-09-22 19:09:24 - PVng5poly_Power state updated to 0.1
2017-09-22 19:09:24 - pvmeter state updated to 0.4
2017-09-22 19:09:24 - PVng5poly_Switch state updated to ON
2017-09-22 19:09:24 - PVng5mono_Power state updated to 0.2
2017-09-22 19:09:24 - PVng5mono_Switch state updated to ON
2017-09-22 19:09:24 - pvmeter state updated to 0.3
2017-09-22 19:09:24 - FGS223_Switch1 state updated to ON

I would suggest to get the logs in debug mode - hopefully they will help identify what’s happening.