[Gelöst] FHEM hängt sich nach einigen Stunden auf / stürzt ab

[Wernieman]

killall hat den Vorteil, alle fhem.pl zu killen. killall hat den Nachteil, alle Prozesse mit "namen" fhem.pl zu killen .... mußt Du selber Kosten/Risiken ermitteln

[NehCoy]

Dann warten wir mal, den nächsten Absturz ab...

[NehCoy]

Da ist er auch schon wieder.
Angefügt die Screenshots des Befehls "top" bevor und nachdem der Befehl "sudo kill -9 >id>" ausgeführt wurde.
Die Konsolen Ein- und Ausgaben sahen dann so aus:

Code Auswählen Erweitern

pi@raspberrypi ~ $ ps aux | grep fhem
root      1765  0.0  0.1   1756   532 ?        S    13:43   0:00 /bin/sh /etc/init.d/fhem start
fhem      1768 31.1  3.0  16068 13728 ?        R    13:43  96:53 perl fhem.pl fhem.cfg
pi        3811  0.0  0.1   3548   864 pts/0    S+   18:54   0:00 grep --color=auto fhem
pi@raspberrypi ~ $ kill -9 1768
-bash: kill: (1768) - Operation not permitted
pi@raspberrypi ~ $ sudo kill -9 1768
pi@raspberrypi ~ $ ps aux | grep fhem
pi        3831  1.0  0.1   3544   808 pts/0    S+   18:55   0:00 grep --color=auto fhem
pi@raspberrypi ~ $

Ebenfalls angefügt: Ein Screenshot von der grafischen SYSMON-Ausgabe.

[Wernieman]

Jetzt würde mich noch die CPU system/idle etc Werte im Grafen interessieren ....

Scheinbar "dreht" bei Dir fhem durch. Das System an sich selber scheint zu funktionieren, sonst würde ein "kill -9" nicht funktionieren. Ein Neustart des fhem war O.K.?

Kannst Du gucken, ob um 17:10 was besonderes im log war? ~10 Minuten vorher/nachher?

[NehCoy]

Der regulären Log ist von mir deaktiviert worden, um diesen als Fehlerquelle auszuschließen.
Aber bis dahin war bis auf das bereits gepostete nicht außergewöhnliches drin.
Hätte höchstens noch die sysmon-Logdatei im Angebot.

[NehCoy]

FHEM hat sich mal aufgehängt.
Kill -9 war wieder möglich.
Dieses mal habe ich versucht FHEM manuell zu starten:

Code Auswählen Erweitern

pi@raspberrypi /opt/fhem $ Can't open ./log/fhem-2014-01.log: Permission denied at fhem.pl line 1960, <$fh> line 10.

pi@raspberrypi /opt/fhem $ sudo perl fhem.pl fhem.cfg
pi@raspberrypi /opt/fhem $ defined(@array) is deprecated at ./FHEM/00_TUL.pm
line 704, <$fh> line 37.
(Maybe you should just omit the defined()?)

Auf der Webfrontend FHEM konnte ich danach wieder zugreifen.
Ob ich auch auf den KNX-Bus zugreifen und Lampen ein- und ausschalten kann, kann ich im Moment nicht testen, da ich Remote auf Verbunden bin.

Ein Auszug aus dem inzwischen weider aktivierten Logfile und die Diagramme von SYSMON sind diesem Beitrag angefügt.

[Wernieman]

Mhhh ... man sieht eigentlich nur, das kurz vor 8:00 Dein System sich verabschiedet hat. Deshalb ist die Kurve von 8:00 bis jetzt so gerade. Kannst Du auch die CPUWerte in die Grafen bekommen? Also nicht nur die Termperatur? Dann würden wir sehen, ob VOR dem Absturz die CPU schon zu tun  hatte und in welchem "Bereich" ..

[NehCoy]

Hallo Wernieman,

danke für deine Antwort!

Kannst Du auch die CPUWerte in die Grafen bekommen?

Ich schau mal, was in der Doku zu SYSMON steht ...

Ob ich auch auf den KNX-Bus zugreifen und Lampen ein- und ausschalten kann, kann ich im Moment nicht testen, da ich Remote auf Verbunden bin.

Ich glaube nicht, dass ich es hätte können.
Im Status des Webfrontends war folgendes angezeigt:

Code Auswählen Erweitern

