FHEM stürzt ab (?)

wolliballa73 · 01 November 2021, 18:21:30

Hallo allerseits,

seit heute habe ich das Problem, dass nach einem Reboot des Raspi der Zugriff auf FHEM:8083 nur für ein paar Minuten möglich ist, danach geht "nix" mehr; in /opt/fhem/log/fhem-xxxx.log wird auch nix mehr geschrieben.
Auf dem System läuft ein knxd - der funktioniert weiterhin; Der Gruppenmonitor der ETS4 greift weiterhin erfolgreich darauf zu.

Der Raspi wurde die letzten Tage komplett neu installiert (Bullseye) und die von mir benötigten Abhängigkeiten nachinstalliert für:
- ENIGMA2
- FritzBox
- OWserver
- KNXD
- ALEXA (das Device wurde aber erstmal auf disable=1 gesetzt)

Zur Fehlersuche kann ich bisher beisteuern:

Prozess läuft:

Code Auswählen

pi@fhem:~ $ service fhem status
● fhem.service - FHEM Home Automation
     Loaded: loaded (/etc/systemd/system/fhem.service; enabled; vendor preset: enabled)
     Active: active (running) since Mon 2021-11-01 18:06:04 CET; 8min ago
    Process: 571 ExecStart=/usr/bin/perl fhem.pl fhem.cfg (code=exited, status=0/SUCCESS)
   Main PID: 620 (perl)
      Tasks: 1 (limit: 2059)
        CPU: 39.652s
     CGroup: /system.slice/fhem.service
             └─620 /usr/bin/perl fhem.pl fhem.cfg

Nov 01 18:06:02 fhem systemd[1]: Starting FHEM Home Automation...
Nov 01 18:06:04 fhem systemd[1]: Started FHEM Home Automation.

Systemauslastung sieht gut aus:

Code Auswählen

pi@fhem:~ $ top
top - 18:15:37 up 9 min,  1 user,  load average: 0,30, 0,12, 0,08
Tasks: 121 total,   1 running, 120 sleeping,   0 stopped,   0 zombie
%CPU(s):  1,7 us,  0,2 sy,  0,0 ni, 98,1 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st
MiB Spch:    923,2 total,    676,2 free,    109,0 used,    138,0 buff/cache
MiB Swap:    100,0 total,    100,0 free,      0,0 used.    763,2 avail Spch

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     ZEIT+ BEFEHL
  620 fhem      20   0   78668  70212   6452 S   5,9   7,4   0:39.69 perl
 1057 pi        20   0   10268   2824   2252 R   1,0   0,3   0:00.13 top
   81 root      20   0       0      0      0 I   0,3   0,0   0:00.48 kworker/2:6-events
  781 pi        20   0   12256   3720   2780 S   0,3   0,4   0:00.06 sshd
    1 root      20   0   31188   7352   5528 S   0,0   0,8   0:06.04 systemd
    2 root      20   0       0      0      0 S   0,0   0,0   0:00.00 kthreadd
    3 root       0 -20       0      0      0 I   0,0   0,0   0:00.00 rcu_gp
    4 root       0 -20       0      0      0 I   0,0   0,0   0:00.00 rcu_par_gp

ein sudo service fhem restart bringt in dieser Situation auch nix mehr, sondern nur noch ein reboot.

Die SD-Karte ist nagelneu.

Kann mir jemand auf die Sprünge helfen, wie ich die Ursache noch weiter einschränken kann?

Vielen Dank...

LG,
Matze

Wernieman · 01 November 2021, 18:32:00

Was steht denn Zuletzt in der fhem.log?
Und was steht bei den anderen üblichen Verdächtigen: /var/log/kern.log und syslog

Vor allem, wenn Du fhem normal versuchst zu starten ...

Und wenn es nicht läuft, läuft es wirklich nicht?
Bitte mal als root:

Code Auswählen

ps aux | grep fhem
netstat -lntp | grep fhem
netstat -lntp | grep 8083

Edit
Gar nicht gesehen, fhem läuft ja bei Dir:

Code Auswählen

620 fhem 20 0 78668 70212 6452 S 5,9 7,4 0:39.69 perl

Bin mal gespannt, auf die Ausgaben ...

Wenn nur ein reboot der Kiste hilf und nicht nur ein fhem-start, ist etwas heftigs im Argen. Ich vermute blockierte Ports, rumgeisterndes FHEM, Speichermangel .... um nur ein paar zu nennen.

Invers · 01 November 2021, 19:52:44

