[behoben] System friert sporadisch ein nach Dist-Upgrade

[Geizeskrank]

Hallo,

ich muss mich seit langer Zeit wieder bei euch melden..

Am Donnerstag hab ich ein Dist-Upgrade von Stretch zu Buster und im gleichen Zug von Buster zu Bullseye durchgeführt.
Das Upgrade selber lief ohne Probleme durch, ich müsste aber direkt auf Bullseye Hochschießen, da unter Buster dm-crypt nicht lief und ich mit der Kernelversion nicht runter wollte.

Die Hardware:

BananaPi (erste Generation)
USB HDD
Netzteil von Anker

Software:

Debian Bullseye
Linux bananapi 5.4.0-4-armmp-lpae #1 SMP Debian 5.4.19-1
-mariadb
-samba

Das Problem:

Der Server ist dafür da um für Kodi die Datenbank und Dateien zur Verfügung zu stellen, nichts wildes, hat die letzten Jahre 1a funktioniert.
Nach dem Upgrade friert das System sporadisch ein und ist über UART nicht und über ssh erst Recht nicht mehr ansprechbar; der Router erkennt die Ethernet Verbindung noch, aber wohl nur ,,elektrisch" .

Was hab ich getan:

Einzeln die Dienste abschalten: keine Lösung
Auslesen von /var/Log/{syslog,messages} (live über UART und nachträglich über die Files) keine Einträge, anscheinend wird im Moment des einfrieren nichts mehr geschrieben

Nächster Schritt wäre Kernel oder System Downgrade, wollte aber erst euer Schwarmwissen abfragen.


Grüße

[willy4711]

Schau mal hier:
viewtopic.php?f=13&t=176955
Solltest zuerst mal im Journal nachsehen, wenn du einen Neustart (bzw. Reset) gemacht hast,
ob da ähnliche Meldungen kommen wie bei mir.
Ob sich dieser Bug auch bei ARM- Prozessoren bemerkbar macht ---> Keinen Ahnung.
Aber nachsehen kostet erstmal nichts.

[Geizeskrank]

Hab eben nachgeschaut, absolut unauffällig den ganzen Log durch.
Auch die vor dem letzten Absturz enden mit regulären cron Einträgen.

Mein erster Gedanke fiel auch direkt auf den Kernel, bin aber noch skeptisch ob ich den aus den unstable Quellen nehmen sollte.

Edit: hab nun 5.5.0.1 drauf... mal sehen

[Geizeskrank]

Okay, der neue Kernel hat es nicht gebracht.
Die Logs sind weiterhin unauffällig, die Dateisysteme clean (außer / nach dem abschießen)

Weitere Ideen zum eingrenzen?

[tijuca]

Ist vermutlich aber eher IO-Wait da nun wohl unattended-upgrades aktiv ist. Macht sich auf derartigen Plattformen immer deutlich bemerkbar wenn das System an sich eben primär auf die Hardware warten muss. Kann man schön in {a,h}top z.B. sehen wie die Load deutlich nach oben geht. Und das über Minuten.

[Geizeskrank]

Unattended upgrades kann ich ausschließen, das Paket ist nicht installiert und die üblichen Verzeichnisse weisen auch nicht darauf hin.

Den load hatte ich auch schon im Blick, doch hab ich einen crash welcher gegen 02:00 (letzter log Eintrag) passiert ist, erst Morgens gegen 07:00 bemerkt; da hätte sich bis dahin wieder alles normalisiert haben sollen.

Wenn ich's dem BananaPi mal richtig gegeben hab, war der load such schon mal über Minuten >5, aber immer über ssh ansprechbar.

Kann ich irgendwie nachvollziehen ob ich in meiner oldstable Konfiguration einen Kernel mit lpae installiert hatte?
Mache nach Installationen immer clean+autoremove

[Geizeskrank]

Ist vermutlich aber eher IO-Wait da nun wohl unattended-upgrades aktiv ist. Macht sich auf derartigen Plattformen immer deutlich bemerkbar wenn das System an sich eben primär auf die Hardware warten muss. Kann man schön in {a,h}top z.B. sehen wie die Load deutlich nach oben geht. Und das über Minuten.

Okay, gibt es noch andere Wege wie unattended upgrades installiert werden können?
Der Pi ist wieder nicht ansprechbar, aber! er regiert auf Ping mit einer Antwortzeit von 8ms bis hoch zu 100ms.

Was komisch ist, mir ist jetzt schon zwei mal aufgefallen, dass der Crash zu einer glatten Uhrzeit (02:00 und 01:00) stattfand.

