Zwave Switches - turned ON by "Ghosts"

Assuming your are on a Raspberry with some sort of Linux and apt get installation:

http://docs.openhab.org/installation/linux.html#backup-and-restore

This part is also valid for openHABian.

OK, so literally you have to copy conf and userdata folder…
Thanks

Just logged in, again - ghost switching - this time with Snapshot 2.2 from today. annoying
And whatever is the reason - in my case for sure it is somehow related to ASTRO-binding…as each time it happens, its consistent from the timing with the event trigger of sunset…today sunset is 19:16…and it happens 19:16
HouseNr_Switch is the only that should react and start when sunset is triggered…
AxisVideo,PVng4, Devolo3…definitely should not react in any way…

2017-09-10 19:16:00.016 [ome.event.ItemCommandEvent] - Item ‘HouseNr_Switch’ received command ON
2017-09-10 19:16:00.020 [vent.ItemStateChangedEvent] - HouseNr_Switch changed from OFF to ON
2017-09-10 19:16:07.092 [vent.ItemStateChangedEvent] - AxisVideo_Switch changed from OFF to ON
2017-09-10 19:16:09.368 [vent.ItemStateChangedEvent] - PVng4_Switch changed from OFF to ON
2017-09-10 19:16:17.644 [vent.ItemStateChangedEvent] - Devolo3_Switch changed from OFF to ON
2017-09-10 19:20:03.805 [ome.event.ItemCommandEvent] - Item ‘RepPres_Switch’ received command ON
2017-09-10 19:20:05.884 [ome.event.ItemCommandEvent] - Item ‘RTonline_Switch’ received command ON
2017-09-10 19:20:07.050 [ome.event.ItemCommandEvent] - Item ‘NG4vidOnline_Switch’ received command ON
2017-09-10 19:20:08.118 [vent.ItemStateChangedEvent] - PVisland_Switch changed from NULL to ON
2017-09-10 19:21:06.621 [ome.event.ItemCommandEvent] - Item ‘DriveInRelay_Switch’ received command OFF
2017-09-10 19:21:06.623 [vent.ItemStateChangedEvent] - DriveInRelay_Switch changed from ON to OFF
2017-09-10 19:25:03.357 [ome.event.ItemCommandEvent] - Item ‘RepPres_Switch’ received command ON
2017-09-10 19:25:05.444 [ome.event.ItemCommandEvent] - Item ‘RTonline_Switch’ received command ON
2017-09-10 19:25:06.706 [ome.event.ItemCommandEvent] - Item ‘NG4vidOnline_Switch’ received command ON
2017-09-10 19:30:03.916 [ome.event.ItemCommandEvent] - Item ‘RepPres_Switch’ received command ON
2017-09-10 19:30:05.988 [ome.event.ItemCommandEvent] - Item ‘RTonline_Switch’ received command ON
2017-09-10 19:30:07.030 [ome.event.ItemCommandEvent] - Item ‘NG4vidOnline_Switch’ received command ON
2017-09-10 19:35:03.225 [ome.event.ItemCommandEvent] - Item ‘RepPres_Switch’ received command ON
2017-09-10 19:35:05.298 [ome.event.ItemCommandEvent] - Item ‘RTonline_Switch’ received command ON
2017-09-10 19:35:06.350 [ome.event.ItemCommandEvent] - Item ‘NG4vidOnline_Switch’ received command ON
2017-09-10 19:39:31.597 [vent.ItemStateChangedEvent] - DriveInRelay_Switch1 changed from ON to OFF
2017-09-10 19:40:03.671 [ome.event.ItemCommandEvent] - Item ‘RepPres_Switch’ received command ON

Perform the following steps in karaf to see if you have the correct astro binding version in place:

bundle:list|grep -i astro
feature:list|grep -i astro

Take a look here how it should look like:

-the binding seems to work as it should, as HouseNr_Switch perfectly switches according to sunset_start…

187 │ Active │ 80 │ 0.9.0.201709071501 │ Astro Binding

openhab> feature:list|grep -i astro
esh-binding-astro │ 0.9.0.SNAPSHOT │ │ Started │ openhab-addons-2.2.0-SNAPSHOT │
openhab-binding-astro │ 2.2.0.SNAPSHOT │ x │ Started │ openhab-addons-2.2.0-SNAPSHOT │ Astro Binding
openhab-binding-astro1 │ 1.11.0.SNAPSHOT │ │ Uninstalled │ openhab-addons-legacy-2.2.0-SNAPSHOT │ Astro Binding (1.x)
esh-binding-astro │ 0.9.0.SNAPSHOT │ │ Started │ addons-2.2.0-SNAPSHOT │
openhab-binding-astro │ 2.2.0.SNAPSHOT │ x │ Started │ addons-2.2.0-SNAPSHOT │ Astro Binding

