Absturz/Blockade durch Logdatei?!

Begonnen von Invers, 22 Juni 2019, 23:12:48

Vorheriges Thema - Nächstes Thema

Invers

Ich hatte seit gestern das Problem, dass fhem nicht mehr reagierte. Befehle aller Art dauerten bis zur Ausführung mehrere Minuten. WEB-Oberfläche gar nicht mehr erreichbar.
Ich habe nach Fehlerursachen geforscht.
Andere Karte, anderes Netzteil, Deaktivierung einige Module und Entfernung von Hardware.
Ich bin dann dahintergekommen, dass es die Logdatei sein muss, weil der Fehler gefühlt immer erst auftrat, nachdem ich etwas im Log nachgesehen hatte, allerdings leider nicht sofort.
Ich habe dann die Logdatei geleert, weil sie schon gross geworden war wegen verbose 5 und siehe da, der Fehler ist weg.
Ich suche also keine Hilfe, möchte eher die Fehlerursache bekannt machen, falls wieder einmal jemand Probleme dieser Art hat.

Eigentlich kann ich mir das Ganze gar nicht vorstellen, geschweige denn, erklären. Ich habe zur Vorsicht mal das Log aufgehoben.
Pi3B+ mit SSD/ Bullseye | FB7590 AX | 12 x Dect200 | CUL433+868 | SDuino | HM-LAN | 3 x Heizung FHT + FKontakte | KeyMatic + 4 FB | HM Wandtaster 2-fach m. LED | 6 x Türkont. TFK-TI | HM-Bew.-Melder innen | 3 x Smoked. HM-SEC-SD-2

rudolfkoenig

Wenn ich die Beschreibung richtig verstanden habe, ist FHEM nicht abgestuerzt, sondern war "nur" eine Weile nicht erreichbar.

Womoeglich hat das Betriebsystem Schwierigkeiten beim Zugriff auf die "Platte", entweder weil sie langsam ist, langsam geworden ist, oder defekte Bloecke hat.
Alternativ: je nach IO-Scheduler kann bei Plattenlast eine Filesystem-Operation laenger blockiert sein.

Invers

"Abgestürzt" war doch nur die Überschrift.
Ich habe doch geschrieben, dass ich die Karte kopiert habe. Eine Platte habe ich nicht dran und auch nicht erwähnt.
Ich habe dazu ein Image von der Karte auf eine andere Karte kopiert.
Eine Plattenlast kann bei mir eigentlich sowieso nicht entstehen.
Alle 10 bis 15 Minuten ein Schaltvorgang und dazwischen gar nichts. Auch kein Logeintrag oder sonstige Reaktion.


Ich kann den Fehler reproduzieren. Wenn ich die alte Logdatei wieder reinkopiere, blockiert fhem erneut. Defekte Karte scheidet also aus.
Es sollte nur ein Tipp sein, für die Leute, die auch irgendwann einmal eine Fehlerquelle ausschliessen müssen.

Hab die Überschrift angepasst.
Pi3B+ mit SSD/ Bullseye | FB7590 AX | 12 x Dect200 | CUL433+868 | SDuino | HM-LAN | 3 x Heizung FHT + FKontakte | KeyMatic + 4 FB | HM Wandtaster 2-fach m. LED | 6 x Türkont. TFK-TI | HM-Bew.-Melder innen | 3 x Smoked. HM-SEC-SD-2

rudolfkoenig

Zitat"Abgestürzt" war doch nur die Überschrift.
Mag sein, ich wollte das fuer andere Leser, die aehnliche Probleme haben, klarstellen.

ZitatIch habe dann die Logdatei geleert, weil sie schon gross geworden war wegen verbose 5 und siehe da, der Fehler ist weg.
...
Eine Plattenlast kann bei mir eigentlich sowieso nicht entstehen.
Diese beiden Aussagen sind mAn widerspruechlich.

Mit "Platte" meinte ich etwas, was zum dauerhaften speichern der Daten geeignet ist, und die erwaehnten Probleme koennen alle haben.
Mit anderen Effekten kann ich das Problem nicht erklaeren, lerne aber gerne dazu.

Invers