Interessenhalber:
netstat -lntp | grep fhem
zeigt bei mir gar nichts an.

Code Auswählen

pi@fhem3:~ $ netstat -lntp | grep fhem
(Es konnten nicht alle Prozesse identifiziert werden; Informationen über
nicht-eigene Processe werden nicht angezeigt; Root kann sie anzeigen.)
pi@fhem3:~ $

Was müsste denn da angezeigt werden? mein fhem läuft.

MadMax-FHEM · 01 November 2021, 19:58:10

Zitat
(Es konnten nicht alle Prozesse identifiziert werden; Informationen über
nicht-eigene Processe werden nicht angezeigt; Root kann sie anzeigen.)

fhem läuft unter User fhem nicht unter User pi...
...den Befehl hast du aber als User pi ausgeführt...

Also als root ausführen...
...wie von Wernieman geschrieben:

Zitat
Bitte mal als root:

Jeweils "sudo" davor sollte auch gehen.

EDIT: wenn aber fhem läuft (tut es ja offenbar), du aber nicht drauf kommst, könnte das (wenn man sieht, dass keine/kaum Last) auch ein "Freeze" in fhem sein, z.B. blockierendes Warten auf "irgendwas"... Dann steht fhem, du kommst nicht drauf, es läuft aber prinzipiell...

Gruß, Joachim

Invers · 01 November 2021, 20:00:11

Das habe ich gemacht. Dann wird gar nichts ausgeschrieben. Es kommt einfach die nächste Promptzeile.

pi@fhem3:~ $ sudo netstat -lntp | grep fhem
pi@fhem3:~ $

Wernieman · 01 November 2021, 21:31:19

Kannst Du mir bitte mal die Ausgabe von "netstat -lntp" uns komplett geben?

Invers · 01 November 2021, 23:20:25

Klar.

Code Auswählen

pi@fhem3:~ $ sudo netstat -lntp
Aktive Internetverbindungen (Nur Server)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
tcp        0      0 0.0.0.0:8091            0.0.0.0:*               LISTEN      26926/perl
tcp        0      0 0.0.0.0:1883            0.0.0.0:*               LISTEN      26926/perl
tcp        0      0 0.0.0.0:7072            0.0.0.0:*               LISTEN      26926/perl
tcp        0      0 127.0.0.1:44641         0.0.0.0:*               LISTEN      26931/node /usr/loc
tcp        0      0 0.0.0.0:80              0.0.0.0:*               LISTEN      549/lighttpd
tcp        0      0 0.0.0.0:8083            0.0.0.0:*               LISTEN      26926/perl
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      542/sshd
tcp6       0      0 :::80                   :::*                    LISTEN      549/lighttpd
tcp6       0      0 :::22                   :::*                    LISTEN      542/sshd

wolliballa73 · 02 November 2021, 07:06:31

Hallo Wernieman,

das Ende der fhem.log:

Code Auswählen

2021.11.01 19:56:33 3: eval: "Nord: ".sprintf("%.1f",ReadingsVal("Temp_aussen","tempNord-get",0))."°C<br />".
"Hütte: ".sprintf("%.1f",ReadingsVal("Temp_aussen","tempHuette-get",0))."°C"
2021.11.01 19:56:33 1: PERL WARNING: Argument "6.30 &deg;C" isn't numeric in sprintf at (eval 129) line 1, <$fh> line 1024.
2021.11.01 19:56:33 3: eval: "Nord: ".sprintf("%.1f",ReadingsVal("Temp_aussen","tempNord-get",0))."°C<br />".
"Hütte: ".sprintf("%.1f",ReadingsVal("Temp_aussen","tempHuette-get",0))."°C"
2021.11.01 19:56:33 1: PERL WARNING: Argument "16.18 &deg;C" isn't numeric in sprintf at (eval 130) line 1, <$fh> line 1025.
2021.11.01 19:56:33 3: eval: "Nord: ".sprintf("%.1f",ReadingsVal("Temp_aussen","tempNord-get",0))."°C<br />".
"Hütte: ".sprintf("%.1f",ReadingsVal("Temp_aussen","tempHuette-get",0))."°C"
2021.11.01 19:56:33 1: PERL WARNING: Argument "6.30 &deg;C" isn't numeric in sprintf at (eval 130) line 1, <$fh> line 1025.
2021.11.01 19:56:33 3: eval: "Nord: ".sprintf("%.1f",ReadingsVal("Temp_aussen","tempNord-get",0))."°C<br />".
"Hütte: ".sprintf("%.1f",ReadingsVal("Temp_aussen","tempHuette-get",0))."°C"
2021.11.01 19:56:33 1: Messages collected while initializing FHEM:SecurityCheck:
  WEBtablet is not password protected
  WEBphone is not password protected

