FHEM bleibt "hängen" - wie debuggen?

[TheTrumpeter]

In den letzten 3 Wochen kam es heute zum 2. Mal vor, dass FHEM irgendwann "hängen" geblieben ist. Der Prozess selbst lief noch, aber es wurde nichts geloggt und auch das Frontend war nicht mehr erreichbar.
Nach stoppen und starten des Prozesses läuft es nun erstmal wieder.

Im fhem-Logfile ist kein Eintrag zur Ursache zu finden. Einzig anhand der Device-Logfiles kann ich nachvollziehen, wann das "Aufängen" passiert sein muss.

Wie finde ich die Ursache dafür, um es abstellen zu können?

[CoolTux]

Woher weist Du das

Im fhem-Logfile ist kein Eintrag zur Ursache zu finden

wenn Du die Ursache noch nicht einmal kennst.
Bitte gib uns die letzten 30 Zeilen vom Log bevor der Crash kommt.

[TheTrumpeter]

"Aufgehängt" hat sich FHEM lt. der Device-Logfiles um ca. 18:15 gestern, gemerkt habe ich es um ca. 21:00. Der von mir ausgelöste Shutdown wurde interessanterweise sauber protokolliert.
Hier das Logfile:

Code Auswählen Erweitern

2018.12.04 07:57:19 1: FHEMWEB SSL/HTTPS error:  SSL accept attempt failed error:1408F09C:SSL routines:ssl3_get_record:http request (peer: 2a03:567:1::20)
2018.12.04 09:35:01 1: FHEMWEB SSL/HTTPS error:  SSL accept attempt failed error:1408F09C:SSL routines:ssl3_get_record:http request (peer: 2a03:567:1::20)
2018.12.04 14:00:25 1: FHEMWEB SSL/HTTPS error:  SSL accept attempt failed error:14094416:SSL routines:ssl3_read_bytes:sslv3 alert certificate unknown (peer: 2a03:567:1::20)
2018.12.04 16:55:54 1: FHEMWEB SSL/HTTPS error:  SSL accept attempt failed (peer: 2a03:567:1::20)
2018.12.04 20:04:05 1: PERL WARNING: Use of uninitialized value $_ in numeric gt (>) at ./FHEM/99_Utils.pm line 63.
2018.12.04 20:37:42 1: PERL WARNING: Use of uninitialized value $_ in numeric gt (>) at ./FHEM/99_Utils.pm line 63.
2018.12.04 21:19:57 1: RMDIR: ./restoreDir/save/2018-11-29
2018.12.05 06:16:23 1: Timeout for PROPLANTA_Run reached, terminated process 9316
2018.12.05 06:25:19 1: PERL WARNING: Use of uninitialized value $_ in numeric gt (>) at ./FHEM/99_Utils.pm line 63.
2018.12.05 06:43:17 1: FHEMWEB SSL/HTTPS error:  SSL accept attempt failed error:1408F09C:SSL routines:ssl3_get_record:http request (peer: 2a03:567:1::20)
2018.12.05 07:32:32 1: FHEMWEB SSL/HTTPS error:  SSL accept attempt failed error:1408F09C:SSL routines:ssl3_get_record:http request (peer: 2a03:567:1::20)
2018.12.05 15:06:36 1: FHEMWEB SSL/HTTPS error:  SSL accept attempt failed (peer: 2a03:567:1::20)
2018.12.05 15:06:37 1: FHEMWEB SSL/HTTPS error:  SSL accept attempt failed (peer: 2a03:567:1::20)
2018.12.05 15:06:37 1: FHEMWEB SSL/HTTPS error:  SSL accept attempt failed (peer: 2a03:567:1::20)
2018.12.05 15:06:42 1: FHEMWEB SSL/HTTPS error:  SSL accept attempt failed (peer: 2a03:567:1::20)
2018.12.05 17:24:29 1: FHEMWEB SSL/HTTPS error:  SSL accept attempt failed error:1408F09C:SSL routines:ssl3_get_record:http request (peer: 2a03:567:1::20)
2018.12.05 17:53:28 1: FHEMWEB SSL/HTTPS error:  SSL accept attempt failed (peer: 2a03:567:1::20)
2018.12.05 17:53:29 1: FHEMWEB SSL/HTTPS error:  SSL accept attempt failed (peer: 2a03:567:1::20)
2018.12.05 21:16:42 0: Server shutdown
(Die Zeilen davor sind eine Fehlermeldung von einem Plot von der Plot-Erstellung.)

[CoolTux]

Eventuell beim nächsten nicht erreichbar sein einmal schauen was die Prozesstabelle sagt.
"top" zum Beispiel und dann nach einem Perlprozess schauen.

[TheTrumpeter]

Der Prozess läuft weiterhin, das habe ich geschaut.

Komisch ist, dass der FHEM-Shutdown dann "ganz normal" geloggt wurde, die Device-Readings in den Device-Logs aber nicht.

[CoolTux]

Der Prozess läuft weiterhin, das habe ich geschaut.

