Dispatching event takes more than 5000ms

Hi!

Ich habe homegear mittels nightly Installscript auf einem PI2 installiert.
Vorher lief es auf dem openhab Image mit.

Seit der Umstellung (ich habe nur die Datenbank kopiert) kommt es sporadisch zu Kommunikationsfehlern zu den Homematic Rolladenaktoren. Weiterhin ist die events.log voll von “Thing updated” (siehe unten). Der Rolladen ist auch nicht runter gefahren.

Eine Idee woran das liegt?

Danke und Gruß

openhab.log

2017-12-02 17:08:05.039 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.CommunicationManager@1af1864' takes more than 5000ms.
2017-12-02 17:08:05.149 [ERROR] [ematic.handler.HomematicThingHandler] - -100 No answer from device. (sending setValue()
OEQ0361541:1
LEVEL
0.0
)
java.io.IOException: -100 No answer from device. (sending setValue()
OEQ0361541:1
LEVEL
0.0
)
	at org.openhab.binding.homematic.internal.communicator.parser.RpcResponseParser.parse(RpcResponseParser.java:50) ~[?:?]
	at org.openhab.binding.homematic.internal.communicator.client.BinRpcClient.sendMessage(BinRpcClient.java:90) ~[?:?]
	at org.openhab.binding.homematic.internal.communicator.client.BinRpcClient.sendMessage(BinRpcClient.java:102) ~[?:?]
	at org.openhab.binding.homematic.internal.communicator.client.BinRpcClient.sendMessage(BinRpcClient.java:78) ~[?:?]
	at org.openhab.binding.homematic.internal.communicator.client.RpcClient.setDatapointValue(RpcClient.java:282) ~[?:?]
	at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway$1.execute(AbstractHomematicGateway.java:602) ~[?:?]
	at org.openhab.binding.homematic.internal.misc.DelayedExecuter.start(DelayedExecuter.java:61) ~[?:?]
	at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.sendDatapoint(AbstractHomematicGateway.java:581) ~[?:?]
	at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.sendDatapoint(AbstractHomematicGateway.java:560) ~[?:?]
	at org.openhab.binding.homematic.handler.HomematicThingHandler.handleCommand(HomematicThingHandler.java:184) ~[?:?]
	at org.eclipse.smarthome.core.thing.internal.profiles.DefaultMasterProfile$1.call(DefaultMasterProfile.java:52) ~[?:?]
	at org.eclipse.smarthome.core.thing.internal.profiles.DefaultMasterProfile$1.call(DefaultMasterProfile.java:1) ~[?:?]
	at org.eclipse.smarthome.core.common.SafeMethodCaller.executeDirectly(SafeMethodCaller.java:218) ~[?:?]
	at org.eclipse.smarthome.core.common.SafeMethodCaller.callAsynchronous(SafeMethodCaller.java:189) ~[?:?]
	at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:83) ~[?:?]
	at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:67) ~[?:?]
	at org.eclipse.smarthome.core.thing.internal.profiles.DefaultMasterProfile.onCommand(DefaultMasterProfile.java:49) ~[?:?]
	at org.eclipse.smarthome.core.thing.internal.CommunicationManager.lambda$2(CommunicationManager.java:177) ~[?:?]
	at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184) [?:?]
	at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175) [?:?]
	at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175) [?:?]
	at java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948) [?:?]
	at java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:580) [?:?]
	at java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:270) [?:?]
	at java.util.concurrent.ConcurrentHashMap$ValueSpliterator.forEachRemaining(ConcurrentHashMap.java:3566) [?:?]
	at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481) [?:?]
	at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471) [?:?]
	at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151) [?:?]
	at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174) [?:?]
	at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) [?:?]
	at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:418) [?:?]
	at org.eclipse.smarthome.core.thing.internal.CommunicationManager.receiveCommand(CommunicationManager.java:172) [105:org.eclipse.smarthome.core.thing:0.9.0.201709121704]
	at org.eclipse.smarthome.core.thing.internal.CommunicationManager.receive(CommunicationManager.java:91) [105:org.eclipse.smarthome.core.thing:0.9.0.201709121704]
	at org.eclipse.smarthome.core.internal.events.OSGiEventManager$1.call(OSGiEventManager.java:193) [98:org.eclipse.smarthome.core:0.9.0.201709121704]
	at org.eclipse.smarthome.core.internal.events.OSGiEventManager$1.call(OSGiEventManager.java:1) [98:org.eclipse.smarthome.core:0.9.0.201709121704]
	at org.eclipse.smarthome.core.common.SafeMethodCaller$CallableWrapper.call(SafeMethodCaller.java:181) [98:org.eclipse.smarthome.core:0.9.0.201709121704]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]

events.log