[Geizeskrank]

Ehrlich gesagt kann ich daraus nichts entnehmen, außer das es vielleicht doch an einem vom Cron ausgelösten/angestoßenen Hänger liegt.

Edit: hab die Crons händisch angestoßen, ohne Resultat

Code: Alles auswählen

root@bananapi:/home/tom# journalctl -b | grep -i 'Apr 06 02'
Apr 06 02:23:46 bananapi cron[386]: (CRON) INFO (pidfile fd = 3)
Apr 06 02:23:46 bananapi systemd[1]: Started Network Time Synchronization.
Apr 06 02:23:46 bananapi cron[386]: (CRON) INFO (Running @reboot jobs)
Apr 06 02:23:46 bananapi systemd[1]: Reached target System Initialization.
Apr 06 02:23:47 bananapi rsyslogd[390]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd.  [v8.2002.0]
Apr 06 02:23:46 bananapi systemd[1]: Started Daily Cleanup of Temporary Directories.
Apr 06 02:23:47 bananapi rsyslogd[390]: [origin software="rsyslogd" swVersion="8.2002.0" x-pid="390" x-info="https://www.rsyslog.com"] start
Apr 06 02:23:46 bananapi systemd[1]: Reached target System Time Set.
Apr 06 02:23:46 bananapi systemd[1]: Reached target System Time Synchronized.
Apr 06 02:23:46 bananapi systemd[1]: Started Daily apt download activities.
Apr 06 02:23:46 bananapi systemd[1]: Started Daily apt upgrade and clean activities.
Apr 06 02:23:46 bananapi systemd[1]: Started Periodic ext4 Online Metadata Check for All Filesystems.
Apr 06 02:23:46 bananapi systemd[1]: Started Daily exim4-base housekeeping.
Apr 06 02:23:46 bananapi systemd[1]: Started Daily rotation of log files.
Apr 06 02:23:46 bananapi systemd[1]: Started Daily man-db regeneration.
Apr 06 02:23:46 bananapi systemd[1]: Reached target Timers.
Apr 06 02:23:46 bananapi systemd[1]: Listening on D-Bus System Message Bus Socket.
Apr 06 02:23:46 bananapi systemd[1]: Reached target Sockets.
Apr 06 02:23:46 bananapi systemd[1]: Reached target Basic System.
Apr 06 02:23:46 bananapi systemd[1]: Started Regular background program processing daemon.
Apr 06 02:23:46 bananapi systemd[1]: Started D-Bus System Message Bus.
Apr 06 02:23:46 bananapi systemd[1]: Starting Remove Stale Online ext4 Metadata Check Snapshots...
Apr 06 02:23:46 bananapi systemd[1]: Condition check resulted in getty on tty2-tty6 if dbus and logind are not available being skipped.
Apr 06 02:23:46 bananapi systemd[1]: Starting MariaDB 10.3.22 database server...
Apr 06 02:23:46 bananapi systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped.
Apr 06 02:23:46 bananapi systemd[1]: Starting System Logging Service...
Apr 06 02:23:46 bananapi systemd[1]: Starting Samba SMB Daemon...
Apr 06 02:23:46 bananapi systemd[1]: Starting OpenBSD Secure Shell server...
Apr 06 02:23:46 bananapi systemd[1]: Starting Login Service...
Apr 06 02:23:47 bananapi systemd[1]: Starting Permit User Sessions...
Apr 06 02:23:47 bananapi systemd[1]: Started System Logging Service.
Apr 06 02:23:47 bananapi systemd[1]: Started Permit User Sessions.
Apr 06 02:23:47 bananapi systemd[1]: Started Getty on tty1.
Apr 06 02:23:47 bananapi systemd[1]: Started Serial Getty on ttyS0.
Apr 06 02:23:47 bananapi systemd[1]: Reached target Login Prompts.
Apr 06 02:23:47 bananapi systemd[1]: e2scrub_reap.service: Succeeded.
Apr 06 02:23:47 bananapi systemd[1]: Started Remove Stale Online ext4 Metadata Check Snapshots.
Apr 06 02:23:48 bananapi systemd-logind[409]: New seat seat0.
Apr 06 02:23:48 bananapi systemd-logind[409]: Watching system buttons on /dev/input/event1 (axp20x-pek)
Apr 06 02:23:48 bananapi systemd[1]: Started Login Service.
Apr 06 02:23:48 bananapi sshd[414]: Server listening on 0.0.0.0 port 53783.
Apr 06 02:23:48 bananapi sshd[414]: Server listening on :: port 53783.
Apr 06 02:23:48 bananapi systemd[1]: Started OpenBSD Secure Shell server.
Apr 06 02:23:49 bananapi mysqld[500]: 2020-04-06  2:23:49 0 [Note] /usr/sbin/mysqld (mysqld 10.3.22-MariaDB-1) starting as process 500 ...
Apr 06 02:23:49 bananapi kernel: sun7i-dwmac 1c50000.ethernet eth0: Link is Up - 1Gbps/Full - flow control rx/tx
Apr 06 02:23:49 bananapi kernel: IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready

