Fhem startet alle 2 min neu

[Stefan_Ne]

Hallo,

ich habe ein update gefahren und seit den komische Probleme.
Fhem starte ca. alle 2  min neu.
Im Log steht server shutdown, dann kommt ein normaler Neustart.
Kein Fehler nichts im Log.

Viele Grüße
Stefan

[r00t2]

Wollte eigentlich nur "Na das ist ja mal was! Viele Grüße zurück!" schreiben, denn eine konkrete Frage scheinst Du ja nicht zu haben... Aber naja

Dafür fallen mir ein paar ein:
Was für Komponenten hat das System?
Wo ist eine Logdatei zum anschauen?
Welche verbose-Levels werden bei den Komponenten gefahren?

Etwas mehr Infos, bitte.

[Stefan_Ne]

Hallo,

hier ein paar Infos:
- Fhem aktuelle Version
- Homatic
- Mysensors
- FS20
alles zusammen ca. 50 Sensoren / Aktoren

Am Samstag wollte ich die Datenbank reduzieren. Ging leider nicht, also erstmal ein update gefahren.
Ab da läuft das Fhem wie ein Sack Muscheln.

Im Anhang das Log. Es wiederholt sich so im 2 Minuten Takt

Viele Grüße
Stefan

[CoolTux]

Hast Du ein watchog konfiguriert. Also auf Betriebssystem Ebene. Nicht in FHEM.
Zeig bitte ein komplettes Log vom Start bis zum nächsten nicht gewollten neustart.

[Stefan_Ne]

Hallo,

ich habe was im Systemlog von Linux entdeckt

Aug  7 17:52:34 M60 systemd[1]: fhem.service: Service hold-off time over, scheduling restart.
Aug  7 17:52:34 M60 systemd[1]: Stopped FHEM Home Automation.
Aug  7 17:52:34 M60 systemd[1]: Starting FHEM Home Automation...
Aug  7 17:54:04 M60 systemd[1]: fhem.service: Start operation timed out. Terminating.
Aug  7 17:54:07 M60 systemd[1]: Failed to start FHEM Home Automation.
Aug  7 17:54:07 M60 systemd[1]: fhem.service: Unit entered failed state.
Aug  7 17:54:07 M60 systemd[1]: fhem.service: Failed with result 'timeout'.
Aug  7 17:54:08 M60 systemd[1]: fhem.service: Service hold-off time over, scheduling restart.
Aug  7 17:54:08 M60 systemd[1]: Stopped FHEM Home Automation.
Aug  7 17:54:08 M60 systemd[1]: Starting FHEM Home Automation...
Aug  7 17:55:38 M60 systemd[1]: fhem.service: Start operation timed out. Terminating.
Aug  7 17:55:41 M60 systemd[1]: Failed to start FHEM Home Automation.
Aug  7 17:55:41 M60 systemd[1]: fhem.service: Unit entered failed state.
Aug  7 17:55:41 M60 systemd[1]: fhem.service: Failed with result 'timeout'.
Aug  7 17:55:41 M60 systemd[1]: fhem.service: Service hold-off time over, scheduling restart.
Aug  7 17:55:41 M60 systemd[1]: Stopped FHEM Home Automation.
Aug  7 17:55:41 M60 systemd[1]: Starting FHEM Home Automation...

Sehe ich das richtig das der Dienst immer wieder neu gestartet wird.

Viele Grüße
Stefan

[Stefan_Ne]

Hallo,

und das ist das Ergebnis von systemctl status fhem.service, das ist eine Endloschleife, Neustart alle 1,5 Min

● fhem.service - FHEM Home Automation
   Loaded: loaded (/etc/systemd/system/fhem.service; enabled; vendor preset: enabled)
   Active: activating (start) since Tue 2018-08-07 18:05:04 CEST; 1min 29s ago
Cntrl PID: 3557 (perl)
    Tasks: 4 (limit: 4915)
   CGroup: /system.slice/fhem.service
           ├─3557 /usr/bin/perl fhem.pl fhem.cfg
           ├─3582 /usr/bin/perl fhem.pl fhem.cfg
           ├─3583 /usr/bin/perl fhem.pl fhem.cfg
           └─3584 /usr/bin/perl fhem.pl fhem.cfg

