setValue() bei HM-CC-RT-DN funktioniert nicht (über HM-CFG-LAN)

Deutsche Foren Fehler
#1

Hallo Zusammen,

erst mal Danke für die Arbeit an diesem großartigen Projekt - das macht echt Spaß damit zu experimentieren! :slight_smile:

Ich bin dabei allerdings in ein Problem gelaufen, als ich versucht habe über die XMLRPC API setValue() abzusetzen - Sachen auslesen mit getValue() klappt wunderbar. Ich habe einfach einmal versucht, den Mode der Geräte auf “AUTO” zu stellen:

    print_r($this->XMLRPC->send("setValue", array(intval($this->peerId), 4, "AUTO_MODE", true)));

Das gibt nichts weiter zurück - das Log sagt allerdings folgendes (der RPC Call wird für drei RTs in Folge abgesetzt):

11/29/14 11:24:25.968 RPC Server (Port 2001): Info: Client number 18 is calling RPC method: setValue Parameters:
(Integer) 4
(Integer) 4
(String) AUTO_MODE
(Boolean) 1
11/29/14 11:24:25.970 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Info: Sending (My-HM-CFG-LAN): 1020B001FD10632DD41200040000000000
11/29/14 11:24:25.970 RPC Server (Port 2001): Info: Connection to client number 18 closed.
11/29/14 11:24:28.049 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 2). Retrying...
11/29/14 11:24:28.049 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Info: Sending (My-HM-CFG-LAN): 1008B001FD10632DD48A00040000000000
11/29/14 11:24:28.149 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 4). Retrying...
11/29/14 11:24:28.149 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Info: Sending (My-HM-CFG-LAN): 1020B001FD10632DD41200040000000000
11/29/14 11:24:28.349 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 3). Retrying...
11/29/14 11:24:28.350 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Info: Sending (My-HM-CFG-LAN): 1014B001FD10632DD4AF00040000000000
11/29/14 11:24:29.439 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Info: No response to packet after 3 tries: 1008B001FD10632DD48A00040000000000
11/29/14 11:24:29.465 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Info: No response to packet after 3 tries: 1014B001FD10632DD4AF00040000000000
11/29/14 11:24:30.051 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 2). Retrying...
11/29/14 11:24:30.052 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Info: Sending (My-HM-CFG-LAN): 1008B001FD10632DD48A00040000000000
11/29/14 11:24:30.252 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 4). Retrying...
11/29/14 11:24:30.252 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Info: Sending (My-HM-CFG-LAN): 1020B001FD10632DD41200040000000000
11/29/14 11:24:30.452 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 3). Retrying...
11/29/14 11:24:30.453 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Info: Sending (My-HM-CFG-LAN): 1014B001FD10632DD4AF00040000000000
11/29/14 11:24:32.154 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 2). Retrying...
11/29/14 11:24:32.154 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Info: Sending (My-HM-CFG-LAN): 1008B001FD10632DD48A00040000000000
11/29/14 11:24:32.354 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 4). Retrying...
11/29/14 11:24:32.355 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Info: Sending (My-HM-CFG-LAN): 1020B001FD10632DD41200040000000000
11/29/14 11:24:32.554 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 3). Retrying...
11/29/14 11:24:32.555 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Info: Sending (My-HM-CFG-LAN): 1014B001FD10632DD4AF00040000000000
11/29/14 11:24:32.872 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Info: No response to packet after 3 tries: 1020B001FD10632DD41200040000000000
11/29/14 11:24:34.257 Info: Peer 2 is unreachable.
11/29/14 11:24:34.406 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Warning: HM-CFG-LAN nearly reached 1% rule.
11/29/14 11:24:34.406 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Info: No response to packet after 3 tries: 1008B001FD10632DD48A00040000000000
11/29/14 11:24:34.457 Info: Peer 4 is unreachable.
11/29/14 11:24:34.557 Info: Peer 3 is unreachable.

Auf den HM-CC-RT-DN läuft die Firmware 1.3 - ein Update auf 1.4 über die homegear CLI scheitert aber leider:

