(gelöst) Unmotivierter Server shutdown nach dem FHEM-Start

Damian · 28 Januar 2020, 22:32:32

Zitat2020.01.28 22:12:51.398 5: CUL_HM Tuer protEvent:CMDs_done
2020.01.28 22:12:51.398 5: CUL_HM Tuer sent ACK:2
2020.01.28 22:12:51.511 4: CUL_HM Tuer dupe: dont process
2020.01.28 22:12:51.877 3: CUL_HM set Wandleuchten_W statusRequest
2020.01.28 22:13:37.577 0: Server shutdown
2020.01.28 22:13:38.620 1: Including fhem.cfg
2020.01.28 22:13:38.844 3: WEBHOME: port 8086 opened
2020.01.28 22:13:38.871 3: Opening CUL device /dev/serial/by-id/usb-busware.de_CUL868-if00
2020.01.28 22:13:38.901 3: Setting CUL serial parameters to 9600,8,N,1

Nach dem Start von FHEM rebootet das System zyklisch.

Zum Hintergrund: Ich habe mein FHEM-System von Windows auf einen neu installierten Pi4 Fhemrelease 6.0 umgezogen.
Nach Anpassung der jeweiligen Device-Namen wird das System sauber hochgefahren, nach ca. 40-50 Sekunden rebootet FHEM ohne weitere Fehlermeldung.

Wie kann ich dem Übeltäter auf die Spur kommen?

Otto123 · 28 Januar 2020, 23:06:55

ZitatNach Anpassung der jeweiligen Device-Namen wird das System sauber hochgefahren,

Hallo Damian,

wie muss ich mir das vorstellen? Du hast nach der Installation FHEM beendet, editierst die fhem.cfg und startest fhem wieder über systemctl start fhem?

Der loggt doch den shutdown? Da bekommt er doch einen entsprechenden Befehl und ist nicht einfach weg?
Systemd sollte dann den restart ausführen.

Ich würde jetzt in erster Linie die "HW Device s" in Verdacht haben und diese Schritt für Schritt aus der Konfig rausnehmen.

Gruß Otto

Damian · 28 Januar 2020, 23:37:34

Zitat von: Otto123 am 28 Januar 2020, 23:06:55
Hallo Damian,

wie muss ich mir das vorstellen? Du hast nach der Installation FHEM beendet, editierst die fhem.cfg und startest fhem wieder über systemctl start fhem?

Gruß Otto

Ja, ich habe eine umfangreiche Konfiguration, die ich nicht Device für Device einzeln nachziehen möchte, zumal es mein Produktivsystem ist. Daher war meine Hoffnung gewesen, die cfg-Datei zu übernehmen. Dabei musste ich die USB-Devices manuell in der cfg anpassen, da mein System bis jetzt unter Windows läuft. Nach dem Umstecken der USB-Geräte und dem Start über 'sudo systemctl start fhem' funktioniert auch alles, soweit ich das bisher beurteilen konnte, bis auf die Reboots von fhem (nicht vom Raspi). Ich gehe davon aus, dass der Service (warum auch immer) von außen beendet und neu startet wird. Innerhalb von FHEM habe ich keine spezifischen Systemaufrufe. Ich gehe davon aus, dass kein Modul und auch nicht FHEM selbst auf die Idee kommt einen shutdown zu initiieren, schon gar nicht ohne eine Fehlermeldung im Log.

Otto123 · 28 Januar 2020, 23:43:21

ZitatDabei musste ich die USB-Devices manuell in der cfg anpassen,

Hast Du als Quelle für deine manuelle Anpassung die Geräte vorher mal einzeln in einer Testinstallation eingebunden?

Du kannst auch einfach versuchen, die USB Geräte einer nach dem anderen ab zu ziehen. Aber kann sein das dann Dein FHEM stehen bleibt.
Hast du initialUsbCheck deaktiviert?

Mir klingt das auch nach einem shutdown von außen. Irgendeiner sendet ein kill an den FHEM Prozess. Müsste man das nicht irgendwo sehen? syslog?

CoolTux · 29 Januar 2020, 05:54:29