Aug 07 18:05:04 M60 systemd[1]: Starting FHEM Home Automation...
root@M60:/opt/fhem/log# systemctl status fhem.service
● fhem.service - FHEM Home Automation
   Loaded: loaded (/etc/systemd/system/fhem.service; enabled; vendor preset: enabled)
   Active: deactivating (final-sigterm) (Result: timeout)
Cntrl PID: 3557 (perl)
    Tasks: 3 (limit: 4915)
   CGroup: /system.slice/fhem.service
           ├─3557 /usr/bin/perl fhem.pl fhem.cfg
           ├─3583 /usr/bin/perl fhem.pl fhem.cfg
           └─3584 /usr/bin/perl fhem.pl fhem.cfg

Aug 07 18:05:04 M60 systemd[1]: Starting FHEM Home Automation...
Aug 07 18:06:34 M60 systemd[1]: fhem.service: Start operation timed out. Terminating.
root@M60:/opt/fhem/log# systemctl status fhem.service
● fhem.service - FHEM Home Automation
   Loaded: loaded (/etc/systemd/system/fhem.service; enabled; vendor preset: enabled)
   Active: activating (start) since Tue 2018-08-07 18:06:38 CEST; 2s ago
Cntrl PID: 3677 (perl)
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/fhem.service
           └─3677 /usr/bin/perl fhem.pl fhem.cfg

Aug 07 18:06:38 M60 systemd[1]: Starting FHEM Home Automation...
root@M60:/opt/fhem/log# systemctl status fhem.service
● fhem.service - FHEM Home Automation
   Loaded: loaded (/etc/systemd/system/fhem.service; enabled; vendor preset: enabled)
   Active: activating (start) since Tue 2018-08-07 18:06:38 CEST; 5s ago
Cntrl PID: 3677 (perl)
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/fhem.service
           └─3677 /usr/bin/perl fhem.pl fhem.cfg

Aug 07 18:06:38 M60 systemd[1]: Starting FHEM Home Automation...
root@M60:/opt/fhem/log# systemctl status fhem.service
● fhem.service - FHEM Home Automation
   Loaded: loaded (/etc/systemd/system/fhem.service; enabled; vendor preset: enabled)
   Active: activating (start) since Tue 2018-08-07 18:06:38 CEST; 9s ago
Cntrl PID: 3677 (perl)
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/fhem.service
           └─3677 /usr/bin/perl fhem.pl fhem.cfg

Aug 07 18:06:38 M60 systemd[1]: Starting FHEM Home Automation...
root@M60:/opt/fhem/log# systemctl status fhem.service
● fhem.service - FHEM Home Automation
   Loaded: loaded (/etc/systemd/system/fhem.service; enabled; vendor preset: enabled)
   Active: activating (start) since Tue 2018-08-07 18:06:38 CEST; 10s ago
Cntrl PID: 3677 (perl)
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/fhem.service
           └─3677 /usr/bin/perl fhem.pl fhem.cfg

Aug 07 18:06:38 M60 systemd[1]: Starting FHEM Home Automation...
root@M60:/opt/fhem/log# systemctl status fhem.service
● fhem.service - FHEM Home Automation
   Loaded: loaded (/etc/systemd/system/fhem.service; enabled; vendor preset: enabled)
   Active: activating (start) since Tue 2018-08-07 18:06:38 CEST; 10s ago
Cntrl PID: 3677 (perl)
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/fhem.service
           └─3677 /usr/bin/perl fhem.pl fhem.cfg

Aug 07 18:06:38 M60 systemd[1]: Starting FHEM Home Automation...
root@M60:/opt/fhem/log# systemctl status fhem.service
● fhem.service - FHEM Home Automation
   Loaded: loaded (/etc/systemd/system/fhem.service; enabled; vendor preset: enabled)
   Active: activating (start) since Tue 2018-08-07 18:06:38 CEST; 11s ago
Cntrl PID: 3677 (perl)
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/fhem.service
           └─3677 /usr/bin/perl fhem.pl fhem.cfg