11/29/14 11:34:07.124 Module HomeMatic BidCoS: Info: Not updating peer with id 2. No physical interface supports firmware updates.

Ich verwende das Ubuntu Paket für 14.04 (0.5.14-1) auf einem Board mit Intel Atom CPU - ich hatte/habe wohl ab und zu Abstürze von homegear wegen “SIGABRT” und habe vorhin das hier versucht: viewtopic.php?f=6&t=50&p=334&hilit=SIGABRT#p334
Daher sind die entsprechenden Module jetzt ggf. etwas neuer als das Paket (gebaut aus homegear_0.5.14.orig.tar.gz von der Downloads Seite). Hat jemand eine Idee, was hier ggf. falsch läuft?

Und am Rande: wie kann ich denn den aktuellen Modus eines RTs auslesen? Wenn ich MANU_MODE oder AUTO_MODE lesen möchte, bekomme ich nur die RPC Antwort, dass dieser Parameter nicht gelesen werden kann

#2

Update von meiner Seite:

Ich habe zwischenzeitlich in einem anderen Thread gelesen, dass der Config Adapter eine Art Rate-Limit für Anfragen hat und dann anscheinend die Kommunikation sperrt. Nachdem ich Adapter und Homegear einmal durchgestartet habe und meine setValue()-Aufrufe mit einem sleep(2) voneinander getrennt habe, funktioniert es!

Scheinbar war ich einfach nur ein wenig…zu schnell? Kann das jemand bestätigen/widerlegen? Was für ein Zeitabstand sollte zwischen Anfragen gewählt werden?

#3

Hallo,

es ist gut möglich, dass die 1%-Grenze für deinen Fehler verantwortlich war. Irgendwo müsste allerdings auch im Log vermerkt sein, dass das 1%-Limit erreicht war. Die 1%-Grenze bezieht sich auf eine Stunde, das bedeutet, ein Gerät (also z. B. der HM-CFG-LAN) darf maximal 36 Sekunden pro Stunde senden. Die Stellantriebe arbeiten im Wake-on-Radio-Modus. Damit dauert das Aufwecken alleine bereits 360 ms plus Paketsendezeit. Bei Nicht-Erreichen kann dieses Paket bis zu drei Mal gesendet werden. Bei Nicht-Erreichen in Queues sogar neun Mal. Das macht also bereits 1 bis 3 Sekunden der 36 erlaubten Sekunden! Normalerweise sollten Geräte aber erreichbar sein, so dass du mit 360 ms rechnen kannst. Das bedeutet, du kannst knapp 100 Pakete dieser Art pro Stunde senden. Eine einfache und sinnvolle Möglichkeit, das zu erhöhen, ist Wake-on-Radio zu deaktivieren. Dazu kannst du den Parameter “BURST_RX” auf false setzen. Damit ist der Stellantrieb zwar nur noch alle zwei bis drei Minuten erreichbar (es sendet alle zwei bis drei Minuten ein “Wake-Me-Up”-Paket), aber die 360 ms entfallen. Damit hast du nur noch die eigentliche Paketsendezeit (1 kBaud pro Sekunde, d. h. rechne mal mit etwa 15 ms pro Paket). Damit kannst du also mehr als 2000 Pakete pro Stunde senden. Außerdem umgehst du einen weiteren Nachteil von Wake-on-Radio: Wake-on-Radio-Pakete wecken nämlich immer alle Wake-on-Radio-Geräte auf. Das bedeutet, bei vielen Paketen dieser Art sind deine Batterien viel, viel schneller leer.

Firmwareupdates funktionieren leider nicht mit dem HM-CFG-LAN (der unterstützt nicht das Wechseln in den Updatemodus).

Das liegt an Unterschieden in den Bibliotheksversionen. Mit deinem eigenen Kompilat sollte es jetzt stabil laufen. Ärgerlich. Mit einem Standard-Ubuntu sollte das Paket eigentlich funktionieren.

