Zwave Switches - turned ON by "Ghosts"

hi,
I have a scenario where you can see what happens…in my home system.
HouseNr Switch is triggerd by a sunset rule at 19h23…Solar_Switch, HomeOffice,PVng5,Devolo3, AxisVideo follow without any reason…

2017-09-07 19:23:00.042 [ItemCommandEvent ] - Item ‘HouseNr_Switch’ received command ON
2017-09-07 19:23:00.049 [ItemStateChangedEvent ] - HouseNr_Switch changed from OFF to ON
2017-09-07 19:23:03.515 [ItemStateChangedEvent ] - Solar_Switch changed from OFF to ON
2017-09-07 19:23:08.565 [ItemStateChangedEvent ] - HomeOffice_Switch changed from OFF to ON
2017-09-07 19:23:10.272 [ItemStateChangedEvent ] - PVng4_Switch changed from OFF to ON
2017-09-07 19:23:11.932 [ItemStateChangedEvent ] - Devolo3_Switch changed from OFF to ON
2017-09-07 19:23:19.269 [ItemStateChangedEvent ] - AxisVideo_Switch changed from OFF to ON
2017-09-07 19:25:03.978 [ItemCommandEvent ] - Item ‘RepPres_Switch’ received command ON
2017-09-07 19:25:06.082 [ItemCommandEvent ] - Item ‘RTonline_Switch’ received command ON
2017-09-07 19:25:08.132 [ItemCommandEvent ] - Item ‘NG4vidOnline_Switch’ received command ON
2017-09-07 19:30:03.995 [ItemCommandEvent ] - Item ‘RepPres_Switch’ received command ON
2017-09-07 19:30:06.082 [ItemCommandEvent ] - Item ‘RTonline_Switch’ received command ON
2017-09-07 19:30:08.291 [ItemCommandEvent ] - Item ‘NG4vidOnline_Switch’ received command ON

Related Openhab.log…

2017-09-07 19:00:04.306 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’
2017-09-07 19:03:03.668 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’
2017-09-07 19:05:43.596 [WARN ] [essage.ApplicationUpdateMessageClass] - Got ApplicationUpdateMessage without request, ignoring. Last message was SendData.
2017-09-07 19:06:03.534 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’
2017-09-07 19:09:04.312 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’
2017-09-07 19:12:04.379 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’
2017-09-07 19:15:03.972 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’
2017-09-07 19:15:10.186 [ERROR] [tocol.commandclass.ZWaveCommandClass] - Error extracting value - length=9, offset=6, size=4.
2017-09-07 19:15:10.206 [ERROR] [tocol.commandclass.ZWaveCommandClass] - Error extracting value - length=9, offset=6, size=4.
2017-09-07 19:15:10.240 [ERROR] [tocol.commandclass.ZWaveCommandClass] - Error extracting value - length=9, offset=6, size=4.
2017-09-07 19:15:50.967 [WARN ] [essage.ApplicationUpdateMessageClass] - Got ApplicationUpdateMessage without request, ignoring. Last message was SendData.
2017-09-07 19:16:28.936 [WARN ] [l.serialmessage.SendDataMessageClass] - NODE 44: Already processed another send data request for this callback Id, ignoring.
2017-09-07 19:16:29.096 [WARN ] [essage.ApplicationUpdateMessageClass] - Got ApplicationUpdateMessage without request, ignoring. Last message was SendData.
2017-09-07 19:18:04.239 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’
2017-09-07 19:21:04.171 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’
2017-09-07 19:23:00.089 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression ‘0 23 19 7 9 ? 2017’ has no future executions anymore
2017-09-07 19:23:00.118 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression ‘0 23 19 7 9 ? 2017’ has no future executions anymore
2017-09-07 19:23:00.122 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression ‘0 23 19 7 9 ? 2017’ has no future executions anymore
2017-09-07 19:24:03.742 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’
2017-09-07 19:26:00.092 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression ‘0 26 19 7 9 ? 2017’ has no future executions anymore
2017-09-07 19:26:00.112 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression ‘0 26 19 7 9 ? 2017’ has no future executions anymore
2017-09-07 19:26:00.118 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression ‘0 26 19 7 9 ? 2017’ has no future executions anymore
2017-09-07 19:27:03.660 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’
2017-09-07 19:30:04.197 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’
2017-09-07 19:31:51.527 [WARN ] [l.serialmessage.SendDataMessageClass] - NODE 43: Already processed another send data request for this callback Id, ignoring.
2017-09-07 19:33:03.727 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’
2017-09-07 19:36:03.671 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’
2017-09-07 19:38:01.469 [WARN ] [andclass.ZWaveApplicationStatusClass] - Unsupported status 0x17 for command class APPLICATION_STATUS (0x22).
2017-09-07 19:38:01.513 [WARN ] [andclass.ZWaveApplicationStatusClass] - Unsupported status 0x17 for command class APPLICATION_STATUS (0x22).
2017-09-07 19:38:03.214 [WARN ] [andclass.ZWaveApplicationStatusClass] - Unsupported status 0x17 for command class APPLICATION_STATUS (0x22).
2017-09-07 19:38:13.729 [WARN ] [andclass.ZWaveApplicationStatusClass] - Unsupported status 0x17 for command class APPLICATION_STATUS (0x22).
2017-09-07 19:38:17.046 [WARN ] [andclass.ZWaveApplicationStatusClass] - Unsupported status 0x17 for command class APPLICATION_STATUS (0x22).
2017-09-07 19:39:04.209 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’
2017-09-07 19:42:04.056 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’
2017-09-07 19:45:03.692 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’
2017-09-07 19:48:04.209 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’
2017-09-07 19:51:04.138 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’
2017-09-07 19:51:42.258 [WARN ] [l.serialmessage.SendDataMessageClass] - NODE 43: Already processed another send data request for this callback Id, ignoring.
2017-09-07 19:51:42.675 [WARN ] [l.serialmessage.SendDataMessageClass] - NODE 43: Already processed another send data request for this callback Id, ignoring.
2017-09-07 19:54:03.689 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’
2017-09-07 19:57:03.584 [WARN ] [.classic.internal.servlet.CmdServlet] - Received unknown command ‘—’ for item ‘RestO2state’

