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


#1

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.

#2

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


#3

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


#4

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.


#5

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.


#6