Protect this FHEM installation by configuring the allowed device allowedWEBhook
You can disable this message with attr global motd none

2021.11.01 19:56:34 3: NodeMCUtest low level cmd queue send ERROR 56000000aa, qlen 1 (reconnect giving up)
2021.11.01 19:56:34 1: usb create starting

ich habe das aber auch schon ein paar Mal beobachtet, da hatte es einfach mit den letzten Events aufgehört...

Code Auswählen

root@fhem:~# ps aux | grep fhem
avahi      365  0.0  0.2   5648  2288 ?        Ss   Nov01   0:01 avahi-daemon: running [fhem.local]
fhem       618  0.0  6.3  67756 60072 ?        S    Nov01   0:11 /usr/bin/perl fhem.pl fhem.cfg
fhem       808  0.0  0.0  25572   680 ?        Sl   Nov01   0:00 lsusb
root      2352  0.0  0.0   6936   580 pts/0    S+   06:56   0:00 grep fhem

Code Auswählen

root@fhem:~# netstat -lntp | grep fhem
root@fhem:~# netstat -lntp | grep 8083
tcp        9      0 0.0.0.0:8083            0.0.0.0:*               LISTEN      618/perl

Code Auswählen

root@fhem:~# netstat -lntp
Aktive Internetverbindungen (Nur Server)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
tcp        0      0 0.0.0.0:7072            0.0.0.0:*               LISTEN      618/perl
tcp       10      0 0.0.0.0:8083            0.0.0.0:*               LISTEN      618/perl
tcp        5      0 0.0.0.0:8084            0.0.0.0:*               LISTEN      618/perl
tcp        0      0 0.0.0.0:8085            0.0.0.0:*               LISTEN      618/perl
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      584/sshd: /usr/sbin
tcp       27      0 0.0.0.0:8088            0.0.0.0:*               LISTEN      618/perl
tcp6       0      0 :::6720                 :::*                    LISTEN      1/init
tcp6       1      0 :::4304                 :::*                    LISTEN      1/init
tcp6       0      0 :::22                   :::*                    LISTEN      584/sshd: /usr/sbin

In /var/log/kern.log finde ich nur Einträge zur Zeit des Reboots - hier die letzten 20:

Code Auswählen

root@fhem:~# tail -n 20 /var/log/kern.log
Nov  1 19:28:27 fhem kernel: [ 1349.581536] [<7f268000>] (ds_disconnect [ds2490]) from [<80797e0c>] (usb_unbind_interface+0x78/0x240)
Nov  1 19:28:27 fhem kernel: [ 1349.581543]  r5:00000000 r4:8247a478
Nov  1 19:28:27 fhem kernel: [ 1349.581557] [<80797d94>] (usb_unbind_interface) from [<807125f4>] (device_release_driver_internal+0x10c/0x1c0)
Nov  1 19:28:27 fhem kernel: [ 1349.581567]  r10:82995d38 r9:8247a4bc r8:00000000 r7:00000000 r6:7f26b054 r5:00000000
Nov  1 19:28:27 fhem kernel: [ 1349.581574]  r4:827b8c20
Nov  1 19:28:27 fhem kernel: [ 1349.581585] [<807124e8>] (device_release_driver_internal) from [<807126c8>] (device_release_driver+0x20/0x24)
Nov  1 19:28:27 fhem kernel: [ 1349.581594]  r7:00000000 r6:00000000 r5:827b8c20 r4:00000001
Nov  1 19:28:27 fhem kernel: [ 1349.581607] [<807126a8>] (device_release_driver) from [<8079803c>] (usb_driver_release_interface+0x68/0x98)
Nov  1 19:28:27 fhem kernel: [ 1349.581621] [<80797fd4>] (usb_driver_release_interface) from [<807a18f8>] (usbdev_ioctl+0x1a88/0x1cdc)
Nov  1 19:28:27 fhem kernel: [ 1349.581629]  r6:00000000 r5:80f05008 r4:8491b600
Nov  1 19:28:27 fhem kernel: [ 1349.581642] [<8079fe70>] (usbdev_ioctl) from [<8034a468>] (sys_ioctl+0x1d4/0x8ec)
Nov  1 19:28:27 fhem kernel: [ 1349.581653]  r10:00000009 r9:85b78000 r8:00000000 r7:85a81a80 r6:85a81a81 r5:80f05008
Nov  1 19:28:27 fhem kernel: [ 1349.581660]  r4:c00c5512
Nov  1 19:28:27 fhem kernel: [ 1349.581671] [<8034a294>] (sys_ioctl) from [<80100040>] (ret_fast_syscall+0x0/0x28)
Nov  1 19:28:27 fhem kernel: [ 1349.581679] Exception stack(0x85b79fa8 to 0x85b79ff0)
Nov  1 19:28:27 fhem kernel: [ 1349.581689] 9fa0:                   7ecc192c 00575b40 00000009 c00c5512 7ecc192c 66627375
Nov  1 19:28:27 fhem kernel: [ 1349.581699] 9fc0: 7ecc192c 00575b40 00000009 00000036 005893a8 76faf370 76f9226c 00582280
Nov  1 19:28:27 fhem kernel: [ 1349.581707] 9fe0: 76d980c4 7ecc191c 76d7f6fd 76e34418
Nov  1 19:28:27 fhem kernel: [ 1349.581718]  r10:00000036 r9:85b78000 r8:80100204 r7:00000036 r6:00000009 r5:00575b40
Nov  1 19:28:27 fhem kernel: [ 1349.581724]  r4:7ecc192c

