OH3 - z-wave polling not working

[jmckenna (James McKenna)]

I’m trying out OH3 (snapshot 2006) after updating from OH 2.5.10, but I’m having an issue where polling is not working. I have some Aeotec micro switches that work by sending a HAIL command to associated to devices which in turn makes the controller poll for status. I also have some older GE switches that need to be polled for status because they do not support associations. Logging just shows “Polling deferred until initialisation complete” message every time a device is polled.

I was able to revert back to OH 2.5.10 by simply rolling back a snapshot of my container and things are working normal again. I would like to transition to OH3 though, and this is a blocker for me right now. Any help would be appreciated. Log below shows system starting up and to the point where polls aren’t working. It is a google drive link so that I could include full log. I can bounce back and forth with my backups pretty easily enough for troubleshooting.

https://drive.google.com/file/d/1wpgdADbNbHL2YWNp7uLhuEw8God79SAE/view?usp=sharing

[chris (Chris Jackson)]

My guess is that this is an initialisation issue. I’m not sure what the devices are, but it seems the device is not initialised, and therefore we don’t poll (as it can cause more problems with initialisation).

There is no difference in the binding between 2.5.10 and OH3 - they are fundamentally the same with the only changes being the change in namespace.

[jmckenna (James McKenna)]

I have probably a dozen or so devices that need polling. These devices shouldn’t need to get re-initialized if I am upgrading in place, right? I used the upgrade instructions for apt found here: Guide: Installing and testing OH3 snapshots/milestones using APT and YUM

Any tips to debugging this? If I revert back to 2.5.10 I have no issues.

[chris (Chris Jackson)]

@jmckenna

These devices shouldn’t need to get re-initialized if I am upgrading in place, right?

If you have a new install of OH3, then they will need reinitialisation. If you’ve copied over all your OH2 backup files, then you’re right, there will be less or no initialisation required.

[jmckenna (James McKenna)]

Turns out things weren’t initializing due to a deserialization error in habot_cards.json. I deleted config file and I’m no longer getting the polling deferred error messages. Yay!

2020-11-11 10:02:18.551 [ERROR] [re.storage.json.internal.JsonStorage] - Couldn't deserialize value 'org.openhab.core.storage.json.internal.StorageEntry@6ce2ea2'. Root cause is: Jun 9, 2019 12:10:04 PM
2020-11-11 10:02:18.552 [ERROR] [re.storage.json.internal.JsonStorage] - Couldn't deserialize value 'org.openhab.core.storage.json.internal.StorageEntry@2e981b12'. Root cause is: Jun 9, 2019 12:12:00 PM`

However, my DSC18 devices are still not working. They work by sending a HAIL which in turn forces a poll. It looks like I get update for wattage, but not on/off state.

2020-11-11 10:39:08.634 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 0C 02 82 01 7E 
2020-11-11 10:39:08.635 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 02 82 01 
2020-11-11 10:39:08.635 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 02 82 01 
2020-11-11 10:39:08.635 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-11-11 10:39:08.635 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:DONE)
2020-11-11 10:39:08.635 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: resetResendCount initComplete=true isDead=false
2020-11-11 10:39:08.635 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Incoming command class COMMAND_CLASS_HAIL, endpoint 0
2020-11-11 10:39:08.635 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY not supported
2020-11-11 10:39:08.635 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Received COMMAND_CLASS_HAIL V1 HAIL
2020-11-11 10:39:08.636 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveDelayedPollEvent
2020-11-11 10:39:08.636 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling initialised at 1800 seconds - start in 75 milliseconds.
2020-11-11 10:39:08.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Commands processed 1.
2020-11-11 10:39:08.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@777f6efe.
2020-11-11 10:39:08.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-11-11 10:39:08.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-11-11 10:39:08.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-11-11 10:39:08.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-11-11 10:39:08.711 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling...
2020-11-11 10:39:09.155 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 00 0C 08 32 02 21 74 00 01 20 40 F5 
2020-11-11 10:39:09.156 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 08 32 02 21 74 00 01 20 40 
2020-11-11 10:39:09.156 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 08 32 02 21 74 00 01 20 40 
2020-11-11 10:39:09.156 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-11-11 10:39:09.156 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:DONE)
2020-11-11 10:39:09.156 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: resetResendCount initComplete=true isDead=false
2020-11-11 10:39:09.156 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Incoming command class COMMAND_CLASS_METER, endpoint 0
2020-11-11 10:39:09.156 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY not supported
2020-11-11 10:39:09.156 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Received COMMAND_CLASS_METER V3 METER_REPORT
2020-11-11 10:39:09.156 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 12: Meter: Type=Electric(1), Scale=W(2), Value=73.792
2020-11-11 10:39:09.156 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveMeterValueEvent
2020-11-11 10:39:09.156 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=73.792
2020-11-11 10:39:09.157 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Updating channel state zwave:device:93af1255:node12:meter_watts to 73.792 [DecimalType]
2020-11-11 10:39:09.157 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Commands processed 1.
2020-11-11 10:39:09.157 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@6d9a199a.
2020-11-11 10:39:09.157 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-11-11 10:39:09.157 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-11-11 10:39:09.157 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-11-11 10:39:09.157 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