Hmm, this looks suspicious to me to be honest. Although that old astro1 binding is in state “Uninstalled” I would try to remove it. You did an upgrade to 2.2 snapshot, so why are there still old remains from an astro1 binding?

Check your addons.cfg if any bindings are loaded from there (that is not recommended anmore), everything should be installed via PaperUI.
If you did a correct update the contents of cache and temp folders should have been deleted , so I have no idea where that old stuff is coming from. Try deleting it manually (only the content, not the folders) and restart openHAB and see what happens …

Good luck …

here is my addons.cfg // I already got informed that here no bindings should be named. Which is already removed/commented out for weeks now. Is there anything else you see I should not do anymore ?

What do you mean by clear cache. i’m not familiar with its folder/file structure. userdata/cache is not easy to read. 2 subfolders…the osgi subfolder has heaps of subfolders with simply numbers…

> package = expert
> 
> # Access Remote Add-on Repository
> # Defines whether the remote openHAB add-on repository should be used for browsing and installing add-ons.
> # This not only makes latest snapshots of add-ons available, it is also required for the installation of
> # any legacy 1.x add-on. (default is true)
> #
> remote = true
> 
> # Include legacy 1.x bindings. If set to true, it also allows the installation of 1.x bindings for which there is
> # already a 2.x version available (requires remote repo access, see above). (default is false)
> #
> legacy = true
> 
> # A comma-separated list of bindings to install (e.g. "sonos,knx,zwave")
> #binding = zwave,http,ntp,mqtt
> 
> # A comma-separated list of UIs to install (e.g. "basic,paper")
> ui = paper,classic,basic,habmin
> 
> # A comma-separated list of persistence services to install (e.g. "rrd4j,jpa")
> #persistence = rrd4j,mapdb
> 
> # A comma-separated list of actions to install (e.g. "mail,pushover")
> #action = mail
> 
> # A comma-separated list of transformation services to install (e.g. "map,jsonpath")
> #transformation = xslt,map
> 
> # A comma-separated list of voice services to install (e.g. "marytts,freetts")
> #voice =
> 
> # A comma-separated list of miscellaneous services to install (e.g. "myopenhab")
> #misc =

All lines should be commented out, like

# legacy = true

and not

> legacy = true

Make sure you do all the settings you still have left in addons.cfg through PaperUI.

One quick update on my side. I noticed this morning I was getting a ton of ghosts in the system. I noticed I was getting a number of Too many publishes in progress errors with the mqtt binding. So I turned on debug on mqtt and saw that the same state updates were repeating multiple times (some 10-20 times). I had my QOS set to 2, so changed it back to 0 and the repeats stopped.

So not sure if it was OH or my mqtt broker that was messing up the QOS check but will continue to run mqtt in debug and see if this solves my issues with ghosts in the system.

Edit: Even after setting mqtt to QOS=0 I’m still seeing multiple messages sent on state changes. I’ll open a new thread to see about addressing that issue.

update also from my side…ASTRO is not in focus anymore, as i today got again the same 4 switches turn ON, but not at 19:14 like sunset but 20:15…so not sure why it was the same time…

2017-09-11 20:15:44.331 [vent.ItemStateChangedEvent] - HomeOffice_Switch changed from OFF to ON
2017-09-11 20:15:44.390 [vent.ItemStateChangedEvent] - AxisVideo_Switch changed from OFF to ON
2017-09-11 20:15:45.983 [vent.ItemStateChangedEvent] - PVng4_Switch changed from OFF to ON
2017-09-11 20:15:49.639 [vent.ItemStateChangedEvent] - Devolo3_Switch changed from OFF to ON

Devolo is MT02646 Home Control Metering Plug
HomeOffice is the Fibaro Switch with LED Ring
PVng4 is again MT02646 Home Control Metering Plug
AxisVideo is again a Fibaro Switch…

So not easy to say its a hardware problem maybe, at least two different types…
Very frustrating and completely unreliable since OH2 upgrade…i know it may not be an OH2 issue but when you read all the stuff that people, devoloper write - it sounds like its a monster of code and its still far from where OH1.x was but the major part should be “fine”.

@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?