Commands no longer sent after daily heal

S1602 Zwave 2.5.0.201905280446 (not a manual install) HUSBZB-1

@cdjackson, as mentioned here... https://github.com/openhab/org.openhab.binding.zwave/pull/1174#issuecomment-496714506, my devices become unresponsive after a daily heal. This seems to have coincided with #1174 . I still see meter and temperature data coming in, but all command Channels stop functioning. I will submit logs to your website.

@cdjackson , did this issue sneak past you? I had submitted logs in a ticket, but haven't heard back.

Sorry - I’ve not had the chance to look over this in the past couple of weeks - ZigBee has been taking taking a lot of time :(

Hopefully I’m getting to the end of the ZigBee updates, so once that is delivered I’ll take a look.

On 17 Jun 2019, at 07:54, Scott Rushworth notifications@github.com wrote:

@cdjackson https://github.com/cdjackson , did this issue sneak past you? I had submitted logs in a ticket, but haven't heard back.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/openhab/org.openhab.binding.zwave/issues/1178?email_source=notifications&email_token=AAH6IQYTYVVT5B6CM4ISP63P24YL5A5CNFSM4HQRT2H2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODX2GX7I#issuecomment-502557693, or mute the thread https://github.com/notifications/unsubscribe-auth/AAH6IQ7TLG4ITHRHSIARM5DP24YL5ANCNFSM4HQRT2HQ.

This problem might be related to the issue people are having with the inclusion. I believe that is caused by a problem (well, change!) in the core. The binding sends events at certain times - inclusion, and heal start. These are then read by HABmin to provide info to the user.

I've concluded that for the inclusion issue, the system never returns from sending an event, and that hangs up the receive thread which then overflows the receive queue.

This looks the same, but I don't have the debug around events that I added for the inclusion issue, but it looks suspicious that things are hanging after the heal starts.

I've already created a change to remove the sending of these events - it removes it from the inclusion and heal, so let's see if it resolves this issue as well.

I'm pretty sure the changes made it into the build, but unfortunately, S1621 (zwave 2.5.0.201906222214) has the same issue. Maybe worse... I'm sitting right now with nearly all of my devices offline after the heal kicked off.

Ok, thanks, can you provide an updated log? I’ll be interested to see if the latest build resolves the inclusion issue...

On 23 Jun 2019, at 09:48, Scott Rushworth notifications@github.com wrote:

I'm pretty sure the changes made it into the build, but unfortunately, S1621 (zwave 2.5.0.201906222214) has the same issue.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/openhab/org.openhab.binding.zwave/issues/1178?email_source=notifications&email_token=AAH6IQ5YGDXYXDR7MY7YQXTP342HPA5CNFSM4HQRT2H2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODYKZVRQ#issuecomment-504732358, or mute the thread https://github.com/notifications/unsubscribe-auth/AAH6IQ4TLDKO4SN6S4PF3A3P342HPANCNFSM4HQRT2HQ.

I'd added a new one to the ticket, but have't heard back. This is still occurring with S1624 and zwave 2.5.0.201906270431.

I did look at your latest log but at the moment I am unable to do any development on zwave or Zigbee as the development system /IDE has not been updated to support these bindings. I’ve been trying to get this resolved and you may have seen my more recent thread on the forum or the issues list.

Until this is fixed I’m a bit screwed as I’m not able to run these bindings in the IDE for test purposes.

Sent from my iPhone

On 28 Jun 2019, at 01:04, Scott Rushworth notifications@github.com wrote:

I'd added a new one to the ticket, but have't heard back. This is still occurring with S1624 and zwave 2.5.0.201906270431.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.

Have you made any progress with your IDE? I just got a new one installed yesterday and it seems to be mostly working. If you're having trouble debugging, you could also try remote debugging a running instance of OH.

I thought this issue might have been resolved, but I fooled myself. I had turned off polling for all of my devices, since they all report on their own. I had updated OH, so I tried out heal again and devices still could receive commands. I left it for a few days and things got weird. The heal didn't seem to actually run, and the controller seemed to be rejecting (I forget the term in the log entry) communications at times, so sometimes commands would get through and motions sensors would turn on/off. But at other times, things would get missed. Automation was a complete mess. I killed the heal, restarted OH and things appear to be back to normal.

I also have a suspicion that somehow running a Zigbee discovery might somehow be causing this too, but need to test this hypothesis.

This issue looks like it might be related to #1195.

I also was wondering if #1195 is related, as both symptoms are cured by disabling the heal.

However, other than the polling commands not being sent because the device is perpetually in initialization, I've not seen the case where commands are not being sent. Although, admittedly, I've not been looking for that symptom.

Here is some strange polling behavior... if polling is disabled, what is it adding to the queue?

2019-07-05 22:01:56.432 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 223: Polling...
2019-07-05 22:01:56.432 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 223: Polling zwave:device:07cb40a2:node223:switch_binary
2019-07-05 22:01:56.432 [DEBUG] [org.openhab.binding.zwave.internal.converter.ZWaveBinarySwitchConverter] - NODE 223: Generating poll message for COMMAND_CLASS_SWITCH_BINARY, endpoint 0
2019-07-05 22:01:56.433 [DEBUG] [org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveBinarySwitchCommandClass] - NODE 223: Creating new message for application command SWITCH_BINARY_GET
2019-07-05 22:01:56.433 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 223: SECURITY NOT required on COMMAND_CLASS_SWITCH_BINARY
2019-07-05 22:01:56.433 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 223: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured
2019-07-05 22:01:56.433 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 223: Polling skipped for zwave:device:07cb40a2:node223:switch_binary on COMMAND_CLASS_BASIC
2019-07-05 22:01:56.433 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 223: Polling zwave:device:07cb40a2:node223:meter_kwh
2019-07-05 22:01:56.433 [DEBUG] [org.openhab.binding.zwave.internal.converter.ZWaveMeterConverter] - NODE 223: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2019-07-05 22:01:56.433 [DEBUG] [org.openhab.binding.zwave.internal.converter.ZWaveMeterConverter] - NODE 223: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2019-07-05 22:01:56.433 [DEBUG] [org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMeterCommandClass] - NODE 223: Creating new message for application command METER_GET
2019-07-05 22:01:56.433 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 223: SECURITY NOT required on COMMAND_CLASS_METER
2019-07-05 22:01:56.433 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 223: Command Class COMMAND_CLASS_METER is NOT required to be secured
2019-07-05 22:01:56.434 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 223: Polling zwave:device:07cb40a2:node223:meter_voltage
2019-07-05 22:01:56.434 [DEBUG] [org.openhab.binding.zwave.internal.converter.ZWaveMeterConverter] - NODE 223: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2019-07-05 22:01:56.434 [DEBUG] [org.openhab.binding.zwave.internal.converter.ZWaveMeterConverter] - NODE 223: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2019-07-05 22:01:56.434 [DEBUG] [org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMeterCommandClass] - NODE 223: Creating new message for application command METER_GET
2019-07-05 22:01:56.434 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 223: SECURITY NOT required on COMMAND_CLASS_METER
2019-07-05 22:01:56.434 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 223: Command Class COMMAND_CLASS_METER is NOT required to be secured
2019-07-05 22:01:56.434 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 223: Polling zwave:device:07cb40a2:node223:meter_watts
2019-07-05 22:01:56.434 [DEBUG] [org.openhab.binding.zwave.internal.converter.ZWaveMeterConverter] - NODE 223: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2019-07-05 22:01:56.434 [DEBUG] [org.openhab.binding.zwave.internal.converter.ZWaveMeterConverter] - NODE 223: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2019-07-05 22:01:56.434 [DEBUG] [org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMeterCommandClass] - NODE 223: Creating new message for application command METER_GET
2019-07-05 22:01:56.434 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 223: SECURITY NOT required on COMMAND_CLASS_METER
2019-07-05 22:01:56.434 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 223: Command Class COMMAND_CLASS_METER is NOT required to be secured
2019-07-05 22:01:56.434 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 223: Adding to device queue
2019-07-05 22:01:56.435 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 223: Added 2885 to queue - size 62
2019-07-05 22:01:56.435 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-07-05 22:01:56.435 [DEBUG] [org.openhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 DF 02 25 02 25 E9 D3 
2019-07-05 22:01:56.436 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 223: Sending REQUEST Message = 01 09 00 13 DF 02 25 02 25 E9 D3 
2019-07-05 22:01:56.440 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-07-05 22:01:56.441 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2885: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 233
2019-07-05 22:01:56.441 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 223: Adding to device queue
2019-07-05 22:01:56.441 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 223: Added 2886 to queue - size 62
2019-07-05 22:01:56.441 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-05 22:01:56.442 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 223: Adding to device queue
2019-07-05 22:01:56.442 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 223: Added 2887 to queue - size 63
2019-07-05 22:01:56.442 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-05 22:01:56.442 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 223: Adding to device queue
2019-07-05 22:01:56.442 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 223: Added 2888 to queue - size 64
2019-07-05 22:01:56.442 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-05 22:01:58.441 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 223: TID 2885: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-07-05 22:01:58.441 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-07-05 22:01:58.441 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransaction] - TID 2885: Transaction ABORTED
2019-07-05 22:01:58.442 [DEBUG] [org.openhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-07-05 22:01:58.442 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2019-07-05 22:01:58.446 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-07-05 22:01:58.446 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-05 22:02:04.323 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 55: Polling...
2019-07-05 22:02:04.323 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 55: Polling deferred until initialisation complete
2019-07-05 22:02:10.263 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 119: Polling...
2019-07-05 22:02:10.264 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 119: Polling deferred until initialisation complete
2019-07-05 22:02:10.441 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 223: TID 2885: Timeout at state ABORTED. 3 retries remaining.
2019-07-05 22:02:10.441 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - TID 2885: Transaction is current transaction, so clearing!!!!!
2019-07-05 22:02:10.441 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransaction] - TID 2885: Transaction CANCELLED
2019-07-05 22:02:10.441 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 223: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-07-05 22:02:10.441 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 223: notifyTransactionResponse TID:2885 CANCELLED
2019-07-05 22:02:10.442 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-07-05 22:02:10.442 [DEBUG] [org.openhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 DF 03 32 01 00 25 EA C6 
2019-07-05 22:02:10.442 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 223: Sending REQUEST Message = 01 0A 00 13 DF 03 32 01 00 25 EA C6 
2019-07-05 22:02:10.446 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-07-05 22:02:10.446 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2886: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 234
2019-07-05 22:02:12.446 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 223: TID 2886: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-07-05 22:02:12.446 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-07-05 22:02:12.446 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransaction] - TID 2886: Transaction ABORTED
2019-07-05 22:02:12.446 [DEBUG] [org.openhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-07-05 22:02:12.447 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2019-07-05 22:02:12.450 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-07-05 22:02:12.450 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-05 22:02:15.417 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 33: Polling...
2019-07-05 22:02:15.418 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 33: Polling zwave:device:07cb40a2:node33:switch_dimmer
2019-07-05 22:02:15.418 [DEBUG] [org.openhab.binding.zwave.internal.converter.ZWaveMultiLevelSwitchConverter] - NODE 33: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2019-07-05 22:02:15.418 [DEBUG] [org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiLevelSwitchCommandClass] - NODE 33: Creating new message for command SWITCH_MULTILEVEL_GET
2019-07-05 22:02:15.418 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 33: SECURITY not supported
2019-07-05 22:02:15.418 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 33: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2019-07-05 22:02:15.418 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 33: Polling zwave:device:07cb40a2:node33:scene_number
2019-07-05 22:02:15.418 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 33: Polling skipped for zwave:device:07cb40a2:node33:scene_number on COMMAND_CLASS_BASIC
2019-07-05 22:02:15.418 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 33: Adding to device queue
2019-07-05 22:02:15.418 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 33: Added 2889 to queue - size 64
2019-07-05 22:02:15.418 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-05 22:02:24.446 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 223: TID 2886: Timeout at state ABORTED. 3 retries remaining.
2019-07-05 22:02:24.446 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - TID 2886: Transaction is current transaction, so clearing!!!!!
2019-07-05 22:02:24.447 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransaction] - TID 2886: Transaction CANCELLED
2019-07-05 22:02:24.447 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 223: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-07-05 22:02:24.447 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 223: notifyTransactionResponse TID:2886 CANCELLED
2019-07-05 22:02:24.447 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-07-05 22:02:24.448 [DEBUG] [org.openhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 DF 03 32 01 20 25 EB E7 
2019-07-05 22:02:24.448 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 223: Sending REQUEST Message = 01 0A 00 13 DF 03 32 01 20 25 EB E7 
2019-07-05 22:02:24.451 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-07-05 22:02:24.451 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2887: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 235
2019-07-05 22:02:26.452 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 223: TID 2887: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-07-05 22:02:26.452 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-07-05 22:02:26.452 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransaction] - TID 2887: Transaction ABORTED
2019-07-05 22:02:26.453 [DEBUG] [org.openhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-07-05 22:02:26.453 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2019-07-05 22:02:26.456 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-07-05 22:02:26.456 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-05 22:02:38.452 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 223: TID 2887: Timeout at state ABORTED. 3 retries remaining.
2019-07-05 22:02:38.453 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - TID 2887: Transaction is current transaction, so clearing!!!!!
2019-07-05 22:02:38.453 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransaction] - TID 2887: Transaction CANCELLED
2019-07-05 22:02:38.453 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 223: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-07-05 22:02:38.453 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 223: notifyTransactionResponse TID:2887 CANCELLED
2019-07-05 22:02:38.453 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-07-05 22:02:38.454 [DEBUG] [org.openhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 DF 03 32 01 10 25 EC D0 
2019-07-05 22:02:38.454 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 223: Sending REQUEST Message = 01 0A 00 13 DF 03 32 01 10 25 EC D0 
2019-07-05 22:02:38.458 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-07-05 22:02:38.459 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2888: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 236
2019-07-05 22:02:40.459 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 223: TID 2888: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-07-05 22:02:40.459 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-07-05 22:02:40.459 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransaction] - TID 2888: Transaction ABORTED
2019-07-05 22:02:40.459 [DEBUG] [org.openhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-07-05 22:02:40.459 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2019-07-05 22:02:40.463 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-07-05 22:02:40.463 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-05 22:02:44.432 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 118: Polling...
2019-07-05 22:02:44.432 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 118: Polling deferred until initialisation complete
2019-07-05 22:02:44.979 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 38: Polling...
2019-07-05 22:02:44.980 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 38: Polling zwave:device:07cb40a2:node38:switch_dimmer
2019-07-05 22:02:44.980 [DEBUG] [org.openhab.binding.zwave.internal.converter.ZWaveMultiLevelSwitchConverter] - NODE 38: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2019-07-05 22:02:44.980 [DEBUG] [org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiLevelSwitchCommandClass] - NODE 38: Creating new message for command SWITCH_MULTILEVEL_GET
2019-07-05 22:02:44.980 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 38: SECURITY not supported
2019-07-05 22:02:44.980 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 38: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2019-07-05 22:02:44.980 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 38: Polling zwave:device:07cb40a2:node38:scene_number
2019-07-05 22:02:44.980 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 38: Polling skipped for zwave:device:07cb40a2:node38:scene_number on COMMAND_CLASS_BASIC
2019-07-05 22:02:44.981 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 38: Adding to device queue
2019-07-05 22:02:44.981 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 38: Added 2890 to queue - size 63
2019-07-05 22:02:44.981 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-05 22:02:52.459 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 223: TID 2888: Timeout at state ABORTED. 3 retries remaining.
2019-07-05 22:02:52.460 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - TID 2888: Transaction is current transaction, so clearing!!!!!
2019-07-05 22:02:52.460 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransaction] - TID 2888: Transaction CANCELLED
2019-07-05 22:02:52.460 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 223: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-07-05 22:02:52.460 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 223: notifyTransactionResponse TID:2888 CANCELLED
2019-07-05 22:02:52.461 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

Another oddity...

2019-07-05 08:38:35.314 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 223: Command received zwave:device:07cb40a2:node223:switch_binary --> OFF [OnOffType]
2019-07-05 08:38:35.315 [DEBUG] [org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveBinarySwitchCommandClass] - NODE 223: Creating new message for application command SWITCH_BINARY_SET
2019-07-05 08:38:35.316 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 223: SECURITY NOT required on COMMAND_CLASS_SWITCH_BINARY
2019-07-05 08:38:35.317 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 223: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured
2019-07-05 08:38:35.317 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 223: Adding to device queue
2019-07-05 08:38:35.318 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 223: Added 6493 to queue - size 62
2019-07-05 08:38:35.318 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-05 08:38:46.594 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 223: TID 6492: Timeout at state ABORTED. 3 retries remaining.
2019-07-05 08:38:46.594 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - TID 6492: Transaction is current transaction, so clearing!!!!!
2019-07-05 08:38:46.594 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransaction] - TID 6492: Transaction CANCELLED
2019-07-05 08:38:46.594 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 223: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-07-05 08:38:46.594 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 223: notifyTransactionResponse TID:6492 CANCELLED
2019-07-05 08:38:46.595 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-07-05 08:38:46.595 [DEBUG] [org.openhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 DF 03 25 01 00 25 7B 40 
2019-07-05 08:38:46.595 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 223: Sending REQUEST Message = 01 0A 00 13 DF 03 25 01 00 25 7B 40 
2019-07-05 08:38:46.599 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-07-05 08:38:46.600 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6493: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 123
2019-07-05 08:38:48.600 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 223: TID 6493: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-07-05 08:38:48.600 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-07-05 08:38:48.600 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransaction] - TID 6493: Transaction ABORTED
2019-07-05 08:38:48.601 [DEBUG] [org.openhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-07-05 08:38:48.601 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2019-07-05 08:38:48.604 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-07-05 08:38:48.604 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-05 08:39:00.601 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 223: TID 6493: Timeout at state ABORTED. 3 retries remaining.
2019-07-05 08:39:00.601 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveTransactionTimer] - TID 6493: Transaction is current transaction, so clearing!!!!!
2019-07-05 08:39:00.601 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransaction] - TID 6493: Transaction CANCELLED
2019-07-05 08:39:00.601 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 223: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-07-05 08:39:00.601 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 223: notifyTransactionResponse TID:6493 CANCELLED
2019-07-05 08:39:00.601 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

