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?