Komisch ist, dass der FHEM-Shutdown dann "ganz normal" geloggt wurde, die Device-Readings in den Device-Logs aber nicht.

Das würde erstmal lediglich auf fehlende Events hinweisen. Interessanter ist da schon eher das Du laut Deiner Aussage FHEMWEB auch nicht aufrufen konntest.

[TheTrumpeter]

Richtig.
Selbst im Heimnetz konnte ich mit Angabe der IP-Adresse nicht hin, was sonst immer funktioniert. Zum Rechner konnte ich aber mit VNC sofort verbinden.

Auch beim letzten Mal war es so, dass der Shutdown sauber im Log protokolliert wurde, davor war fast 12h kein anderer Logeintrag mehr, auch nicht in den Device-Logs. (War über Nacht...)

[Wernieman]

Du hast SSL auf fhemweb installiert?

(Und DU betreibst ein Desktop-Server-System?)

Mich würde aktuell eher interessiren, wie der Speicherverbrauch aussah. Sagt die /var/log/kern.log in der Zeit etwas? z.B. wegen oem-Killer?

Irgendwie hatten wir irgendwo diese Woche doch schon mal das Thema?

[TheTrumpeter]

Du hast SSL auf fhemweb installiert?

Ich habe SSL gemäss FHEM-Wiki aktiviert, ja.

(Und DU betreibst ein Desktop-Server-System?)

Was genau meinst Du? Ich habe FHEM auf einem RasPi installiert. Von Aussen greife ich über VNC-Cloud bzw. über die im Router freigegeben FHEM-Web-Ports zu.

Mich würde aktuell eher interessiren, wie der Speicherverbrauch aussah. Sagt die /var/log/kern.log in der Zeit etwas? z.B. wegen oem-Killer?

Speichernutzung war lt. FHEM-Modul "sysmon" beim letzten Eintrag unauffällig.
Im Kernel-Log ist ausser den Infos über Runter- und Rauftakten im fragwürdigen Zeitraum nichts enthalten.

[Wernieman]

naja VNC ist  für die Dekstopübertragung zuständig. Also hast Du ein Grafisches-System auf dem PI ....

[TheTrumpeter]

naja VNC ist  für die Dekstopübertragung zuständig. Also hast Du ein Grafisches-System auf dem PI ....

OK, das meinst Du.
Ja, Jessi läuft drauf.

[erdo_king]

Mal ein paar Ideen in den Raum werfen (brainstorm)
- Ram voll (unwahrscheinlich)
- HDD voll / Speicherkarte mit Zugriffen überlastet (unwahrscheinlich)
- Spannungsprobleme bei USB-Geräten? zB Antenne? -> Systemlogs/dmesg


Für mich klingt es danach, dass ein Gerät sich weghängt und FHEMin einen Timeout rennt ...

- Telnet irgendwohin?
- WLAN oder Kabel?

[Beta-User]

Klingt nach einem blockierenden Aufruf von irgendwas (IP-basiert, aber nicht erreichbar). In allen anderen Fällen müßte m.E. sonst was im log stehen oder die Maschine würde gar nicht mehr reagieren; aber wenn sogar der Desktop noch erreichbar ist?!?

Vielleicht mal hier starten:
https://wiki.fhem.de/wiki/FHEM_startet_nicht_-_Tipps_zur_Fehlersuche

Und dann freezemon oä. anwerfen.

Generell aber: Ein Server ist ein Server. Da hat ein Desktop nix drauf verloren (nur meine Meinung, die allerdings ein paar andere hier teilen), auch wenn irgendeiner in einem seeeehr langweiligen Video was anderes behauptet. (Der Hinweis auf "jessie" deutet darauf hin, dass der Betreffende nicht zwischen einer Desktop- und einer lite-Version unterscheiden kann, vielleicht liest du dich da mal ein?).

Empfehlung: "Richtig" machen, nochmal eine SD-Karte für das aktuelle Raspbian (stretch) vorbereiten, und dann die lite-Variante installieren. Dann ssh statt VNC nutzen (und für den Fall, dass ungeschütztes Portforwarding vorliegt, auch das gleich ändern...) und dann an der Konsole arbeiten. Wie man eine FHEM-Installation umzieht, sollte sowieso geübt werden .
Ist erst mal gewöhnungsbedürftig, aber langfristig deutlich zielführender.

Just my2ct.

Beta-User

[Wernieman]

Ich kann Betta-User nur Zustimmen!

[TheTrumpeter]

Klingt nach einem blockierenden Aufruf von irgendwas (IP-basiert, aber nicht erreichbar). In allen anderen Fällen müßte m.E. sonst was im log stehen oder die Maschine würde gar nicht mehr reagieren; aber wenn sogar der Desktop noch erreichbar ist?!?

Vielleicht mal hier starten:
https://wiki.fhem.de/wiki/FHEM_startet_nicht_-_Tipps_zur_Fehlersuche

Was genau meinst Du mit dem ersten Satz?
Irgend etwas, das ich per FHEMWEB selbst verursache? Bei beiden "Ausfällen" war ich nicht per VNC verbunden, vielleicht aber kurz vorher per FHEMWEB.