Und hier noch /var/log/syslog zu dem Zeitpunkt, als fhem.log aufgehört hat:

Code Auswählen

Nov  1 19:49:48 fhem systemd[1]: Starting Backend server for 1-wire control...
Nov  1 19:51:18 fhem systemd[1]: owserver.service: start operation timed out. Terminating.
Nov  1 19:52:48 fhem systemd[1]: owserver.service: State 'final-sigterm' timed out. Killing.
Nov  1 19:52:48 fhem systemd[1]: owserver.service: Killing process 380 (owserver) with signal SIGKILL.
Nov  1 19:52:48 fhem systemd[1]: owserver.service: Failed with result 'timeout'.
Nov  1 19:52:48 fhem systemd[1]: owserver.service: Unit process 380 (owserver) remains running after unit stopped.
Nov  1 19:52:48 fhem systemd[1]: Failed to start Backend server for 1-wire control.
Nov  1 19:52:49 fhem systemd[1]: owserver.service: Scheduled restart job, restart counter is at 14.
Nov  1 19:52:49 fhem systemd[1]: Stopped Backend server for 1-wire control.
Nov  1 19:52:49 fhem systemd[1]: owserver.service: Found left-over process 380 (owserver) in control group while starting unit. Ignoring.
Nov  1 19:52:49 fhem systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Nov  1 19:52:49 fhem systemd[1]: Starting Backend server for 1-wire control...
Nov  1 19:54:19 fhem systemd[1]: owserver.service: start operation timed out. Terminating.
Nov  1 19:55:49 fhem systemd[1]: owserver.service: State 'final-sigterm' timed out. Killing.
Nov  1 19:55:49 fhem systemd[1]: owserver.service: Killing process 380 (owserver) with signal SIGKILL.
Nov  1 19:55:49 fhem systemd[1]: owserver.service: Failed with result 'timeout'.
Nov  1 19:55:49 fhem systemd[1]: owserver.service: Unit process 380 (owserver) remains running after unit stopped.
Nov  1 19:55:49 fhem systemd[1]: Failed to start Backend server for 1-wire control.
Nov  1 19:55:49 fhem systemd[1]: owserver.service: Scheduled restart job, restart counter is at 15.
Nov  1 19:55:49 fhem systemd[1]: Stopped Backend server for 1-wire control.
Nov  1 19:55:49 fhem systemd[1]: owserver.service: Found left-over process 380 (owserver) in control group while starting unit. Ignoring.
Nov  1 19:55:49 fhem systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Nov  1 19:55:49 fhem systemd[1]: Starting Backend server for 1-wire control...
Nov  1 19:57:20 fhem systemd[1]: owserver.service: start operation timed out. Terminating.
Nov  1 19:58:50 fhem systemd[1]: owserver.service: State 'final-sigterm' timed out. Killing.
Nov  1 19:58:50 fhem systemd[1]: owserver.service: Killing process 380 (owserver) with signal SIGKILL.
Nov  1 19:58:50 fhem systemd[1]: owserver.service: Failed with result 'timeout'.
Nov  1 19:58:50 fhem systemd[1]: owserver.service: Unit process 380 (owserver) remains running after unit stopped.
Nov  1 19:58:50 fhem systemd[1]: Failed to start Backend server for 1-wire control.
Nov  1 19:58:50 fhem systemd[1]: owserver.service: Scheduled restart job, restart counter is at 16.