In my case it happened 2 days in a row…always arround the time where Astro binding does trigger a sunset event…
But again, last 2 days nothing happened…strange and highly annoying when you go on holidays and all night long some devices are ON…that should not

MQTT items
qos=1
retain=true

I never experimented with Node-Red, though …

What is that item doing?

Regex?

Looks like an old version, that astro message was suppressed in logs a while ago …

Regarding RestO2state…its a value from my wood heating that is pushed via RestAPI. As it is off right now it does not provide useful values…so its a ‘—’, which seems to produce the Error Extracting stuff.

Since my transfer to OH2 its still little messy but right now i try to get the major items smooth.

When you say “long ago”…how can I fix this if i’m using 2.1 OH (so quite outdated)…with .kar binding file and i do not want to update the complete system to 2.2 (as several users see more instability)…
Can i upload the latest Astro jar file to addons and it takes the latest one…so the single file and not the one from kar file?

I have never used that but as far as I understand several other posts regarding this “offline” file it always draws the binding versions from that kar file during binding re-installation and not the latest/newest.

As long as you don’t have a slow data connection I would not use the kar file …

Nope, astro binding is part from ESH and therefore there is no jar file to download. But their is a hack for it which seems to work:

But do note that sometimes the further development of a binding requires also changes in the runtime (don’t know if that is the case with this hack) so you could encounter even more problems because of the “mismatch”.

Actually that was only the case from #1025 to #1033 where there was a critical bug which has been fixed now.
I’m using #1034 at the moment and it runs pretty smoothly. This was also the case before #1025. There have been several issues with the astro binding lately but at the moment it runs without any problems.

Read this post and the ones above it to see what happens if you are using that kar file the wrong way:

Hm, thats funny - i did update via web often and after build 1025 it was a mess. So i decided to leave oh2.2 away from my home for a while…will give it another try now…

Don’t forget a backup :grinning:

The only problem I found today was that Alexa does not switch my tv via harmony binding anymore, although it works fine with my zwave lights.
No time yet to dig into it any deeper, but maybe it’s just a hickup …

ok…maybe i was too quick. lets see how the snapshotting goes this time…

Could you please link me to some place where backup is described so i do also get all the paper ui DB entries…would be a nightmare if i loose all that stuff. also how to restore. Did not see anything in the doc.manual section…thanks!

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.