Queue full exception during ZWave thread

zwave
Tags: #<Tag:0x00007fe04ffa0168>

(Avner) #1

I’m using a development branch (version 2.1.0.201704162057).
It starts ok and shows zwave events (note1). After a while, zwave events stops showing up, and at some point (several hours later), the openhab.log file shows an exception error (note2).
This issue was obsereved here

---------------------------------------------------

note1

tail -f /var/log/openhab2/events.log
...
2017-05-04 01:05:33.511 [ItemStateChangedEvent     ] - Hsm100AlarmMotion changed from ON to OFF
2017-05-04 01:05:33.512 [ItemStateChangedEvent     ] - zwave_device_baa75210_node3_alarm_motion changed from ON to OFF
...
2017-05-04 01:14:01.192 [ItemStateChangedEvent     ] - zwave_device_baa75210_node6_alarm_motion changed from OFF to ON
2017-05-04 01:14:43.567 [ItemStateChangedEvent     ] - zwave_device_baa75210_node6_alarm_motion changed from ON to OFF

note2

tail -f  /var/log/openhab2/openhab.log
...
2017-05-04 06:36:31.001 [ERROR] [WaveSerialHandler$ZWaveReceiveThread] - Exception during ZWave thread. 
java.lang.IllegalStateException: Queue full
        at java.util.AbstractQueue.add(AbstractQueue.java:98)[:1.8.0_121]
        at java.util.concurrent.ArrayBlockingQueue.add(ArrayBlockingQueue.java:312)[:1.8.0_121]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.processReceiveMessage(ZWaveTransactionManager.java:345)[200:org.openhab.binding.zwave:2.1.0.201704162057]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.incomingPacket(ZWaveController.java:1215)[200:org.openhab.binding.zwave:2.1.0.201704162057]
        at org.openhab.binding.zwave.handler.ZWaveControllerHandler.incomingMessage(ZWaveControllerHandler.java:636)[200:org.openhab.binding.zwave:2.1.0.201704162057]
        at org.openhab.binding.zwave.handler.ZWaveSerialHandler$ZWaveReceiveThread.run(ZWaveSerialHandler.java:320)[200:org.openhab.binding.zwave:2.1.0.201704162057]

Motion sensor hsm100 fail to initialise
(Chris Jackson) #2

The exception in isolation doesn’t really mean anything - other than a queue seems to be full ;). I’d need to see a log to find out why.


(vossivossi) #3

@chris: I encountered exactly the same problem (Queue full) with the development branch (20170423) when I tried to include a new device last weekend. I then switched back to the snapshot main branch (906 last weekend) and I could do the inclusion.
As I am always collecting tons of debug logs, I can provide my “Queue Full”-log:

ionCommandHandler[0x04], type=Request[0x00], dest=70, callback=16, payload=10 46 03 20 03 FF 
2017-04-29 12:23:53.879 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 35 03 20 03 FF 08 
2017-04-29 12:23:53.880 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.880 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:53.880 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:53.893 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:53.894 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.894 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.894 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.943 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 35 03 20 03 FF 08 
2017-04-29 12:23:53.943 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.944 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:53.944 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:53.971 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 35 03 20 03 FF 08 
2017-04-29 12:23:53.972 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.972 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:53.972 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:54.013 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:54.014 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.014 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:54.014 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:54.047 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 10 FF 0A 71 05 00 00 00 FF 07 00 01 08 8B 
2017-04-29 12:23:54.048 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.048 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=255, callback=16, payload=10 FF 0A 71 05 00 00 00 FF 07 00 01 08 
2017-04-29 12:23:54.048 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=255, callback=16, payload=10 FF 0A 71 05 00 00 00 FF 07 00 01 08 
2017-04-29 12:23:54.058 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 35 03 20 03 FF 08 
2017-04-29 12:23:54.059 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.059 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:54.059 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:54.064 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 35 03 20 03 FF 08 
2017-04-29 12:23:54.065 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.065 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:54.065 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:54.105 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 35 03 20 03 FF 08 
2017-04-29 12:23:54.106 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.106 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:54.106 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:54.143 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 46 03 20 03 FF 7B 
2017-04-29 12:23:54.144 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.144 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=70, callback=16, payload=10 46 03 20 03 FF 
2017-04-29 12:23:54.144 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=70, callback=16, payload=10 46 03 20 03 FF 
2017-04-29 12:23:54.154 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 46 03 20 03 FF 7B 
2017-04-29 12:23:54.155 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.155 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=70, callback=16, payload=10 46 03 20 03 FF 
2017-04-29 12:23:54.155 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=70, callback=16, payload=10 46 03 20 03 FF 
2017-04-29 12:23:54.204 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:54.205 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.205 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:54.205 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:54.215 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:54.216 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.216 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:54.216 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:54.322 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 35 03 20 03 FF 08 
2017-04-29 12:23:54.323 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.323 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:54.323 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:54.364 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 46 03 20 03 FF 7B 
2017-04-29 12:23:54.365 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.365 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=70, callback=16, payload=10 46 03 20 03 FF 
2017-04-29 12:23:54.365 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=70, callback=16, payload=10 46 03 20 03 FF 
2017-04-29 12:23:54.439 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 35 03 20 03 FF 08 
2017-04-29 12:23:54.440 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.440 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:54.440 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:54.474 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 46 03 20 03 FF 7B 
2017-04-29 12:23:54.475 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.475 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=70, callback=16, payload=10 46 03 20 03 FF 
2017-04-29 12:23:54.475 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=70, callback=16, payload=10 46 03 20 03 FF 
2017-04-29 12:23:54.485 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 10 FF 0A 71 05 00 00 00 FF 07 00 01 08 8B 
2017-04-29 12:23:54.486 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.486 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=255, callback=16, payload=10 FF 0A 71 05 00 00 00 FF 07 00 01 08 
2017-04-29 12:23:54.486 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=255, callback=16, payload=10 FF 0A 71 05 00 00 00 FF 07 00 01 08 
2017-04-29 12:23:54.492 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:54.493 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.493 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:54.493 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:54.503 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 35 03 20 03 FF 08 
2017-04-29 12:23:54.504 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.504 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:54.504 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:54.513 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:54.514 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.514 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:54.514 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:54.564 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:54.565 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:54.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:54.634 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 35 03 20 03 FF 08 
2017-04-29 12:23:54.635 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.635 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:54.635 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:54.667 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:54.668 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.668 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:54.668 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:54.677 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 46 03 20 03 FF 7B 
2017-04-29 12:23:54.678 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:54.678 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=70, callback=16, payload=10 46 03 20 03 FF 
2017-04-29 12:23:54.678 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=70, callback=16, payload=10 46 03 20 03 FF 
2017-04-29 12:23:54.679 [ERROR] [WaveSerialHandler$ZWaveReceiveThread] - Exception during ZWave thread. 
java.lang.IllegalStateException: Queue full
	at java.util.AbstractQueue.add(Unknown Source)[:1.8.0_131]
	at java.util.concurrent.ArrayBlockingQueue.add(Unknown Source)[:1.8.0_131]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.processReceiveMessage(ZWaveTransactionManager.java:345)[217:org.openhab.binding.zwave:2.1.0.201704232237]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.incomingPacket(ZWaveController.java:1216)[217:org.openhab.binding.zwave:2.1.0.201704232237]
	at org.openhab.binding.zwave.handler.ZWaveControllerHandler.incomingMessage(ZWaveControllerHandler.java:636)[217:org.openhab.binding.zwave:2.1.0.201704232237]
	at org.openhab.binding.zwave.handler.ZWaveSerialHandler$ZWaveReceiveThread.run(ZWaveSerialHandler.java:320)[217:org.openhab.binding.zwave:2.1.0.201704232237]