2017-12-02 17:08:08.869 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-HM-PBI-4-FM:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:LEQ0252832' has been updated.
2017-12-02 17:08:09.134 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-HM-LC-Bl1PBU-FM:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:OEQ0361541' has been updated.
2017-12-02 17:08:09.362 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD00030D41' has been updated.
2017-12-02 17:08:09.612 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD00030D42' has been updated.
2017-12-02 17:08:09.862 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD00030D43' has been updated.
2017-12-02 17:08:10.097 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD000493E1' has been updated.
2017-12-02 17:08:10.352 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD000493E2' has been updated.
2017-12-02 17:08:10.602 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD000493E3' has been updated.
2017-12-02 17:08:10.837 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD00061A81' has been updated.
2017-12-02 17:08:11.071 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD00061A82' has been updated.
2017-12-02 17:08:11.313 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD000F4240' has been updated.
2017-12-02 17:08:11.548 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD001E8480' has been updated.
2017-12-02 17:08:11.798 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD002DC6C0' has been updated.
2017-12-02 17:08:14.353 [vent.ItemStateChangedEvent] - Haushalt_Current changed from 665.2 to 962.3000000000001
2017-12-02 17:08:14.369 [vent.ItemStateChangedEvent] - Haushalt_Total changed from 11567.848 to 11567.850600000002
2017-12-02 17:08:14.962 [hingStatusInfoChangedEvent] - 'homematic:HG-HM-LC-Bl1PBU-FM:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:OEQ0361541' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
2017-12-02 17:08:17.024 [hingStatusInfoChangedEvent] - 'homematic:HG-HM-LC-Bl1PBU-FM:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:OEQ0361541' changed from OFFLINE (COMMUNICATION_ERROR) to ONLINE
2017-12-02 17:08:17.040 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-HM-LC-Bl1PBU-FM:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:OEQ0361541' has been updated.
2017-12-02 17:08:21.361 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-HM-RC-8:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:LEQ0790415' has been updated.
2017-12-02 17:08:21.689 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-HM-ES-PMSw1-Pl:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:LEQ1344572' has been updated.
2017-12-02 17:08:21.939 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-HM-LC-Bl1PBU-FM:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:OEQ0041389' has been updated.
2017-12-02 17:08:22.369 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-HM-LC-Bl1PBU-FM:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:OEQ0034839' has been updated.
2017-12-02 17:08:22.369 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-HM-LC-Bl1PBU-FM:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:OEQ0041313' has been updated.
2017-12-02 17:08:22.681 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-HM-PBI-4-FM:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:LEQ0252832' has been updated.
2017-12-02 17:08:22.963 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-HM-LC-Bl1PBU-FM:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:OEQ0361541' has been updated.
2017-12-02 17:08:23.197 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD00030D41' has been updated.
2017-12-02 17:08:23.440 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD00030D42' has been updated.
2017-12-02 17:08:23.690 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD00030D43' has been updated.
2017-12-02 17:08:23.925 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD000493E1' has been updated.
2017-12-02 17:08:24.174 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD000493E2' has been updated.
2017-12-02 17:08:24.582 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD000493E3' has been updated.
2017-12-02 17:08:24.895 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD00061A81' has been updated.
2017-12-02 17:08:24.973 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD00061A82' has been updated.
2017-12-02 17:08:25.176 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD000F4240' has been updated.
2017-12-02 17:08:25.353 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD001E8480' has been updated.
2017-12-02 17:08:25.384 [me.event.ThingUpdatedEvent] - Thing 'homematic:HG-IT-Switch:51D140F6-BDA2-EA3E-ACE3-97D6CBC77848:ITD002DC6C0' has been updated.

homegear.log

12/02/17 17:08:02.197 RPC Server (Port 2001): Info: Client number 9010 is calling RPC method: setValue (2) Parameters:
(String) OEQ0361541:1
(String) LEVEL
(Float) 0
12/02/17 17:08:02.202 HM-LGW "My-HM-LGW": Info: Sending (My-HM-LGW): 0C0BA011FDA0215939C4020100
12/02/17 17:08:03.128 HM-LGW "My-HM-LGW": Info: No answer to packet 0C0BA011FDA0215939C4020100
12/02/17 17:08:04.761 RPC Server (Port 2001): Info: Connection from ::ffff:192.168.178.250:50907 accepted. Client number: 9013
12/02/17 17:08:04.762 RPC Server (Port 2001): Info: RPC server client id for client number 9013 is: 4341
12/02/17 17:08:04.763 RPC Server (Port 2001): Info: Client number 9013 is calling RPC method: setValue (2) Parameters:
(String) OEQ0361541:1
(String) LEVEL
(Float) 0

Hallo @s4ndst0rm,

das Gateway scheint noch zu antworten, es ist also kein LAN-Problem. Ob das Paket vom LAN-Gateway tatsächlich gesendet wird, wissen wir nicht, ich gehe aber mal davon aus. Die Meldung “No answer to packet” kommt vom LAN-Gateway, d. h. es wurde keine Antwort vom Rollladenaktor empfangen. Da dieser auch nicht geschaltet hat, hat er die Funkpakete drei Mal nicht empfangen. Wenn du mal ins Log zu einem Zeitpunkt schaust, zu dem es klappt, wie ist der RSSI (der wird mitgeloggt)? Ich tippe auf Empfangsprobleme. Wie viele Wände sind zwischen LAN-Gateway und Aktor? Sind Metallstrukturen (z. B. Treppengeländer) dazwischen?

Viele Grüße

Sathya