"100 No answer from device" - Befehle werden verzögert umgesetzt

Hallo zusammen,

mein erster Post, seid gnäidg :slight_smile:

ich verwende einen raspberry mit openhabian und habe darüber auch homegear installiert. Zusammen mit hmland und dem Homematic-USB-Stick verwende ich einige Komponenten bisher ohne Probleme. Nun habe ich Anfang der Woche ein Update über openhabian angestoßen, dabei wurde auch homegear aktualisiert. Seit dem reagieren alle Homematic-Komponenten teilweise stark zeitverzögert. Auffällig für mich sind dann diese initialen Fehler beim ersten Befehl an eine HM-Komponente (100 No answer from Device).

im en-Forum hatte scheinbar jemand ein ähnliches Problem, leider ist die dort genannte Lösung für mich nicht offensichtlich.

Danke und Grüße
joe2k

openhab2: events.log & openhab.log

==> /var/log/openhab2/openhab.log <==
2018-11-08 20:11:54.172 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ1797461:0#RSSI'    
2018-11-08 20:11:54.179 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ1797461:0#SIGNAL_STRENGTH'

==> /var/log/openhab2/events.log <==
2018-11-08 20:12:04.438 [ome.event.ItemCommandEvent] - Item 'kg_licht_flur' received command ON
2018-11-08 20:12:04.454 [vent.ItemStateChangedEvent] - kg_licht_flur changed from OFF to ON