Durch das Lesen der Variablen “CONTROL_MODE”. “0” ist “AUTO-MODE”, “1” ist “MANU-MODE”, “2” ist “PARTY-MODE” und “3” “BOOST-MODE”.

Liebe Grüße

Sathya

#4

Hi,

danke für die schnelle und ausführliche Antwort :slight_smile:

Ich schaue mir das mit dem Wake-on-Radio an - und ja, die Fehlermeldung bezüglich 1% habe ich im Log gesehen, aber anscheinend nicht in dem Teil, den ich kopiert hatte (da war ich wohl schon geblockt). Ich schaue mal, was da für mich am besten funktioniert! Ich habe allerdings noch nicht ganz verstanden, was der technische Hintergrund dieser EInschränkung ist…? Wenn ich z.B. einen Bewegungsmelder an einen belebten Ort aufhänge und damit etwas auslösen möchte (z.B. verschiedene Schalter, Heizkörper, whatever), kann ich doch wahrscheinlich ganz leicht mal versehentlich in dieses Limit laufen, oder?

Doh. OK.

Mit dem Paket hatte ich so alle 2-5 Stunden mal einen Absturz (das ging immer mit einem XMLRPC Call einher - die nutze ich gerade im 5 Minuten Takt um Temperaturgraphen zu erstellen). Mit dem eigenen Kompilat habe ich jetzt seit > 24 Stunden keine Probleme mehr.

Ähm ja, das habe ich zwischenzeitlich durch Lesen das XML Files dann auch verstanden :slight_smile:

Nochmal, vielen Dank!

#5

Der Grund sind gesetzliche Vorgaben. Umgehen kannst du das Ganze, indem du mehrere Schnittstellen verwendest, auf die sich die Last verteilt. Im Betrieb ohne Wake-on-Radio wirst du das Limit allerdings so schnell nicht erreichen. Bald wird es auch Homegear-Servicemeldungen geben, über die du feststellen kannst, ob das 1%-Limit erreicht ist. Ich weiß, das Limit ist doof…

Liebe Grüße

Sathya

#6

Leider ist das SIGABRT Problem nicht weg:

Das sagt das homegear.log File:

12/01/14 02:20:01.679 RPC Server (Port 2001): Info: Client number 13425 is calling RPC method: getDeviceInfo Parameters:
(Integer) 2
(Array length=1)
{
  (String) NAME
}
12/01/14 02:20:01.680 RPC Server (Port 2001): Info: Connection from 127.0.0.1:55778 accepted. Client number: 13427
12/01/14 02:20:01.680 RPC Server (Port 2001): Info: Connection to client number 13425 closed.
12/01/14 02:20:01.683 RPC Server (Port 2001): Info: Connection from 127.0.0.1:55780 accepted. Client number: 13428
12/01/14 02:20:01.683 RPC Server (Port 2001): Info: Client number 13427 is calling RPC method: getPeerId Parameters:
(String) LEQ0780016
12/01/14 02:20:01.683 RPC Server (Port 2001): Info: Client number 13428 is calling RPC method: getValue Parameters:
(Integer) 2
(Integer) 4
(String) VALVE_STATE
(Boolean) 0
12/01/14 02:20:01.683 RPC Server (Port 2001): Info: Connection to client number 13427 closed.
12/01/14 02:20:01.687 RPC Server (Port 2001): Info: Connection to client number 13428 closed.
12/01/14 02:20:01.687 RPC Server (Port 2001): Info: Connection from 127.0.0.1:55782 accepted. Client number: 13429
12/01/14 02:20:01.687 Error: Signal SIGABRT (6) received.
12/01/14 02:20:01.687 RPC Server (Port 2001): Info: Connection from 127.0.0.1:55784 accepted. Client number: 13430
12/01/14 02:20:01.688 RPC Server (Port 2001): Info: Client number 13430 is calling RPC method: getPeerId Parameters:Info: Client number 13430 is calling RPC method: getPeerId Parameters:

Das sagt das homegear.err File:

terminate called without an active exception
12/01/14 02:20:01.687 Error: Signal SIGABRT (6) received.