Ich habe keinerlei neue Devices eingebunden. Ich meine, dass die Probleme erst mit dem Umstieg auf stretch (ja, vorhin habe ich jessie gesagt) aufgetreten sind.

Alles was in den "Tipps zur Fehlersuche" steht, habe ich ohnehin gemacht, erfolglos.
Der Prozess läuft und erzeugt keine auffällige CPU-Last, an den Berechtigungen habe ich ewig nix geändert, im fhem.log ist nix auffälliges drin.

An den USB-Ports hängt ein RS485-Dongle (seit 1,5 Jahren), ein nano-cul (seit dem Sommer) sowie natürlich ein (Sandisk-) Flashspeicher, der die Logfiles enthält.

Generell aber: Ein Server ist ein Server. Da hat ein Desktop nix drauf verloren (nur meine Meinung, die allerdings ein paar andere hier teilen), auch wenn irgendeiner in einem seeeehr langweiligen Video was anderes behauptet. (Der Hinweis auf "jessie" deutet darauf hin, dass der Betreffende nicht zwischen einer Desktop- und einer lite-Version unterscheiden kann, vielleicht liest du dich da mal ein?).

Empfehlung: "Richtig" machen, nochmal eine SD-Karte für das aktuelle Raspbian (stretch) vorbereiten, und dann die lite-Variante installieren. Dann ssh statt VNC nutzen (und für den Fall, dass ungeschütztes Portforwarding vorliegt, auch das gleich ändern...) und dann an der Konsole arbeiten. Wie man eine FHEM-Installation umzieht, sollte sowieso geübt werden .
Ist erst mal gewöhnungsbedürftig, aber langfristig deutlich zielführender.

Meine Hardcore-Terminalzeiten sind lange vorbei, davor scheue ich mich einfach... abgesehen davon sehe ich nicht, welchen Vorteil das haben soll. Ja, das System ist schlanker und weniger belastet, aber eigentlich langweilt sich der Raspi jetzt auch schon.

Mal ein paar Ideen in den Raum werfen (brainstorm)
- Ram voll (unwahrscheinlich)
- HDD voll / Speicherkarte mit Zugriffen überlastet (unwahrscheinlich)
- Spannungsprobleme bei USB-Geräten? zB Antenne? -> Systemlogs/dmesg

Nein, nein, und dmesg leer. USB-Geräte siehe oben.
Raspi bekommt konstant 5,3V. Das könnte ich beliebig erhöhen, sehe aber nicht wofür.

Für mich klingt es danach, dass ein Gerät sich weghängt und FHEMin einen Timeout rennt ...

- Telnet irgendwohin?
- WLAN oder Kabel?

Telnet ist zwar aktiviert, aber niemand war verbunden.
WLAN.

Ich habe anhand der Device-Logs nun die genaue Ausfallzeit nachvollzogen, muss gestern kurz nach 18:16 gewesen sein.

Kernel-Log sagt dazu nur, dass der Raspi da grad mit niedrigem Takt lief.

Code Auswählen Erweitern

Dec  5 18:10:22 raspberrypi kernel: [892669.158210] rpi_firmware_get_throttled: 16 callbacks suppressed
Dec  5 18:10:22 raspberrypi kernel: [892669.158217] Under-voltage detected! (0x00050005)
Dec  5 18:10:40 raspberrypi kernel: [892687.878297] Under-voltage detected! (0x00050005)
Dec  5 18:11:01 raspberrypi kernel: [892708.678454] Under-voltage detected! (0x00050005)
Dec  5 18:14:37 raspberrypi kernel: [892925.009827] rpi_firmware_get_throttled: 14 callbacks suppressed
Dec  5 18:14:37 raspberrypi kernel: [892925.009831] Voltage normalised (0x00000000)
Dec  5 18:14:46 raspberrypi kernel: [892933.319942] Voltage normalised (0x00000000)
Dec  5 18:15:11 raspberrypi kernel: [892958.280065] Voltage normalised (0x00000000)
Dec  5 18:15:40 raspberrypi kernel: [892987.400359] rpi_firmware_get_throttled: 15 callbacks suppressed
Dec  5 18:15:40 raspberrypi kernel: [892987.400367] Under-voltage detected! (0x00050005)
Dec  5 18:16:03 raspberrypi kernel: [893010.280429] Under-voltage detected! (0x00050005)
Dec  5 18:17:20 raspberrypi kernel: [893087.240940] Under-voltage detected! (0x00050005)
Dec  5 18:21:19 raspberrypi kernel: [893326.442531] rpi_firmware_get_throttled: 1 callbacks suppressed
Dec  5 18:21:19 raspberrypi kernel: [893326.442548] Under-voltage detected! (0x00050005)
Dec  5 18:21:25 raspberrypi kernel: [893332.682553] rpi_firmware_get_throttled: 5 callbacks suppressed
Dec  5 18:21:25 raspberrypi kernel: [893332.682560] Voltage normalised (0x00000000)

Bin leider immer noch ratlos.