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
2020.02.18 14:44:46 1: undefined
zu finden.
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...
Das mache ich gerne.
ich verstehe halt nicht, wieso die Konfiguration monatelang problemlos gelaufen ist.
collectord. conf:
[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:
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"
Nicht Config-Ausschnitte sondern "lists":
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
Das List ist oben zu finden (habe zu schnell auf Return gehauen)
Ein Ausschnitt aus der Log-Datei:
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
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:
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.
Sieht eigentlich unverdächtig aus. Warum ist jedes Gerät über 2 Ports angebunden? Eins davon ist vermutlich lepresenced?!?
Auf beiden Geräten laufen presenced (port 5111) und lepresenced (port 5333).
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.
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.
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.
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.