[Geizeskrank]

War wohl laut kern.log ein reboot

Code: Alles auswählen

Apr  5 20:27:52 bananapi kernel: [ 9371.385667] hrtimer: interrupt took 334476 ns
Apr  5 22:28:30 bananapi kernel: [16609.523295] Process accounting resumed
Apr  5 22:28:36 bananapi kernel: [16615.478806] Process accounting resumed
Apr  6 02:23:47 bananapi kernel: [    0.000000] Booting Linux on physical CPU 0x0
Apr  6 02:23:47 bananapi kernel: [    0.000000] Linux version 5.4.0-4-armmp (debian-kernel@lists.debian.org) (gcc version 9.2.1 20200203 (Debian 9.2.1-28)) #1 SMP Debian 5.4.19-1 (2020-02-13)

[Geizeskrank]

Nach Erhöhung des Swap hat er etwas länger durchgehalten, ist aber nach 25h uptime trotzdem hängen geblieben.

Steht noch aus ob er rebootet oder schlicht einfriert... hat noch jemand Ideen dazu?

[willy4711]

Hast du denn das Journal persistent gemacht ?
Der obige Auszug (-b) stellt nur die gerade laufende Sitzung da.
Nach einem Absturz +(Neustart ??)
erreichst du das Journal der letzten Sitzung mit:

Code: Alles auswählen

journalctl -b -1 -n 20

Damit würden die letzten 20 Zeilen dargestellt werden

Persistent machen:

Code: Alles auswählen

mkdir /var/log/journal

[Geizeskrank]

Hab das Journal jetzt persistent gemacht.
Ich hatte erst mit dem Schalter -1 aufgerufen, aber der sprang direkt einen Start weiter zurück.
Man sieht ja, dass die Einträge gegen 02:00 gemacht worden sind und ich hab den Befehl mit den wieder-gestarteten System gegen 10:00 gemacht; also hat er warum auch immer, die alte Laufzeit mit in die neue hinein gezählt.

Noch verrückter wird es hier:

Code: Alles auswählen

root@bananapi:/var/log/journal# last -x reboot
reboot   system boot  5.4.0-4-armmp    Thu Jan  1 01:00   still running
reboot   system boot  5.4.0-4-armmp    Thu Jan  1 01:00   still running
reboot   system boot  5.4.0-4-armmp    Tue Apr  7 17:24   still running

wtmp begins Tue Apr  7 17:24:17 2020

Die dritte Zeile stimmt, die ersten beiden sind grober Unfug...

Code: Alles auswählen

root@bananapi:/var/log/journal# date
Tue Apr  7 21:34:31 CEST 2020

Ich muss zugeben, dass ich erstmal wieder in Schwung kommen muss, meine aktiven Linuxtage sind nun mehr als 10 Jahre her, es hat sich sehr viel verändert in Debian und ich habe seit dem die Systeme mehr genutzt als Probleme gehabt; mein Oldstable lief vor dem Dist-Upgrade laut top ~230 Tage, ich ärger mich schon wider besseren Wissens ein Dist-Upgrade gemacht zu haben, aber man muss ja auch mit der Zeit gehen.

Ist es sinnvoll die Mem / Swap Auslastung zu protokollieren?

[willy4711]

zum Journal:
Wenn du eine Bestimmte Sitzung abfragen willst (habe mal den Rest gelöscht):

Code: Alles auswählen

 journalctl --list-boots
 -3 98cc8c8917c14287baac2be0dd21d766 Tue 2020-04-07 05:26:01 CEST—Tue 2020-04-07 19:50:20 CEST
 -2 d9fa8cc7b31649d59523df8ced4e471a Tue 2020-04-07 19:50:20 CEST—Tue 2020-04-07 20:02:58 CEST
 -1 d4d57c8e1a8e43f59dcc672f5c4d3e12 Tue 2020-04-07 20:02:58 CEST—Tue 2020-04-07 20:38:54 CEST
  0 104700956551452d9c0c4300fa25fd55 Tue 2020-04-07 20:38:55 CEST—Tue 2020-04-07 22:27:13 CEST