TUL
EIB   disconnected

Nach einem Systemneustart mit "sudo reboot" steht da nun:

Code Auswählen Erweitern

TUL
EIB   Initialized

Damit wird diese Fehlermeldung doch irgendeinen Grund gehabt haben.

Code Auswählen Erweitern

pi@raspberrypi /opt/fhem $ defined(@array) is deprecated at ./FHEM/00_TUL.pm
line 704, <$fh> line 37.

Gruß
NehCoy

[Wernieman]

"deprecated" bedeutet eigentlich, das es in Perl als veraltet gilt und in Zukunft aus Perl entfernt wird. Ist also eher eine Warnung als ein Fehler

Hast Du vor 8:00 etwas besonderes im Logfile? Ansonsten mal "verbose 5" setzen

[NehCoy]

Also ich sehe in dem Beitrag angehängten Logfile nichts besonderes.
"verbose" habe ich jetzt mal auf "5" gesetzt.


Edit:
Ähm ... Die "Load" wird doch angezeigt.
Der mittlere Graph. Steigt ab gegen 7:30 Uhr linear an...

[Wernieman]

Die Load und die CPU Usage sind aber Unterschiedliche Sachen. Eine load von 1 bedeutet, das 1 Prozess auf io-Wartet. Ich habe schon Server mit einer Load von 10.000 gesehen, wo sich die CPU gelangweilt hat (O.K. das ist schon ein faild). Auche eine load von 1, die CPU dreht aber durch ist auch schon vorgekommen.

Kurzgefasst:
load ist ein Hinweis, aber keine "echte" Auslastungsanzeige

[Carsten]

Ich hab schonmal gefragt, aber keine Antwort gesehen.
Hast du den TUL direkt im Raspi? Wenn ja, häng ihn ( und alle anderen USB-Geräte ) mal an ein aktives (!) USB-Hub.

Ich hatte ein ähnliches Verhalten bei einem UMTS-Stick, den ich zum Testen auch direkt im Raspi hatte. Prinzipiell funktionierte alles, aber unter bestimmten Bedingungen ( ich nehme an, schlechtes Netz ) brauchte er mehr Strom und der Raspi fing an zu Mucken.

Meine Vermutung ist, dass der Stick nicht genug Strom bekommt, abschmiert und FHEM durchdreht, weil er nicht mehr ( richtig ) erreichbar ist.

Edit: Ich meine übrigens nicht, dass du den Raspi über den Hub speisen sollst, sondern nur die angehängten USB-Geräte. Ersteres steht dir natürlich auch frei, prinzipiell sollte sich das Problem aber schon lösen, wenn der Raspi die USB-Peripherie nicht mehr selbst versorgen muss, sofern du nichts an den GPIOs angeschlossen hast.

[NehCoy]

Hi Carsten,

falls du das gefragt hast und ich darauf nicht geantwortet habe, tut mir das leid.
Nein, dass ist noch nicht der Fall. Steht aber auf meiner ToDo-Liste.
Nur die Hubs, die ich daheim rumfahren habe, haben leider kein eigenes Netzteil!

[Carsten]

Naja, die kosten ja nicht die Welt und man kriegt sie überall. Hab mir letztens noch welche für 5€ aus dem Tchibo-Rabattregal gekauft

[NehCoy]

Hallo!

Ich habe jetzt mal einen aktiven Hub bestellt. Komme nicht dazu einen kaufen zu gehen.
Dabei habe ich auch darauf geachtet, dass das Netzteil "genug" Power hat.
Habe aktive 7-Port Hubs gefunden, deren Netzteil nur 2A liefert. 

Zur Fehlermeldung (Logfile mit verbose 5): Da steht was besonderes

Code Auswählen Erweitern

2014.02.03 08:23:28 5: waiting to receive 8 bytes ...
2014.02.03 08:23:28 5: Received fixlen packet: bc11

2014.02.03 08:23:28 5: Received fixlen packet: 0919

2014.02.03 08:23:28 5: Received fixlen packet: 00e1

2014.02.03 08:23:28 5: Received fixlen packet: 00

2014.02.03 08:23:28 5: Received fixlen packet: 80

2014.02.03 08:23:28 5: getRequest len: 8 packet: bc11091900e10080

