[gelöst] FHEM Absturz verursacht durch collectord?

[JWRu]

Die Weboberfläche meines Systems war heute Morgen plötzlich nicht mehr zu erreichen. Die nähere Untersuchung ergab, dass FHEM in einer Restart-Schleife hing. Irgendetwas verursachte einen Absturz, das Betriebssystem hat dann (wegen "restart=always" in fhem.service) den Dienst neu gestartet usw. usw.
Ich habe wohl auch den Verusacher gefunden: Sobald ich den Dienst collectord stoppe, startet FHEM einwandfrei.
Die PRESENCE-Devices, die auf collectord zugreifen, stehen dann auf "disconnected". Ich kann dann sogar collectord wieder starten. Sobald ich aber eines der PRESENCE-Devices auf "active" setzen will, geht die Restart-Schleife wieder los.
Im FHEM Log ist zum Absturzzeitpunkt nur eine Zeile

Code Auswählen Erweitern

2020.02.18 14:44:46 1: undefined
zu finden.

[mumpitzstuff]

Was soll uns das nun sagen?

Es wäre mit Sicherheit hilfreich, wenn du lists deiner presence devices und deine collectord configuration posten würdest...

[JWRu]

Das mache ich gerne.
ich verstehe halt nicht, wieso die Konfiguration monatelang problemlos gelaufen ist.

collectord. conf:

Code Auswählen Erweitern

[ZBox]
address=127.0.0.1
port=5333
presence_timeout=180
absence_timeout=180

[ZBox_BT]
address=127.0.0.1
port=5111
presence_timeout=180
absence_timeout=180

[RasPi-Zero]
address=192.168.178.86
port=5333
presence_timeout=180
absence_timeout=180

[RasPi-Zero_BT]
address=192.168.178.86
port=5111
presence_timeout=180
absence_timeout=180

List eines PRESENCE-Devices:

Code Auswählen Erweitern


Internals:
   ADDRESS    XX:XX:XX:XX:XX:XX
   DEF        lan-bluetooth XX:XX:XX:XX:XX:XX 127.0.0.1:5222 120
   DeviceName 127.0.0.1:5222
   FUUID      5c447ba1-f33f-c1fa-49a1-1c98c9e269b699d9
   INTERVAL_NORMAL 120
   INTERVAL_PRESENT 120
   MODE       lan-bluetooth
   NAME       Jochen_GTag
   NEXT_OPEN  1582038858
   NOTIFYDEV  global
   NR         209
   NTFY_ORDER 50-Jochen_GTag
   PARTIAL   
   STATE      disconnected
   TYPE       PRESENCE
   OLDREADINGS:
   READINGS:
     2020-02-07 09:11:44   command_accepted yes
     2020-02-17 23:59:38   daemon          lepresenced V0.9
     2020-02-17 23:59:38   device_name     Gigaset G-tag
     2020-02-18 15:07:11   model           lan-bluetooth
     2020-02-17 23:59:38   presence        present
     2020-02-17 23:59:38   room            RasPi-Zero
     2020-02-17 23:59:38   rooms           RasPi-Zero
     2020-02-17 23:59:38   rssi            -71
     2020-02-17 23:59:38   rssi_RasPi-Zero -71
     2020-02-17 23:02:42   rssi_ZBox       -80
     2020-02-18 16:13:18   state           disconnected
   helper:
     ABSENT_COUNT 0
     PRESENT_COUNT 0
Attributes:
   absenceThreshold 3
   room       Anwesenheit
   stateFormat presence room
   userattr   Anwesenheit Anwesenheit_map structexclude

Die Bluetooth-MAC habe ich etwas "verfremdet"

[MadMax-FHEM]

Nicht Config-Ausschnitte sondern "lists":

Code Auswählen Erweitern


list Devicename


in FhemWeb...
...Ausgabe hier posten.

Es wäre auch gut, etwas mehr Log zu sehen...
...nur der Schnipsel, der deiner Meinung nach die Ursache andeutet ist etwas wenig...

Gruß, Joachim

[JWRu]

Das List ist oben zu finden (habe zu schnell auf Return gehauen)

Ein Ausschnitt aus der Log-Datei:

Code Auswählen Erweitern

2020.02.18 13:40:09 3: Sduino: SimpleWrite_XQ, disable receiver (XQ)
2020.02.18 13:40:09 3: Sduino_2: SimpleWrite_XQ, disable receiver (XQ)
2020.02.18 13:40:09 3: Sduino: StartInit, get version, retry = 0
2020.02.18 13:40:09 3: Sduino_2: StartInit, get version, retry = 0
2020.02.18 13:40:09 3: DbLog myDbLog - Creating Push-Handle to database mysql:database=fhem;host=localhost;port=3306 with user fhemuser
2020.02.18 13:40:09 3: DbLog myDbLog - Push-Handle to db mysql:database=fhem;host=localhost;port=3306 created
2020.02.18 13:40:09 3: DbLog myDbLog - UTF8 support enabled
2020.02.18 13:40:09 3: NUT antwortet nicht
2020.02.18 13:40:09 1: 192.168.178.13:3493 disconnected, waiting to reappear (UPS_1)
2020.02.18 13:40:09 1: 192.168.178.13:3493 reappeared (UPS_1)
2020.02.18 13:40:09 3: Opening HMLANGW:keepAlive device 192.168.178.87:2001
2020.02.18 13:40:09 3: HMLANGW device opened
2020.02.18 13:40:09 1: undefined
2020.02.18 13:40:11 3: telnetPort: port 7027 opened
2020.02.18 13:40:11 3: WEB: port 8083 opened
2020.02.18 13:40:11 3: WEBphone: port 8084 opened
2020.02.18 13:40:11 3: WEBtablet: port 8085 opened
2020.02.18 13:40:11 2: eventTypes: loaded 4923 events from ./log/eventTypes.txt
2020.02.18 13:40:12 3: TelegramBot_Define WeRu_FHEM_bot: called
2020.02.18 13:40:12 3: EN2IR: interval is 0, no periodic updates will done.
2020.02.18 13:40:12 3: EN2IR: Defined with URL http://192.168.178.90:83/ featurelevel 6