==> /var/log/openhab2/openhab.log <==
2018-11-08 20:12:09.571 [ERROR] [ematic.handler.HomematicThingHandler] - -100 No answer from device. (sending setValue()
MEQ1560788:1
STATE
true
)
java.io.IOException: -100 No answer from device. (sending setValue()
MEQ1560788:1
STATE
true
)
at org.openhab.binding.homematic.internal.communicator.parser.RpcResponseParser.parse(RpcResponseParser.java:47) [222:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.client.BinRpcClient.sendMessage(BinRpcClient.java:78) [222:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.client.BinRpcClient.sendMessage(BinRpcClient.java:90) [222:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.client.BinRpcClient.sendMessage(BinRpcClient.java:66) [222:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.client.RpcClient.setDatapointValue(RpcClient.java:298) [222:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway$1.execute(AbstractHomematicGateway.java:672) [222:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.misc.DelayedExecuter.start(DelayedExecuter.java:61) [222:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.sendDatapoint(AbstractHomematicGateway.java:651) [222:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.sendDatapoint(AbstractHomematicGateway.java:630) [222:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.handler.HomematicThingHandler.handleCommand(HomematicThingHandler.java:276) [222:org.openhab.binding.homematic:2.3.0]
at sun.reflect.GeneratedMethodAccessor132.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [102:org.eclipse.smarthome.core:0.10.0.oh230]
at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [102:org.eclipse.smarthome.core:0.10.0.oh230]
at com.sun.proxy.$Proxy141.handleCommand(Unknown Source) [222:org.openhab.binding.homematic:2.3.0]
at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:75) [109:org.eclipse.smarthome.core.thing:0.10.0.oh230]
at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [109:org.eclipse.smarthome.core.thing:0.10.0.oh230]
at sun.reflect.GeneratedMethodAccessor131.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [102:org.eclipse.smarthome.core:0.10.0.oh230]
at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [102:org.eclipse.smarthome.core:0.10.0.oh230]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]

==> /var/log/openhab2/events.log <==
2018-11-08 20:12:13.300 [ome.event.ItemCommandEvent] - Item 'kg_licht_flur' received command OFF
2018-11-08 20:12:13.319 [vent.ItemStateChangedEvent] - kg_licht_flur changed from ON to OFF

==> /var/log/openhab2/openhab.log <==
2018-11-08 20:12:13.380 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ1560788:0#RSSI'
2018-11-08 20:12:13.386 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ1560788:0#SIGNAL_STRENGTH'

==> /var/log/openhab2/events.log <==
2018-11-08 20:12:15.473 [vent.ItemStateChangedEvent] - kg_licht_flur changed from OFF to ON
2018-11-08 20:12:15.502 [vent.ItemStateChangedEvent] - kg_licht_flur changed from ON to OFF
2018-11-08 20:12:15.961 [vent.ItemStateChangedEvent] - kg_licht_flur changed from OFF to ON
2018-11-08 20:12:16.020 [vent.ItemStateChangedEvent] - kg_licht_flur changed from ON to OFF

und homegear.log zu der Zeit:

11/08/18 20:11:25.651 HomeMatic BidCoS packet received (hmland, RSSI: -76 dBm): 121200838B5737F00001000A5F466354E35DE6
11/08/18 20:11:26.567 RPC Server (Port 2001): Info: Client number 44930 is calling RPC method: ping (2) Parameters:
(String) 8b6f5bf4
11/08/18 20:11:41.571 RPC Server (Port 2001): Info: Client number 44930 is calling RPC method: ping (2) Parameters:
(String) 8b6f5bf4
11/08/18 20:11:54.165 HomeMatic BidCoS packet received (hmland, RSSI: -64 dBm): 0D44A61043C24CFD774E06013900
11/08/18 20:11:54.166 Module HomeMatic BidCoS: Info: BRIGHTNESS on channel 1 of HomeMatic BidCoS peer 19 with serial number MEQ1797461 was set to 0x39.
11/08/18 20:11:56.575 RPC Server (Port 2001): Info: Client number 44930 is calling RPC method: ping (2) Parameters:
(String) 8b6f5bf4
11/08/18 20:12:04.446 RPC Server (Port 2001): Info: Client number 44930 is calling RPC method: setValue (2) Parameters:
(String) MEQ1560788:1
(String) STATE
(Boolean) 1
11/08/18 20:12:04.447 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "hmland": Info: Sending (hmland): 0E41A011FD774E40D9750201C80000
11/08/18 20:12:07.012 RPC Server (Port 2001): Info: Connection from ::ffff:127.0.0.1:47110 accepted. Client number: 44955
11/08/18 20:12:07.012 RPC Server (Port 2001): Info: RPC server client id for client number 44955 is: 770
11/08/18 20:12:07.013 RPC Server (Port 2001): Info: Client number 44955 is calling RPC method: setValue (2) Parameters:
(String) MEQ1560788:1
(String) STATE
(Boolean) 1
11/08/18 20:12:10.071 Module HomeMatic BidCoS: Info: Setting peer to unreachable, because the queue processing was interrupted.
11/08/18 20:12:10.071 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 16). Retrying...
11/08/18 20:12:10.171 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "hmland": Info: Sending (hmland): 0E42A011FD774E40D9750201C80000
11/08/18 20:12:11.585 RPC Server (Port 2001): Info: Client number 44955 is calling RPC method: ping (2) Parameters:
(String) 8b6f5bf4
11/08/18 20:12:13.176 Module HomeMatic BidCoS: Info: Setting peer to unreachable, because the queue processing was interrupted.
11/08/18 20:12:13.177 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 16). Retrying...
11/08/18 20:12:13.277 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "hmland": Info: Sending (hmland): 0E42A011FD774E40D9750201C80000
11/08/18 20:12:13.304 RPC Server (Port 2001): Info: Client number 44955 is calling RPC method: setValue (2) Parameters:
(String) MEQ1560788:1
(String) STATE
(Boolean) 0
11/08/18 20:12:13.372 HomeMatic BidCoS packet received (hmland, RSSI: -80 dBm): 0E41800240D975FD774E0101C80046
11/08/18 20:12:13.373 Module HomeMatic BidCoS: Info: WORKING on channel 1 of HomeMatic BidCoS peer 16 with serial number MEQ1560788 was set to 0x00.
11/08/18 20:12:13.431 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "hmland": Info: Sending (hmland): 0E43A011FD774E40D9750201000000
11/08/18 20:12:15.456 HomeMatic BidCoS packet received (hmland, RSSI: -81 dBm): 0E42800240D975FD774E0101C80050
11/08/18 20:12:15.456 Module HomeMatic BidCoS: Info: Queue 552 is empty and there are no pending queues.
11/08/18 20:12:15.457 Module HomeMatic BidCoS: Info: STATE on channel 1 of HomeMatic BidCoS peer 16 with serial number MEQ1560788 was set to 0xC8.
11/08/18 20:12:15.457 Module HomeMatic BidCoS: Info: WORKING on channel 1 of HomeMatic BidCoS peer 16 with serial number MEQ1560788 was set to 0x00.
11/08/18 20:12:15.950 HomeMatic BidCoS packet received (hmland, RSSI: -81 dBm): 0E42800240D975FD774E0101C80050
11/08/18 20:12:15.951 Module HomeMatic BidCoS: Info: STATE on channel 1 of HomeMatic BidCoS peer 16 with serial number MEQ1560788 was set to 0xC8.
11/08/18 20:12:15.951 Module HomeMatic BidCoS: Info: WORKING on channel 1 of HomeMatic BidCoS peer 16 with serial number MEQ1560788 was set to 0x00.
11/08/18 20:12:15.964 HomeMatic BidCoS packet received (hmland, RSSI: -82 dBm): 0E42800240D975FD774E0101C80050
11/08/18 20:12:15.964 Module HomeMatic BidCoS: Info: STATE on channel 1 of HomeMatic BidCoS peer 16 with serial number MEQ1560788 was set to 0xC8.
11/08/18 20:12:15.964 Module HomeMatic BidCoS: Info: WORKING on channel 1 of HomeMatic BidCoS peer 16 with serial number MEQ1560788 was set to 0x00.
11/08/18 20:12:16.008 HomeMatic BidCoS packet received (hmland, RSSI: -72 dBm): 0E43800240D975FD774E0101000050
11/08/18 20:12:16.008 Module HomeMatic BidCoS: Info: STATE on channel 1 of HomeMatic BidCoS peer 16 with serial number MEQ1560788 was set to 0x00.
11/08/18 20:12:16.008 Module HomeMatic BidCoS: Info: WORKING on channel 1 of HomeMatic BidCoS peer 16 with serial number MEQ1560788 was set to 0x00.

Keiner wenigstens einen Hinweis? Bin für jeden Tipp dankbar!

Da muss @sathya was zu sagen… ich hab keine Idee.

Kann es irgendwie im zusammenspiel mit hmland liegen? Habe knapp 30 HM Geräte verbunden, mag da nicht einfach herumprobieren und bin nach wie vor über Hinweise dankbar.

Ich habe nun über openhabian homegear erneut installiert, bin auf openhan 2.4M5 gegangen und seit gestern Abend läuft es zügig und bisher stabil. Falls Interesse besteht, kann ich Vergleichs-Logs ziehen. Andernfalls ist das Problem für mich vorerst erledigt.

2 Likes