Jetzt sieht du jeweils den Anfang und das Ende der Sitzung. Ich will jetzt mal die Letzten Zeilen der Sitzung sehen,
die um 19:50 beendet wurde

Code: Alles auswählen

ournalctl -b 98cc8c8917c14287baac2be0dd21d766 -n 10
-- Logs begin at Thu 2020-04-02 11:41:08 CEST, end at Tue 2020-04-07 22:39:19 CEST. --
Apr 07 19:50:20 XFCE systemd[1]: Reached target Reboot.
Apr 07 19:50:20 XFCE systemd[1]: Shutting down.
Apr 07 19:50:20 XFCE systemd[1]: Hardware watchdog 'iTCO_wdt', version 0
Apr 07 19:50:20 XFCE systemd[1]: Set hardware watchdog to 10min.
Apr 07 19:50:20 XFCE kernel: watchdog: watchdog0: watchdog did not stop!
Apr 07 19:50:20 XFCE systemd-shutdown[1]: Syncing filesystems and block devices.
Apr 07 19:50:20 XFCE systemd-shutdown[1]: Sending SIGTERM to remaining processes...
Apr 07 19:50:20 XFCE haveged[960]: haveged: Stopping due to signal 15
Apr 07 19:50:20 XFCE haveged[960]: haveged starting up
Apr 07 19:50:20 XFCE systemd-journald[374]: Journal stopped

Deine Befehle haben mit dem Journal nichts zu tun.

Mal zum Schnuppern:
https://www.digitalocean.com/community/ ... stemd-logs

[Geizeskrank]

Heute hat es ihn nach mehr als 2 Tagen Upzeit wieder zerlegt, anbei mal das Journal

Code: Alles auswählen

root@bananapi:/home/tom# journalctl -b -1 -n 20
-- Logs begin at Fri 2020-02-07 16:50:54 CET, end at Sat 2020-04-11 16:14:48 CEST. --
Apr 11 13:41:39 bananapi systemd-logind[402]: Removed session 204.
Apr 11 13:56:01 bananapi sshd[16776]: Accepted publickey for tom from IPADRESSE port 46685 ssh2: RSA SHA256
Apr 11 13:56:01 bananapi sshd[16776]: pam_unix(sshd:session): session opened for user tom by (uid=0)
Apr 11 13:56:01 bananapi systemd-logind[402]: New session 205 of user tom.
Apr 11 13:56:02 bananapi systemd[1]: Started Session 205 of user tom.
Apr 11 13:56:17 bananapi sshd[16776]: pam_unix(sshd:session): session closed for user tom
Apr 11 13:56:17 bananapi systemd[1]: session-205.scope: Succeeded.
Apr 11 13:56:17 bananapi systemd-logind[402]: Session 205 logged out. Waiting for processes to exit.
Apr 11 13:56:17 bananapi systemd-logind[402]: Removed session 205.
Apr 11 14:14:23 bananapi sshd[16811]: Accepted password for tom from 192.168.0.106 port 52771 ssh2
Apr 11 14:14:24 bananapi sshd[16811]: pam_unix(sshd:session): session opened for user tom by (uid=0)
Apr 11 14:14:24 bananapi systemd-logind[402]: New session 206 of user tom.
Apr 11 14:14:24 bananapi systemd[1]: Started Session 206 of user tom.
Apr 11 14:14:26 bananapi su[16821]: pam_unix(su:auth): Couldn't open /etc/securetty: No such file or directory
Apr 11 14:14:28 bananapi su[16821]: pam_unix(su:auth): Couldn't open /etc/securetty: No such file or directory
Apr 11 14:14:29 bananapi su[16821]: (to root) tom on pts/0
Apr 11 14:14:29 bananapi su[16821]: pam_unix(su:session): session opened for user root by tom(uid=1000)
Apr 11 14:17:01 bananapi CRON[16840]: pam_unix(cron:session): session opened for user root by (uid=0)
Apr 11 14:17:01 bananapi CRON[16841]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Apr 11 14:17:01 bananapi CRON[16840]: pam_unix(cron:session): session closed for user root
~

Der BananaPi lief über die ganze Dauer normal, zum Zeitpunkt des Absturz' hab ich etwas mit Tor gespielt, evtl. hat das etwas mehr Ressourcen gebraucht als gewöhnlich, sollte doch aber kein Grund zum Absturz sein...

Weiter: Warum werden bei den SSH Verbindungen andere Ports angezeigt, als der mit dem ich mich verbinde?

