[SOLVED] Some Z-Wave battery devices are not updating battery level

chris · February 22, 2019, 3:17pm

Ok, but the binding knows nothing specific about the device, so I’m not sure why it would decide to not work only for the battery here.

Ah - ok, then that will be problematic

exec · February 22, 2019, 3:32pm

think you’re right.

ok, set the level to DEBUG and restartet openhab.

here is the error in openhab.log at 16:18:01.451

2019-02-22 16:18:01.451 [ERROR] [pse.smarthome.core.thing.internal.ThingManagerImpl] - Exception occurred during notification about bridge status change on thing 'zwave:device:7c2d2216:node26': 1

and this is the debug output containing NODE 26

2019-02-22 16:17:45.904 [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Channel zwave:device:7c2d2216:node26:sensor_door linked - polling started.
2019-02-22 16:17:45.933 [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Channel zwave:device:7c2d2216:node26:battery-level linked - polling started.
2019-02-22 16:17:48.870 [col.serialmessage.SerialApiGetInitDataMessageClass] - NODE 26: Node found
2019-02-22 16:17:49.037 [ab.binding.zwave.internal.protocol.ZWaveController] - NODE 26: Init node thread start
2019-02-22 16:17:49.637 [ternal.protocol.initialization.ZWaveNodeSerializer] - NODE 26: Serializing from file /var/lib/openhab2/zwave/network_d7fd06c9__node_26.xml
2019-02-22 16:17:50.227 [ab.binding.zwave.internal.protocol.ZWaveController] - NODE 26: Restore from config: Ok.
2019-02-22 16:17:50.400 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Command class COMMAND_CLASS_ZWAVEPLUS_INFO, endpoint 0 created
2019-02-22 16:17:50.400 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Command class COMMAND_CLASS_WAKE_UP, endpoint 0 created
2019-02-22 16:17:50.427 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Command class COMMAND_CLASS_VERSION, endpoint 0 created
2019-02-22 16:17:50.448 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created
2019-02-22 16:17:50.460 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Command class COMMAND_CLASS_ASSOCIATION, endpoint 0 created
2019-02-22 16:17:50.661 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Command class COMMAND_CLASS_FIRMWARE_UPDATE_MD, endpoint 0 created
2019-02-22 16:17:50.672 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Command class COMMAND_CLASS_SECURITY, endpoint 0 created
2019-02-22 16:17:50.673 [al.protocol.commandclass.ZWaveSecurityCommandClass] - NODE 26: Updated networkKey
2019-02-22 16:17:50.674 [al.protocol.commandclass.ZWaveSecurityCommandClass] - NODE 26: setupNetworkKey useSchemeZero=false
2019-02-22 16:17:50.677 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Command class COMMAND_CLASS_BATTERY, endpoint 0 created
2019-02-22 16:17:50.677 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Command class COMMAND_CLASS_DEVICE_RESET_LOCALLY, endpoint 0 created
2019-02-22 16:17:50.711 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Command class COMMAND_CLASS_ALARM, endpoint 0 created
2019-02-22 16:17:50.735 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Command class COMMAND_CLASS_CONFIGURATION, endpoint 0 created
2019-02-22 16:17:50.736 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Command class COMMAND_CLASS_MANUFACTURER_SPECIFIC, endpoint 0 created
2019-02-22 16:17:50.747 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Command class COMMAND_CLASS_BASIC, endpoint 0 created
2019-02-22 16:17:50.748 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Command class COMMAND_CLASS_POWERLEVEL, endpoint 0 created
2019-02-22 16:17:50.753 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Command class COMMAND_CLASS_ASSOCIATION_GRP_INFO, endpoint 0 created
2019-02-22 16:17:50.754 [nhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 26: Device discovery completed
2019-02-22 16:18:00.664 [nhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 26: Device discovery resolved to thingType zwave:vision_zd2102plus_00_000
2019-02-22 16:18:00.803 [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 26: Starting initialisation from EMPTYNODE
2019-02-22 16:18:00.868 [ab.binding.zwave.internal.protocol.ZWaveController] - NODE 26: Init node thread finished
2019-02-22 16:18:00.869 [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 26: Node advancer - advancing to IDENTIFY_NODE
2019-02-22 16:18:00.871 [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 26: Node advancer: Initialisation starting
2019-02-22 16:18:01.421 [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Controller status changed to ONLINE.
2019-02-22 16:18:01.421 [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Controller is ONLINE. Starting device initialisation.
2019-02-22 16:18:01.423 [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Updating node properties.
2019-02-22 16:18:01.424 [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Updating node properties. MAN=265
2019-02-22 16:18:01.424 [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Updating node properties. MAN=265. SET. Was 265
2019-02-22 16:18:01.429 [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Properties synchronised
2019-02-22 16:18:01.438 [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Update ASSOCIATION group_ZWaveAssociationGroup [index=1, name=Lifeline, profile1=0, profile2=1, associations=[node_1]]: Adding node_1
2019-02-22 16:18:01.446 [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Initialising Thing Node...
2019-02-22 16:18:01.447 [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Initialising cmd channel zwave:device:7c2d2216:node26:sensor_door for OpenClosedType
2019-02-22 16:18:01.448 [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Initialising state channel zwave:device:7c2d2216:node26:sensor_door for OpenClosedType
2019-02-22 16:18:01.685 [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 26: ProtocolInfo
2019-02-22 16:18:01.686 [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 26: Listening = false
2019-02-22 16:18:01.687 [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 26: Routing   = true
2019-02-22 16:18:01.687 [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 26: Beaming   = true
2019-02-22 16:18:01.688 [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 26: Version   = 4
2019-02-22 16:18:01.689 [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 26: FLIRS     = false
2019-02-22 16:18:01.689 [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 26: Security  = false
2019-02-22 16:18:01.690 [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 26: Max Baud  = 40000
2019-02-22 16:18:01.691 [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 26: Basic    = BASIC_TYPE_ROUTING_SLAVE
2019-02-22 16:18:01.691 [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 26: Generic  = GENERIC_TYPE_SENSOR_NOTIFICATION
2019-02-22 16:18:01.692 [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 26: Specific = SPECIFIC_TYPE_NOTIFICATION_SENSOR
2019-02-22 16:18:01.692 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Creating new instance of command class COMMAND_CLASS_NO_OPERATION
2019-02-22 16:18:01.693 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created
2019-02-22 16:18:01.694 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Version = 1, version set. Enabling extra functionality.
2019-02-22 16:18:01.694 [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 26: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes.
2019-02-22 16:18:01.695 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Creating new instance of command class COMMAND_CLASS_BASIC
2019-02-22 16:18:01.695 [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Command class COMMAND_CLASS_BASIC, endpoint 0 created
2019-02-22 16:18:01.696 [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 26: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes.
2019-02-22 16:18:01.713 [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 26: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@81bf0e
2019-02-22 16:18:01.714 [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 26: Node Init transaction completed with response COMPLETE
2019-02-22 16:18:01.714 [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 26: Node advancer - advancing to REQUEST_NIF
2019-02-22 16:18:01.715 [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2019-02-22 16:18:01.717 [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 26: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@183373a
2019-02-22 16:18:01.719 [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 26: Bump transaction 40 priority from Controller to Immediate
2019-02-22 16:18:01.720 [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 26: Adding to device queue
2019-02-22 16:18:01.721 [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 26: Added 40 to queue - size 11

i noticed something else. scanning the zwave.log for battery, for all ZD-2102 getting something like this

2019-02-22 16:17:45.933 [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Channel zwave:device:7c2d2216:node26:battery-level linked - polling started.

but the POPE009303 shows me

2019-02-22 16:18:01.086 [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 6: Initialising cmd channel zwave:device:7c2d2216:node6:battery-level for PercentType
2019-02-22 16:18:01.089 [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 6: Initialising state channel zwave:device:7c2d2216:node6:battery-level for PercentType

as i mentioned, POP is my only device that is reporting its battery-level.

exec · March 2, 2019, 7:10pm

Hey @chris, can you read something out of these logs?
Do you need more information?

chris · March 2, 2019, 11:13pm

Sorry - I missed this. Since you didn’t reply to my message, the system doesn’t notify me…

I’ve no idea what this is, but I doubt it’s related. Is there any more information printed with the exception?

This doesn’t really provide a lot…

Interesting - if you don’t see the same message, then this could explain the problem. Apparently there is a bug in ESH (now OH I guess ) where the bindings aren’t always notified when channels are linked. I’m not familiar with this, but @mhilbush might be able to provide a reference?

mhilbush · March 3, 2019, 12:04pm

I’ve not logged an issue on this, because it happens so infrequently and I can’t see anything that is a direct cause. Sometimes it happens for all channels; sometimes for just a couple channels. When it happens, it usually occurs at startup. I expect it is a timing issue related to the way bundles/services are loaded. Stopping and starting the binding always resolves the issue (i.e. an openHAB restart is not required). I also resolved it once by saving a change to my zwave.items file.

The issue manifests itself by the channel for a fully initialized device never being polled, and with the absence of the “Channel xxxxx linked - polling started” messages in the log.

If I can’t figure out what’s causing it, I might try to convince @chris to consider using the isLinked method when deciding to poll the channels.

exec · March 3, 2019, 7:01pm

There is, but if it’s helpful…

2019-02-22 16:18:01.451 [ERROR] [pse.smarthome.core.thing.internal.ThingManagerImpl] - Exception occurred during notification about bridge status change on thing 'zwave:device:7c2d2216:node26': 1
java.lang.ArrayIndexOutOfBoundsException: 1
        at org.openhab.binding.zwave.handler.ZWaveThingHandler.initialiseNode(ZWaveThingHandler.java:226) ~[?:?]
        at org.openhab.binding.zwave.handler.ZWaveThingHandler.bridgeStatusChanged(ZWaveThingHandler.java:512) ~[?:?]
        at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$4.run(ThingManagerImpl.java:901) [109:org.eclipse.smarthome.core.thing:0.10.0.oh240]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]

When I had a look into Habmin today I recognized all ZD-2102 stuck in “Node initialising: REQUEST_NIF”. Last time some of them were in this status, but now it’s all of them.

After restarting the zwave addon one of the nodes seems to be fully initialised in Habmin. I’ll check this again tomorrow.

Hi Mark, thanks for your input. I tried commenting out some of the Battery items and adding them back later on. Also touched the items file and restarted the zwave addon. But till now nothing changed.

This is the message I receive.

But these are missing

Initialising cmd channel...
Initialising state channel...

chris · March 3, 2019, 7:20pm

Yes, the stack traces are very useful. Can you run this again with the latest snapshot binding please. Maybe also enable trace logging.

What do you mean they are “stuck”? Are you waking these devices up?

It would be good to get a full log from startup.

exec · March 3, 2019, 7:52pm

With snapshot 2.5, this error is gone!
The first one just sent a battery report!

Thought it’s not ok, they are all in this “status”? I woke up some of them several times with no effect.

exec · March 4, 2019, 7:12am

@chris

I think this issue is now SOLVED for me to.

After all ZD-2102 woke up, everything is working as expected with snapshot 2.5.

No more “REQUEST_NIF” in Habmin
Exception at startup is gone
All devices reporting their battery-status

Don’t know the reason, but thank you very much for your support!