Die Logdatei war anfangs nicht sehr gross, aber durch meine Tests, Neustarts und verbose 5 wuchs sie dann an und wurde für mich unübersichtlich. Es sind rund 2,5 MB.
Vor verbose 5 waren es rund 4000 Zeilen, später dann mit verbose 5 waren es 34000 Zeilen. Aber als der Fehler erstmalig auftrat, waren es um die 1000 Zeilen.

Für mich ist die ganze Sache noch viel unerklärlicher. Deshalb hat ja auch die Fehlersuche sehr lange gedauert, da ich die Datei natürlich gar nicht verdächtigt hatte. Ist halt völlig irre.
Ich hätte das auch garnicht hier geschrieben, aber ich hoffe halt, dass irgendwann doch jemand davon profitiert. Immerhin kann ja ein Test nicht schaden.
Pi3B+ mit SSD/ Bullseye | FB7590 AX | 12 x Dect200 | CUL433+868 | SDuino | HM-LAN | 3 x Heizung FHT + FKontakte | KeyMatic + 4 FB | HM Wandtaster 2-fach m. LED | 6 x Türkont. TFK-TI | HM-Bew.-Melder innen | 3 x Smoked. HM-SEC-SD-2

KölnSolar

ZitatEs sind rund 2,5 MB
Das ist meines Erachtens klein. Ich hatte schon das 10-fache.