Und kurz vor dem Reboot steht nichts im Logfile? Wenn Du ein systemctl stop fhem und danach systemctl start fhem machst, brauch er dann lange bis zu nach der Befehlsabgabe wieder einen prompt hast um weitere Befehle eingeben zu können?

Wernieman · 29 Januar 2020, 08:09:09

Wie sieht Deine system.d Config aus?

Irgendwie erinnert mich das an einen Fehler, welchen wir vor kurzem schon mal hatten ....

CoolTux · 29 Januar 2020, 08:21:02

Zitat von: Wernieman am 29 Januar 2020, 08:09:09
Wie sieht Deine system.d Config aus?

Irgendwie erinnert mich das an einen Fehler, welchen wir vor kurzem schon mal hatten ....

Eventuell schlägt hier der Systemd Watchdog zu. Aber das ist nur eine Vermutung. Daher würde mich interessieren ob der systemctl Befehl korrekt und relativ zeitnah den prompt wieder frei gibt.

Otto123 · 29 Januar 2020, 08:52:10

Zitat von: CoolTux am 29 Januar 2020, 08:21:02
Eventuell schlägt hier der Systemd Watchdog zu.

Wie genau schlägt der zu? Ich dachte wenn der Prozess weg ist?
Im Log braucht er 46 sec zwischen dem letzten CUL_HM Eintrag und dem Eintrag von FHEM Server Shutdown. Das bedeutet doch für mich: FHEM lebt, er bekommt einen Shutdown Befehl (woher auch immer) und protokolliert den ordentlich.
Was prüft der systemd watchdog? Der kann doch nur den eigenen Prozess prüfen?

Damian · 29 Januar 2020, 09:08:56

Ich bin jetzt nicht zuhause, daher kann ich erst heute Abend im System nachschauen. Was ich sagen kann ist, dass der Reboot nicht lange dauert. Im Browser kommt kurz die Meldung, dass die WEB-Instanz nicht erreichbar ist und kurz danach (5-10 Sekunden) geht´s weiter. Solange dauert offenbar der Bootvorgang.

Es scheint auch nicht mit den HW-Devices direkt etwas zu tun zu haben. Ich meine sie schon mal alle aus der cfg zum Testen ausgetragen zu haben (werde ich aber noch mal testen). Die automatisch Einbindung der Geräte habe ich deaktiviert.

Die HW-Devices sind: CUL868, CUL433, HMLAN und SML über USB.

Eine "nackte" Installation von fhem rebootet nicht, es hat also etwas mit meiner Konfiguration zu tun.

CoolTux · 29 Januar 2020, 09:15:25

Zitat von: Otto123 am 29 Januar 2020, 08:52:10
Wie genau schlägt der zu? Ich dachte wenn der Prozess weg ist?
Im Log braucht er 46 sec zwischen dem letzten CUL_HM Eintrag und dem Eintrag von FHEM Server Shutdown. Das bedeutet doch für mich: FHEM lebt, er bekommt einen Shutdown Befehl (woher auch immer) und protokolliert den ordentlich.
Was prüft der systemd watchdog? Der kann doch nur den eigenen Prozess prüfen?

Ich hatte mal das Problem das auf Grund einer Testconfig kein FHEM Logfile in global vergeben war, somit wurde das Loging auf die Konsole ausgegeben und der systemd hat dadurch nicht mehr mitbekommen das FHEM korrekt gestartet wurde. Und hat dann alle 2 Minuten den FHEM Prozess neu gestartet.

yersinia · 29 Januar 2020, 10:05:12

Ich lese mal mit, ich habe das Problem - allerdings sporadisch - ebenso. Es hat bisher aber keine negativen Auswirkungen; außer die ein oder andere Schrecksekunde wenn FHEM länger zum starten (=Webfrontend) benötigt.
Selten passiert es, dass FHEM nach einem shutdown restart nach erfolgreichem Start wieder runterfährt und startet und dann normal läuft. Das Phänomen beobachte ich seit ca 1 Jahr, auf Raspi 3 und Raspi 4. Wie gesagt, sporadisch und selten. System-log und FHEM-log geben keine Auskunft über mögliche Ursachen.
Weiterhin hatte ich letztens den Eindruck, dass FHEM nach einem shutdown nicht nur runter- sondern auch (ungewollt) wieder hochfährt. oO
(dass der FHEM service nach einem shutdown weiterhin läuft ist wahrscheinlich gewollt)

