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

[Damian]

2020.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]

Nach 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]

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]

Dabei 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]

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]

Wie sieht Deine system.d Config aus?

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

[CoolTux]

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]

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]

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]

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]

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]

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

[Byte09]

....
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]

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

Offenbar scheitert der Startvorgang.
Der Aufruf:

sudo systemctl start fhem

liefert eine Fehlermeldung:

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

journalctl -xe

liefert:

-- 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]

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

[Damian]

Da es ein frisch installiertes System ist, nichts was einen überraschen sollte:

pi@raspberrypi:/etc/systemd/system $ cat fhem.service
# $Id: fhem.service 19235 2019-04-21 13:26:17Z betateilchen $

[Unit]
Description=FHEM Home Automation
Wants=network.target
After=network.target
#Requires=postgresql.service
#After=postgresql.service
#Requires=mysql.service
#After=mysql.service

[Service]
Type=forking
User=fhem
Group=dialout
WorkingDirectory=/opt/fhem
ExecStart=/usr/bin/perl fhem.pl fhem.cfg
#ExecStart=/usr/bin/perl fhem.pl configDB
Restart=always

[Install]
WantedBy=multi-user.target

[Otto123]

Ich meine wir hatten letztens so was ähnliches. Da fehlte glaub ich bloß ein Modul im System. Dummerweise gab es da auch keinen Hinweis in einem Log.

[CoolTux]

Für einen Test und kurzfristige Lösung

Ersetze forking durch simple

[yersinia]

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

here you go

Code Auswählen Erweitern

# $Id: fhem.service 19235 2019-04-21 13:26:17Z betateilchen $

[Unit]
Description=FHEM Home Automation
Wants=network.target
After=network.target
#Requires=postgresql.service
#After=postgresql.service
#Requires=mysql.service
#After=mysql.service

[Service]
Type=forking
User=fhem
Group=dialout
WorkingDirectory=/opt/fhem
ExecStart=/usr/bin/perl fhem.pl fhem.cfg
#ExecStart=/usr/bin/perl fhem.pl configDB
Restart=always

[Install]
WantedBy=multi-user.target
Ich habe FHEM Ende Dezember auf RasPi 4 mit Raspbian Buster (via) installiert und über restore wie in Ottos Blog beschrieben

Code Auswählen Erweitern

sudo tar -xvzf /home/pi/FHEM-201xxxxx_xxxxxx.tar.gz -C /opt/fhem/
migriert. Bewusst bzw manuell habe ich fhem.service nicht angepackt.

uname -a

Code Auswählen Erweitern

Linux fhempi4 4.19.93-v7l+ #1290 SMP Fri Jan 10 16:45:11 GMT 2020 armv7l GNU/Linux

[Morgennebel]

www.devuan.org und ohne systemd arbeiten...

Ciao, -MN

[Damian]

Endlich - Fehler gefunden.

Es hat mich zwei Tage Suche meine Lebens gekostet 

Die Herausforderung war eine cfg-Datei mit 624 entities zu überprüfen

Server started with 624 defined entities (fhem.pl:21056/2020-01-26 perl:5.028001 os:linux user:fhem pid:2407)

Ich wette, dass keiner drauf kommen wird.

Als Tipp zum raten, es war ein Attribut in global, welches von fhem sogar selbst gesetzt wurde

[herrmannj]

Nun ist die Neugier geweckt.

[enno]

https://de.wikipedia.org/wiki/Clickbaiting

Jetzt bin ich aber gespannt...

Gruss
  Enno

[CoolTux]

Es war das Logfile Attribut!

Was habe ich gewonnen?

[herrmannj]

Verbose. (Glaube nicht dass ich damit gewinne. Aber he...)

[enno]

Wenn es was zu gewinnen gibt  Ich tippe auf Attribut nofork

Gruss
  Enno

[TomLee]

featurelevel das ab jetzt per default aktiviert ist.

[Damian]

Wenn es was zu gewinnen gibt  Ich tippe auf Attribut nofork

Gruss
  Enno

Du hast gewonnen!

Hilfe zum Attribut:

nofork
Wenn dieses Attribut oder "attr global logfile -" gesetzt ist, dann wird FHEM nicht im Hintergrund abgearbeitet. Dieses Attribut ist bei einigen FHEM Installationen auf FRITZ!-Boxen notwendig, und wird fuer Windows automatisch gesetzt.

[CoolTux]

Ah siehste und ich hatte "attr global logfile -"

[Wernieman]

Stimmt .. war irgendwo schon mal so ..

Dürfte an dem Config-File liegen. Das geht nicht davon aus, das geforkt wird ..

P.S. Unter welchem user wird fhem jetzt ausgeführt? Prüfe das mal ..

[CQuadrat]

Also war Windows schuld [emoji6]


Duck und weg....





Gesendet mit meiner Reiseschreibmaschine.

[enno]

Du hast gewonnen!

Super! Danke! Ich spende den Gewinn CoolTux... 

Gruss
  Enno