Aug 07 18:06:38 M60 systemd[1]: Starting FHEM Home Automation...
root@M60:/opt/fhem/log# systemctl status fhem.service
● fhem.service - FHEM Home Automation
   Loaded: loaded (/etc/systemd/system/fhem.service; enabled; vendor preset: enabled)
   Active: activating (start) since Tue 2018-08-07 18:06:38 CEST; 12s ago
Cntrl PID: 3677 (perl)
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/fhem.service
           └─3677 /usr/bin/perl fhem.pl fhem.cfg

Aug 07 18:06:38 M60 systemd[1]: Starting FHEM Home Automation...
root@M60:/opt/fhem/log# systemctl status fhem.service
● fhem.service - FHEM Home Automation
   Loaded: loaded (/etc/systemd/system/fhem.service; enabled; vendor preset: enabled)
   Active: activating (start) since Tue 2018-08-07 18:06:38 CEST; 12s ago
Cntrl PID: 3677 (perl)
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/fhem.service
           └─3677 /usr/bin/perl fhem.pl fhem.cfg

Aug 07 18:06:38 M60 systemd[1]: Starting FHEM Home Automation...
root@M60:/opt/fhem/log# systemctl status fhem.service
● fhem.service - FHEM Home Automation
   Loaded: loaded (/etc/systemd/system/fhem.service; enabled; vendor preset: enabled)
   Active: activating (start) since Tue 2018-08-07 18:06:38 CEST; 13s ago
Cntrl PID: 3677 (perl)
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/fhem.service
           └─3677 /usr/bin/perl fhem.pl fhem.cfg

Aug 07 18:06:38 M60 systemd[1]: Starting FHEM Home Automation...
root@M60:/opt/fhem/log# systemctl status fhem.service
● fhem.service - FHEM Home Automation
   Loaded: loaded (/etc/systemd/system/fhem.service; enabled; vendor preset: enabled)
   Active: activating (start) since Tue 2018-08-07 18:06:38 CEST; 14s ago
Cntrl PID: 3677 (perl)
    Tasks: 2 (limit: 4915)
   CGroup: /system.slice/fhem.service
           ├─3677 /usr/bin/perl fhem.pl fhem.cfg
           └─3720 /usr/bin/perl fhem.pl fhem.cfg

Aug 07 18:06:38 M60 systemd[1]: Starting FHEM Home Automation...
root@M60:/opt/fhem/log# systemctl status fhem.service
● fhem.service - FHEM Home Automation
   Loaded: loaded (/etc/systemd/system/fhem.service; enabled; vendor preset: enabled)
   Active: activating (start) since Tue 2018-08-07 18:06:38 CEST; 14s ago
Cntrl PID: 3677 (perl)
    Tasks: 4 (limit: 4915)
   CGroup: /system.slice/fhem.service
           ├─3677 /usr/bin/perl fhem.pl fhem.cfg
           ├─3720 /usr/bin/perl fhem.pl fhem.cfg
           ├─3723 /usr/bin/perl fhem.pl fhem.cfg
           └─3724 /usr/bin/perl fhem.pl fhem.cfg

Aug 07 18:06:38 M60 systemd[1]: Starting FHEM Home Automation...

Grüße

[Stefan_Ne]

Hallo,

und hier das Log mit einer fast leeren fhem.cfg.