Grüße

[OrangeJuice]

Hast du mal geschaut, ob Tor aktuell ist? Es gab in letzter Zeit einige Bugs. Firefox hatte auch ein paar Bugs die zum Teil aktiv ausgenutzt wurden und erst mit Version 68.7 und 75 geschlossen wurden.

Das liest sich auch nicht so toll.

Zusätzlich weisen die Tor-Entwickler darauf hin, dass man sicherstellen sollte, dass die Erweiterung zum Blockieren von aktiven Inhalten NoScript in der aktuellen Version 11.0.17 installiert ist. Ansonsten könnte JavaScript auf Websites in nicht näher beschriebenen Situationen aufgrund eines Bugs trotzdem ausgeführt werden. In der Standardeinstellung aktualisiert sich NoScript automatisch.
heise.de

[Geizeskrank]

Hi, Tor ist aus den bullseye Paketquellen, sollte dementsprechend aktuell sein; es läuft auch nur als relay ohne localhost Zugriff.

Ich hab den BananaPi aber auch mit inaktiven Tor beim Sterben zugesehen

[dingsvomdach]

Wie wäre es testweise mit einer frischen, sauberen Installation ohne Altlasten? Deine Daten liegen hoffentlich auf einer separaten Partition?

Die OS-Partition kann man sich vorher von einem Live-System aus wegsichern (z.B. sektorbasiert per dd oder dateibasiert per fsarchiver). Das mache ich übrigens vor einem Dist-Upgrade prinzipiell, spart nämlich Nerven wenn es hinterher "knistert" und man fix zurück kann.

[dingsvomdach]

Noch eine Idee:

Laß auf einer Konsole folgenden Einzeiler mitlaufen

Code: Alles auswählen

while [ 1 -gt 0 ];do top -b -n 1 -o %MEM | head -n 15 | tee -a top.txt && top -b -n 1 -o %CPU | head -n 15 | tee -a top.txt && echo | tee -a top.txt && echo | tee -a top.txt && sleep 10;done

Erklärung:
Alle 10s werden die größten Verbraucher (Prozesse) von RAM und CPU in eine Datei (top.txt) mitgeschrieben inkl. Zeitstempel. Wenn die Kiste wieder einfriert, kann man eventuell aus dem Logfile etwas schlußfolgern.

[Geizeskrank]

Wie wäre es testweise mit einer frischen, sauberen Installation ohne Altlasten? Deine Daten liegen hoffentlich auf einer separaten Partition?

Die OS-Partition kann man sich vorher von einem Live-System aus wegsichern (z.B. sektorbasiert per dd oder dateibasiert per fsarchiver). Das mache ich übrigens vor einem Dist-Upgrade prinzipiell, spart nämlich Nerven wenn es hinterher "knistert" und man fix zurück kann.

Hi, ich habe schon eine zweite SD Karte mit frischem Buster bereit zu liegen, möchte aber vorher natürlich versuchen das aktuelle System weiter zu betreiben.
Den Einzeiler hab ich direkt mal laufen lassen, aber mit 30 Sekunden Sleep Zeit, da mir sonst die Datei zu schnell zu groß wurde.
Ich hab dann nach 24h "normaler Laufzeit" ohne Freeze den Pi mal ordentlich schwitzen lassen, der load lag dabei über mehrere Stunden zwischen 2-4 und war in den Spitzen über Minuten sogar >10 … es passierte nichts, alles lief normal weiter.

Heute morgen beendete ich dann screen in welchem der Code lief und ließ das System normal weiterfahren; als ich auf Arbeit ankam, wollte ich einen kurzen check über htop machen und musste feststellen, dass ich schon wieder ein SSH Time Out bekam

Ich dachte bis heute früh, dass es wohl doch am tor relay gelegen haben muss, weil er fehlerfrei lief seitdem dies aus war; aber dem ist wohl doch nicht so, der Pi freezte quasi im Leerlauf

[Geizeskrank]

Ich hab den Titel auf behoben statt gelöst gesetzt, da ich nur vermute, dass es an der SD Karte lag und keine 100% Bestätigung hab'.

Also, ich habe das System neu aufgesetzt und die SD Karte nur noch für /boot gelassen; / ist auf eine SATA migriert und seit dem haben sich die Abstürze eingestellt; es war letztendlich das schlüssigste was übrig geblieben ist, nach den sporadischen Ausfällen und dazu fehlerhaften bzw. unvollständigen Logeinträgen.

Danke an alle die Hilfe angeboten haben