Dein Problem muss irgendwo anders liegen. Ich würd auf OS-Ebene tippen oder etwas, was in Abhängigkeit der Größe archivieren soll. :-\
RPi3/2 buster/stretch-SamsungAV_E/N-RFXTRX-IT-RSL-NC5462-Oregon-CUL433-GT-TMBBQ-01e-CUL868-FS20-EMGZ-1W(GPIO)-DS18B20-CO2-USBRS232-USBRS422-Betty_Boop-EchoDot-OBIS(Easymeter-Q3/EMH-KW8)-PCA301(S'duino)-Deebot(mqtt2)-zigbee2mqtt

Invers

Ich selber habe keinerlei Archivierung veranlasst. Ich mache das immer manuell per Imagebackup unter Windows.
Die Logdatei wird ja jeden Monat neu erzeugt und machte noch nie Probleme. Ich habe sie ja auch nicht weggeworfen. Der Alias zur Löschung lautet bei mir:
dellog AS {qx(truncate $currlogfile --size 0);Log 1, "Logfile gelöscht";}
Ich weiss nicht, ob die Datei damit gelöscht, oder nur geleert wird.
Der Inhalt der Logdatei wird ja vermutlich unter fhem nicht ausgewertet. Ein Zugriff auf die Log war im Fehlerfall nicht notwendig, daher vermute ich, dass der Zugriff (das Schreiben ins Log durch fhem) genügt hat.
Wenn ich die Datei aufgerufen habe, lief fhem noch kurze Zeit anstandslos, dann wurde aber blockiert. Da das Verhalten nicht regelmäßig auftrat, also z.B. 10 Sekunden nach dem Öffnen, war ein Zusammenhang nicht sofort erkennbar. Zu dem Zeitpunkt des Fehlers hatte ich auch (wie Andere) Probleme mit dem Echo-Modul - npm-Login. Wenn das nicht klappte, blockierte fhem auch sofort. Ich dachte, Echo hat Schuld, aber es wurde vermutlich hier nur durch den Fehler ein Logeintrag erzeugt, der dann den Fehler hervorrief.
Alles sehr kompliziert und daher nicht richtig gut einzugrenzen.
Sei es, wie es sei - es ist und bleibt erst einmal merkwürdig.
Pi3B+ mit SSD/ Bullseye | FB7590 AX | 12 x Dect200 | CUL433+868 | SDuino | HM-LAN | 3 x Heizung FHT + FKontakte | KeyMatic + 4 FB | HM Wandtaster 2-fach m. LED | 6 x Türkont. TFK-TI | HM-Bew.-Melder innen | 3 x Smoked. HM-SEC-SD-2

LuckyDay

hast du z.B.
attr <web> reverseLogs  1

das wäre ein Killer bei großen Files

Invers

Nein, habe ich nicht. Es lief ja auch bisher alles klaglos. Das System habe ich ja erst letzten Monat neu aufgesetzt. Lief und läuft wie geölt. Nicht einmal der HM-Lan macht Probleme. Raspi hängt am Kabel direkt am Router. Ich habe nicht einmal Perl-Warnungen. Auch Freezemon zeigt nur die "normalen" Unregelmäßigkeiten.
Ich hatte auch das Logfile wieder zurückgespielt und der Fehler war wieder da. Logfile geleert und der Fehler ist weg. Und, wie gesagt, 1,5 MB ist auch nicht der Blocker.
Wenn ich Lust haben sollte, teile ich die Datei mal so lange auf, bis die Fehlerstelle eingegrenzt ist. Ich weiss nur nicht, ob das überhaupt möglich ist, sollte aber gehen, ohne Probleme zu machen.
Wenn das Wetter schlechter wird, ziehe ich das vielleicht mal durch.
Pi3B+ mit SSD/ Bullseye | FB7590 AX | 12 x Dect200 | CUL433+868 | SDuino | HM-LAN | 3 x Heizung FHT + FKontakte | KeyMatic + 4 FB | HM Wandtaster 2-fach m. LED | 6 x Türkont. TFK-TI | HM-Bew.-Melder innen | 3 x Smoked. HM-SEC-SD-2

KölnSolar

ZitatWenn ich Lust haben sollte, teile ich die Datei mal so lange auf, bis die Fehlerstelle eingegrenzt ist.
"Fehlerstelle" wird es keine geben. Du schriebst ja selber schon, dass die Log-Datei keinerlei Auswertungen unterliegt. Es ist eine "dumme" Datei, die halt immer weiter um zusätzliche Daten erweitert wird. Ich kann mich daher nur Rudis ersten Gedanken anschließen.

Nimm doch mal bei "stehendem" FHEM per Editor einige Zeilen aus der Datei. Dann Start von FHEM. Mit verbose5 sollte Sie dann relativ flott wieder "überlaufen"(oder FHEM erst gar nicht starten ? :-\). Das Ganze über putty mit top/ps aux beobachten. Oder es dauert und sie wird nun viel größer. Das wäre ja ein Indiz, dass irgendwelche "Puffer" voll laufen..., also ein OS-nahes Problem.
RPi3/2 buster/stretch-SamsungAV_E/N-RFXTRX-IT-RSL-NC5462-Oregon-CUL433-GT-TMBBQ-01e-CUL868-FS20-EMGZ-1W(GPIO)-DS18B20-CO2-USBRS232-USBRS422-Betty_Boop-EchoDot-OBIS(Easymeter-Q3/EMH-KW8)-PCA301(S'duino)-Deebot(mqtt2)-zigbee2mqtt

Invers

Danke. Werde ich gelegentlich in Angriff nehmen, denke ich.
Pi3B+ mit SSD/ Bullseye | FB7590 AX | 12 x Dect200 | CUL433+868 | SDuino | HM-LAN | 3 x Heizung FHT + FKontakte | KeyMatic + 4 FB | HM Wandtaster 2-fach m. LED | 6 x Türkont. TFK-TI | HM-Bew.-Melder innen | 3 x Smoked. HM-SEC-SD-2

binford6000

Hallo Invers,
ich hatte dieses Verhalten heute Nachmittag auch!

Habe bei einem echodevice (37_echodevice.pm) mal verbose 5 eingestellt und das Logfile auf 7,6 MByte aufgebläht.
Danach hat fhem nicht mehr reagiert, es lief aber noch. Also fhem gestoppt, das Logfile gelöscht und verbose 5 aus dem echodevice rausgelöscht. fhem wieder gestartet und schwupps: Alles wieder gut  ::) ???

fhem läuft bei mir in einem LXC auf nem Proxmox Host (SSD).
VG Sebastian

MadMax-FHEM

Auf meinen Testsystemen hab ich das auch schon beobachtet...

Testsysteme, weil da halt viel getestet wird... ;)
...und da schon mal mehr geloggt wird...

Plattformen: PI3 mit SD...

Könnte jetzt nicht sagen ab welcher Größe aber bei 1, 2, 3MB wird es soweit sein...

Dass fhem generell nicht mehr reagiert hatte ich (glaub ich noch nicht), träge wohl schon...
...außer ich versuche das fhem-Log per Web anzuzeigen...

Dann ist's/war's "vorbei"...

Auf meinem Hauptsystem bin ich immer deutlich untet 1MB (außer es läuft mal was gewaltig schief aber dann is auch schon egal ;)  ) und da gibt es keine Probleme...