Wernieman · 29 Januar 2020, 10:54:38

Auch da würde mich das System.d-File interessieren ..

Byte09 · 29 Januar 2020, 11:28:44

Zitat von: yersinia am 29 Januar 2020, 10:05:12....
Weiterhin hatte ich letztens den Eindruck, dass FHEM nach einem shutdown nicht nur runter- sondern auch (ungewollt) wieder hochfährt. oO
(dass der FHEM service nach einem shutdown weiterhin läuft ist wahrscheinlich gewollt)

dieses hatte ich heute morgen auch - ist mir allerdings heute das erste mal aufgefallen. Ich glaube aber das ist eine andere Baustelle - falls es eine ist/wird .

gruss Byte09

Damian · 29 Januar 2020, 16:27:21

Ich habe mal meine vier HW-Devices herausgenommen - Reboot besteht weiterhin.

Offenbar scheitert der Startvorgang.
Der Aufruf:

sudo systemctl start fhem

liefert eine Fehlermeldung:

ZitatJob for fhem.service failed because a timeout was exceeded.
See "systemctl status fhem.service" and "journalctl -xe" for details.

journalctl -xe

liefert:

Zitat
Zitat-- A start job for unit fhem.service has finished with a failure.
--
-- The job identifier is 5176 and the job result is failed.
Jan 29 16:21:55 raspberrypi systemd[1]: fhem.service: Service RestartSec=100ms expired, scheduling restart.
Jan 29 16:21:55 raspberrypi systemd[1]: fhem.service: Scheduled restart job, restart counter is at 2.
-- Subject: Automatic restarting of a unit has been scheduled
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- Automatic restarting of the unit fhem.service has been scheduled, as the result for
-- the configured Restart= setting for the unit.
Jan 29 16:21:55 raspberrypi systemd[1]: Stopped FHEM Home Automation.
-- Subject: A stop job for unit fhem.service has finished
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- A stop job for unit fhem.service has finished.
--
-- The job identifier is 5234 and the job result is done.
Jan 29 16:21:55 raspberrypi systemd[1]: Starting FHEM Home Automation...
-- Subject: A start job for unit fhem.service has begun execution
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- A start job for unit fhem.service has begun execution.
--
-- The job identifier is 5234.
Jan 29 16:23:25 raspberrypi systemd[1]: fhem.service: Start operation timed out. Terminating.
Jan 29 16:23:25 raspberrypi systemd[1]: fhem.service: Failed with result 'timeout'.
-- Subject: Unit failed
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- The unit fhem.service has entered the 'failed' state with result 'timeout'.
Jan 29 16:23:25 raspberrypi systemd[1]: Failed to start FHEM Home Automation.
-- Subject: A start job for unit fhem.service has failed
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- A start job for unit fhem.service has finished with a failure.
--
-- The job identifier is 5234 and the job result is failed.
Jan 29 16:23:25 raspberrypi systemd[1]: fhem.service: Service RestartSec=100ms expired, scheduling restart.
Jan 29 16:23:25 raspberrypi systemd[1]: fhem.service: Scheduled restart job, restart counter is at 3.
-- Subject: Automatic restarting of a unit has been scheduled
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- Automatic restarting of the unit fhem.service has been scheduled, as the result for
-- the configured Restart= setting for the unit.
Jan 29 16:23:25 raspberrypi systemd[1]: Stopped FHEM Home Automation.
-- Subject: A stop job for unit fhem.service has finished
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- A stop job for unit fhem.service has finished.
--
-- The job identifier is 5292 and the job result is done.
Jan 29 16:23:25 raspberrypi systemd[1]: Starting FHEM Home Automation...
-- Subject: A start job for unit fhem.service has begun execution
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- A start job for unit fhem.service has begun execution.
--
-- The job identifier is 5292.

D. h., offensichtlich läuft irgendetwas beim Start auf timeout, der Service wird beendet und neu durchgestartet.

Wernieman · 29 Januar 2020, 16:32:22

Ich wiederhole mich ungern:
Wie Sieht Deine system.d für fhem aus?