Whereas polling logging in 2.5.10 has a lot more output when the poll goes out:

020-11-11 11:30:44.320 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling...
2020-11-11 11:30:44.320 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling zwave:device:93af1255:node12:switch_binary
2020-11-11 11:30:44.320 [DEBUG] [converter.ZWaveBinarySwitchConverter] - NODE 12: Generating poll message for COMMAND_CLASS_SWITCH_BINARY, endpoint 0
2020-11-11 11:30:44.320 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 12: Creating new message for application command SWITCH_BINARY_GET
2020-11-11 11:30:44.320 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY not supported
2020-11-11 11:30:44.321 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured
2020-11-11 11:30:44.321 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling zwave:device:93af1255:node12:meter_watts
2020-11-11 11:30:44.321 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 12: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2020-11-11 11:30:44.321 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 12: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2020-11-11 11:30:44.321 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 12: Creating new message for application command METER_GET
2020-11-11 11:30:44.321 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY not supported
2020-11-11 11:30:44.321 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Command Class COMMAND_CLASS_METER is NOT required to be secured
2020-11-11 11:30:44.321 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling zwave:device:93af1255:node12:meter_current
2020-11-11 11:30:44.321 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 12: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2020-11-11 11:30:44.321 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 12: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2020-11-11 11:30:44.321 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 12: Creating new message for application command METER_GET
2020-11-11 11:30:44.321 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY not supported
2020-11-11 11:30:44.322 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Command Class COMMAND_CLASS_METER is NOT required to be secured
2020-11-11 11:30:44.322 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling zwave:device:93af1255:node12:meter_kwh
2020-11-11 11:30:44.322 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 12: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2020-11-11 11:30:44.322 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 12: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2020-11-11 11:30:44.322 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 12: Creating new message for application command METER_GET
2020-11-11 11:30:44.322 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY not supported
2020-11-11 11:30:44.322 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Command Class COMMAND_CLASS_METER is NOT required to be secured
2020-11-11 11:30:44.322 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling zwave:device:93af1255:node12:meter_voltage
2020-11-11 11:30:44.322 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 12: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2020-11-11 11:30:44.322 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 12: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2020-11-11 11:30:44.322 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 12: Creating new message for application command METER_GET
2020-11-11 11:30:44.322 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY not supported
2020-11-11 11:30:44.322 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Command Class COMMAND_CLASS_METER is NOT required to be secured
2020-11-11 11:30:44.323 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling zwave:device:93af1255:node12:meter_reset
2020-11-11 11:30:44.323 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 12: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2020-11-11 11:30:44.323 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue
2020-11-11 11:30:44.323 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Added 462 to queue - size 10

I can see that the binding is largely unchanged between OH 2.5.10 and OH3, but @chris, do you have any ideas why these extra polls wouldn’t go out?

[jmckenna (James McKenna)]

After debugging, I think the issue is related to https://github.com/openhab/openhab-core/issues/1707

ZWaveThingHandler::channelLinked is not getting called on startup.

[jmckenna (James McKenna)]

