collectord hält letzten Status sobald eins der Geräte ausfällt

[mumpitzstuff]

Ich versuche seit gestern collectord zu betreiben und bin auf das Problem gestoßen, dass sobald eine lepresenced Instanz nicht mehr erreichbar ist, der Presence Status komplett einfriert. Meins Erachtens liegt das an der aggregateRooms() Funktion in collectord, die ein undef zurück liefert, sobald ein Teilnehmer nicht mehr erreichbar ist.

Das ist für mich wenig nachvollziehbar, denn das eine lepresenced Instanz mal nicht mehr erreichbar ist, kann ja mal passieren und ist doch eigentlich auch kein Problem wenn man 2 oder sogar mehr davon hat. Das in meinen Augen richtige Verhalten an der Stelle wäre, den Status der verbliebenden lepresenced Instanzen heranzuziehen und zu aggregieren.

Komisch ist auch, das sich die eine lepresenced Instanz kurze Zeit (wenige Stunden später) nach dem Aufsetzen von collectord verabschiedet hat. Zuvor lief diese schon einige Tage ohne Probleme und der Status wurde von der Maininstanz direkt von lepresenced abgefragt. Aber das ist ein anderes Thema und das muss ich erst noch untersuchen...

[Markus Bloch]

Hallo mumpitzstuff,

Ich versuche seit gestern collectord zu betreiben und bin auf das Problem gestoßen, dass sobald eine lepresenced Instanz nicht mehr erreichbar ist, der Presence Status komplett einfriert. Meins Erachtens liegt das an der aggregateRooms() Funktion in collectord, die ein undef zurück liefert, sobald ein Teilnehmer nicht mehr erreichbar ist.

Der Grund für dieses Verhalten in aggregateRooms() ist die Möglichkeit einen expliziten Check sofort in allen Räumen durchzuführen (Befehl "now"). Dabei werden alle letztbekannten Ergebnisse zu den jeweiligen Räumen gelöscht und ein sofortiger Check angefordert. Sobald der erste Raum ein Ergebnis liefert würde dann sofort ein Status an FHEM zurückgegeben (bspw. "absent") was aber nicht das Ergebnis aller Räume wiederspiegelt. Daher wird erst dann ein Ergebnis zurüclgeliefert, wenn für jeden verbundenen Raum ein Ergebnis zur Verfügung steht.

Das ist für mich wenig nachvollziehbar, denn das eine lepresenced Instanz mal nicht mehr erreichbar ist, kann ja mal passieren und ist doch eigentlich auch kein Problem wenn man 2 oder sogar mehr davon hat. Das in meinen Augen richtige Verhalten an der Stelle wäre, den Status der verbliebenden lepresenced Instanzen heranzuziehen und zu aggregieren.

Sobald ein Raum nicht mehr erreichbar ist, wird der Raum nicht mehr für die Aggregation herangezogen. Das bedingt jedoch, dass eine Signalisierung des Verbindungsabruchs durch Perl erfolgt. Wenn die Verbindung jedoch abbricht ohne jegliche Indikation (bspw. Firewall blockiert oder Prozess wird hart gekillt) so gibt es keine sofortige Indikation an collectord, dass die Verbindung weg ist. Hier kann man nur durch Keep-Alives eine unterbrochene Verbindung erkennen. Ich sehe, dass ich das interessanterweise nicht eingebaut habe.

Bitte führe mal folgende Änderungen durch:

Code Auswählen Erweitern

Index: collectord
===================================================================
--- collectord  (revision 16312)
+++ collectord  (working copy)
@@ -518,6 +518,9 @@

     if(defined($client_socket))
     {
+        # activate TCP keep-alive mechanism
+        $client_socket->setsockopt(SOL_SOCKET, SO_KEEPALIVE, 1);
+
         # send the given address to the presence daemon
         $client_socket->send($do_address."|".$values{absence_timeout}."\n");
     }
