HMIP-WTH-2 - nach firmware-update auf 2.6.1 viel mehr notifys und volle Logs

Begonnen von thomas.z, 01 März 2020, 13:06:25

Vorheriges Thema - Nächstes Thema

thomas.z

Moin,

der Update der WTH-2 hat das Problem nicht verursacht. Ich hatte im Eifer nicht bedacht, dass ich noch eine HeatingGroup mit einem HMIP-WTH-B Thermostaten habe. Dieser hat kein Update bekommen. Aber auch in dieser Gruppe war und ist das Problem vorhanden.

Gruß
Thomas

Moin Allerseits,
seit kurzem automatisiere ich mein Heim, genau gesagt zunächst die Steuerung der Raumheizung. Dazu habe ich 5 Räume nach und nach mit HMIP-Komponenten versehen. Mein Ziel ist, die Heizung nach Bedarf automatisch zu schalten. In FHEM logge ich die 5. Räume mit, um Plots zum Verlauf von Soll- und Ist-Temperatur, TH-Position und Feuchte zu erhalten.

Das hat bis gestern zum Update der HMIP-WTH-2 von 2.0.2 auf 2.6.0 gut funktioniert. Nach dem update reagierte die debmatic zunächst nicht mehr (webui). Es gab viele Java-Fehlermeldungen. Ich habe dann die aktuelle debmatic Version installiert (apt upgrade). Zunächst hakte es immer noch. Nach reboot und entfernen der Batterien aus den WTH schien alles wieder gut zu funktionieren.

Heute früh zeigten die Temperatur-Plots jedoch seltsam gezackte Verläufe. Die Kontrolle der Logs ergab, dass nun viel mehr Daten gelogged wurden, die z. T. technisch sinnlos (Temperaturänderungen um 0.2° in 10s) erscheinen.

Die FileLogs basieren nicht auf Readings der WTH, sondern des je Raum definierten virtuellen Gerätes.

Beispiel Log vorher:

2020-02-28_12:40:27 wz_hzg 1.SET_POINT_TEMPERATURE: 19.0
2020-02-28_12:40:27 wz_hzg 1.HUMIDITY: 41
2020-02-28_12:40:28 wz_hzg 1.ACTUAL_TEMPERATURE: 19.5
2020-02-28_13:30:22 wz_hzg 1.SET_POINT_TEMPERATURE: 19.0
2020-02-28_13:30:22 wz_hzg 1.LEVEL: 0.0
2020-02-28_13:30:23 wz_hzg 1.ACTUAL_TEMPERATURE: 19.5
2020-02-28_13:32:34 wz_hzg 1.SET_POINT_TEMPERATURE: 19.0
2020-02-28_13:32:35 wz_hzg 1.LEVEL: 0.0
2020-02-28_13:32:35 wz_hzg 1.ACTUAL_TEMPERATURE: 19.5
2020-02-28_13:36:21 wz_hzg 1.SET_POINT_TEMPERATURE: 19.0
2020-02-28_13:36:21 wz_hzg 1.HUMIDITY: 41
2020-02-28_13:36:21 wz_hzg 1.ACTUAL_TEMPERATURE: 19.5
2020-02-28_14:22:57 wz_hzg 1.SET_POINT_TEMPERATURE: 19.0
2020-02-28_14:22:57 wz_hzg 1.LEVEL: 0.0
2020-02-28_14:22:57 wz_hzg 1.ACTUAL_TEMPERATURE: 19.5
2020-02-28_14:25:43 wz_hzg 1.SET_POINT_TEMPERATURE: 19.0
2020-02-28_14:25:43 wz_hzg 1.LEVEL: 0.0
2020-02-28_14:25:44 wz_hzg 1.ACTUAL_TEMPERATURE: 19.5
2020-02-28_14:29:22 wz_hzg 1.SET_POINT_TEMPERATURE: 19.0
2020-02-28_14:29:22 wz_hzg 1.HUMIDITY: 41
2020-02-28_14:29:23 wz_hzg 1.ACTUAL_TEMPERATURE: 19.6
2020-02-28_15:00:03 wz_hzg 1.SET_POINT_TEMPERATURE: 21.0
2020-02-28_15:00:03 wz_hzg 1.HUMIDITY: 41
2020-02-28_15:00:03 wz_hzg 1.ACTUAL_TEMPERATURE: 19.5


Beispiel Log nachher:

2020-03-01_05:13:44 bo_hzg 1.ACTUAL_TEMPERATURE: 20.1
2020-03-01_05:31:28 bo_hzg 1.SET_POINT_TEMPERATURE: 19.0
2020-03-01_05:31:28 bo_hzg 1.ACTUAL_TEMPERATURE: 20.1
2020-03-01_05:31:28 bo_hzg 1.HUMIDITY: 50
2020-03-01_05:31:28 bo_hzg 1.SET_POINT_TEMPERATURE: 19.0
2020-03-01_05:31:28 bo_hzg 1.HUMIDITY: 50
2020-03-01_05:31:29 bo_hzg 1.ACTUAL_TEMPERATURE: 20.1
2020-03-01_05:51:33 bo_hzg 1.SET_POINT_TEMPERATURE: 19.0
2020-03-01_05:51:33 bo_hzg 1.LEVEL: 0.0
2020-03-01_05:51:33 bo_hzg 1.ACTUAL_TEMPERATURE: 20.1
2020-03-01_05:51:52 bo_hzg 1.SET_POINT_TEMPERATURE: 19.0
2020-03-01_05:51:52 bo_hzg 1.ACTUAL_TEMPERATURE: 19.9
2020-03-01_05:51:52 bo_hzg 1.HUMIDITY: 50
2020-03-01_05:51:53 bo_hzg 1.SET_POINT_TEMPERATURE: 19.0
2020-03-01_05:51:53 bo_hzg 1.HUMIDITY: 50
2020-03-01_05:51:53 bo_hzg 1.ACTUAL_TEMPERATURE: 19.9

Die Log-Dateien wachsen nun sehr schnell an, die plots sehen seltsam aus (siehe Anhang .png).
Heute habe ich FHEM neugestartet (systemctl restart), danach kamen wieder Fehlermeldungen im journal.