2014.02.03 08:23:28 5: receiving telegram with len: 9
2014.02.03 08:23:28 5: waiting to receive 1 bytes ...
2014.02.03 08:23:28 5: Received fixlen packet: 23

2014.02.03 08:23:28 5: getRequest len: 1 packet: 23

2014.02.03 08:23:28 5: receiving telegram with len: 9
2014.02.03 08:23:28 5: Telegram: (8): bc11091900e10080
2014.02.03 08:23:28 5: Buf: (0):
2014.02.03 08:23:28 5: msg cmd: 0x80 datalen: 2
2014.02.03 08:23:28 5: msg cmd: 0x80 datalen: 2 apci: 2
2014.02.03 08:23:28 5: decode_tpuart byte len: 1 array size: 1
2014.02.03 08:23:28 5: SimpleRead msg.type: write, msg.src: 1109, msg.dst: 3100
2014.02.03 08:23:28 5: SimpleRead data: 00
2014.02.03 08:23:28 4: SimpleRead: B1109w310000

2014.02.03 08:23:28 4: EIB: B1109w310000
2014.02.03 08:23:28 5: EIB dispatch B1109w310000
2014.02.03 08:23:28 2: EIB EIB_3100 off
2014.02.03 08:23:28 5: Triggering EIB_3100 (1 changes)
2014.02.03 08:23:28 5: Notify loop for EIB_3100 off
2014.02.03 08:23:28 4: eventTypes: EIB EIB_3100 off -> off
2014.02.03 08:23:29 5: waiting to receive 8 bytes ...
2014.02.03 08:23:29 5: Received fixlen packet: bc11

2014.02.03 08:23:29 5: Received fixlen packet: 0919

2014.02.03 08:23:29 5: Received fixlen packet: 00

2014.02.03 08:23:29 5: Received fixlen packet: e100

2014.02.03 08:23:29 5: Received fixlen packet: 80

2014.02.03 08:23:29 5: getRequest len: 8 packet: bc11091900e10080

2014.02.03 08:23:29 5: receiving telegram with len: 9
2014.02.03 08:23:29 5: waiting to receive 1 bytes ...
2014.02.03 08:23:29 5: Received fixlen packet: 23

2014.02.03 08:23:29 5: getRequest len: 1 packet: 23

2014.02.03 08:23:29 5: receiving telegram with len: 9
2014.02.03 08:23:29 5: Telegram: (8): bc11091900e10080
2014.02.03 08:23:29 5: Buf: (0):
2014.02.03 08:23:29 5: msg cmd: 0x80 datalen: 2
2014.02.03 08:23:29 5: msg cmd: 0x80 datalen: 2 apci: 2
2014.02.03 08:23:29 5: decode_tpuart byte len: 1 array size: 1
2014.02.03 08:23:29 5: SimpleRead msg.type: write, msg.src: 1109, msg.dst: 3100
2014.02.03 08:23:29 5: SimpleRead data: 00
2014.02.03 08:23:29 4: SimpleRead: B1109w310000

2014.02.03 08:23:29 4: EIB: B1109w310000
2014.02.03 08:23:29 5: EIB dispatch B1109w310000
2014.02.03 08:23:29 2: EIB EIB_3100 off
2014.02.03 08:23:29 5: Triggering EIB_3100 (1 changes)
2014.02.03 08:23:29 5: Notify loop for EIB_3100 off
2014.02.03 [b]08:23:29[/b] 4: eventTypes: EIB EIB_3100 off -> off
[b]2014.02.03 08:23:29 5: waiting to receive 8 bytes ...[/b]
2014.02.03 [b]19:50:28[/b] 1: Including fhem.cfg

Gruß
NehCoy

Edit:
Das warten auf Bytes war auch der letzte Eintrag vom letzten aufhängen heute Nacht:

Code Auswählen Erweitern