018.08.07 18:32:06 3: WEBremote: port 8084 opened
2018.08.07 18:32:06 3: WEBtablet: port 8085 opened
2018.08.07 18:32:06 1: Including ./log/fhem.save
2018.08.07 18:32:06 1: Including fhem.cfg
2018.08.07 18:32:06 3: telnetPort: port 7072 opened
2018.08.07 18:32:06 3: WEB: port 8083 opened
2018.08.07 18:32:06 3: WEB_ext: port 8086 opened
2018.08.07 18:32:06 3: WEBremote: port 8084 opened
2018.08.07 18:32:06 3: WEBtablet: port 8085 opened
2018.08.07 18:32:06 1: Including ./log/fhem.save
2018.08.07 18:33:08 0: Server shutdown
2018.08.07 18:33:09 1: PERL WARNING: "my" variable $Device masks earlier declaration in same scope at ./FHEM/99_myUtils.pm line 58.
2018.08.07 18:33:09 1: PERL WARNING: "my" variable $Sensor masks earlier declaration in same scope at ./FHEM/99_myUtils.pm line 59.
2018.08.07 18:33:09 1: Including fhem.cfg
2018.08.07 18:33:09 3: telnetPort: port 7072 opened
2018.08.07 18:33:09 3: WEB: port 8083 opened
2018.08.07 18:33:09 3: WEB_ext: port 8086 opened
2018.08.07 18:33:09 3: WEBremote: port 8084 opened
2018.08.07 18:33:09 3: WEBtablet: port 8085 opened
2018.08.07 18:33:09 1: Including ./log/fhem.save
2018.08.07 18:33:09 0: Featurelevel: 5.8
2018.08.07 18:33:09 0: Server started with 9 defined entities (fhem.pl:17089/2018-08-04 perl:5.024001 os:linux user:fhem pid:5149)
2018.08.07 18:34:39 0: Server shutdown
2018.08.07 18:34:39 1: PERL WARNING: "my" variable $Device masks earlier declaration in same scope at ./FHEM/99_myUtils.pm line 58.
2018.08.07 18:34:39 1: PERL WARNING: "my" variable $Sensor masks earlier declaration in same scope at ./FHEM/99_myUtils.pm line 59.
2018.08.07 18:34:39 1: Including fhem.cfg
2018.08.07 18:34:39 3: telnetPort: port 7072 opened
2018.08.07 18:34:39 3: WEB: port 8083 opened
2018.08.07 18:34:39 3: WEB_ext: port 8086 opened
2018.08.07 18:34:39 3: WEBremote: port 8084 opened
2018.08.07 18:34:39 3: WEBtablet: port 8085 opened
2018.08.07 18:34:39 1: Including ./log/fhem.save
2018.08.07 18:34:39 0: Featurelevel: 5.8
2018.08.07 18:34:39 0: Server started with 9 defined entities (fhem.pl:17089/2018-08-04 perl:5.024001 os:linux user:fhem pid:5168)
2018.08.07 18:36:09 0: Server shutdown
2018.08.07 18:36:10 1: PERL WARNING: "my" variable $Device masks earlier declaration in same scope at ./FHEM/99_myUtils.pm line 58.
2018.08.07 18:36:10 1: PERL WARNING: "my" variable $Sensor masks earlier declaration in same scope at ./FHEM/99_myUtils.pm line 59.
2018.08.07 18:36:10 1: Including fhem.cfg
2018.08.07 18:36:10 3: telnetPort: port 7072 opened
2018.08.07 18:36:10 3: WEB: port 8083 opened
2018.08.07 18:36:10 3: WEB_ext: port 8086 opened
2018.08.07 18:36:10 3: WEBremote: port 8084 opened
2018.08.07 18:36:10 3: WEBtablet: port 8085 opened
2018.08.07 18:36:10 1: Including ./log/fhem.save
2018.08.07 18:36:10 0: Featurelevel: 5.8
2018.08.07 18:36:10 0: Server started with 9 defined entities (fhem.pl:17089/2018-08-04 perl:5.024001 os:linux user:fhem pid:5193)

Der Fehler bleibt. Restart in Endlosschleife

Viele Grüße

[Frank_Huber]

Hast mal die myutils leer gemacht?

Gesendet von meinem Doogee S60 mit Tapatalk

[Stefan_Ne]

Guten Morgen,

nach langem probieren habe ich eine Lösung gefunden.
Alles ausschalten ( inkl. aller Sensor / Aktoren Gateways), Konfig leeren ohne Erfolg.

Was am Ende geholfen hat, fhem.cfg löschen und eine leere anlegen.
Anschließend habe ich ein Backup von vor dem Update genommen, läuft !

Zum Test habe ich die vermeidlich defekte Konfig noch einmal versucht, läuft nicht.

Somit ist die Konfig irgendwie kaputt.

Besten Dank für Eure Hilfe

Viele Grüße
Stefan

[r00t2]

...Somit ist die Konfig irgendwie kaputt....

Vergleiche doch mal die "kaputte" Config mit der "funktionierenden".

Vielleicht erschließt sich dadurch das Problem und man kann es zukünftig besser eingrenzen bzw. umgehen.

[Xguide]

Hallo zusammen,