Mar 01 11:17:01 tinkerboard CRON[22545]: pam_unix(cron:session): session closed for user root
Mar 01 11:25:01 tinkerboard CRON[22789]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 01 11:25:01 tinkerboard CRON[22790]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Mar 01 11:25:01 tinkerboard CRON[22789]: pam_unix(cron:session): session closed for user root
Mar 01 11:30:01 tinkerboard CRON[22973]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 01 11:30:01 tinkerboard CRON[22974]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Mar 01 11:30:01 tinkerboard CRON[22973]: pam_unix(cron:session): session closed for user root
Mar 01 11:35:01 tinkerboard CRON[23178]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 01 11:35:01 tinkerboard CRON[23179]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Mar 01 11:35:01 tinkerboard CRON[23178]: pam_unix(cron:session): session closed for user root
Mar 01 11:43:50 tinkerboard systemd[1]: Stopping FHEM Home Automation...
Mar 01 11:43:59 tinkerboard systemd[1]: fhem.service: Main process exited, code=exited, status=3/NOTIMPLEMENTED
Mar 01 11:43:59 tinkerboard systemd[1]: fhem.service: Failed with result 'exit-code'.
Mar 01 11:43:59 tinkerboard systemd[1]: Stopped FHEM Home Automation.
Mar 01 11:43:59 tinkerboard systemd[1]: Starting FHEM Home Automation...
Mar 01 11:44:00 tinkerboard systemd[1]: Started FHEM Home Automation.
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]: Mar 01, 2020 11:44:14 AM io.vertx.core.eventbus.impl.HandlerRegistration
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]: SEVERE: Failed to handleMessage
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]: de.eq3.cbcs.legacy.communication.rpc.RpcRemoteException: Error requesting method setReadyConfig: Method lookup error: No method 'Unknown method: setReadyConfig' on server Code: 200
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at de.eq3.cbcs.legacy.communication.rpc.internal.format.xml.XmlRpcParser.parseMethodResponse(XmlRpcParser.java:156)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at de.eq3.cbcs.legacy.communication.rpc.internal.format.xml.XmlRequestResponseProcessor.parseResponse(XmlRequestResponseProcessor.java:171)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at de.eq3.cbcs.legacy.communication.rpc.internal.transport.http.HttpTransport.sendRequest(HttpTransport.java:107)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at de.eq3.cbcs.legacy.communication.rpc.internal.rpc.RpcClient.sendRequest(RpcClient.java:94)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at de.eq3.cbcs.legacy.communication.rpc.internal.rpc.RpcClient.invoke(RpcClient.java:82)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at com.sun.proxy.$Proxy26.setReadyConfig(Unknown Source)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at de.eq3.ccu.virtualdevice.service.internal.rega.BackendUpdateDevicesCommand.updateDevicesForClient(BackendUpdateDevicesCommand.java:121)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at de.eq3.ccu.virtualdevice.service.internal.rega.BackendUpdateDevicesCommand.run(BackendUpdateDevicesCommand.java:29)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at de.eq3.ccu.virtualdevice.service.internal.rega.BackendWorker.handle(BackendWorker.java:27)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at de.eq3.ccu.virtualdevice.service.internal.rega.BackendWorker.handle(BackendWorker.java:11)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at io.vertx.core.eventbus.impl.HandlerRegistration.deliver(HandlerRegistration.java:212)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at io.vertx.core.eventbus.impl.HandlerRegistration.handle(HandlerRegistration.java:191)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at io.vertx.core.eventbus.impl.EventBusImpl.lambda$deliverToHandler$3(EventBusImpl.java:505)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at io.vertx.core.impl.ContextImpl.lambda$wrapTask$2(ContextImpl.java:337)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at io.vertx.core.impl.TaskQueue.lambda$new$0(TaskQueue.java:60)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at java.base/java.lang.Thread.run(Thread.java:834)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]: Mar 01, 2020 11:44:14 AM io.vertx.core.impl.ContextImpl
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]: SEVERE: Unhandled exception
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]: de.eq3.cbcs.legacy.communication.rpc.RpcRemoteException: Error requesting method setReadyConfig: Method lookup error: No method 'Unknown method: setReadyConfig' on server Code: 200
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at de.eq3.cbcs.legacy.communication.rpc.internal.format.xml.XmlRpcParser.parseMethodResponse(XmlRpcParser.java:156)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at de.eq3.cbcs.legacy.communication.rpc.internal.format.xml.XmlRequestResponseProcessor.parseResponse(XmlRequestResponseProcessor.java:171)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at de.eq3.cbcs.legacy.communication.rpc.internal.transport.http.HttpTransport.sendRequest(HttpTransport.java:107)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at de.eq3.cbcs.legacy.communication.rpc.internal.rpc.RpcClient.sendRequest(RpcClient.java:94)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at de.eq3.cbcs.legacy.communication.rpc.internal.rpc.RpcClient.invoke(RpcClient.java:82)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at com.sun.proxy.$Proxy26.setReadyConfig(Unknown Source)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at de.eq3.ccu.virtualdevice.service.internal.rega.BackendUpdateDevicesCommand.updateDevicesForClient(BackendUpdateDevicesCommand.java:121)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at de.eq3.ccu.virtualdevice.service.internal.rega.BackendUpdateDevicesCommand.run(BackendUpdateDevicesCommand.java:29)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at de.eq3.ccu.virtualdevice.service.internal.rega.BackendWorker.handle(BackendWorker.java:27)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at de.eq3.ccu.virtualdevice.service.internal.rega.BackendWorker.handle(BackendWorker.java:11)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at io.vertx.core.eventbus.impl.HandlerRegistration.deliver(HandlerRegistration.java:212)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at io.vertx.core.eventbus.impl.HandlerRegistration.handle(HandlerRegistration.java:191)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at io.vertx.core.eventbus.impl.EventBusImpl.lambda$deliverToHandler$3(EventBusImpl.java:505)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at io.vertx.core.impl.ContextImpl.lambda$wrapTask$2(ContextImpl.java:337)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at io.vertx.core.impl.TaskQueue.lambda$new$0(TaskQueue.java:60)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Mar 01 11:44:14 tinkerboard start_hmserver.sh[1504]:         at java.base/java.lang.Thread.run(Thread.java:834)
Mar 01 11:44:17 tinkerboard start_hmserver.sh[1504]: Mar 01, 2020 11:44:17 AM io.vertx.core.impl.BlockedThreadChecker
Mar 01 11:44:17 tinkerboard start_hmserver.sh[1504]: WARNING: Thread Thread[vert.x-eventloop-thread-4,5,main] has been blocked for 2804 ms, time limit is 2000
Mar 01 11:44:18 tinkerboard start_hmserver.sh[1504]: Mar 01, 2020 11:44:18 AM io.vertx.core.impl.BlockedThreadChecker
Mar 01 11:44:18 tinkerboard start_hmserver.sh[1504]: WARNING: Thread Thread[vert.x-eventloop-thread-4,5,main] has been blocked for 3804 ms, time limit is 2000
Mar 01 11:44:19 tinkerboard start_hmserver.sh[1504]: Mar 01, 2020 11:44:19 AM io.vertx.core.impl.BlockedThreadChecker
Mar 01 11:44:19 tinkerboard start_hmserver.sh[1504]: WARNING: Thread Thread[vert.x-eventloop-thread-4,5,main] has been blocked for 4804 ms, time limit is 2000
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]: Mar 01, 2020 11:44:20 AM io.vertx.core.impl.BlockedThreadChecker
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]: WARNING: Thread Thread[vert.x-eventloop-thread-4,5,main] has been blocked for 5804 ms, time limit is 2000
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]: io.vertx.core.VertxException: Thread blocked
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.misc.Unsafe.park(Native Method)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:458)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega.registerCallback(VirtualDeviceHandlerRega.java:99)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.lang.reflect.Method.invoke(Method.java:566)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.cbcs.legacy.communication.rpc.internal.rpc.AnnotationAwareRpcHandler.execute(AnnotationAwareRpcHandler.java:80)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.ccu.server.internal.RpcMessageHandler.handle(RpcMessageHandler.java:70)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.ccu.server.internal.RpcMessageHandler.handle(RpcMessageHandler.java:24)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.HandlerRegistration.deliver(HandlerRegistration.java:212)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.HandlerRegistration.handle(HandlerRegistration.java:191)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.EventBusImpl.lambda$deliverToHandler$3(EventBusImpl.java:505)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.EventBusImpl$$Lambda$107/0xa6edb828.handle(Unknown Source)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.impl.ContextImpl.lambda$wrapTask$2(ContextImpl.java:337)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.impl.ContextImpl$$Lambda$90/0xa918ee28.run(Unknown Source)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:403)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:445)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
Mar 01 11:44:20 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.lang.Thread.run(Thread.java:834)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]: Mar 01, 2020 11:44:21 AM io.vertx.core.impl.BlockedThreadChecker
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]: WARNING: Thread Thread[vert.x-eventloop-thread-4,5,main] has been blocked for 6804 ms, time limit is 2000
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]: io.vertx.core.VertxException: Thread blocked
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.misc.Unsafe.park(Native Method)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:458)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega.registerCallback(VirtualDeviceHandlerRega.java:99)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.lang.reflect.Method.invoke(Method.java:566)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.cbcs.legacy.communication.rpc.internal.rpc.AnnotationAwareRpcHandler.execute(AnnotationAwareRpcHandler.java:80)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.ccu.server.internal.RpcMessageHandler.handle(RpcMessageHandler.java:70)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.ccu.server.internal.RpcMessageHandler.handle(RpcMessageHandler.java:24)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.HandlerRegistration.deliver(HandlerRegistration.java:212)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.HandlerRegistration.handle(HandlerRegistration.java:191)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.EventBusImpl.lambda$deliverToHandler$3(EventBusImpl.java:505)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.EventBusImpl$$Lambda$107/0xa6edb828.handle(Unknown Source)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.impl.ContextImpl.lambda$wrapTask$2(ContextImpl.java:337)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.impl.ContextImpl$$Lambda$90/0xa918ee28.run(Unknown Source)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:403)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:445)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
Mar 01 11:44:21 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.lang.Thread.run(Thread.java:834)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]: Mar 01, 2020 11:44:22 AM io.vertx.core.impl.BlockedThreadChecker
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]: WARNING: Thread Thread[vert.x-eventloop-thread-4,5,main] has been blocked for 7804 ms, time limit is 2000
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]: io.vertx.core.VertxException: Thread blocked
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.misc.Unsafe.park(Native Method)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:458)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega.registerCallback(VirtualDeviceHandlerRega.java:99)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.lang.reflect.Method.invoke(Method.java:566)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.cbcs.legacy.communication.rpc.internal.rpc.AnnotationAwareRpcHandler.execute(AnnotationAwareRpcHandler.java:80)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.ccu.server.internal.RpcMessageHandler.handle(RpcMessageHandler.java:70)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.ccu.server.internal.RpcMessageHandler.handle(RpcMessageHandler.java:24)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.HandlerRegistration.deliver(HandlerRegistration.java:212)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.HandlerRegistration.handle(HandlerRegistration.java:191)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.EventBusImpl.lambda$deliverToHandler$3(EventBusImpl.java:505)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.EventBusImpl$$Lambda$107/0xa6edb828.handle(Unknown Source)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.impl.ContextImpl.lambda$wrapTask$2(ContextImpl.java:337)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.impl.ContextImpl$$Lambda$90/0xa918ee28.run(Unknown Source)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:403)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:445)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
Mar 01 11:44:22 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.lang.Thread.run(Thread.java:834)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]: Mar 01, 2020 11:44:23 AM io.vertx.core.impl.BlockedThreadChecker
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]: WARNING: Thread Thread[vert.x-eventloop-thread-4,5,main] has been blocked for 8804 ms, time limit is 2000
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]: io.vertx.core.VertxException: Thread blocked
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.misc.Unsafe.park(Native Method)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:458)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega.registerCallback(VirtualDeviceHandlerRega.java:99)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.lang.reflect.Method.invoke(Method.java:566)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.cbcs.legacy.communication.rpc.internal.rpc.AnnotationAwareRpcHandler.execute(AnnotationAwareRpcHandler.java:80)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.ccu.server.internal.RpcMessageHandler.handle(RpcMessageHandler.java:70)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.ccu.server.internal.RpcMessageHandler.handle(RpcMessageHandler.java:24)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.HandlerRegistration.deliver(HandlerRegistration.java:212)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.HandlerRegistration.handle(HandlerRegistration.java:191)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.EventBusImpl.lambda$deliverToHandler$3(EventBusImpl.java:505)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.EventBusImpl$$Lambda$107/0xa6edb828.handle(Unknown Source)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.impl.ContextImpl.lambda$wrapTask$2(ContextImpl.java:337)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.impl.ContextImpl$$Lambda$90/0xa918ee28.run(Unknown Source)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:403)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:445)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
Mar 01 11:44:23 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.lang.Thread.run(Thread.java:834)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]: Mar 01, 2020 11:44:24 AM io.vertx.core.impl.BlockedThreadChecker
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]: WARNING: Thread Thread[vert.x-eventloop-thread-4,5,main] has been blocked for 9804 ms, time limit is 2000
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]: io.vertx.core.VertxException: Thread blocked
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.misc.Unsafe.park(Native Method)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:458)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega.registerCallback(VirtualDeviceHandlerRega.java:99)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.lang.reflect.Method.invoke(Method.java:566)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.cbcs.legacy.communication.rpc.internal.rpc.AnnotationAwareRpcHandler.execute(AnnotationAwareRpcHandler.java:80)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.ccu.server.internal.RpcMessageHandler.handle(RpcMessageHandler.java:70)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at app//de.eq3.ccu.server.internal.RpcMessageHandler.handle(RpcMessageHandler.java:24)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.HandlerRegistration.deliver(HandlerRegistration.java:212)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.HandlerRegistration.handle(HandlerRegistration.java:191)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.EventBusImpl.lambda$deliverToHandler$3(EventBusImpl.java:505)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.eventbus.impl.EventBusImpl$$Lambda$107/0xa6edb828.handle(Unknown Source)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.impl.ContextImpl.lambda$wrapTask$2(ContextImpl.java:337)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at app//io.vertx.core.impl.ContextImpl$$Lambda$90/0xa918ee28.run(Unknown Source)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:403)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:445)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at app//io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
Mar 01 11:44:24 tinkerboard start_hmserver.sh[1504]:         at java.base@11.0.6/java.lang.Thread.run(Thread.java:834)
Mar 01 11:45:01 tinkerboard CRON[23580]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 01 11:45:01 tinkerboard CRON[23581]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 01 11:45:01 tinkerboard CRON[23582]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Mar 01 11:45:01 tinkerboard CRON[23584]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Mar 01 11:45:01 tinkerboard CRON[23581]: pam_unix(cron:session): session closed for user root
Mar 01 11:45:01 tinkerboard CRON[23580]: pam_unix(cron:session): session closed for user root


Meine primäre Vermutung für die Ursache ist eine "fehlerhafte firmware", aber da so viele Komponenten mitspielen, hat vielleicht noch jemand eine Idee, was das verursachen könnte und was ich prüfen sollte.
Bedarf liefere ich gerne weitere Informationen nach. Als Anfänger fällt mir die Auswahl benötigter Informationen noch etwas schwer ...

Danke!

Gruß
Thomas
--
tinkerboard s, RPI-RF-MOD, debmatic 3.61.7.90, fhem 5.9.21052, HMIP-WTH-x, HMIP-eTRV-x, HMIP-BSM, Delock 11826, RPI 3b mit ebus Adapter 2.2 RPI, SMA-EM, Compleo eBox-Smart