I’m not quite following since you have the log file and the timestamp of the exception 
… but I’ve opened a ticket (C8RnqWkhvY3) and included the portion of the log 2s prior to the exception. It looks to me like the last event before the exception was about 3min before it occurred.
Ok, sorry, where is that then 
? It’s definitely not in the log you emailed me - that log only has 1 exception, and it’s not the same as the one above -:
2017-06-01 00:30:11.810 [Handler$ZWaveReceiveThread] - Exception during ZWave thread.
java.lang.IllegalStateException: Queue full
Sorry if I’m missing something, but I get a lot of emails, github requests, PMs, and forum messages every day and it’s not easy to try and correlate different information in different places, or logs that don’t tie up. It may seem like I’m being difficult, but I can spend really a lot of time trying to correlate all these things so I’d just like to be clear.
I’ve just looked at the log you sent on the ticket, and again, this is a different exception that you posted in the link above which is what I’ve been looking for. In the link above, the exception is -:
java.lang.reflect.InvocationTargetException
and in your logs it’s -:
java.lang.IllegalStateException: Queue full
Sorry - but I’m also confused now - the exceptions are very different and I wanted to see a log from the first one you raised. Do you have this? Or am I just missing the point completely 
.
Yes, this is a terrible way to track issues! Probably best for me to be opening issues for these on Github so all the info can be tracked in one place. As far as coming across as being difficult, I almost said the same in regards to my own posts! It’s easy for me to leave off the personal touch while immersed in the technical. You’re doing the impossible here and I completely understand getting stuff done with a million irons in the fire. No offense taken, and hopefully none given. Your efforts are VERY much appreciated!
For this issue, this may be the piece that’s alluding you 
:
Yes - this is actually why I started the ticket system given here we are often looking at security. I didn’t want to have to ask people to post logs with secure information onto github. Some people don’t mind, but there’s a risk if you post these logs with secure information, someone can break into your network as it would not be too hard to crack the keys.
No - it’s not eluding me, but I need to see the information from this event. I asked to get a log relating to this event and you’ve sent a log with another exception - hence the confusion. I’ve no way to correlate this with the karaf console.
You said -:
So from this can I assume that they are happening at the same time? I’d be a bit surprised if this was the case, but is this your point as to why I have the information with the logs you’ve provided?
I don’t think this is the case since the exception you want me to look at from the console says it occurs in the alarm command class, while the log only appears to show meter messages.
Somehow we need to find the messages that are occurring when this exception happens. Maybe I need to improve the logging somewhere - it’s a bit annoying that some messages seem to only go to the console and don’t end up in the logs. I wonder if there’s a log configuration setting that can change this…
Thanks .
I have zwave devices no longer responding before the stack trace comes through in the console. I have a rule that notifies me when one of the energy monitors has not reported for 3 minutes. From the log, it looks like the exception comes in a few minutes after the energy monitor stops reporting. The console trace and log exception appear to be related, but I can’t say for certain that they happen simultaneously.
I thought you were meaning that you were not finding the exception in the log file. But you had the timestamp, so I did not understand what more information you would need… or that I could provide.
I also think I should clarify that it is the second stack trace that correlates to the exception in the log file:[quote=“5iver, post:1009, topic:21653”]
Exception in thread “Thread-43” java.lang.ArrayIndexOutOfBoundsException: 0
[/quote]
It’s interesting if these two exceptions are related - that might also make sense. The first one likely stops processing of the recieved packets, and then the second one (the queue full exception) that’s in the log is probably caused by messages not being processed due to the first exception screwing up the processor.
I need to spend some time looking at the issue with alarms this afternoon. I’ll take a look at trying to add something to better catch the exceptions and log them in the log rather than karaf console. If I can do this we can hopefully get a nice clean log that avoids my current confusion 
.
@shadowmite and others who have reported issues with notifications not working. I just did a test here and it seems to work fine (using a Sensative Strips). In the logs I’ve seen from someone, there was really nothing at all being logged from the command class, and this all looks ok here.
So, I’ll create an update tonight and let’s see if it’s working - if not, send me a log and we’ll take another look.
@5iver I’ve also added some code to try and catch all exceptions in command classes that aren’t already caught. Let’s see if that helps get everything logged in one place ;).
Thanks Chris… I’ll be trying that out tonight right away…
Can I get you another karaf debug log? I’m testing it out again and it’s still not sending alarm messages – at least the item isn’t receiving any updates. Maybe that’s where the problem is and not in the z-wave binding?
openHAB 2.1.0~20170608211238-1 (Build #942)
Just for laughs, I logged another “unlock” in the console from my Kwikset lock.
I redacted anything that looked security related. Maybe there’s another clue there?
15:52:43.600 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = xxxxxxx
15:52:43.617 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
15:52:43.631 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=xxxxxxx
15:52:43.644 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=xxxxxx
15:52:43.659 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=xxxxxx
15:52:43.693 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
15:52:43.711 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Application Command Request (ALIVE:DYNAMIC_VALUES)
15:52:43.761 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Incoming command class COMMAND_CLASS_SECURITY, endpoint 0
15:52:43.781 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: SECURITY check internal
15:52:43.803 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 6: Received COMMAND_CLASS_SECURITY V1 SECURITY_NONCE_GET
15:52:43.812 [DEBUG] [andclass.impl.CommandClassSecurityV1] - Creating command message SECURITY_NONCE_REPORT version 1
15:52:43.821 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build null
15:52:43.831 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Added to secure queue - size 1
15:52:43.850 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Commands processed 1.
15:52:43.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@15320f0.
15:52:43.863 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
15:52:43.877 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
15:52:43.884 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
15:52:43.890 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
15:52:43.897 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from secureQueue
15:52:43.908 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
15:52:43.920 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer =
15:52:43.943 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 6: Sending REQUEST Message =
15:52:43.963 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
15:52:43.970 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
15:52:43.974 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 14627: Transaction Start type SendData
15:52:43.979 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 14627: [WAIT_RESPONSE] requiresResponse=true callback: 129
15:52:43.992 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
15:52:43.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
15:52:44.005 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 0
15:52:44.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
15:52:44.027 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
15:52:44.033 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Jun 11 15:52:46 EDT 2017 - 1999ms
15:52:44.039 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = xxxxxxx
15:52:44.044 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 14627: [WAIT_RESPONSE] requiresResponse=true callback: 129
15:52:44.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
15:52:44.067 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
15:52:44.072 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Jun 11 15:52:46 EDT 2017 - 1959ms
15:52:44.078 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
15:52:44.084 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
15:52:44.089 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
15:52:44.102 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 14627: [WAIT_RESPONSE] requiresResponse=true callback: 129
15:52:44.106 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
15:52:44.120 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
15:52:44.135 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 14627: [WAIT_RESPONSE] requiresResponse=true callback: 129
15:52:44.139 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message =
15:52:44.145 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
15:52:44.157 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 14627: [WAIT_RESPONSE] requiresResponse=true callback: 129
15:52:44.176 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
15:52:44.174 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
15:52:44.189 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 6: Sent Data successfully placed on stack.
15:52:44.197 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=SendData[0x13], type=Request[0x00], dest=0, callback=129, payload=
15:52:44.209 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 14627: TransactionAdvance ST: WAIT_RESPONSE
15:52:44.220 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 14627: TransactionAdvance WT: null {}
15:52:44.216 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=SendData[0x13], type=Request[0x00], dest=0, callback=129, payload=
15:52:44.237 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 14627: TransactionAdvance RX: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
15:52:44.255 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 14627: TransactionAdvance TO: WAIT_REQUEST
15:52:44.261 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 14627: Advanced to WAIT_REQUEST
15:52:44.276 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: TID 14627: Transaction not completed
15:52:44.291 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=129, payload=81 00 00 02
15:52:44.299 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message =
15:52:44.305 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 14627: [WAIT_REQUEST] requiresResponse=true callback: 129
15:52:44.308 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
15:52:44.332 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 14627: [WAIT_REQUEST] requiresResponse=true callback: 129
15:52:44.339 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 14627: (Callback 129)
15:52:44.349 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
15:52:44.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 14627: callback 129
15:52:44.377 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
15:52:44.376 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=129, payload=81 00 00 02
15:52:44.387 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 6: SendData Request. CallBack ID = 129, Status = Transmission complete and ACK received(0)
15:52:44.411 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 14627: Transaction COMPLETED
15:52:44.418 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 14627: TransactionAdvance ST: DONE
15:52:44.420 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=
15:52:44.425 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 14627: TransactionAdvance WT: null {}
15:52:44.479 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 14627: TransactionAdvance RX: Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=129, payload=
15:52:44.486 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=
15:52:44.492 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 14627: TransactionAdvance TO: DONE
15:52:44.498 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Response processed after 524ms
15:52:44.512 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: TID 14627: Transaction completed
15:52:44.519 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: notifyTransactionResponse TID:14627 DONE
15:52:44.534 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
15:52:44.540 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
15:52:44.572 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=
15:52:44.581 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
15:52:44.589 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Application Command Request (ALIVE:DYNAMIC_VALUES)
15:52:44.599 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Decapsulating COMMAND_CLASS_SECURITY
15:52:44.624 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 6: SECURITY_RXD xx xx xx xx
15:52:44.658 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Incoming command class COMMAND_CLASS_ALARM, endpoint 0
15:52:44.667 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 6: Received COMMAND_CLASS_ALARM V1 NOTIFICATION_REPORT
15:52:44.701 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Commands processed 1.
15:52:44.736 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1b4bb59.
15:52:44.746 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
15:52:44.757 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
15:52:44.773 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
15:52:44.785 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
15:52:44.802 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 7: listening == false, frequentlyListening == false, awake == false
15:52:44.807 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Node not awake!
15:52:44.829 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == false, frequentlyListening == false, awake == false
15:52:44.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Node not awake!
15:52:44.850 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == false, frequentlyListening == false, awake == false
15:52:44.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Node not awake!
15:52:44.867 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 7: listening == false, frequentlyListening == false, awake == false
15:52:44.879 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Node not awake!
15:52:44.889 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
15:52:44.895 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
15:52:44.911 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timerIs this using the version I just posted a few minutes ago?
Wow. Didn’t see that you just posted that
I’ll try it out and report back here in a few.
Just tried out your latest build. I am still not getting any alarm messages to the item 
I will post a log next.
EDIT***
@chris Below is my karaf zwave debug log during a manual “unlock” event. Alarms aren’t sent to the item for any event.
This is on your new build from 11-june-2017. The lock is “NODE 6” in the below snippet.
16:36:41.495 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = xxxxx
16:36:41.514 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
16:36:41.530 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=4, callback=0, payload=xxxxx
16:36:41.546 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=4, callback=0, payload=xxxxx
16:36:41.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=4, callback=0, payload=xxxxx
16:36:41.575 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
16:36:41.597 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Application Command Request (ALIVE:REQUEST_NIF)
16:36:41.596 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = xxxxx
16:36:41.606 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Incoming command class COMMAND_CLASS_SECURITY, endpoint 0
16:36:41.619 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Command class COMMAND_CLASS_SECURITY not found, trying to add it.
16:36:41.638 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 4: Creating new instance of command class COMMAND_CLASS_SECURITY
16:36:41.639 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
16:36:41.653 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=xxxxx
16:36:41.699 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=xxxxx
16:36:41.744 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE Node 4: Manufacturer=014A, Type=0004, Id=0001: Command class COMMAND_CLASS_SECURITY, endpoint 0 created
16:36:41.776 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Adding command class COMMAND_CLASS_SECURITY to endpoint 0
16:36:41.786 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Adding command class COMMAND_CLASS_SECURITY to the list of supported command classes.
16:36:41.808 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: SECURITY check internal
16:36:41.817 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 4: Received COMMAND_CLASS_SECURITY V0 SECURITY_NONCE_GET
16:36:41.837 [DEBUG] [andclass.impl.CommandClassSecurityV1] - Creating command message SECURITY_NONCE_REPORT version 1
16:36:41.850 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build null
16:36:41.866 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Added to secure queue - size 1
16:36:41.882 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Commands processed 1.
16:36:41.890 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@600036.
16:36:41.902 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
16:36:41.918 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
16:36:41.935 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=xxxxx
16:36:41.959 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
16:36:41.968 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Application Command Request (ALIVE:DYNAMIC_VALUES)
16:36:41.981 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Incoming command class COMMAND_CLASS_SECURITY, endpoint 0
16:36:42.007 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: SECURITY check internal
16:36:42.020 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 6: Received COMMAND_CLASS_SECURITY V1 SECURITY_NONCE_GET
16:36:42.028 [DEBUG] [andclass.impl.CommandClassSecurityV1] - Creating command message SECURITY_NONCE_REPORT version 1
16:36:42.039 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build null
16:36:42.058 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Added to secure queue - size 2
16:36:42.075 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Commands processed 1.
16:36:42.091 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1b369f3.
16:36:42.099 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
16:36:42.117 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
16:36:42.125 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
16:36:42.144 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
16:36:42.148 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from secureQueue
16:36:42.155 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
16:36:42.197 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = xxxxx
16:36:42.216 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 4: Sending REQUEST Message = xxxxx
16:36:42.275 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
16:36:42.272 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
16:36:42.298 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 231: Transaction Start type SendData
16:36:42.290 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
16:36:42.302 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 231: [WAIT_RESPONSE] requiresResponse=true callback: 191
16:36:42.317 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
16:36:42.322 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
16:36:42.330 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 0
16:36:42.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
16:36:42.372 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = xxxxx
16:36:42.375 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Jun 11 16:36:44 EDT 2017 - 1999ms
16:36:42.397 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 231: [WAIT_RESPONSE] requiresResponse=true callback: 191
16:36:42.398 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
16:36:42.408 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
16:36:42.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
16:36:42.435 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Jun 11 16:36:44 EDT 2017 - 1940ms
16:36:42.444 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
16:36:42.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
16:36:42.477 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 231: [WAIT_RESPONSE] requiresResponse=true callback: 191
16:36:42.483 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
16:36:42.502 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
16:36:42.521 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 231: [WAIT_RESPONSE] requiresResponse=true callback: 191
16:36:42.528 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
16:36:42.545 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 231: [WAIT_RESPONSE] requiresResponse=true callback: 191
16:36:42.555 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
16:36:42.578 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: Sent Data successfully placed on stack.
16:36:42.594 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 231: TransactionAdvance ST: WAIT_RESPONSE
16:36:42.601 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 231: TransactionAdvance WT: null {}
16:36:42.620 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 231: TransactionAdvance RX: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
16:36:42.637 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 231: TransactionAdvance TO: WAIT_REQUEST
16:36:42.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 231: Advanced to WAIT_REQUEST
16:36:42.667 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 231: Transaction not completed
16:36:42.674 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
16:36:42.696 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
16:36:42.706 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
16:36:42.712 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
16:36:42.731 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Jun 11 16:36:47 EDT 2017 - 4937ms
I can confirm the same, but I’m still waiting for my BE469s to complete initialization. Habmin doesn’t say Node: Initializing for them, but Reinitialize is not an Advanced Option and I still see User Codes coming in.
I also see these:
Exception in thread "Thread-431423" java.lang.NullPointerException
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass.getMessage(ZWaveAlarmCommandClass.java:316)
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass.getDynamicValues(ZWaveAlarmCommandClass.java:381)
at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.doDynamicStages(ZWaveNodeInitStageAdvancer.java:953)
at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.access$10(ZWaveNodeInitStageAdvancer.java:932)
at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer$1.run(ZWaveNodeInitStageAdvancer.java:202)
and these:
java.lang.reflect.InvocationTargetException
at sun.reflect.GeneratedMethodAccessor481.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveCommandClass.handleApplicationCommandRequest(ZWaveCommandClass.java:245)
at org.openhab.binding.zwave.internal.protocol.ZWaveNode.processCommand(ZWaveNode.java:1284)
at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveReceiveThread.run(ZWaveTransactionManager.java:414)
Caused by: java.lang.NullPointerException
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass.handleNotificationReport(ZWaveAlarmCommandClass.java:140)
... 6 more
… in the Karaf console but no exceptions in the log for the zwave binding. The second one can be triggered by a lock or unlock, but not exclusively.
Damn - I wish I knew how to trap these things! 
.
I’ve added one more line of debug and updated the binding - it would be interesting to see what this shows.
I’m not seeing any of those exceptions. Where are you seeing them? Karaf console log right?
Can you post a new log with the latest version please?
The log I posted most recently (above) is using the latest version. Or wait, did you update a second time this evening?
Using your LATEST Latest binding (downloaded 11pm EDT).
Below is a capture from the log with your latest binding on a “lock” event. No alarm was sent to the item as before.
00:10:26.373 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = xxxxxx
00:10:26.394 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
00:10:26.413 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=xxxxxx
00:10:26.432 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=xxxxxx
00:10:26.452 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=xxxxxx
00:10:26.461 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 318: [WAIT_REQUEST] requiresResponse=true callback: 27
00:10:26.476 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Application Command Request (ALIVE:DYNAMIC_VALUES)
00:10:26.487 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Incoming command class COMMAND_CLASS_SECURITY, endpoint 0
00:10:26.503 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: SECURITY check internal
00:10:26.512 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 6: Received COMMAND_CLASS_SECURITY V1 SECURITY_NONCE_GET
00:10:26.525 [DEBUG] [andclass.impl.CommandClassSecurityV1] - Creating command message SECURITY_NONCE_REPORT version 1
00:10:26.540 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build null
00:10:26.552 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Added to secure queue - size 1
00:10:26.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Commands processed 1.
00:10:26.575 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1f7d9ad.
00:10:26.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Checking transaction 318 ApplicationCommandHandler.
00:10:26.598 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Checking transaction : state >> WAIT_REQUEST
00:10:26.611 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Checking transaction : node >> 4
00:10:26.623 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Checking transaction : class >> 152 == 48.
00:10:26.640 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Checking transaction : commd >> 64 == 3.
00:10:26.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Ignoring transaction since not waiting for data.
00:10:26.654 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
00:10:26.677 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
00:10:26.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
00:10:26.697 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
00:10:26.710 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
00:10:26.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
00:10:26.736 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Jun 12 00:10:27 EDT 2017 - 333ms
00:10:27.069 [DEBUG] [sactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
00:10:27.090 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 4: TID 318: Timeout at state WAIT_REQUEST. 3 retries remaining.
00:10:27.109 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
00:10:27.123 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 318: Transaction ABORTED
00:10:27.147 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = xxxxxx
00:10:27.158 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = xxxxxx
00:10:27.179 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
00:10:27.175 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
00:10:27.205 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
00:10:27.220 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
00:10:27.235 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
00:10:27.233 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
00:10:27.256 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
00:10:27.251 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
00:10:27.271 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 318: [ABORTED] requiresResponse=true callback: 27
00:10:27.279 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
00:10:27.283 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Jun 12 00:10:39 EDT 2017 - 11855ms
00:10:27.313 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
00:10:27.324 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
00:10:27.350 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
00:10:27.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
00:10:27.384 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Jun 12 00:10:39 EDT 2017 - 11753msCorrect. But I do not see any exceptions in the zwave binding log.