@chris
I think the z-wave binding needs a similar fix as to what the insteon binding did after reading comments from above issue: https://github.com/openhab/openhab-addons/pull/8803/commits/fb335787e0660664fcbf655529e42429db3f7eab

[chris (Chris Jackson)]

@jmckenna

channelLinked is not getting called on startup

I believe that this issue was being fixed in future updates of OH3. I’d prefer not to bodge the binding when the fix should be made in the framework.

[Dejan]

@jmckenna

houldn’t need to get re-initial

@chris I have one question about pooling in OH3 with battery powered devices… I have one problem with 3 Fibaro Heat Controllers with additional temperature sensors.
Problem is that I have pooling time set to 1 hour(before has been 1 day) but items are still not periodicly updated… I receive only “Sensortemperature2” updates regulary from additional sensor connected to head(when temperature change It can be in 3 minutes, 20 minutes…) for example battery status updates I receive maybe 1x per day but maybe… For example Im recharge battery from 77% to 100% on one of thermostat and in receive update after 1,5 days when Im manualy restart openhab and controller PING and REQUEST_NIF all things… Same happen if I change temperature on head I don’t receive setpoint_heating update(In 1,5 days)… Is this normal or is something wrong with “pooling”?

Im on 3.0.0M2 OH and zwave biddings.

Thanks for your time and help.

[chris (Chris Jackson)]

@Dejan

Problem is that I have pooling time set to 1 hour(before has been 1 day) but items are still not periodicly updated

For a battery device, the polling time will not really make a lot of difference. Polling will only work when the device is awake - so what is important is the configuration of the wakeup period.

Normally you should configure the device so that it sends updates when the sensor changes and not use polling. Polling is not nice in general, and doesn’t really work in battery devices.

[Dejan]

Thanks for reply. Default wakeup is set to 3600 on controller thing. All other non battery powered items(dimmers, sockets, rollershutters) work ok and send periodic changes(watts, kwh) or on change(watts, kwh, state, dimmer). I have issues only with Heat Controllers … They communicate with controller this I know because they send temperature data from additional sensors connected to them but do not send item updates which is made directly on them. For example I rotate temperature setpoint from 21 to 24 and they do not send that change even after more than all day but if I restart openhab I receive new value when thing initialize…
Can I somehow force that initialization for that 3 devices every 1 hour or is that bad idea? Or how I can force device to send update regulary?
Device normaly heal at night for example last heal is 2020-11-13T02:14:00Z heal settings is set to 2AM.
Device is Fibaro FGT001 db reference 749

I have one brand new thermostat and will add it and try to make more tests…

Thanks.

[chris (Chris Jackson)]

@Dejan

Default wakeup is set to 3600 on controller thing

In theory then, the other devices should also be set to this - but are they actually set?

@Dejan

They communicate with controller this I know because they send temperature data from additional sensors connected to them but do not send item updates which is made directly on them.

If the device is only sending some data, then that seems to be a device configuration issue I would think.

Just one point to note - just because a device sends data to the controller, does not mean the controller can send data to the device. The controller can only send data TO the device when the device wakes up and tells the controller it can receive data.

@Dejan

Can I somehow force that initialization for that 3 devices every 1 hour or is that bad idea?

I don’t really think you want to do that. You should work out why the device isn’t sending the data. The logs might be useful (in debug mode) and you can view them with the viewer below.

Z-Wave Log Viewer

[Dejan]

I will try this weekend analyze what happening with test unit…

How exactly I can see in logs if other devices wake up at 3600s(1h) is there some specific event?

Fibaro FGT001 have in settings only 2 settings which can be changed:
Override Schedule duration(Time to reset manual settings of setpoint temperature)
Additional functions here I can enable bit 2 (increase receiver sensitivity (shortens battery life)) if it will help somehow.

Im already enable debug mode today. Tomorrow I will include test FGT001 into network and analyze what exactly happen when I change setpoint on valve…

Is maybe somewhere in GUI or logs possible to se FW version on zwave modules or I can get this(same as fw updates) only on Fibaro controller?

This is my network map and looks like all thermostatic heads(node 2,3,7) can directly talk to controller so probably can’t be routing(distance) issue …

