Hallo beisammen,
erst einmal vielen Dank für dieses tolle Programm und ein herzliches Hallo in die Homegear-Runde! Bislang konnte ich alle Konfigurationen erfolgreich selbst vornehmen, auch dank dieses tollen Forums, aber für mein aktuelle Problem habe ich leider keine Tipps in anderen Diskussionen finden können:
Kurz und knapp
Reproduzierbar startet Homegear erfolgreich, sendet und empfängt Pakete, bis im Log-File eine “no answer to packet”-Meldung auftaucht. Anschließend ist zwar Senden noch möglich, aber es werden keine Pakete mehr empfangen.
Nachfolgend versuche den Aufbau etwas genauer zu beschreiben und auch, was ich schon alles versucht habe um das Problem einzukreisen:
Ökosystem
Ich betreibe einen Raspi 3 mit HM-MOD-RPI-PCB Modul. Ich verwende die Homegear-Version 0.6.7-1480 auf einem aktuellen Raspbian Jessie. Als Front-End setze ich ioBroaker ein. Testweise habe ich folgende Komponenten mit Homegear gepaired: HM-Sys-sRP-Pl, HM-PB-4-WM, HM-Sen-MDIR-O, HM-Sen-MDIR-O-2, HM-Sen-MDIR-SM, HM-Sec-SC, HM-LC-Sw1-Ba-PCB.
Vor dem Fehler
Nach dem Start von Homegear verhält sich die Kommunikation wie erwartet. Auch das Log ist unauffällig …
10/13/16 19:04:40.581 Starting Homegear...
10/13/16 19:04:40.581 Homegear version 0.6.7-1480
10/13/16 19:04:40.581 Git commit SHA of libhomegear-base: -
10/13/16 19:04:40.581 Git branch of libhomegear-base: -
10/13/16 19:04:40.582 Git commit SHA of Homegear: -
10/13/16 19:04:40.582 Git branch of Homegear: -
10/13/16 19:04:40.582 Info: Setting allowed core file size to "4294967295" for user with id 0 and group with id 0.
10/13/16 19:04:40.583 Info: Core file size now is "4294967295".
10/13/16 19:04:40.583 Info: Setting maximum thread priority to "4294967295" for user with id 0 and group with id 0.
10/13/16 19:04:40.583 Info: Maximum thread priority now is "4294967295".
10/13/16 19:04:40.592 Info: Backing up database...
10/13/16 19:04:40.673 Initializing database...
10/13/16 19:04:40.677 Info: Loading family module mod_miscellaneous.so
10/13/16 19:04:40.681 /etc/homegear/families/miscellaneous.conf
10/13/16 19:04:40.681 Info: Loading family module mod_homematicbidcos.so
10/13/16 19:04:40.693 /etc/homegear/families/homematicbidcos.conf
10/13/16 19:04:40.695 Info: Setting up physical interfaces and GPIOs...
10/13/16 19:04:40.696 Info: Dropping privileges to user homegear (112) and group homegear (119)
10/13/16 19:04:40.697 Info: Homegear is (now) running as user with id 112 and group with id 119.
10/13/16 19:04:40.697 Starting script engine server...
10/13/16 19:04:40.727 Initializing licensing controller...
10/13/16 19:04:40.727 Loading licensing controller data...
10/13/16 19:04:40.728 Loading devices...
10/13/16 19:04:40.728 Loading XML RPC devices...
10/13/16 19:04:41.729 Loading device 2
10/13/16 19:04:41.729 Module HomeMatic BidCoS: Info: Central address set to 0xXXXXXX.
10/13/16 19:04:41.730 Module HomeMatic BidCoS: Loading peer 1
10/13/16 19:04:41.746 Module HomeMatic BidCoS: Loading peer 2
10/13/16 19:04:41.751 Module HomeMatic BidCoS: Loading peer 3
10/13/16 19:04:41.755 Module HomeMatic BidCoS: Loading peer 4
10/13/16 19:04:41.760 Module HomeMatic BidCoS: Loading peer 5
10/13/16 19:04:41.763 Module HomeMatic BidCoS: Loading peer 6
10/13/16 19:04:41.766 Module HomeMatic BidCoS: Loading peer 7
10/13/16 19:04:41.772 Loading XML RPC devices...
10/13/16 19:04:41.774 Loading device 1
10/13/16 19:04:41.775 Start listening for packets...
10/13/16 19:04:43.776 Initializing RPC client...
10/13/16 19:04:43.776 Starting XML RPC server RPCServer1 listening on 0.0.0.0:2001...
10/13/16 19:04:43.779 Starting XML RPC server RPCServer2 listening on 0.0.0.0:2002, SSL enabled...
10/13/16 19:04:43.779 RPC Server (Port 2001): Info: RPC Server started listening on address 0.0.0.0 and port 2001
10/13/16 19:04:43.809 Starting XML RPC server RPCServer3 listening on 0.0.0.0:2003, SSL enabled, authentication enabled...
10/13/16 19:04:43.810 RPC Server (Port 2002): Info: RPC Server started listening on address 0.0.0.0 and port 2002
10/13/16 19:04:43.837 Starting CLI server...
10/13/16 19:04:43.837 RPC Server (Port 2003): Info: RPC Server started listening on address 0.0.0.0 and port 2003
10/13/16 19:04:43.837 Initializing event handler...
10/13/16 19:04:43.838 Loading events...
10/13/16 19:04:43.838 Startup complete. Waiting for physical interfaces to connect.
10/13/16 19:04:43.838 All physical interfaces are connected now.
10/13/16 19:04:43.838 Starting UPnP server...
10/13/16 19:04:43.839 Info: UPnP server: Binding to address: 192.168.X.X
10/13/16 19:04:43.840 UPnP Server: Info: Started listening.
10/13/16 19:04:46.231 Module HomeMatic BidCoS: HM-MOD-RPI-PCB "My-HM-MOD-RPI-PCB": Info: Init queue completed. Sending peers...
10/13/16 19:04:46.414 Module HomeMatic BidCoS: HM-MOD-RPI-PCB "My-HM-MOD-RPI-PCB": Info: Peer sending completed.
10/13/16 19:04:47.999 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -61 dBm): 0BB8A25818036418081C00FB
10/13/16 19:04:48.133 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -51 dBm): 0EB8820218081C1803640101C4003D
10/13/16 19:04:50.955 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -65 dBm): 1473845E2DD9D2000000870D43000000000008E8F8
10/13/16 19:04:57.244 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -60 dBm): 0B86A2581144011124BD0000
10/13/16 19:04:57.377 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -54 dBm): 0E8682021124BD1144010101000046
10/13/16 19:05:01.438 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -62 dBm): 0B0FA258166AB31672350000
10/13/16 19:05:01.580 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -70 dBm): 0CF48670160209000000008E3E
10/13/16 19:05:03.712 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -53 dBm): 0B96A25814331512479E0000
10/13/16 19:05:03.847 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -42 dBm): 0E96820212479E1433150101000031
10/13/16 19:05:07.836 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -59 dBm): 0CEF8670166A2800000000C037
10/13/16 19:05:21.581 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -70 dBm): 0BF4A2581602091653830000
10/13/16 19:05:21.717 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -65 dBm): 0EF48202165383160209010100062B
10/13/16 19:05:27.837 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -58 dBm): 0BEFA258166A28113C410021
10/13/16 19:05:27.969 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -39 dBm): 0EEF8202113C41166A2801011A002E
10/13/16 19:05:32.815 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -64 dBm): 0C4A867012B75300000000D13A
10/13/16 19:05:37.628 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -55 dBm): 0C5386701602C600000000D62F
10/13/16 19:05:47.936 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -69 dBm): 0C728670129BF400000000DE35
10/13/16 19:05:50.535 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -55 dBm): 0C0E86701669D200000000943C
10/13/16 19:05:52.815 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -63 dBm): 0B4AA25812B75313025C00CC
10/13/16 19:05:52.945 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -55 dBm): 0E4A820213025C12B7530101A0003E
10/13/16 19:05:55.306 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -55 dBm): 0C4686701144D200000000E92F
10/13/16 19:05:57.628 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -55 dBm): 0B53A2581602C61671630000
10/13/16 19:05:57.761 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -34 dBm): 0E5382021671631602C60101000035
10/13/16 19:06:02.625 RPC Server (Port 2001): Info: Connection from 127.0.0.1:46836 accepted. Client number: 11
10/13/16 19:06:02.626 RPC Server (Port 2001): Info: RPC server client id for client number 11 is: 0
10/13/16 19:06:02.627 RPC Server (Port 2001): Info: Client number 11 is calling RPC method: ping (1) Parameters:
(String) hm-rpc.0
10/13/16 19:06:02.652 RPC Server (Port 2001): Info: Connection to client number 11 closed (3).
10/13/16 19:06:07.936 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -69 dBm): 0B72A258129BF41808770079
10/13/16 19:06:08.072 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -54 dBm): 0E728202180877129BF401015E0035
10/13/16 19:06:10.535 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -55 dBm): 0B0EA2581669D216716D0000
10/13/16 19:06:10.667 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -51 dBm): 0E0E820216716D1669D20101000032
10/13/16 19:06:15.306 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -55 dBm): 0B46A2581144D2115043001F
10/13/16 19:06:15.438 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -56 dBm): 0E4682021150431144D20101180033
10/13/16 19:06:38.317 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -86 dBm): 0CE08670129CAB000000007E44
10/13/16 19:06:40.997 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -60 dBm): 0C878670114401000000008A3E
10/13/16 19:06:56.503 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -60 dBm): 0CB9867018036400000000A737
10/13/16 19:06:58.316 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -86 dBm): 0BE0A258129CAB1267A40000
10/13/16 19:06:58.449 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -60 dBm): 0EE082021267A4129CAB010100002F
10/13/16 19:07:00.997 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -60 dBm): 0B87A25811440112B1340000
10/13/16 19:07:01.132 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -56 dBm): 0E87820212B1341144010101000034
10/13/16 19:07:03.301 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -70 dBm): 0DC884101B8F9A13CD1A06011100
10/13/16 19:07:05.716 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -52 dBm): 0C97867014331500000000903D
10/13/16 19:07:13.342 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -70 dBm): 0D10A6103465D3FD901906010D00
10/13/16 19:07:13.343 Module HomeMatic BidCoS: Info: BRIGHTNESS on channel 1 of HomeMatic BidCoS peer 4 with serial number LEQ1282851 was set to 0x0D.
… bis zu der Zeile “… Info: No answer to packet …”.
ab hier ist kein Empfang mehr möglich
10/13/16 19:07:13.530 Module HomeMatic BidCoS: HM-MOD-RPI-PCB "My-HM-MOD-RPI-PCB": Info: Sending (My-HM-MOD-RPI-PCB): 1011A001FD90193465D301040000000001
10/13/16 19:07:14.283 Module HomeMatic BidCoS: HM-MOD-RPI-PCB "My-HM-MOD-RPI-PCB": Info: No answer to packet 1011A001FD90193465D301040000000001
10/13/16 19:08:02.649 RPC Server (Port 2001): Info: Connection from 127.0.0.1:46854 accepted. Client number: 12
10/13/16 19:08:02.650 RPC Server (Port 2001): Info: RPC server client id for client number 12 is: 1
10/13/16 19:08:02.650 RPC Server (Port 2001): Info: Client number 12 is calling RPC method: init (1) Parameters:
(String) http://127.0.0.1:2004
(String) hm-rpc.0
10/13/16 19:08:02.651 Info: Adding server "http://127.0.0.1".
10/13/16 19:08:02.651 Info: Calling init methods on server "http://127.0.0.1".
10/13/16 19:08:02.677 RPC Server (Port 2001): Info: Connection to client number 12 closed (3).
10/13/16 19:08:03.151 RPC client: Info: Calling RPC method "system.listMethods" on server http://127.0.0.1.
10/13/16 19:08:03.159 RPC client: Info: Calling RPC method "listDevices" on server 127.0.0.1.
Test: Senden während “fehlerhaftem” Empfang
Das weitere Log wiederholt sich nun ständig, bis ich einen Schaltbefehl veranlasse:
10/13/16 19:31:35.670 RPC Server (Port 2001): Info: Client number 45 is calling RPC method: setValue (1) Parameters:
(String) IEQ0405230:1
(String) STATE
(Boolean) 0
10/13/16 19:31:35.671 Module HomeMatic BidCoS: HM-MOD-RPI-PCB "My-HM-MOD-RPI-PCB": Info: Sending (My-HM-MOD-RPI-PCB): 0E00B011FD00011769440201000000
10/13/16 19:31:38.254 RPC Server (Port 2001): Info: Connection to client number 45 closed (3).
10/13/16 19:31:39.212 Module HomeMatic BidCoS: HM-MOD-RPI-PCB "My-HM-MOD-RPI-PCB": Info: No answer to packet 0E00B011FD00011769440201000000
10/13/16 19:31:39.212 Module HomeMatic BidCoS: Info: Setting peer to unreachable, because the queue processing was interrupted.
10/13/16 19:31:39.213 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 7). Retrying...
10/13/16 19:31:39.213 Module HomeMatic BidCoS: HM-MOD-RPI-PCB "My-HM-MOD-RPI-PCB": Info: Sending (My-HM-MOD-RPI-PCB): 0E00B011FD00011769440201000000
10/13/16 19:31:42.715 Module HomeMatic BidCoS: HM-MOD-RPI-PCB "My-HM-MOD-RPI-PCB": Info: No answer to packet 0E00B011FD00011769440201000000
10/13/16 19:31:42.715 Module HomeMatic BidCoS: Info: Setting peer to unreachable, because the queue processing was interrupted.
10/13/16 19:31:42.716 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 7). Retrying...
10/13/16 19:31:42.716 Module HomeMatic BidCoS: HM-MOD-RPI-PCB "My-HM-MOD-RPI-PCB": Info: Sending (My-HM-MOD-RPI-PCB): 0E00B011FD00011769440201000000
10/13/16 19:31:46.214 Module HomeMatic BidCoS: HM-MOD-RPI-PCB "My-HM-MOD-RPI-PCB": Info: No answer to packet 0E00B011FD00011769440201000000
10/13/16 19:31:46.215 Module HomeMatic BidCoS: Info: Setting peer to unreachable, because the queue processing was interrupted.
10/13/16 19:31:46.215 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 7). Retrying...
10/13/16 19:31:46.215 Module HomeMatic BidCoS: HM-MOD-RPI-PCB "My-HM-MOD-RPI-PCB": Info: Sending (My-HM-MOD-RPI-PCB): 0E00B011FD00011769440201000000
10/13/16 19:31:49.717 Module HomeMatic BidCoS: HM-MOD-RPI-PCB "My-HM-MOD-RPI-PCB": Info: No answer to packet 0E00B011FD00011769440201000000
10/13/16 19:31:49.718 Module HomeMatic BidCoS: Info: Setting peer to unreachable, because the queue processing was interrupted.
10/13/16 19:31:49.718 Info: Peer 7 is unreachable.
10/13/16 19:31:49.718 RPC client: Info: Calling RPC method "system.multicall" on server 127.0.0.1.
10/13/16 19:31:50.183 Info: Peer 7 is reachable again.
10/13/16 19:31:50.183 RPC client: Info: Calling RPC method "system.multicall" on server 127.0.0.1.
Der Befehl erreicht den Aktor und wird umgehend ausgeführt, die Bestätigung wird aber nicht mehr (oder zu spät?) empfangen.
Test: Senden gleich nach dem Start von Homegear
Führe ich denselben Schaltbefehl gleich nach einem Neustart von Homegear aus, funktioniert es prima und wird folgendermaßen protokolliert:
10/13/16 19:36:11.968 RPC Server (Port 2001): Info: RPC server client id for client number 11 is: 0
10/13/16 19:36:11.971 RPC Server (Port 2001): Info: Client number 11 is calling RPC method: setValue (1) Parameters:
(String) IEQ0405230:1
(String) STATE
(Boolean) 0
10/13/16 19:36:11.972 Module HomeMatic BidCoS: HM-MOD-RPI-PCB "My-HM-MOD-RPI-PCB": Info: Sending (My-HM-MOD-RPI-PCB): 0E02B011FD00011769440201000000
10/13/16 19:36:12.485 HomeMatic BidCoS packet received (My-HM-MOD-RPI-PCB, RSSI: -62 dBm): 0E028002176944FD00010101000042
10/13/16 19:36:12.485 Module HomeMatic BidCoS: Info: Queue 0 is empty and there are no pending queues.
10/13/16 19:36:12.486 Module HomeMatic BidCoS: Info: STATE on channel 1 of HomeMatic BidCoS peer 7 with serial number IEQ040XXXX was set to 0x00.
10/13/16 19:36:12.486 Module HomeMatic BidCoS: Info: WORKING on channel 1 of HomeMatic BidCoS peer 7 with serial number IEQ040XXXX was set to 0x00.
10/13/16 19:36:12.548 RPC Server (Port 2001): Info: Connection to client number 11 closed (3).
Ich bin leider mit meinem Latein am Ende. Habt ihr eine Idee, woran das liegen könnte?
Viele Grüße,
max