2014.02.04 06:02:28 4: eventTypes: SYSMON sysmon ram: Total: 437.68 MB, Used: 29.75 MB, 6.80 %, Free: 407.93 MB -> ram: Total: .* MB, Used: .* MB, .* %, Free: .* MB
2014.02.04 06:02:40 5: waiting to receive 8 bytes ...
2014.02.04 06:02:40 5: Received fixlen packet: bc11
2014.02.04 06:02:40 5: Received fixlen packet: 0f11
2014.02.04 06:02:40 5: Received fixlen packet: 0f
2014.02.04 06:02:40 5: Received fixlen packet: e100
2014.02.04 06:02:40 5: Received fixlen packet: 80
2014.02.04 06:02:40 5: getRequest len: 8 packet: bc110f110fe10080
2014.02.04 06:02:40 5: receiving telegram with len: 9
2014.02.04 06:02:40 5: waiting to receive 1 bytes ...
2014.02.04 06:02:40 5: Received fixlen packet: 22
2014.02.04 06:02:40 5: getRequest len: 1 packet: 22
2014.02.04 06:02:40 5: receiving telegram with len: 9
2014.02.04 06:02:40 5: Telegram: (8): bc110f110fe10080
2014.02.04 06:02:40 5: Buf: (0):
2014.02.04 06:02:40 5: msg cmd: 0x80 datalen: 2
2014.02.04 06:02:40 5: msg cmd: 0x80 datalen: 2 apci: 2
2014.02.04 06:02:40 5: decode_tpuart byte len: 1 array size: 1
2014.02.04 06:02:40 5: SimpleRead msg.type: write, msg.src: 110f, msg.dst: 210f
2014.02.04 06:02:40 5: SimpleRead data: 00
2014.02.04 06:02:40 4: SimpleRead: B110fw210f00
2014.02.04 06:02:40 4: EIB: B110fw210f00
2014.02.04 06:02:40 5: EIB dispatch B110fw210f00
2014.02.04 06:02:40 2: EIB EIB_210f off
2014.02.04 06:02:40 5: Triggering EIB_210f (1 changes)
2014.02.04 06:02:40 5: Notify loop for EIB_210f off
2014.02.04 06:02:40 4: eventTypes: EIB EIB_210f off -> off
2014.02.04 06:02:41 5: waiting to receive 8 bytes ...
2014.02.04 06:02:41 5: Received fixlen packet: bc110e
2014.02.04 06:02:41 5: Received fixlen packet: 19
2014.02.04 06:02:41 5: Received fixlen packet: 0ce1
2014.02.04 06:02:41 5: Received fixlen packet: 00
2014.02.04 06:02:41 5: Received fixlen packet: 80
2014.02.04 06:02:41 5: getRequest len: 8 packet: bc110e190ce10080
2014.02.04 06:02:41 5: receiving telegram with len: 9
2014.02.04 06:02:41 5: waiting to receive 1 bytes ...
2014.02.04 06:02:41 5: Received fixlen packet: 28
2014.02.04 06:02:41 5: getRequest len: 1 packet: 28
2014.02.04 06:02:41 5: receiving telegram with len: 9
2014.02.04 06:02:41 5: Telegram: (8): bc110e190ce10080
2014.02.04 06:02:41 5: Buf: (0):
2014.02.04 06:02:41 5: msg cmd: 0x80 datalen: 2
2014.02.04 06:02:41 5: msg cmd: 0x80 datalen: 2 apci: 2
2014.02.04 06:02:41 5: decode_tpuart byte len: 1 array size: 1
2014.02.04 06:02:41 5: SimpleRead msg.type: write, msg.src: 110e, msg.dst: 310c
2014.02.04 06:02:41 5: SimpleRead data: 00
2014.02.04 06:02:41 4: SimpleRead: B110ew310c00
2014.02.04 06:02:41 4: EIB: B110ew310c00
2014.02.04 06:02:41 5: EIB dispatch B110ew310c00
2014.02.04 06:02:41 2: EIB EIB_310c off
2014.02.04 06:02:41 5: Triggering EIB_310c (1 changes)
2014.02.04 06:02:41 5: Notify loop for EIB_310c off
2014.02.04 06:02:41 4: eventTypes: EIB EIB_310c off -> off
2014.02.04 06:02:41 5: waiting to receive 8 bytes ...
2014.02.04 07:12:32 1: Including fhem.cfg

Wenn ich das hier aber richtig verstehe, dann wartet er immer auf die Mindesframelänge von 8 Bytes. Ist das Paket länger, wartet er auf die noch fehlende Anzahl.
Dennoch ist nicht auszuschließen, dass er bei der Kommunikation mit dem TPUART abstürzt/sich aufhängt (die grüne LED des Moduls blinkt ja sehr schnell und schwach).
Bin mal gespannt, ob eine bessere Spannungsversorgung das Problem löst...