Battery z-wave items not correctly initialized and of state "offline" after restart

Moerky · November 7, 2017, 9:41pm

I use the latest z-wave binding and have several z-wave (plus) items which work fine. Except for the batery one (Fibaro FGMS001 Motion Sensor). Every time I restart openhab the show as “offline”. Then I have to wakeup them (pressing 3 times the switch, holding them against the z-wave stick) - after that everything is fine until the next restart. Any help appreciated

chris · November 7, 2017, 9:43pm

What do the debug logs show? Devices should not show up as offline, but will show up as initialising (but online). If this isn’t the case, then please check the logs.

Devices should then move through the initialisation after the device wakes up for the first time after the restart.

Moerky · November 7, 2017, 10:21pm

This shows in Paper UI:
grafik

And the log with a grep on node 8 shows:

2017-11-07 23:01:17.970 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 8: Not initialized yet, ignoring message.
2017-11-07 23:01:52.729 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 8: Not initialized yet, ignoring message.
2017-11-07 23:02:17.770 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 8: Not initialized yet, ignoring message.
2017-11-07 23:15:02.421 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 8: Not initialized yet, ignoring message.
2017-11-07 23:16:37.658 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:2fb19967:node8:sensor_binary --> REFRESH
2017-11-07 23:16:37.662 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:2fb19967:node8:sensor_temperature --> REFRESH
2017-11-07 23:16:37.666 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:2fb19967:node8:sensor_seismicintensity --> REFRESH
2017-11-07 23:16:37.671 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:2fb19967:node8:sensor_luminance --> REFRESH
2017-11-07 23:16:37.676 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:2fb19967:node8:alarm_motion --> REFRESH
2017-11-07 23:16:37.683 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:2fb19967:node8:alarm_tamper --> REFRESH
2017-11-07 23:16:37.688 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:2fb19967:node8:battery-level --> REFRESH
2017-11-07 23:16:37.692 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:2fb19967:node8:alarm_general --> REFRESH
2017-11-07 23:16:47.296 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Controller status changed to ONLINE.
2017-11-07 23:16:47.297 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Controller is ONLINE. Starting device initialisation.
2017-11-07 23:16:47.301 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising Thing Node…
2017-11-07 23:16:47.302 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising channel zwave:device:2fb19967:node8:sensor_binary
2017-11-07 23:16:47.394 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising cmd channel zwave:device:2fb19967:node8:sensor_binary
2017-11-07 23:16:47.395 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising poll channel zwave:device:2fb19967:node8:sensor_binary
2017-11-07 23:16:47.401 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising state channel zwave:device:2fb19967:node8:sensor_binary
2017-11-07 23:16:47.402 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising state channel zwave:device:2fb19967:node8:sensor_binary
2017-11-07 23:16:47.408 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising channel zwave:device:2fb19967:node8:sensor_temperature
2017-11-07 23:16:47.409 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising cmd channel zwave:device:2fb19967:node8:sensor_temperature
2017-11-07 23:16:47.410 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising poll channel zwave:device:2fb19967:node8:sensor_temperature
2017-11-07 23:16:47.412 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising state channel zwave:device:2fb19967:node8:sensor_temperature
2017-11-07 23:16:47.413 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising channel zwave:device:2fb19967:node8:sensor_seismicintensity
2017-11-07 23:16:47.414 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising cmd channel zwave:device:2fb19967:node8:sensor_seismicintensity
2017-11-07 23:16:47.415 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising poll channel zwave:device:2fb19967:node8:sensor_seismicintensity
2017-11-07 23:16:47.417 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising state channel zwave:device:2fb19967:node8:sensor_seismicintensity
2017-11-07 23:16:47.418 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising channel zwave:device:2fb19967:node8:sensor_luminance
2017-11-07 23:16:47.419 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising cmd channel zwave:device:2fb19967:node8:sensor_luminance
2017-11-07 23:16:47.420 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising poll channel zwave:device:2fb19967:node8:sensor_luminance
2017-11-07 23:16:47.421 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising state channel zwave:device:2fb19967:node8:sensor_luminance
2017-11-07 23:16:47.422 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising channel zwave:device:2fb19967:node8:alarm_motion
2017-11-07 23:16:47.428 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising cmd channel zwave:device:2fb19967:node8:alarm_motion
2017-11-07 23:16:47.429 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising poll channel zwave:device:2fb19967:node8:alarm_motion
2017-11-07 23:16:47.430 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising state channel zwave:device:2fb19967:node8:alarm_motion
2017-11-07 23:16:47.431 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising channel zwave:device:2fb19967:node8:alarm_tamper
2017-11-07 23:16:47.433 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising cmd channel zwave:device:2fb19967:node8:alarm_tamper
2017-11-07 23:16:47.434 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising poll channel zwave:device:2fb19967:node8:alarm_tamper
2017-11-07 23:16:47.435 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising state channel zwave:device:2fb19967:node8:alarm_tamper
2017-11-07 23:16:47.436 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising channel zwave:device:2fb19967:node8:battery-level
2017-11-07 23:16:47.439 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising cmd channel zwave:device:2fb19967:node8:battery-level
2017-11-07 23:16:47.441 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising poll channel zwave:device:2fb19967:node8:battery-level
2017-11-07 23:16:47.442 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising state channel zwave:device:2fb19967:node8:battery-level
2017-11-07 23:16:47.443 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising channel zwave:device:2fb19967:node8:alarm_general
2017-11-07 23:16:47.453 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising cmd channel zwave:device:2fb19967:node8:alarm_general
2017-11-07 23:16:47.454 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising poll channel zwave:device:2fb19967:node8:alarm_general
2017-11-07 23:16:47.458 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising state channel zwave:device:2fb19967:node8:alarm_general
2017-11-07 23:16:47.467 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Polling intialised at 1800 seconds - start in 1800000 milliseconds.
pi@raspi:~ $ cat /var/log/openhab2/openhab.log | grep “NODE 8”
2017-11-06 23:56:49.392 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 8: Not initialized yet, ignoring message.
2017-11-07 00:05:02.166 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 8: Not initialized yet, ignoring message.
2017-11-07 00:06:40.795 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 8: Not initialized yet, ignoring message.
2017-11-07 00:06:45.578 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 8: Not initialized yet, ignoring message.
2017-11-07 00:06:46.722 [WARN ] [rialmessage.IsFailedNodeMessageClass] - NODE 8: Is currently marked as failed by the controller!
2017-11-07 00:06:46.745 [WARN ] [rialmessage.IsFailedNodeMessageClass] - NODE 8: Is currently marked as failed by the controller!
2017-11-07 00:06:46.809 [WARN ] [rialmessage.IsFailedNodeMessageClass] - NODE 8: Is currently marked as failed by the controller!
2017-11-07 00:07:20.147 [WARN ] [l.serialmessage.SendDataMessageClass] - NODE 8: Already processed another send data request for this callback Id, ignoring.
2017-11-07 04:07:23.746 [WARN ] [l.serialmessage.SendDataMessageClass] - NODE 8: Already processed another send data request for this callback Id, ignoring.
2017-11-07 04:07:24.234 [WARN ] [l.serialmessage.SendDataMessageClass] - NODE 8: Already processed another send data request for this callback Id, ignoring.
2017-11-07 08:07:32.623 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 8: Not initialized yet, ignoring message.
2017-11-07 08:13:54.910 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 8: Not initialized yet, ignoring message.
2017-11-07 09:13:57.446 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 8: Not initialized yet, ignoring message.
2017-11-07 19:13:45.859 [WARN ] 2017-11-07 19:13:53.511 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 8: Not initialized yet, ignoring message.
2017-11-07 19:13:55.220 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 8: Not initialized yet, ignoring message.
2017-11-07 19:13:55.621 [WARN ] [rialmessage.IsFailedNodeMessageClass] - NODE 8: Is currently marked as failed by the controller!
2017-11-07 19:14:29.316 [WARN ] [l.serialmessage.SendDataMessageClass] - NODE 8: Already processed another send data request for this callback Id, ignoring.
2017-11-07 19:30:14.282 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 8: Not initialized yet, ignoring message.
2017-11-07 19:30:18.334 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 8: Not initialized yet, ignoring message.
2017-11-07 19:30:46.523 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 8: Not initialized yet, ignoring message.
2017-11-07 23:15:02.421 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 8: Not initialized yet, ignoring message.
2017-11-07 23:16:37.658 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:2fb19967:node8:sensor_binary --> REFRESH
2017-11-07 23:16:37.662 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:2fb19967:node8:sensor_temperature --> REFRESH
2017-11-07 23:16:37.666 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:2fb19967:node8:sensor_seismicintensity --> REFRESH
2017-11-07 23:16:37.671 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:2fb19967:node8:sensor_luminance --> REFRESH
2017-11-07 23:16:37.676 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:2fb19967:node8:alarm_motion --> REFRESH
2017-11-07 23:16:37.683 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:2fb19967:node8:alarm_tamper --> REFRESH
2017-11-07 23:16:37.688 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:2fb19967:node8:battery-level --> REFRESH
2017-11-07 23:16:37.692 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:2fb19967:node8:alarm_general --> REFRESH
2017-11-07 23:16:47.296 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Controller status changed to ONLINE.
2017-11-07 23:16:47.297 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Controller is ONLINE. Starting device initialisation.
2017-11-07 23:16:47.301 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising Thing Node…
2017-11-07 23:16:47.302 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising channel zwave:device:2fb19967:node8:sensor_binary
2017-11-07 23:16:47.394 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising cmd channel zwave:device:2fb19967:node8:sensor_binary
2017-11-07 23:16:47.395 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising poll channel zwave:device:2fb19967:node8:sensor_binary
2017-11-07 23:16:47.401 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising state channel zwave:device:2fb19967:node8:sensor_binary
2017-11-07 23:16:47.402 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising state channel zwave:device:2fb19967:node8:sensor_binary
2017-11-07 23:16:47.408 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising channel zwave:device:2fb19967:node8:sensor_temperature
2017-11-07 23:16:47.409 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising cmd channel zwave:device:2fb19967:node8:sensor_temperature
2017-11-07 23:16:47.410 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising poll channel zwave:device:2fb19967:node8:sensor_temperature
2017-11-07 23:16:47.412 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising state channel zwave:device:2fb19967:node8:sensor_temperature
2017-11-07 23:16:47.413 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising channel zwave:device:2fb19967:node8:sensor_seismicintensity
2017-11-07 23:16:47.414 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising cmd channel zwave:device:2fb19967:node8:sensor_seismicintensity
2017-11-07 23:16:47.415 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising poll channel zwave:device:2fb19967:node8:sensor_seismicintensity
2017-11-07 23:16:47.417 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising state channel zwave:device:2fb19967:node8:sensor_seismicintensity
2017-11-07 23:16:47.418 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising channel zwave:device:2fb19967:node8:sensor_luminance
2017-11-07 23:16:47.419 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising cmd channel zwave:device:2fb19967:node8:sensor_luminance
2017-11-07 23:16:47.420 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising poll channel zwave:device:2fb19967:node8:sensor_luminance
2017-11-07 23:16:47.421 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising state channel zwave:device:2fb19967:node8:sensor_luminance
2017-11-07 23:16:47.422 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising channel zwave:device:2fb19967:node8:alarm_motion
2017-11-07 23:16:47.428 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising cmd channel zwave:device:2fb19967:node8:alarm_motion
2017-11-07 23:16:47.429 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising poll channel zwave:device:2fb19967:node8:alarm_motion
2017-11-07 23:16:47.430 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising state channel zwave:device:2fb19967:node8:alarm_motion
2017-11-07 23:16:47.431 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising channel zwave:device:2fb19967:node8:alarm_tamper
2017-11-07 23:16:47.433 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising cmd channel zwave:device:2fb19967:node8:alarm_tamper
2017-11-07 23:16:47.434 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising poll channel zwave:device:2fb19967:node8:alarm_tamper
2017-11-07 23:16:47.435 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising state channel zwave:device:2fb19967:node8:alarm_tamper
2017-11-07 23:16:47.436 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising channel zwave:device:2fb19967:node8:battery-level
2017-11-07 23:16:47.439 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising cmd channel zwave:device:2fb19967:node8:battery-level
2017-11-07 23:16:47.441 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising poll channel zwave:device:2fb19967:node8:battery-level
2017-11-07 23:16:47.442 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising state channel zwave:device:2fb19967:node8:battery-level
2017-11-07 23:16:47.443 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising channel zwave:device:2fb19967:node8:alarm_general
2017-11-07 23:16:47.453 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising cmd channel zwave:device:2fb19967:node8:alarm_general
2017-11-07 23:16:47.454 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising poll channel zwave:device:2fb19967:node8:alarm_general
2017-11-07 23:16:47.458 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising state channel zwave:device:2fb19967:node8:alarm_general
2017-11-07 23:16:47.467 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Polling intialised at 1800 seconds - start in 1800000 milliseconds.

chris · November 7, 2017, 10:37pm

Any chance of the log without the grep?

Moerky · November 7, 2017, 10:49pm

Sure but I can’t paste it due to the max number of lines limitation, I try it via mail

chris · November 8, 2017, 8:32am

Mail is probably ok, or you can open a ticket on my website (cd-jackson.com) or you can put it in dropbox or some other such system and link to it…

Moerky · November 8, 2017, 8:44am

I wrote you a mail & opened a ticket

nibi79 · November 8, 2017, 9:29am

could it be the same problem?

chris · November 8, 2017, 7:10pm

These nodes (at least node 8) doesn’t seem to be part of your network -:

I would suggest to reset them and include them again so the controller knows about them.

Moerky · November 13, 2017, 11:42am

That worked, I disconnected them from the z-wave stick, resettet them and included them again. Thank you!