Auf dem Testsystem wird halt einfach gestoppt, Log wegverschoben (wegen Analyse) und dann wieder gestartet...

Gruß, Joachim
FHEM PI3B+ Bullseye: HM-CFG-USB, 40x HM, ZWave-USB, 13x ZWave, EnOcean-PI, 15x EnOcean, HUE/deCONZ, CO2, ESP-Multisensor, Shelly, alexa-fhem, ...
FHEM PI2 Buster: HM-CFG-USB, 25x HM, ZWave-USB, 4x ZWave, EnOcean-PI, 3x EnOcean, Shelly, ha-bridge, ...
FHEM PI3 Buster (Test)

justme1968

ich hatte schon logfiles mit mehreren 100mb. das ist völlig problemlos.

wie rudi schon gesagt hat: ich bin mir ziemlich sicher dass kein fhem problem ist. das logfile wird nur geschrieben. d.h. zeilen hinten angehängt.

vielleicht mal mit top/iotop und strace an fhem schauen was genau passiert.
hue, tradfri, alexa-fhem, homebridge-fhem, LightScene, readingsGroup, ...

https://github.com/sponsors/justme-1968

Invers

Im normal laufenden System habe ich folgende Anzeige, die ich allerdings nicht deuten kann:

top - 20:03:29 up 1 day, 51 min,  2 users,  load average: 0,05, 0,06, 0,04
Tasks: 130 total,   1 running,  78 sleeping,   0 stopped,   1 zombie
%Cpu(s):  0,8 us,  0,3 sy,  0,0 ni, 98,8 id,  0,0 wa,  0,0 hi,  0,1 si,  0,0 st
KiB Mem :   948304 total,   306404 free,   252196 used,   389704 buff/cache
KiB Swap:   102396 total,   102396 free,        0 used.   629316 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
24215 fhem      20   0  112928 106908   8732 S   2,6 11,3  30:36.80 perl
13357 pi        20   0    8512   3348   2856 R   1,0  0,4   0:01.27 top
  697 pi        20   0  137284  28980  20104 S   0,3  3,1   3:36.27 lxpanel
    1 root      20   0   27084   6076   4880 S   0,0  0,6   0:05.67 systemd
    2 root      20   0       0      0      0 S   0,0  0,0   0:00.14 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
    8 root       0 -20       0      0      0 I   0,0  0,0   0:00.00 mm_percpu_wq
    9 root      20   0       0      0      0 S   0,0  0,0   0:04.90 ksoftirqd/0
   10 root      20   0       0      0      0 I   0,0  0,0   0:26.59 rcu_sched
   11 root      20   0       0      0      0 I   0,0  0,0   0:00.00 rcu_bh
   12 root      rt   0       0      0      0 S   0,0  0,0   0:00.03 migration/0
   13 root      20   0       0      0      0 S   0,0  0,0   0:00.00 cpuhp/0
   14 root      20   0       0      0      0 S   0,0  0,0   0:00.00 cpuhp/1
   15 root      rt   0       0      0      0 S   0,0  0,0   0:00.02 migration/1
   16 root      20   0       0      0      0 S   0,0  0,0   0:02.40 ksoftirqd/1
   19 root      20   0       0      0      0 S   0,0  0,0   0:00.00 cpuhp/2


Für iotop bin ich zu doof, da kommt bei Eingabe:
-bash: iotop: Kommando nicht gefunden.

bei
strace -p 24215
kommt dann:
strace: attach: ptrace(PTRACE_SEIZE, 24215): Operation not permitted
pi@fhem3:~ $ strace -p 24215
strace: attach: ptrace(PTRACE_SEIZE, 24215): Operation not permitted

Damit kann ich also offenbar auch noch nicht umgehen.

Ich werde also versuchen, mich zu bilden und dann das zu grosse oder defekte Log noch einmal einspielen und testen.

Danke.
Pi3B+ mit SSD/ Bullseye | FB7590 AX | 12 x Dect200 | CUL433+868 | SDuino | HM-LAN | 3 x Heizung FHT + FKontakte | KeyMatic + 4 FB | HM Wandtaster 2-fach m. LED | 6 x Türkont. TFK-TI | HM-Bew.-Melder innen | 3 x Smoked. HM-SEC-SD-2