Will see when I will have some logs…

[Dejan]

As usual Im need to connect it and test it today before sleep…

This is how look my thermostat valve thing and items are created like this on other valves:

I think Im found why doesn’t work…

22:03:52.727 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 57: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
22:03:52.728 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 57: Incoming command class COMMAND_CLASS_THERMOSTAT_SETPOINT, endpoint 1
22:03:52.729 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 57: Received COMMAND_CLASS_THERMOSTAT_SETPOINT V0 THERMOSTAT_SETPOINT_REPORT
22:03:52.730 [DEBUG] [s.ZWaveThermostatSetpointCommandClass] - NODE 57: Thermostat Setpoint report Scale = 0
22:03:52.731 [DEBUG] [s.ZWaveThermostatSetpointCommandClass] - NODE 57: Thermostat Setpoint Value = 17
22:03:52.732 [DEBUG] [s.ZWaveThermostatSetpointCommandClass] - NODE 57: Thermostat Setpoint Report, Type Heating (1), value = 17
22:03:52.733 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 57: Got an event from Z-Wave network: ZWaveThermostatSetpointValueEvent
22:03:52.734 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 57: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_THERMOSTAT_SETPOINT, value=17
22:03:52.735 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 57: Updating channel state zwave:device:0b64393fce:node57:thermostat_setpoint_heating1 to 17 °C [QuantityType]
22:03:52.736 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 57: Commands processed 1.
22:03:52.737 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 57: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@5f6426ec.

It send change to “thermostat_setpoint_heating1” and not “thermostat_setpoint_heating”. I will test more tomorrow…

If I post full debug logs from zwave addon public does them include security info/keys?

[Bruce_Osborne]

@Dejan

It send change to “thermostat_setpoint_heating1” and not “thermostat_setpoint_heating”. I will test more tomorrow…

Why guess? In the UI click on the Thing and then the Channels tab to view the names.

[Dejan]

Im sorry but I don’t understand what you mean… Yesterday I have been already 14h at computer(work) and 20h wake up so didn’t have more “power” to anything else and yust write post to notify chris that probably is notthing wrong and I found problem…

I know names and thing have 3 battery channels. Im use first one(ZWave_Floor1_Office_Thermostat_BatteryLevel) but it is not automaticly updated and is updated only when I reboot openhab or once per 1-3 days same is with Setpoint there are two and I use first one(ZWave_Floor1_Office_Thermostat_Setpointheating) which is not updated on change but only at openhab restart. When Im change them to second one so to ZWave_Floor1_Office_Thermostat_BatteryLevel1 and ZWave_Floor1_Office_Thermostat_Setpointheating1 Im start receiving updates from heat controllers(They are send that data before but OH has ignore them because there is no linked item). By debugging Im found that.

I can confirm that now I get updates from heat controllers on setpoint change and probably also for battery change(I need to recharge one of head)…
Thanks.

[chris (Chris Jackson)]

@Dejan

How exactly I can see in logs if other devices wake up at 3600s(1h) is there some specific event?

Yes, there is a wakeup event.

@Dejan

Fibaro FGT001 have in settings only 2 settings which can be changed

Ok, looking further at this, this device is a FLIRS device so is basically always awake, so it won’t support wakeup. Of course FLIRS devices have other dependencies, but probably this should be ok.

Anyway, I see it’s now working

[Lolodomo]

@chris

I believe that this issue was being fixed in future updates of OH3. I’d prefer not to bodge the binding when the fix should be made in the framework.

Chris, as I understood the discussion in the issue, this is not planed to be fixed in the core, this is a kind of breaking change for bindings that has to be fixed in each binding relying on that

[chris (Chris Jackson)]

Thanks @Lolodomo - I thought I’d read that this was being fixed, but I didn’t follow it closely? I’m surprised though - so we can no longer rely on this notification being sent reliably? It seems useless to have it then if it’s not reliable

It’s stupid (IMHO) to require all bindings to implement workarounds for a shortcoming in the core.

[Lolodomo]

Please enter in the discussion of the issue to try changing that.

I agree with you, there was even no list built of potentially impacted bindings.