MadMax-FHEM · 02 November 2021, 07:53:21

Ich würde mal (schnelle Hilfe/schneller Versuch) folgendes tun:

Code Auswählen


attr initialUsbCheck disable 1

Und auch mal den OWServer disablen.

Dann mal schauen.
Ist es dann gut:

versuchen OWServer wieder ans Laufen zu bekommen, kann mich erinnern, dass dazu einiges im Forum.war bzgl. Blockieren...

Wenn es das nicht war: weiter suchen...

EDIT: was mir nicht gefällt, ich aber auch nicht wirklich "deuten" kann sind die Kernel-Meldungen... Welche HW-Plattform hast du? USB-Geräte angeschlossen?

EDIT: auch die "eval" im fhem Log finde ich "eigenartig" deutet darauf hin (so ich das richtig interpretiere), dass da eun (schwerer) Fehler ("Exception") abgefangen wurde...

EDIT: du schreibst zwar SD Karte ist neu aber wie hast du installiert? Alles neu, also neues System und fhem neu "from scratch" oder aus einem Backup? Wenn backup: fhem-Backup oder SD-Backup?

Gruß, Joachim

erwin · 02 November 2021, 08:53:13

Hi,
ich tippe ebenfalls auf initialUSBcheck, das hatte wir auch vor kurzem mit knxd abstürzen...:
https://forum.fhem.de/index.php/topic,123532.0.html
l.g. erwin

Wernieman · 02 November 2021, 08:53:33

Ich kann Joachim und erwin nur zustimmen:

1. Die letzte Meldung von Mail ist "2021.11.01 19:56:34 1: usb create starting" .. also setzte bitte mal das attr. Ausnahmsweise mal mit direktem Editieren der Config.

2. Kannst DU mal owserver deinstallieren? Und in FHEM disablen? Irgendetwas diesbezüglich stimmt nicht (syslog/kern.log)

Dann mal probieren, ob FHEM bis dahin läuft

3. Bitte um Info
- Was für USB-Geräte hast Du?
- Was für eine Distri hast Du installiert, bitte incl. Version?
- Auf was für einer Hardwareplatform?

Beta-User · 02 November 2021, 09:18:40

Ergänzend würde es aber nicht schaden, auch (mind.) das fragliche userReadings-Attribut zu fixen, das da ständig evaluiert wird:
- trigger setzen (!)
- ReadingsNum()

Wobei sich grundsätzlich die Frage stellt, warum man an sich nummerische Readingwerte mit Einheiten ergänzt (und dann so loggt) statt stateFormat zu verwenden, um die Anzeige aufzuhübschen...

erwin · 03 November 2021, 18:55:57

Hi,
falls Matze bestätigen kann, das es mit initialUSBCheck zusammenhängt.... würde ich Rudolf ersuchen, für die 6.1 das aus der fhem.cfg herauszunehmen!
Das wär dann der 2te Fall binnen 2Wochen, wo das einen (externen) daemon massiv stört!
l.g. erwin

Otto123 · 03 November 2021, 20:09:06

Zitat von: erwin am 03 November 2021, 18:55:57
würde ich Rudolf ersuchen, für die 6.1 das aus der fhem.cfg herauszunehmen!
Das wär dann der 2te Fall binnen 2Wochen, wo das einen (externen) daemon massiv stört!
l.g. erwin

Ich wünsche Dir Erfolg

falls die Anzahl der Stimmen gezählt wird:
https://forum.fhem.de/index.php/topic,93698.msg909605.html#msg909605

Beta-User · 04 November 2021, 10:47:32

Zitat von: erwin am 03 November 2021, 18:55:57
Hi,
falls Matze bestätigen kann, das es mit initialUSBCheck zusammenhängt....

...könnte man ggf. alternativ auch checken, ob es nicht sinnvoll wäre, den aufgerufenen Code zu überarbeiten...?

Hatte das irgendwann mal - auf Basis deutlich geringerer Perl-Kenntnisse - auch einen Vorschlag gemacht, wie das der Spur nach aussehen könnte: https://forum.fhem.de/index.php/topic,97756.msg911243.html#msg911243.
Den (bisher unveränderten) Ablauf "per Schnittstelle" kann man in https://forum.fhem.de/index.php/topic,100054.msg938984.html#msg938984 ganz gut sehen.

Werde aber nicht kurzfristig dazu kommen, und diese USB-Ansprechcodes sind nach wie vor ein Buch mit ein paar Siegeln für mich...