Queue full exception during ZWave thread

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:





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…

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…

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

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

So it should normally not throw a Java exception?

No - we try and avoid exceptions.

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?

@chris
I did an exclusion of a node, and I’m on my way to a full queue… I think it’s a matter of a few mintes before the queue is full.

2019-06-25 08:09:28.654 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 43 0E 32 02 A1 64 00 01 CC 21 00 00 00 00 00 00 BB 
2019-06-25 08:09:28.654 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 86<>42 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=67, callback=0, payload=00 43 0E 32 02 A1 64 00 01 CC 21 00 00 00 00 00 00 
2019-06-25 08:09:28.833 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 43 0E 32 02 A1 6C 00 00 2C 6B 00 00 00 00 00 00 18 
2019-06-25 08:09:28.833 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 87<>41 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=67, callback=0, payload=00 43 0E 32 02 A1 6C 00 00 2C 6B 00 00 00 00 00 00 
2019-06-25 08:09:28.952 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 43 0E 32 02 21 74 00 12 A6 F5 00 00 00 00 00 00 86 
2019-06-25 08:09:28.952 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 88<>40 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=67, callback=0, payload=00 43 0E 32 02 21 74 00 12 A6 F5 00 00 00 00 00 00 
2019-06-25 08:09:29.141 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 43 0E 32 02 21 64 00 10 AA 2E 01 2C 00 10 A9 82 55 
2019-06-25 08:09:29.142 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 89<>39 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=67, callback=0, payload=00 43 0E 32 02 21 64 00 10 AA 2E 01 2C 00 10 A9 82 

I was in the karaf console at the time, and saw this exception, which hopefully will provide some additional clues…

Exception in thread "ZWaveReceiveProcessorThread" java.lang.NullPointerException                                         
	at org.openhab.binding.zwave.event.BindingEventFactory.formatEvent(BindingEventFactory.java:90)
	at org.openhab.binding.zwave.handler.ZWaveControllerHandler.ZWaveIncomingEvent(ZWaveControllerHandler.java:612)
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.notifyEventListeners(ZWaveController.java:558)
	at org.openhab.binding.zwave.internal.protocol.serialmessage.RemoveNodeMessageClass.handleRequest(RemoveNodeMessageClass.java:73)
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:228)
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:196)
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveReceiveThread.run(ZWaveTransactionManager.java:614)

Binding version

271 │ Active │  80 │ 2.5.0.201906240431    │ org.openhab.binding.zwave

Edit: Yep, here’s the Queue Full exception

2019-06-25 08:13:42.723 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-06-25 08:13:42.723 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 128<>0 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-06-25 08:13:42.723 [ERROR] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Exception during ZWave thread. 
java.lang.IllegalStateException: Queue full
	at java.util.AbstractQueue.add(AbstractQueue.java:98) ~[?:?]
	at java.util.concurrent.ArrayBlockingQueue.add(ArrayBlockingQueue.java:312) ~[?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.processReceiveMessage(ZWaveTransactionManager.java:409) ~[271:org.openhab.binding.zwave:2.5.0.201906240431]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.incomingPacket(ZWaveController.java:1064) ~[271:org.openhab.binding.zwave:2.5.0.201906240431]
	at org.openhab.binding.zwave.handler.ZWaveControllerHandler.incomingMessage(ZWaveControllerHandler.java:625) ~[271:org.openhab.binding.zwave:2.5.0.201906240431]
	at org.openhab.binding.zwave.handler.ZWaveSerialHandler$ZWaveReceiveThread.run(ZWaveSerialHandler.java:329) [271:org.openhab.binding.zwave:2.5.0.201906240431]

Regarding the above, I think it’s odd that the NPE is logged to the console, not to openhab.log. Do you know why that would that be the case? It was just dumb luck that I happened to have the console open at the time…

Is this with the very latest binding? I’m a bit surprised as I removed the event system :confused: Maybe I screwed it up somehow…

Binding version

271 │ Active │ 80 │ 2.5.0.201906240431 │ org.openhab.binding.zwave

Strange - I’ll take another look. I’m assuming that the builds are really working as I know CI is not working at all on ZWave or ZigBee at the moment…

Ok, so I removed this issue from the wrong thing handler. This is in fact the same problem I originally found last week, that I wrapped the debug around, but I only removed it from the thing handler, and not the controller thing handler.

I’ll take a look at this tonight.

1 Like

But what is it about this line of code that it started throwing an NPE? You already check for translationProviderLocal being null, so it must be the call to ZWaveActivator.getContext().getBundle()?

Given that the binding didn’t change, I assume this is wrapped up in the various other system changes. I will just remove all this code as it’s only used in HABmin and it was decided that openHAB didn’t want to include this concept in general and the event notification concept was rejected.

Fair enough…

My testing so far of https://github.com/openhab/org.openhab.binding.zwave/pull/1192 looks encouraging. After running inclusion/exclusion I’ve not seen any instances of the NPE and Queue Full exceptions.

Thanks Mark. I’ve not had the chance to test this as the development system for both ZigBee and ZWave is still broken and I’ve done a build and put it in my production system.

I might just merge this based on your testing, although I’m a bit uncomfortable with the development system being down.

I’ve also tested a few heals (of mains powered devices), which ran successfully. No NPEs or Queue Full exceptions.

I didn’t do any heals of battery-devices because I think the heal of battery-powered devices still have issues (as described in my other posts).

1 Like