Have you made any progress with your IDE?

It's partly working now - we're still working on getting ZigBee working :( Kai made a change tonight but apparently we need to wait for the next snapshot to see if it's fixed.

I also have a suspicion that somehow running a Zigbee discovery might somehow be causing this too, but need to test this hypothesis.

Really? I'm not sure how the two bindings can be linked 😖

I also was wondering if #1195 is related, as both symptoms are cured by disabling the heal.

Yes, it's likely a duplicate.

Here is some strange polling behavior... if polling is disabled, what is it adding to the queue?

Polling is not disabled in this log -:

2019-07-05 22:01:56.432 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 223: Polling...

Clearly the polling is being called

Another oddity...

Please can you explain what you think is odd? At a quick glance it looks ok - well - there are things not right in here, but I'm not sure what your point is and it would help if you can explain the issue you see.

Well, I spoke too soon - the IDE is still not working here for ZWave or ZigBee. I tried a complete new install of the system and it still fails to resolve the dependencies with a basic system.

Really? I'm not sure how the two bindings can be linked confounded

I think this was just coincidence. I definitely have some odd things happening and I've been troubleshooting it for a while now. The zwave network heal exacerbates it. What I'm seeing are missed events... lots of them for all zwave devices. I've swapped out the controller (combo HUSBZB1) and it is still happening. I have command polling disabled and the poll interval set to 1 day. Is there any way to completely disable polling? I was pointing out in the logs the strange polling behavior, where the polling seems pretty much continuous and always seems to fail, and there's always 3 retries remaining. In the second log, I was specifically pointing out the "Transaction is current transaction, so clearing!!!!!". I've enabled command polling again, but the missed events still happen. I've monitored the serial port with od -x < /dev/ttyUSB0 and it looked like there may be some lulls in traffic (up to a few minutes) which made me think hardware, but the binding or nrjavaserial were also not in sync with the serial traffic when it was flowing. Zigbee does not seem to be effected by this... just zwave. It almost seems like the zwave binding might be overloading the controller. When monitoring zwave traffic in Zensys Tools, I didn't see zwave traffic stop. I also do not see any issues/errors on the system itself.

I'm still trying to track this down. Originally, I thought these symptoms were caused by the heal, but it was only making it worse. I'm not sure if this is just my setup, the binding, or core, but I've seen some posts in the forum with issues that look like they could be related. I'll open another issue if I ever get it figured out.

Things that didn't help:

Swapping out the controller
Changing USB ports
Removing Zigbee binding
Power cycled all devices
Reverting removal of safecaller
Upgrading OH (currently on S1634)
Enabling command polling
Downgrading binding to pre-bnd (REALLY points to a core issue)

Yet to try:

Get the network healed (it's been about 2 months, but no hardware changes)
Zwave sniffer
Downgrade OH
Swap out server hardware
See if this happens with HomeAssistant

Zniffer help me out with this one. It appears that my network was greatly in need of a heal (actually, several). After manually healing the mains powered devices a few times, there were no more missed events. I had turned off the daily heal due to #1195 and feel the issues I had were a direct result. I'm going to close this issue, as I do not see anything specific in the binding or OH that caused this.

I've reopened this because I was incorrect in thinking that #1195 was a related issue.

https://github.com/openhab/org.openhab.binding.zwave/issues/1195#issuecomment-518100902

@cdjackson

I would like to inquire politely if any further work will be done on this issue. Can not say exactly if I have the same or just a similar problem. For more information you can also look here.

Thank you very much.

openhab / org.openhab.binding.zwave

Commands no longer sent after daily heal #1178