Wobei ich jetzt nicht sagen kann, woher die “terminate” Zeile kommt - der letzte Eintrag davor im err-Log ist über einen Tag alt. Das kann ja jetzt irgendwann dazwischen passiert sein - oder es gehört zum SIGABRT.

Soll ich das Loglevel mal hochdrehen? Gibt es da einen sinnvollen Wert?

#7

Hey,

SIGABRT darf natürlich auf gar keinen Fall auftreten! Das wär echt klasse, wenn du mir helfen könntest, den Fehler zu finden :wink:. Die Logs helfen dazu leider nur begrenzt weiter. Wir brauchen einen Core-dump mit Debuginformationen. Den bekommst du folgendermaßen:

Führ erst einmal folgende Zeile als root aus:

Dann kompilier Homegear noch einmal mit

und ersetz die Binaries (homegear und die Module).

Wenn Homegear jetzt abschmiert, wird eine Datei “core” in “/var/log/homegear” erzeugt. Pack diese zusammen mit den beiden Logdateien in ein Archiv und uploade es hier: https://cloudl.eu/public.php?service=files&t=068db90dfce671ab4a3f897be357f33b.

Damit kann ich den Fehler dann hoffentlich identifizieren :wink:.

Liebe Grüße

Sathya

#8

Gerne, ich lasse das gleich mal komplieren und tausche dann später Binaries und Module aus! :slight_smile:

#9

Ist schon wieder abgeschmiert - habe gerade das Binary und die Module durch den Debug-Build ausgetauscht und melde mich dann, sobald ich was hab!

#10

Super :slight_smile:. Zum Glück lässt sich das Ganze schnell reproduzieren :wink:.

#11

Hi,

hab die Daten hochgeladen. Der Crash war um 2:26 - wurde danach allerdings direkt neugestartet, weil ich mir einen monit dafür eingerichtet hab :wink:

Grüße!

#12

Hey,

eine Sache habe ich vergessen: Ich brauche für’s Debuggen auch noch die zugehörigen Binaries :blush: (homegear und die Module). Magst du die mir auch noch hochladen? Dann schaue ich mir das gleich an :wink:.

Neuer ownCloud-Link:
cloudl.eu/public.php?service=fi … 4d143458a2

Liebe Grüße

Sathya

#13

…auch erledigt!

#14

Cool, danke! Dann schauen wir mal :wink:.

#15

ok, analysiert. Hier mal der Backtrace:

#0  0xb76e9424 in __kernel_vsyscall ()
#1  0xb7196577 in __GI___open_catalog (cat_name=0xb1900e48 "@\253\017\255\b\020\220\261(\016\220\261\230\r\220\261\360\a\220\261(\v%\b", nlspath=0xb22fe108 "\b\020\220\261(\016\220\261\274\341/\262\377\377\377\377\070\341/\262\311o\v\b@\016\220\261", env_var=0xb22fe108 "\b\020\220\261(\016\220\261\274\341/\262\377\377\377\377\070\341/\262\311o\v\b@\016\220\261", 
    catalog=0x804e38a <__gnu_cxx::__exchange_and_add_dispatch(_Atomic_word*, int)+38>) at open_catalog.c:110
