search

openhab / org.openhab.binding.zigbee

openHAB binding for ZigBee
Eclipse Public License 2.0
73 stars 112 forks source link

AshFrameHandler: Queue full #879

Open magx2 opened 2 days ago

magx2 commented 2 days ago

Hey,

Lately I've sarted getting this issues from my zigbee controller:

2024-11-19 17:25:55.401 [ERROR] [e.ember.internal.ash.AshFrameHandler] - AshReceiveParserThread Exception: 
java.lang.IllegalStateException: Queue full
    at java.util.AbstractQueue.add(AbstractQueue.java:98) ~[?:?]
    at java.util.concurrent.ArrayBlockingQueue.add(ArrayBlockingQueue.java:329) ~[?:?]
    at com.zsmartsystems.zigbee.dongle.ember.internal.ash.AshFrameHandler.handleIncomingFrame(AshFrameHandler.java:242) ~[bundleFile:?]
    at com.zsmartsystems.zigbee.dongle.ember.internal.ash.AshFrameHandler.access$700(AshFrameHandler.java:59) ~[bundleFile:?]
    at com.zsmartsystems.zigbee.dongle.ember.internal.ash.AshFrameHandler$AshReceiveParserThread.run(AshFrameHandler.java:319) [bundleFile:?]

Prior to this error I've upgraded my ZBDongle-E to the latest version using this website.

Any idea what might be the issue?

cdjackson commented 2 days ago

It's hard to say without a log to see what is happening, but I'd say if this is random, then it probably means something external is causing the system not to keep up - eg something is using too much processing power or blocking other bindings for a second or two. If it's systematic, and always happens on startup, then maybe it's an incompatibility with the new firmware.

magx2 commented 1 day ago

I don't think it's random. I had this some time ago and I had to restart the machine (restarting docker with OH did not worked).

This time I also restarted the machine and the queue got emptied. Let's see for how long.

About the logs. I've got this enabled in my log4j2.xml, but there was not coming any new messages (only error that I've posted above)

<Logger name="org.openhab.binding.zigbee" level="debug" additivity="false">
    <AppenderRef ref="ZIGBEE"/>
</Logger>
cdjackson commented 1 day ago

I don't think it's random.

Ok, if it's not random, then you're saying that it happens every time you do a certain thing? If so, then please just replicate that and I'll take a look at the log.

This time I also restarted the machine and the queue got emptied. Let's see for how long.

The queue should be normally empty and it always starts with nothing in it when the binding starts. If the queue is not maintained (ie it's not normally close to empty), then a) you'll get a queue full exception (as you see), but it will also cause problems with delays. What I mean by this is if the queue has a delay through it (which will happen if the data is not being read out fast enough), then this in turn would cause other problems since the ASH protocol will retry any command not ack'd within 400ms. This is why just increasing the queue size isn't really a solution (just before you ask ;) ).

I've got this enabled in my log4j2.xml,

The logging you've enabled is only part of what's needed - this is only the binding - all the hard graft happens in the lower level zigbee library... If you log on to the OH console and type log:set DEBUG com.zsmartsystems.zigbee that's should work (it's much easier than editing the logger config file).

magx2 commented 1 day ago

Ok, if it's not random, then you're saying that it happens every time you do a certain thing? If so, then please just replicate that and I'll take a look at the log.

I think it's time based. I will leave my system running and I will see it happen again

The queue should be normally empty and it always starts with nothing in it when the binding starts. If the queue is not maintained (ie it's not normally close to empty), then a) you'll get a queue full exception (as you see), but it will also cause problems with delays. What I mean by this is if the queue has a delay through it (which will happen if the data is not being read out fast enough), then this in turn would cause other problems since the ASH protocol will retry any command not ack'd within 400ms. This is why just increasing the queue size isn't really a solution (just before you ask ;) ).

Yeah, so in general everything that was zigbee connected stopped working (makes sense) which is probably, because ACK's are not coming to/from devices.

The logging you've enabled is only part of what's needed - this is only the binding - all the hard graft happens in the lower level zigbee library... If you log on to the OH console and type log:set DEBUG com.zsmartsystems.zigbee that's should work (it's much easier than editing the logger config file).

I prefer using XML file cause I can comment/uncomment parts of my configuration whenever I want. In opposite I would need to SSH into my machine, then log into docker and finally log into Karaf - too much overhead ;).

Will this config be fine?

<Logger name="org.openhab.binding.zigbee" level="debug" additivity="false">
    <AppenderRef ref="ZIGBEE"/>
</Logger>
<Logger name="com.zsmartsystems.zigbee" level="debug" additivity="false">
    <AppenderRef ref="ZIGBEE"/>
</Logger>
cdjackson commented 1 day ago

I think it's time based.

As I said - the system should keep up. It's not a big buffer, so it's not going to just increase slowly over time. If it's not keeping up, then your computer has some sort of problem since the speed of the serial comms is very slow.

Almost certainly this will be some sort of external issue - ie it's very unlikely to be a bug in the binding that causes this.