I don’t think this can in any way be attributed to the binding. There is nothing else in the log around the time the NIF is received, so the binding is not doing anything to make the device busy as far as I can tell.
I know it’s easy to say “I changed X, and therefore it must be caused by X” - however - it’s not always the case.
And of course I am not gonna argue. I have snapshot of OH 2.2 and 2.3 with stable Z-wave build, I’ll get logs to confirm.
Thanks - I’m certainly happy to look at the logs, and if we can see an issue, then I’m happy to fix 
.
You are the best. I have to say I am impressed with support you guys provide. Better than enterprise 
Ok, I’m not sure what to do from here. Since I don’t have the device, I can’t check what’s going on - I configured a thing to use the same thing-type, and as best as I can tell, it’s working here.
If you go to edit the thing, do you now see the node ID in the configuration parameters -:
@chris Here is log from 2.2 and stable z-wave when DZMX is not busy and updates on/off status:
Full log - https://paste.ee/p/lVUOL
2018-07-21 06:57:56.598 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 49
2018-07-21 06:57:56.598 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 06 02 26 02 25 43 A3
2018-07-21 06:57:56.599 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 6: Sending REQUEST Message = 01 09 00 13 06 02 26 02 25 43 A3
2018-07-21 06:57:56.608 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2018-07-21 06:57:56.610 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2018-07-21 06:57:56.610 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2018-07-21 06:57:56.611 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2018-07-21 06:57:56.611 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2018-07-21 06:57:56.611 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 6: Sent Data successfully placed on stack.
2018-07-21 06:57:56.625 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 43 00 00 02 AA
2018-07-21 06:57:56.627 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2018-07-21 06:57:56.627 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 43 00 00 02 00 00 A4
2018-07-21 06:57:56.627 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 43 00 00 02 00 00 A4
2018-07-21 06:57:56.627 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=43 00 00 02
2018-07-21 06:57:56.628 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 6: SendData Request. CallBack ID = 67, Status = Transmission complete and ACK received(0)
2018-07-21 06:57:56.628 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 6: Starting initialisation from DONE
2018-07-21 06:57:56.628 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@4d91b9db already registered
2018-07-21 06:57:56.628 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=6, callback=67, payload=06 02 26 02
2018-07-21 06:57:56.628 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=43 00 00 02
2018-07-21 06:57:56.629 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=67, expected=ApplicationCommandHandler, cancelled=false MISMATCH
2018-07-21 06:57:56.636 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 06 03 26 03 63 B1
2018-07-21 06:57:56.638 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2018-07-21 06:57:56.639 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 06 03 26 03 63 B1
2018-07-21 06:57:56.639 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 06 03 26 03 63 B1
2018-07-21 06:57:56.639 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 06 03 26 03 63
2018-07-21 06:57:56.640 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 6: Application Command Request (ALIVE:DONE)
2018-07-21 06:57:56.640 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 6: Starting initialisation from DONE
2018-07-21 06:57:56.640 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@4d91b9db already registered
2018-07-21 06:57:56.640 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 6: Incoming command class SWITCH_MULTILEVEL
2018-07-21 06:57:56.641 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 6: Received SWITCH_MULTILEVEL command V1
2018-07-21 06:57:56.641 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 6: Switch Multi Level report, value = 99
2018-07-21 06:57:56.642 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2018-07-21 06:57:56.642 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-07-21 06:57:56.642 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_MULTILEVEL, value = 99
2018-07-21 06:57:56.642 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Updating channel state zwave:device:1590aeb5569:node6:switch_dimmer to 100 [PercentType]
2018-07-21 06:57:56.660 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=6, callback=67, payload=06 02 26 02
2018-07-21 06:57:56.661 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 06 03 26 03 63
2018-07-21 06:57:56.665 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=67, expected=ApplicationCommandHandler, cancelled=false transaction complete!
2018-07-21 06:57:56.666 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2018-07-21 06:57:56.666 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-07-21 06:57:56.668 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 6: Response processed after 68ms/1857ms.
2018-07-21 06:57:56.668 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 48
2018-07-21 06:57:56.668 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 06 02 26 02 25 44 A4
2018-07-21 06:57:56.668 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 6: Sending REQUEST Message = 01 09 00 13 06 02 26 02 25 44 A4
2018-07-21 06:57:56.678 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2018-07-21 06:57:56.680 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2018-07-21 06:57:56.681 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2018-07-21 06:57:56.681 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2018-07-21 06:57:56.681 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2018-07-21 06:57:56.681 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 6: Sent Data successfully placed on stack.
2018-07-21 06:57:56.697 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 44 00 00 02 AD
2018-07-21 06:57:56.699 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2018-07-21 06:57:56.699 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 44 00 00 02 00 00 A3
2018-07-21 06:57:56.700 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 44 00 00 02 00 00 A3
2018-07-21 06:57:56.700 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=44 00 00 02
2018-07-21 06:57:56.700 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 6: SendData Request. CallBack ID = 68, Status = Transmission complete and ACK received(0)
2018-07-21 06:57:56.701 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 6: Starting initialisation from DONE
2018-07-21 06:57:56.701 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@4d91b9db already registered
2018-07-21 06:57:56.702 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=6, callback=68, payload=06 02 26 02
2018-07-21 06:57:56.702 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=44 00 00 02
2018-07-21 06:57:56.702 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=68, expected=ApplicationCommandHandler, cancelled=false MISMATCH
2018-07-21 06:57:56.706 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 06 03 26 03 63 B1
2018-07-21 06:57:56.708 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2018-07-21 06:57:56.708 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 06 03 26 03 63 B1
2018-07-21 06:57:56.709 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 06 03 26 03 63 B1
2018-07-21 06:57:56.709 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 06 03 26 03 63
2018-07-21 06:57:56.709 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 6: Application Command Request (ALIVE:DONE)
2018-07-21 06:57:56.710 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 6: Starting initialisation from DONE
2018-07-21 06:57:56.710 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@4d91b9db already registered
2018-07-21 06:57:56.710 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 6: Incoming command class SWITCH_MULTILEVEL
2018-07-21 06:57:56.711 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 6: Received SWITCH_MULTILEVEL command V1
2018-07-21 06:57:56.711 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 6: Switch Multi Level report, value = 99
2018-07-21 06:57:56.711 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2018-07-21 06:57:56.712 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-07-21 06:57:56.712 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_MULTILEVEL, value = 99
2018-07-21 06:57:56.712 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Updating channel state zwave:device:1590aeb5569:node6:switch_dimmer to 100 [PercentType]
2018-07-21 06:57:56.720 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=6, callback=68, payload=06 02 26 02
2018-07-21 06:57:56.720 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 06 03 26 03 63
2018-07-21 06:57:56.720 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=68, expected=ApplicationCommandHandler, cancelled=false transaction complete!
2018-07-21 06:57:56.720 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2018-07-21 06:57:56.721 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-07-21 06:57:56.721 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 6: Response processed after 51ms/1857ms.
In both instances, the binding is sending exactly the same thing -:
New binding…
Old binding…
The only difference is that in the first one, there is a NIF sent from the device beforehand - was there a difference in how you are triggering these two events?
Nope, no difference. I just pressed button on actual dimmer to turn on/off lights, Node 6.
@Lolodomo There are some config parameters that can be used trigger a report when a threshold is reached, but I don’t use them. I just have auto-report time set to 30, which generates a report every 15 min.
Yes, this should get you a report every hour.
Ok, maybe it’s just the log you sent from 2.2 missed the bit before this - something must have been sent from the switch to tell the binding to send the poll - can you see if you can provide that as well. The only thing I can think of is that the timing is different and the new binding is polling quicker than the old one.
I’ve seen this a few times when a device gets into a funky state.
@r27 Try using the air gap switch to cycle power to the device.
I have 3 of these devices, all acting same with new z-wave. With all respect I don’t think that this is device issue. But thanks for suggestion.
When I first dropped it into addons, I got a pile of errors. Still looking at those. After restarting the binding, everything looked OK. Deleting/rediscovering DZMX1 was successful and device is working properly. Your workaround appears to have resolved this for now! For someone whose so busy, you get a ridiculous amount done! 
Wow. This makes me lier I am leaving … will be back …
I just checked the code that handles the NIF and sends the poll, and it’s exactly the same as in the master branch and hasn’t changed for 2 years (last update 31 Jul 2016) - in fact this is the same from the very first OH2 as the commit message is “Initial Commit”. The timing is the same at 75ms.
While I do agree it’s very unlikely given it worked when you swapped back to the old version, and also it’s affecting 3 devices, please can you try what @mhilbush suggested - just so we can rule it out?
At the moment, we seem to be in a situation where everything is exactly the same, so “obviously” there can’t be a problem - except there is 
.
No worries. Just offering up a few ideas. If it’s happening with all 3 devices, then it’s probably not the device.
@chris I’m trying to remember other times when I’ve seen application busy. Neighbor updates can take quite a while. When a device is doing a neighbor update, will it report busy? Edit: I’m not necessarily saying that’s the problem here.
I’m not sure - I don’t know that I’ve seen this before - at least not in a systematic way. Looking at the log from @r27 there are 2 updates approx 30 seconds apart, and seemingly nothing else happening between them, so I don’t think it’s that.
It may still be a timing issue - maybe 75ms is just too marginal, and maybe on some (fast) systems it is more marginal, and maybe the new binding is just a bit faster… Maybe 
… I don’t think there’s just one issue, so it’s possibly a buildup of issues like this (maybe! ).
Combo of a fast system AND having removed some of the logging. (although I can’t remember if you removed it or just moved to TRACE level). 
It could very well be that I saw it because I’m running on an OC’ed core i5.
What is the hex sequence for app busy? I have some old logs lying around that I can grep for it.
Did you conclude whether the issue with manual thing definition has the same root cause as the issue you just opened? Or, possibly related to the issue I opened a while ago.
In the issue I opened, it appeared that the config description simply is not used when defining a thing using the Thing DSL. In any event, I probably should update my issue title to be less narrowly defined.