#2  0x080b6fa1 in RPC::RPCServer::Client::~Client (this=0xb1900e40, __in_chrg=<optimized out>) at Libraries/RPC/RPCServer.cpp:42
#3  0x080b6fc9 in RPC::RPCServer::Client::~Client (this=0xb1900e40, __in_chrg=<optimized out>) at Libraries/RPC/RPCServer.cpp:45
#4  0x080cbec4 in std::_Sp_counted_ptr<RPC::RPCServer::Client*, (__gnu_cxx::_Lock_policy)2>::_M_dispose (this=0xb1900808) at /usr/include/c++/4.8/bits/shared_ptr_base.h:290
#5  0x08054df8 in std::_Sp_counted_base<(__gnu_cxx::_Lock_policy)2>::_M_release (this=0xb1900808) at /usr/include/c++/4.8/bits/shared_ptr_base.h:144
#6  0x08053fe6 in std::__shared_count<(__gnu_cxx::_Lock_policy)2>::~__shared_count (this=0xb22fe27c, __in_chrg=<optimized out>) at /usr/include/c++/4.8/bits/shared_ptr_base.h:546
---Type <return> to continue, or q <return> to quit---
#7  0x080c3d14 in std::__shared_ptr<RPC::RPCServer::Client, (__gnu_cxx::_Lock_policy)2>::~__shared_ptr (this=0xb22fe278, __in_chrg=<optimized out>) at /usr/include/c++/4.8/bits/shared_ptr_base.h:781
#8  0x080c3d27 in std::shared_ptr<RPC::RPCServer::Client>::~shared_ptr (this=0xb22fe278, __in_chrg=<optimized out>) at /usr/include/c++/4.8/bits/shared_ptr.h:93
#9  0x080ba077 in RPC::RPCServer::mainThread (this=0xa8a28b0) at Libraries/RPC/RPCServer.cpp:340
#10 0x080cc38a in std::_Mem_fn<void (RPC::RPCServer::*)()>::operator()<, void>(RPC::RPCServer*) const (this=0xa8845f8, __object=0xa8a28b0) at /usr/include/c++/4.8/functional:601
#11 0x080cc253 in std::_Bind_simple<std::_Mem_fn<void (RPC::RPCServer::*)()> (RPC::RPCServer*)>::_M_invoke<0u>(std::_Index_tuple<0u>) (this=0xa8845f4) at /usr/include/c++/4.8/functional:1732
#12 0x080cc093 in std::_Bind_simple<std::_Mem_fn<void (RPC::RPCServer::*)()> (RPC::RPCServer*)>::operator()() (this=0xa8845f4) at /usr/include/c++/4.8/functional:1720
#13 0x080cbffc in std::thread::_Impl<std::_Bind_simple<std::_Mem_fn<void (RPC::RPCServer::*)()> (RPC::RPCServer*)> >::_M_run() (this=0xa8845e8) at /usr/include/c++/4.8/thread:115
#14 0xb741ef4e in std::(anonymous namespace)::execute_native_thread_routine (__p=0xa8845e8) at ../../../../../src/libstdc++-v3/src/c++11/thread.cc:84
#15 0xb76b9f70 in start_thread (arg=0xb22feb40) at pthread_create.c:312
#16 0xb72544ce in fstab_convert (state=0x0) at fstab.c:169

komplett verstehen tue ich das Problem ehrlich gesagt nicht. Aus irgendeinem Grund erreicht der shared_ptr-Zähler des gerade erst erzeugten Client-Objektes im Hauptthread des RPC servers “0”. Dadurch wird das Objekt gleich wieder zerstört und der zugehörige Lesethread abgebrochen (daher SIGABRT). Das kann nur sein, wenn eine Client-ID doppelt verwendet wird, was eigentlich nicht möglich ist.
Ich habe mal drei Änderungen im Quelltext vorgenommen. Schau mal ob es mit der GitHub-Version jetzt funktioniert - es sollte keinen Absturz mehr geben. Falls es jetzt funktioniert, schick mir trotzdem alle Fehlermeldungen, welche im Fehlerlog innerhalb von 24 Stunden anfallen.

Liebe Grüße

Sathya

#16

Hallo Sathya,

sorry für die äußerst späte Rückmeldung, ich hatte nur vergessen zu sagen, dass ich etwas viel um die Ohren hatte und zwischenzeitlich in den Urlaub gereist bin :wink:

Allerdings habe ich kurz vor Abreise noch schnell die Version kompiliert und ausgetauscht - läuft seitdem stabil und einwandfrei durch!

Bist du eigentlich beim 31C3 zu finden?

#17

Nein, dieses Jahr nicht :wink:. Wobei wir einen schönen Vortrag hätten halten können, da wir zwischenzeitlich den Standard-AES-Schlüssel herausgefunden haben und damit durch Sniffen der Anlernpakete auch den geänderten AES-Schlüssel herausfinden können.