ich befinde mich gerade im selben Dillema.
Aktuell versuche ich mein fhem vom Raspberry Pi auf einen NUC (Proxmox Container) umzuziehen.
Das Phänomen ist wie bei Stefan, ein Neustart alle ca. 2 Minuten.
Debugging auf global verbose 5 zeigt mit vor dem fhem shutdown immer andere nicht auffällige Einträge.
Ich habe meine Konfiguration schon auf das Minimum zusammengeschrumpft um den Übeltäter zu finden, allerdings ohne Erfolg.
Die ausgelieferter fhem.cfg.demo funktioniert tadellos. Alsbald ich diese durch meine tausche ist es aus.

Hat noch jemand einen Tipp?

Code Auswählen Erweitern


2018.12.07 12:10:19 4: Connection accepted from WEB_192.168.XXX.XXX_XXXXX
2018.12.07 12:10:22 5: Starting notify loop for global, 1 event(s), first is SHUTDOWN
2018.12.07 12:10:22 5: createNotifyHash
2018.12.07 12:10:22 4: BlockingCall (HMinfo_archConfigExec): created child (8198), uses telnetPort to connect back
2018.12.07 12:10:22 5: Homemode_MCHome: Events from monitored device global: SHUTDOWN
2018.12.07 12:10:22 5: End notify loop for global
2018.12.07 12:10:22 0: Server shutdown

2018.12.07 12:13:26 4: Connection accepted from WEB_192.168.XXX.XXX_XXXXX
2018.12.07 12:13:28 5: Starting notify loop for global, 1 event(s), first is SHUTDOWN
2018.12.07 12:13:28 5: createNotifyHash
2018.12.07 12:13:28 4: BlockingCall (HMinfo_archConfigExec): created child (8375), uses telnetPort to connect back
2018.12.07 12:13:28 5: Homemode_MCHome: Events from monitored device global: SHUTDOWN
2018.12.07 12:13:28 5: End notify loop for global
2018.12.07 12:13:28 0: Server shutdown
#Homemode entfernt
2018.12.07 12:14:50 5: Notify_SMA_SunnyIsland_Debug: processing time: inverter_processing_time: 0.1027
2018.12.07 12:14:50 5: Notify_SMA_SunnyIsland_Debug: processing time: 0.1027
2018.12.07 12:14:50 5: End notify loop for SMA_SunnyIsland
2018.12.07 12:14:50 4: Connection accepted from WEB_192.168.XXX.XXX_XXXXX: EOF
2018.12.07 12:15:00 5: Starting notify loop for global, 1 event(s), first is SHUTDOWN
2018.12.07 12:15:00 4: BlockingCall (HMinfo_archConfigExec): created child (8466), uses telnetPort to connect back
2018.12.07 12:15:00 5: End notify loop for global
2018.12.07 12:15:00 0: Server shutdown


[Wernieman]

Code Auswählen Erweitern

2018.12.07 12:13:28 5: Homemode_MCHome: Events from monitored device global: SHUTDOWN
Irgendeine User-Regel schaltet Dir Dein FHEM aus ....

[CoolTux]

Muss nicht unbedingt sein. Der Hinweis kommt aus dem HOMEMODE Modul. Aber das ist nur ein Log aus der NotifyFn vom Modul. Es sagt nur aus das es ein globales Event SHUTDOWN gab. Kann auch ein reguläres systemctl stop fhem gewesen sein.

[Xguide]

Hallo Wernieman,

danke für den Hinweis, das war es aber nicht. Ich habe das Device inzwischen auch gelöscht gehabt und es passierte trotzdem noch.

Inzwischen bin ich glaube ich ein Stück weiter und begreifen kann ich es noch nicht.
Ich habe den Tipp von Stefan gerade umgesetzt, meine fhem.cfg auf Textbasis in die Auslieferungs-Config gepackt - was soll ich sagen, noch kein Neustart

Ich teste mal alles durch....

[CoolTux]

Ich denke das dieses immer wieder starten alle 2 Minuten vom watchdog des systemd kommt. Wieso das so ist kann ich aber nicht genau sagen. Wenn man aber den Parameter Restart in der /etc/systemd/system/fhem.service mal auf no stellt sollte es eigentlich klappen. Ist aber nur zum testen.