@@ -603,6 +606,9 @@

             if(defined($client_socket))
             {
+                # activate TCP keep-alive mechanism
+                $client_socket->setsockopt(SOL_SOCKET, SO_KEEPALIVE, 1);
+
                 # give a success message
                 $log_queue->enqueue(threads->tid()."|$do_room reconnected to ".$values{address}.":".$values{port}." after $reconnect_count tries for device $do_address (UUID: $do_uuid)");
                 $status_queue->enqueue("$do_uuid;$do_room;socket_reconnected");


Viele Grüße

Markus

[mumpitzstuff]

Ich kann es mal einbauen und testen...

Ich hatte übrigens auch manuell den Status angefordert, der war aber trotzdem eingefroren.

Aktuell habe ich aber noch andere Probleme und bin stark am überlegen collectord wieder komplett raus zu werfen. Beim Direktzugriff auf lepresenced ohne collectord konnte ich recht genau festlegen, dass nach 30 min Abwesenheit auf absent umgeschaltet wird. Hier hatte ich nur den Port angepasst um auf collectord umzustellen:

Code Auswählen Erweitern

Internals:
   ADDRESS    7C:2F:80:C4:58:B8
   CHANGED   
   DEF        lan-bluetooth 7C:2F:80:C4:58:B8 127.0.0.1:5222 10 120
   DeviceName 127.0.0.1:5222
   FD         61
   INTERVAL_NORMAL 10
   INTERVAL_PRESENT 120
   MODE       lan-bluetooth
   NAME       GTAG_ACHIM
   NOTIFYDEV  global
   NR         75
   NTFY_ORDER 50-GTAG_ACHIM
   PARTIAL   
   STATE      present
   TYPE       PRESENCE
   READINGS:
     2018-03-05 10:22:52   battery         ok
     2018-03-05 10:22:52   batteryLevel    56
     2018-03-06 09:57:50   command_accepted yes
     2018-03-06 10:49:24   daemon          lepresenced V0.83
     2018-03-06 10:49:24   device_name     Gigaset G-tag
     2018-03-06 10:49:24   model           lan-lepresenced
     2018-03-06 10:49:24   presence        present
     2018-03-06 09:57:30   room           
     2018-03-06 10:49:24   rooms           RPI0,RPI2
     2018-03-06 10:49:24   rssi            -78
     2018-03-06 10:49:24   rssi_RPI0       -78
     2018-03-06 10:49:24   state           present
   helper:
     CURRENT_STATE present
     CURRENT_TIMEOUT present
Attributes:
   absenceThreshold 180
   devStateIcon absent:status_away_1@red .*:status_available
   event-on-change-reading presence
   room       RESIDENTS

Code Auswählen Erweitern

2018-01-02_16:44:39 GTAG_ACHIM presence: maybe absent
2018-01-02_17:14:19 GTAG_ACHIM presence: absent
2018-01-04_11:28:10 GTAG_ACHIM presence: maybe absent
2018-01-04_11:57:50 GTAG_ACHIM presence: absent

Seitdem ich collectord verwende (nur Port geändert) sieht das so aus:

Code Auswählen Erweitern

2018-03-05_15:57:16 GTAG_ACHIM presence: maybe absent
2018-03-05_16:42:27 GTAG_ACHIM presence: absent
2018-03-06_12:07:58 GTAG_ACHIM presence: maybe absent
2018-03-06_13:04:19 GTAG_ACHIM presence: absent

Mit anderen Worten unvorhersehbar und für mich aktuell leider unbrauchbar.

Meine collectord config sieht so aus:

Code Auswählen Erweitern

[RPI2]
address=127.0.0.1
port=5333
presence_timeout=120
absence_timeout=10

[RPI0]
address=192.168.1.100
port=5333
presence_timeout=120
absence_timeout=10

[Markus Bloch]

Deine Beobachtungen passen auf meine Vermutung, dass eine hängende Verbindung von collectord zu lepresenced der Grund für die Probleme sind.

Was sagen denn die Logfiles von collectord und deinen lepresenced-Instanzen mit und ohne die vorgeschlagene Änderung?

Gruß
Markus

[mumpitzstuff]

Das ist mein nächstes Problem, da wollte ich auch schon rein sehen, nur ich finde sie nicht. Unter /var/log ist absolut nichts zu finden, weder von lepresenced noch von collectord. Ich hab auch auf dem Haupt Pi und dem Pi Zero gesucht und nichts gefunden. Wenn ich wüsste wie das Logfile heißen müsste, dann könnte ich mal danach suchen...

Und das mit den komischen Zeiten kann eigentlich nicht an einer hängenden Verbindung liegen. Es ist alles aktiv und rennt einwandfrei in dieser Zeit. Ich hab jetzt mehrmals den Tag in Silberpapier eingewickelt und so ein absent simuliert und es kommt eigentlich immer eine sehr dubiose Zeit zustande.

[Markus Bloch]

Es gibt auch in der aktuellen Linuxwelt keine Logfiles mehr, da mit Der Einführung von systemd sämtliche Meldungen im Journal gespeichert werden. Das Journal kann man mit dem Befehl journalctl einsehen.

Viele Grüße

Markus

[mumpitzstuff]

Hmm das war schwieriger als gedacht hier irgendwas brauchbares zu erhalten. Hier ist erst mal ein Logfile von collectord (G-Tag wurde nach dem Start von collectord in Silberpapier eingewickelt).

G-Tag 1: beginnt im Logfile mit 6... ist der von meiner Frau und der ist die ganze Zeit present
G-Tag 2: beginnt im Logfile mit 9... ist mein G-Tag und wurde in Silberpapier eingewickelt
G-Tag 3: beginnt im Logfile mit 7... ist der G-Tag von Oma und Opa und aktuell immer absent

Laut Logfile in FHEM ist mein G-Tag um 19:13 Uhr auf maybe absent gegangen und erst um 20:10 Uhr auf absent. Das ist leider fast eine halbe Stunde zu spät. Ich lasse aktuell einen zweiten Versuch laufen.

[mumpitzstuff]

Hier noch der Zweite Versuch, alles noch ohne deine Änderung:

Auch hier ist wieder das der G-Tag den ich mit Silberpapier umwickelt habe:

Code Auswählen Erweitern

2018-03-07 21:00:21 - (Main Thread) - received new command from 127.0.0.1:37248 - 7C:2F:80:C4:58:B8|10
2018-03-07 21:00:21 - (Main Thread) - generating new UUID for client 127.0.0.1 - a7b5f6fc5668335f8959e93177edc827

Laut FHEM war der G-Tag um 21:16 Uhr maybe absent und um 22:02 absent.

Inzwischen habe ich auch eine Vermutung woran es liegen könnte. Ich habe das Abfrageintervall von collectord und vom PRESENCE device jeweils auf 10s gelegt. Durch einen gewissen Jitter kommt es jetzt vermutlich dazu, dass das PRESENCE Device manchmal keinen neuen Wert erhält, weil dieser vielleicht erst Millisekunden später zur Verfügung gestanden hätte. Wenn das der Fall ist, dann wird vermutlich der presenceThreshold nicht um 1 nach unten gezählt. Je nachdem wie oft das dann passiert und wie hoch mal den presenceThreshold eingestellt hat, verschiebt sich der Wechsel nach absent unvorhersehbar nach hinten. Um diese Theorie zu untermauern, setze ich jetzt mal die collectord timeouts etwas niedriger an als die vom PRESENCE device. Melde mich mit den Ergebnissen.

[mumpitzstuff]

Hat sich leider nicht ganz bewahrheitet aber halb:

Mit der Einstellung

Code Auswählen Erweitern

presence_timeout=118
absence_timeout=8


sieht das im Logfile so aus:

Code Auswählen Erweitern

2018.03.07 23:53:24 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.07 23:53:24 4: PRESENCE (GTAG_ACHIM) - device is absent after 163 checks. 17 checks left before going absent
2018.03.07 23:53:40 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.07 23:53:40 4: PRESENCE (GTAG_ACHIM) - device is absent after 164 checks. 16 checks left before going absent
2018.03.07 23:53:56 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.07 23:53:56 4: PRESENCE (GTAG_ACHIM) - device is absent after 165 checks. 15 checks left before going absent
2018.03.07 23:54:12 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.07 23:54:12 4: PRESENCE (GTAG_ACHIM) - device is absent after 166 checks. 14 checks left before going absent
2018.03.07 23:54:28 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.07 23:54:28 4: PRESENCE (GTAG_ACHIM) - device is absent after 167 checks. 13 checks left before going absent
2018.03.07 23:54:44 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.07 23:54:44 4: PRESENCE (GTAG_ACHIM) - device is absent after 168 checks. 12 checks left before going absent
2018.03.07 23:55:00 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.07 23:55:00 4: PRESENCE (GTAG_ACHIM) - device is absent after 169 checks. 11 checks left before going absent
2018.03.07 23:55:16 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.07 23:55:16 4: PRESENCE (GTAG_ACHIM) - device is absent after 170 checks. 10 checks left before going absent
2018.03.07 23:55:32 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.07 23:55:32 4: PRESENCE (GTAG_ACHIM) - device is absent after 171 checks. 9 checks left before going absent
2018.03.07 23:55:48 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.07 23:55:48 4: PRESENCE (GTAG_ACHIM) - device is absent after 172 checks. 8 checks left before going absent
2018.03.07 23:56:04 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.07 23:56:04 4: PRESENCE (GTAG_ACHIM) - device is absent after 173 checks. 7 checks left before going absent
2018.03.07 23:56:20 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.07 23:56:20 4: PRESENCE (GTAG_ACHIM) - device is absent after 174 checks. 6 checks left before going absent
2018.03.07 23:56:36 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.07 23:56:36 4: PRESENCE (GTAG_ACHIM) - device is absent after 175 checks. 5 checks left before going absent
2018.03.07 23:56:52 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.07 23:56:52 4: PRESENCE (GTAG_ACHIM) - device is absent after 176 checks. 4 checks left before going absent
2018.03.07 23:57:08 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.07 23:57:08 4: PRESENCE (GTAG_ACHIM) - device is absent after 177 checks. 3 checks left before going absent
2018.03.07 23:57:24 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.07 23:57:24 4: PRESENCE (GTAG_ACHIM) - device is absent after 178 checks. 2 checks left before going absent
2018.03.07 23:57:40 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.07 23:57:40 4: PRESENCE (GTAG_ACHIM) - device is absent after 179 checks. 1 check left before going absent
2018.03.07 23:57:56 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.07 23:57:56 2: ROOMMATE set rr_ACHIM absent

Mit der Einstellung

Code Auswählen Erweitern

presence_timeout=60
absence_timeout=5


so

Code Auswählen Erweitern

2018.03.08 00:20:35 4: PRESENCE (GTAG_ACHIM) - device is absent after 1 check. 179 checks left before going absent
2018.03.08 00:20:35 5: PRESENCE (GTAG_ACHIM) - received data: command accepted
2018.03.08 00:20:41 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.08 00:20:41 4: PRESENCE (GTAG_ACHIM) - device is absent after 2 checks. 178 checks left before going absent
2018.03.08 00:20:56 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.08 00:20:56 4: PRESENCE (GTAG_ACHIM) - device is absent after 3 checks. 177 checks left before going absent
2018.03.08 00:21:11 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.08 00:21:11 4: PRESENCE (GTAG_ACHIM) - device is absent after 4 checks. 176 checks left before going absent
2018.03.08 00:21:26 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.08 00:21:26 4: PRESENCE (GTAG_ACHIM) - device is absent after 5 checks. 175 checks left before going absent
2018.03.08 00:21:37 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.08 00:21:37 4: PRESENCE (GTAG_ACHIM) - device is absent after 6 checks. 174 checks left before going absent
2018.03.08 00:21:51 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.08 00:21:51 4: PRESENCE (GTAG_ACHIM) - device is absent after 7 checks. 173 checks left before going absent
2018.03.08 00:22:02 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.08 00:22:02 4: PRESENCE (GTAG_ACHIM) - device is absent after 8 checks. 172 checks left before going absent
2018.03.08 00:22:16 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.08 00:22:16 4: PRESENCE (GTAG_ACHIM) - device is absent after 9 checks. 171 checks left before going absent
2018.03.08 00:22:27 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.08 00:22:27 4: PRESENCE (GTAG_ACHIM) - device is absent after 10 checks. 170 checks left before going absent
2018.03.08 00:22:41 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.08 00:22:41 4: PRESENCE (GTAG_ACHIM) - device is absent after 11 checks. 169 checks left before going absent
2018.03.08 00:22:56 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.08 00:22:56 4: PRESENCE (GTAG_ACHIM) - device is absent after 12 checks. 168 checks left before going absent
2018.03.08 00:23:11 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.08 00:23:11 4: PRESENCE (GTAG_ACHIM) - device is absent after 13 checks. 167 checks left before going absent
2018.03.08 00:23:26 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.08 00:23:26 4: PRESENCE (GTAG_ACHIM) - device is absent after 14 checks. 166 checks left before going absent
2018.03.08 00:23:41 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.08 00:23:41 4: PRESENCE (GTAG_ACHIM) - device is absent after 15 checks. 165 checks left before going absent
2018.03.08 00:23:56 5: PRESENCE (GTAG_ACHIM) - received data: absence;room=;rooms=;rssi=;
2018.03.08 00:23:56 4: PRESENCE (GTAG_ACHIM) - device is absent after 16 checks. 164 checks left before going absent

Die Intervalle können hier irgendwie alles zwischen 6s und 15s sein. Wahrscheinlich wäre das auch im ersten Beispiel zu sehen, wenn ich früher Verbose 5 aktiviert hätte.

[Markus Bloch]

Bei der Nutzung von collectord gilt folgendes Verhalten in Bezug auf die Intervalle:

Die Intervalle, welche in der PRESENCE-Definition angegeben sind, werden durch den collectord auch genutzt. Da ja aber jeder Raum eigene Intervalle in der collectord.cfg gesetzt hat, werden die Intervalle aus PRESENCE als Reporting-Intervalle verwendet. Bedeutet also, erst, wenn das entsprechende Intervall verstrichen ist, darf erst eine Statusmeldung an PRESENCE gesendet werden. Anschließend gilt bis zum nächsten Interval Sendepause.

Hintergrund dieses Verhaltens: Wenn in einem Raum der Tag anwesend ist und in anderen Räumen nicht, würde dennoch von den abwesenden Räumen aller 8-Sekunden (mit deinen aktuellen Einstellungen) eine Statusmeldung kommen und diese so direkt an PRESENCE gehen und das obwohl der Tag in einem anderen Raum anwesend ist.

Wenn man also die Intervalle direkt in PRESENCE runterdreht bewirkt man also eine häufigere Statusmeldung durch den collectord, sobald irgendein Raum ein Ergebnis meldet (absent/present).

Ich hoffe das war verständlich formuliert.

Viele Grüße

Markus