Der Restart von FHEM passierte hier um 13:40:11

Hier ein anderer Ausschnitt aus dem Log

Code Auswählen Erweitern

2020.02.18 11:28:43 3: Sduino: SimpleWrite_XQ, disable receiver (XQ)
2020.02.18 11:28:43 3: Sduino_2: SimpleWrite_XQ, disable receiver (XQ)
2020.02.18 11:28:43 3: Sduino: StartInit, get version, retry = 0
2020.02.18 11:28:43 3: Sduino_2: StartInit, get version, retry = 0
2020.02.18 11:28:43 3: DbLog myDbLog - Creating Push-Handle to database mysql:database=fhem;host=localhost;port=3306 with user fhemuser
2020.02.18 11:28:43 3: DbLog myDbLog - Push-Handle to db mysql:database=fhem;host=localhost;port=3306 created
2020.02.18 11:28:43 3: DbLog myDbLog - UTF8 support enabled
2020.02.18 11:28:43 3: NUT antwortet nicht
2020.02.18 11:28:43 1: 192.168.178.13:3493 disconnected, waiting to reappear (UPS_1)
2020.02.18 11:28:43 1: 192.168.178.13:3493 reappeared (UPS_1)
2020.02.18 11:28:43 2: Sduino_2: CheckCmdResp, initialized v3.4.1
2020.02.18 11:28:43 3: Sduino_2: CheckCmdResp, enable receiver (XE)
2020.02.18 11:28:43 2: Sduino: CheckCmdResp, initialized v3.4.1
2020.02.18 11:28:43 3: Sduino: CheckCmdResp, enable receiver (XE)
2020.02.18 11:28:43 3: FHEM2FHEM device opened (FHEM2)
2020.02.18 11:28:43 1: undefined
2020.02.18 11:28:45 3: telnetPort: port 7027 opened
2020.02.18 11:28:45 3: WEB: port 8083 opened
2020.02.18 11:28:45 3: WEBphone: port 8084 opened
2020.02.18 11:28:45 3: WEBtablet: port 8085 opened
2020.02.18 11:28:45 2: eventTypes: loaded 4923 events from ./log/eventTypes.txt
2020.02.18 11:28:45 3: TelegramBot_Define WeRu_FHEM_bot: called
2020.02.18 11:28:46 3: EN2IR: interval is 0, no periodic updates will done.
2020.02.18 11:28:46 3: EN2IR: Defined with URL http://192.168.178.90:83/ featurelevel 6
2020.02.18 11:28:46 2: Daemmerungsschalter: Unknown sensor device Helligkeit_aussen specified
2020.02.18 11:28:46 3: Opening UPS_1 device 192.168.178.13:3493
2020.02.18 11:28:46 3: UPS_1 device opened
2020.02.18 11:28:46 3: Opening Flowmeter_03 device /dev/serial/by-id/usb-FTDI_FT232R_USB_UART_AH05N0OQ-if00-port0
2020.02.18 11:28:46 3: Setting Flowmeter_03 serial parameters to 9600,8,N,1

Der Restart hier um 11:28:45

in /var/log/daemon.log finde ich jedesmal dann so etwas:

Code Auswählen Erweitern

Feb 18 11:28:44 ZBox systemd[1]: fhem.service: Service hold-off time over, scheduling restart.
Feb 18 11:28:44 ZBox systemd[1]: Stopped FHEM Home Automation.
Feb 18 11:28:44 ZBox systemd[1]: Starting FHEM Home Automation...
Feb 18 11:28:45 ZBox systemd[1]: Started FHEM Home Automation.


[mumpitzstuff]

Sieht eigentlich unverdächtig aus. Warum ist jedes Gerät über 2 Ports angebunden? Eins davon ist vermutlich lepresenced?!?

[JWRu]

Auf beiden Geräten laufen presenced (port 5111) und lepresenced (port 5333).

[mumpitzstuff]

Okay. Wenn das schon Monate läuft, sollte das ja nicht die Ursache sein. Hast du irgend was aktualisiert in den letzten Tagen bzw. kannst du Spaßeshalber mal ein Backup einspielen und gucken, ob die Probleme damit weg sind? Oder schlicht mal den Rechner neu booten... wird schwierig hier was konstruktives beizutragen, dazu ist die Datenlage zu dünn.

[JWRu]

Habe alle PRESENCE-Devices gelöscht, collectord wieder aktiviert, Devices neu angelegt - alles läuft wieder wie früher.
Weiß der Himmel, was das war.

[JWRu]

Ich muss das Thema nochmal hervorkramen. Nachdem alles drei Wochen lang problemlos lief, gestern wieder dasselbe: FHEM hing in einer Endlos-Restartschleife. Ich musste wieder den Service collectord stoppen, damit FHEM startete.

[JWRu]

Das Problem saß mal wieder vor dem Bildschirm.
Es war ein notify auf ein PRESENCE-Device, das FHEM in die Restartschleife geschickt hat.
Ich hatte ein "exit(0)" in den Perl-Code geschrieben, weil ich dachte, diesen bei einer bestimmten Bedingung damit abbrechen zu können.
Der Befehl hat aber auch das aufrufende FHEM sauber beendet, so dass ich in den Logs keine Spuren gefunden habe. FHEM ist dann wieder gestartet, das notify hat wieder ausgelöst, usw. usw.