2017-04-29 12:23:54.679 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Stopped ZWave thread: Receive
2017-04-29 12:23:55.367 [DEBUG] [sactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions

You will find the java exception at 12:23:54.679 .


(Chris Jackson) #4

It might be interesting to look a bit earlier into this log, but I really wonder how you have things configured? Looking at this short except - there are 25 messages received here in around 3/4 of a second (ie messages even 20 or 30 milliseconds!!!) -:

Lots of messages are duplicated - possibly because you have duplicated association settings (ie added the controller into multiple groups)? I’m not sure why else this is happening, but if you then try and do something intensive like include a device, or try and configure something, and with this VERY high loading, I’m not surprised that things will have a problem.


(vossivossi) #5

I just checked all 90 nodes. The controller is only in association group 1.


(Chris Jackson) #6

Ok - maybe it’s something else - maybe it’s just a few nodes that have a problem - if I look in the log, node 53 alone has 10 messages in the 3/4 of a second - node 51 is about the same, and node 53 is a bit less…

Something is wrong somewhere with these nodes or their configuration.


(vossivossi) #7

Ok, here the log in the seconds before



2017-04-29 12:23:43.367 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 117: listening == false, frequentlyListening == false, awake == false
2017-04-29 12:23:43.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 117: Node not awake!
2017-04-29 12:23:43.367 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 117: listening == false, frequentlyListening == false, awake == false
2017-04-29 12:23:43.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 117: Node not awake!
2017-04-29 12:23:43.367 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 108: listening == false, frequentlyListening == false, awake == false
2017-04-29 12:23:43.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 108: Node not awake!
2017-04-29 12:23:43.367 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 117: listening == false, frequentlyListening == false, awake == false
2017-04-29 12:23:43.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 117: Node not awake!
2017-04-29 12:23:43.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-04-29 12:23:43.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2017-04-29 12:23:43.367 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 88 11 
2017-04-29 12:23:43.367 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 88 11 
2017-04-29 12:23:43.367 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2017-04-29 12:23:43.367 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 33187: Transaction Start type IsFailedNodeID 
2017-04-29 12:23:43.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 33187: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-04-29 12:23:43.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2017-04-29 12:23:43.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2017-04-29 12:23:43.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2017-04-29 12:23:43.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-29 12:23:43.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 12:23:45 CEST 2017 - 2000ms
2017-04-29 12:23:43.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 33187: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-04-29 12:23:43.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-29 12:23:43.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 12:23:45 CEST 2017 - 2000ms
2017-04-29 12:23:43.369 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-04-29 12:23:43.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-04-29 12:23:43.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-04-29 12:23:43.370 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 01 99 
2017-04-29 12:23:43.371 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:43.371 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-04-29 12:23:43.371 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-04-29 12:23:43.960 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 84 12 32 02 21 74 00 00 02 10 00 00 00 00 00 00 00 00 00 00 02 
2017-04-29 12:23:43.961 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:43.961 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=132, callback=0, payload=00 84 12 32 02 21 74 00 00 02 10 00 00 00 00 00 00 00 00 00 00 
2017-04-29 12:23:43.961 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=132, callback=0, payload=00 84 12 32 02 21 74 00 00 02 10 00 00 00 00 00 00 00 00 00 00 
2017-04-29 12:23:44.960 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 84 12 32 02 21 74 00 00 00 00 00 00 00 00 00 00 00 00 00 00 10 
2017-04-29 12:23:44.961 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:44.961 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=132, callback=0, payload=00 84 12 32 02 21 74 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2017-04-29 12:23:44.961 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=132, callback=0, payload=00 84 12 32 02 21 74 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2017-04-29 12:23:45.367 [DEBUG] [sactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
2017-04-29 12:23:45.367 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 33187: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2017-04-29 12:23:45.367 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 33187: Transaction is current transaction, so clearing!!!!!
2017-04-29 12:23:45.367 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 33187: Transaction CANCELLED
2017-04-29 12:23:45.367 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:33187 CANCELLED
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-04-29 12:23:45.367 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 117: listening == false, frequentlyListening == false, awake == false
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 117: Node not awake!
2017-04-29 12:23:45.367 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 117: listening == false, frequentlyListening == false, awake == false
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 117: Node not awake!
2017-04-29 12:23:45.367 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 108: listening == false, frequentlyListening == false, awake == false
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 108: Node not awake!
2017-04-29 12:23:45.367 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 117: listening == false, frequentlyListening == false, awake == false
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 117: Node not awake!
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 33187: Transaction event listener: DONE: CANCELLED -> 
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: -- To notify -- TIMEOUT_WAITING_FOR_CONTROLLER
2017-04-29 12:23:45.367 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 08 BD 
2017-04-29 12:23:45.367 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 08 BD 
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete 33187 -- 
2017-04-29 12:23:45.367 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 136: Node Init response (0) TIMEOUT_WAITING_FOR_CONTROLLER
2017-04-29 12:23:45.367 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2017-04-29 12:23:45.367 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 33190: Transaction Start type AddNodeToNetwork 
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 33190: [WAIT_REQUEST] requiresResponse=true callback: 8
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 12:23:50 CEST 2017 - 5000ms
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 33190: [WAIT_REQUEST] requiresResponse=true callback: 8
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-29 12:23:45.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 12:23:50 CEST 2017 - 5000ms
2017-04-29 12:23:45.369 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-04-29 12:23:45.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-04-29 12:23:45.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-04-29 12:23:45.420 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 08 06 89 00 35 
2017-04-29 12:23:45.421 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:45.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=6, callback=8, payload=08 06 89 00 
2017-04-29 12:23:45.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=6, callback=8, payload=08 06 89 00 
2017-04-29 12:23:46.693 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 40 06 43 03 0B 22 01 09 D0 
2017-04-29 12:23:46.694 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:46.694 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=64, callback=0, payload=00 40 06 43 03 0B 22 01 09 
2017-04-29 12:23:46.694 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=64, callback=0, payload=00 40 06 43 03 0B 22 01 09 
2017-04-29 12:23:48.422 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 3F 06 31 05 01 22 01 0E D6 
2017-04-29 12:23:48.423 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:48.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=63, callback=0, payload=00 3F 06 31 05 01 22 01 0E 
2017-04-29 12:23:48.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=63, callback=0, payload=00 3F 06 31 05 01 22 01 0E 
2017-04-29 12:23:48.855 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 7A 0A 32 02 21 34 00 00 00 00 00 00 BE 
2017-04-29 12:23:48.855 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:48.855 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=122, callback=0, payload=00 7A 0A 32 02 21 34 00 00 00 00 00 00 
2017-04-29 12:23:48.856 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=122, callback=0, payload=00 7A 0A 32 02 21 34 00 00 00 00 00 00 
2017-04-29 12:23:50.367 [DEBUG] [sactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
2017-04-29 12:23:50.367 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 33190: Timeout at state WAIT_REQUEST. 3 retries remaining.
2017-04-29 12:23:50.367 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 33190: Transaction is current transaction, so clearing!!!!!
2017-04-29 12:23:50.367 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 33190: Transaction CANCELLED
2017-04-29 12:23:50.367 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-04-29 12:23:50.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:33190 CANCELLED
2017-04-29 12:23:50.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-04-29 12:23:50.367 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 117: listening == false, frequentlyListening == false, awake == false
2017-04-29 12:23:50.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 117: Node not awake!
2017-04-29 12:23:50.367 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 117: listening == false, frequentlyListening == false, awake == false
2017-04-29 12:23:50.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 117: Node not awake!
2017-04-29 12:23:50.367 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 108: listening == false, frequentlyListening == false, awake == false
2017-04-29 12:23:50.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 108: Node not awake!
2017-04-29 12:23:50.367 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 117: listening == false, frequentlyListening == false, awake == false
2017-04-29 12:23:50.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 117: Node not awake!
2017-04-29 12:23:50.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-04-29 12:23:50.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2017-04-29 12:23:50.367 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 09 78 
2017-04-29 12:23:50.367 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 09 78 
2017-04-29 12:23:50.367 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2017-04-29 12:23:50.367 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 33188: Transaction Start type AddNodeToNetwork 
2017-04-29 12:23:50.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 33188: [WAIT_REQUEST] requiresResponse=true callback: 9
2017-04-29 12:23:50.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2017-04-29 12:23:50.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2017-04-29 12:23:50.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2017-04-29 12:23:50.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-29 12:23:50.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 12:23:55 CEST 2017 - 5000ms
2017-04-29 12:23:50.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 33188: [WAIT_REQUEST] requiresResponse=true callback: 9
2017-04-29 12:23:50.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-29 12:23:50.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 12:23:55 CEST 2017 - 5000ms
2017-04-29 12:23:50.369 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-04-29 12:23:50.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-04-29 12:23:50.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-04-29 12:23:50.371 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 09 01 00 00 BA 
2017-04-29 12:23:50.372 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:50.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=1, callback=9, payload=09 01 00 00 
2017-04-29 12:23:50.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=1, callback=9, payload=09 01 00 00 
2017-04-29 12:23:52.791 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:52.792 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:52.792 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:52.792 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:52.960 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:52.961 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:52.961 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:52.961 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.026 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:53.027 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.027 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.027 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.071 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:53.072 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.072 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.072 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.142 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:53.143 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.143 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.143 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.151 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:53.152 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.152 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.152 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.228 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:53.229 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.229 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.229 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.264 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:53.265 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.265 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.265 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.274 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:53.275 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.275 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.275 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.331 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:53.332 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.332 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.332 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.373 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:53.373 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.374 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.374 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.383 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:53.384 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.384 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.384 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.448 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 46 03 20 03 FF 7B 
2017-04-29 12:23:53.448 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.449 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=70, callback=16, payload=10 46 03 20 03 FF 
2017-04-29 12:23:53.449 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=70, callback=16, payload=10 46 03 20 03 FF 
2017-04-29 12:23:53.479 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:53.480 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.480 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.480 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.523 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:53.524 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.524 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.524 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.563 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:53.564 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.564 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.564 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.574 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:53.575 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.575 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.575 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.581 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 35 03 20 03 FF 08 
2017-04-29 12:23:53.582 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.582 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:53.582 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=53, callback=16, payload=10 35 03 20 03 FF 
2017-04-29 12:23:53.632 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:53.633 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.681 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:53.682 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.682 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.682 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.797 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 33 03 20 03 FF 0E 
2017-04-29 12:23:53.798 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-29 12:23:53.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=16, payload=10 33 03 20 03 FF 
2017-04-29 12:23:53.807 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 46 03 20 03 FF 7B 
2017-04-29 12:23:53.808 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6

(vossivossi) #8

All the nodes in the logs (51,53,70) are thermostats (Heatit, TF016 by ThermoFloor). As they used to produce a lot of timeouts in the logs at the beginning I reduced polling for them to only 1x a day. Since then I do not see any timeouts for them in the logs anymore. They report quite often the actual temperature and the setpoint temperature.
Unfortunately they have Firmware 1.7 which has only 1 configuration parameter, so I do not see a way to change any configuration:






(Chris Jackson) #9

Ok - not sure what to suggest then. Maybe this was just a “one off” - I’d just keep an eye on the log to see if this sort of thing is really happening often or not…


(vossivossi) #10

Well, I have the logs from the last weeks in full detail. I just checked a few of them with the log viewer on your webpage right now. My thermostats seem to do this VERY OFTEN (repeating 30+ basic reports within 1 second). Could this be a source of instability for the network? I do not need frequent updates from them at all…


(vossivossi) #11

I am just curious: What is the actual queue size limit?


(Chris Jackson) #12

There isn’t meant to be one, but the initial size is set to 128 and it’s meant to be able to grow.


(vossivossi) #13

So it should normally not throw a Java exception?


(Chris Jackson) #14

No - we try and avoid exceptions.


(Avner) #15

I wanted to collect log files and did another test that also resulted in events still stopping after some time (but without Queue Full exception error)
The observations and the log files are here.
I used http://www.cd-jackson.com/index.php/openhab/zwave-log-viewer to view the log file and there are chatty events from node5 which of a dead device.
@chris can you please take a look?
Also, I read that if other dead nodes (of devices that no longer exist) on the zwave stick can create side effects. Is there a way to remove them without resetting the stick?