[deconz] events from deconz are received but not propagated in openhab, error message Get full state failed

[msandres13]

Expected Behavior

zigbee switch issues event on deconz, deconz binding receives that event and propagates it to openhab reliable.

Current Behavior

My containerized openhab instance is using the deconz plugin and a separate Raspberrypi running deconz natively. A rule which receives the event from zigbee switches generates a Telegram message using a bot.
This works consistently sometimes for days, sometimes for hours after the restart of the container.
Then it stops working randomly until the deconz plugin is paused and then started again.
Used dockerhub container version is image: "openhab/openhab:3.3.0"
deconz uses this package:

apt show deconz
Package: deconz
Version: 2.17.01-debian-buster-stable
Priority: extra
Section: non-free / misc
Maintainer: Manuel Pietschmann <manuel.pietschmann@dresden-elektronik.de>
Installed-Size: 41.6 MB
Depends: libqt5core5a, libqt5network5, libqt5widgets5, libqt5gui5, libqt5serialport5, libqt5websockets5, libqt5sql5, libqt5qml5, libcap2-bin, sqlite3, lsof, curl
Homepage: http://www.dresden-elektronik.de
Download-Size: 6,399 kB
APT-Manual-Installed: yes
APT-Sources: http://phoscon.de/apt/deconz bullseye/main arm64 Packages
Description: A generic ZigBee monitoring and control tool
  The deCONZ application allows to monitor and control arbitrary ZigBee PRO based devices.

In the Telegram channel I see notification stopped at 11:33PM 14th of Jul.
https://nextcloud.andres.one/s/mgCA8zxtMCq2SgL (Picture)
link to the log file https://nextcloud.andres.one/s/CeemYpy6YCsBNZ3 (log file)
Log file shows Problems here

2022-07-14 05:13:34.928 [DEBUG] [internal.handler.DeconzBridgeHandler] - Get full state failed
	at org.openhab.binding.deconz.internal.netutils.AsyncHttpClient$1.onComplete(AsyncHttpClient.java:109) [bundleFile:?]

at

 2022-07-15 10:25:16.415 [DEBUG] [internal.handler.DeconzBridgeHandler] - Start initializing bridge deconz:deconz:a3e5e5988e

I pressed pause on the deconz thing and pressed play again. deconz did reinitialize and the event propagation started working again.

Possible Solution

no idea.

Steps to Reproduce (for Bugs)

since the Problem is intermittent I dont know how to willing force the problem. For me it happens usually several times a week if I do not restart the openhab instance. I can pickup a change to try with a code fix or catch patch.

Context

I want notifications on Telegram reliable if a Door or Window in my House is opened or closed.

Your Environment

• Version used: dockerhub image openhab/openhab:3.3.0
• Operating System and version ubuntu server 22.04

[msandres13]

2022_6_31_10_21_no_deconz_events.tar.gz
2022_6_31_10_21_no_deconz_events_recovery.tar.gz
Data from dead event handling, occurrence, last event seen on 30th of July 11:54am
First test switch event seen again after pausing deconz plugin and pressed play again. 31st of July 8:23am

[msandres13]

Maybe this is related to #9517
I recognized that the server which run openhab does not use ntp and does not run in the same TZ.
I corrected that. Lets see if the problem reoccurs.

[Owlbertz]

I am encountering a similar issue with my sensors. This occurs for contact sensors (openclose), motion sensors (of various vendors) and remotes.
Toggling switches/light via the Deconz bridge works well, but openHAB stops to receive updates from the sensors after a while. Restarting openHAB solves this issue for some (varying) time.

[msandres13]

@Owlbertz can you try the nexttime to pause and start again the deconz thing? That always fixes the problem in my case.

[msandres13]

Today it failed again after a few hours. I see this error message. Looks like the channel is not restarted after that error.

`2022-08-05 11:44:36.750 [TRACE] [internal.handler.DeconzBridgeHandler] - deconz:deconz:a3e5e5988e starts refreshing the fullStateCache
2022-08-05 11:44:36.753 [DEBUG] [internal.handler.DeconzBridgeHandler] - Get full state failed
java.util.concurrent.CompletionException: java.io.EOFException: HttpConnectionOverHTTP@1551cb03::SocketChannelEndPoint@30926e0b{l=/172.31.0.4:50504,r=/192.168.2.59:9080,ISHUT,fill=-,flush=-,to=1/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@1551cb03(l:/172.31.0.4:50504 <-> r:/192.168.2.59:9080,closed=false)=>HttpChannelOverHTTP@4e2c480(exchange=HttpExchange@d33cb4{req=HttpRequest[GET /api/0F4E0083FE HTTP/1.1]@1b41f67e[TERMINATED/null] res=HttpResponse[null 0 null]@3880212b[PENDING/null]})[send=HttpSenderOverHTTP@2a54247f(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@337b8b1d{s=START}],recv=HttpReceiverOverHTTP@279d790a(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]]
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346) ~[?:?]
	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:632) ~[?:?]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) [?:?]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088) [?:?]
	at org.openhab.binding.deconz.internal.netutils.AsyncHttpClient$1.onComplete(AsyncHttpClient.java:109) [bundleFile:?]
	at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:218) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:210) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:481) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:461) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.client.HttpReceiver.abort(HttpReceiver.java:557) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.client.HttpReceiver.responseFailure(HttpReceiver.java:453) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.failAndClose(HttpReceiverOverHTTP.java:413) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.earlyEOF(HttpReceiverOverHTTP.java:385) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1620) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.shutdown(HttpReceiverOverHTTP.java:269) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:185) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:80) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:131) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:172) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [bundleFile:9.4.46.v20220331]
	at java.lang.Thread.run(Thread.java:829) [?:?]`

[msandres13]

openhab.log
events.log
Last successful sensor update was on 11:33

[msandres13]

Found a workaround to make deconz reliably work. I wrote a script which restarts the deconz plugin when the error message shows up in the openhab.log. You need to start it with screen or better with systemd to it always is running.

#!/usr/bin/env bash
set -x
set -e
export COMPOSE_INTERACTIVE_NO_CLI=1
while :
  do read line
     echo "==> found error pattern ${line}"
     docker-compose exec -T openhab /openhab/runtime/bin/client -p habopen bundle:restart org.openhab.binding.deconz
done < <(tail -F /srv/openhab3/openhab_userdata/logs/openhab.log | grep --line-buffered -F "Get full state failed")

Since a plugin restart with every "Get full state failed" message fixes the problem, we need to understand what needs to be done in the code where the log is written in order to recover the error.
I am not familiar with the APIs used here so it would be great if somebody could propose a fix.

[msandres13]

            } else if (t instanceof SocketTimeoutException || t instanceof TimeoutException
                    || t instanceof CompletionException) {
                logger.debug("Get full state failed", t);
            } else {

So instead of just writing a log the bridge object probably needs an reset