Raspberry Pi 3 Absturz - IPS Schuld?

Du würdest ja gerne mal „dmesg“ aufrufen wollen, um zu schauen, ob es dort relevante Meldungen gibt. Diese Logs sind nach dem Neustart aber immer wieder weg.

Wenn er die Ausgabe von dmesg in eine Datei schreibt, sollten die Meldungen den Neustart überleben.

dmesg -w >> dmesg.log

wie rufst Du Deinen Pi im Netz auf? Über den Namen oder über die IP-Adresse? Wer vergibt bei Dir den Namen? Macht das die Fritzbox? Als erstes würde mich interessieren, ob Du -wenn der Pi nicht mehr erreichbar ist- ihn noch auf seiner IP anpingen kannst. Wenn das funktioniert, folgt die Frage, ob Du dann auch über die IP (192.168.x.x:3777/) das Web-Front erreichst.

Jürgen

Also zunächstmal lief der Pi jetzt wieder knapp 36h ohne Probleme.

wie rufst Du Deinen Pi im Netz auf? Über den Namen oder über die IP-Adresse? Wer vergibt bei Dir den Namen? Macht das die Fritzbox? Als erstes würde mich interessieren, ob Du -wenn der Pi nicht mehr erreichbar ist- ihn noch auf seiner IP anpingen kannst. Wenn das funktioniert, folgt die Frage, ob Du dann auch über die IP (192.168.x.x:3777/) das Web-Front erreichst.

Ja, die IP ist von der Fritzbox vergeben worden und ich habe sie dort oder im Pi selber nie händisch geändert. Aufrufen tue ich über verschiedene Wege…

  • Für Admin-/Datentransfersachen vom Desktop aus per SSH mit Putty oder WinSCP.
  • Am Smartphone/Tablet per IPS App
  • und an verschiedenen PCs das IPS WF über die IP im Browser.

Nein, wenn mein Problem auftaucht, kann ich die IP nicht anpingen und auch nicht das Web-Front aufrufen.

Code:
dmesg -w >> dmesg.log

Das funktioniert allerdings nur wenn ich es per SSH in ausführe. Das müsste ja irgendwie dauerhaft in ein Logfile geschrieben werden, während des Betriebes.

Ich habe nochmal in die vorhandenen LogFiles(hier aus dem syslog) geschaut. Dieser Block taucht immer zu dem Zeitpunkt auf, wenn IPS abstürzt. Zumindest vermute ich das, denn da setzt das Datenlogging der Energiezähler aus und ist ab dann konstant auf einem Wert

Jan 10 21:14:17 raspberry dhcpcd[438]: eth0: hardware address 50:58:96:76:85:6e claims 192.168.1.10
Jan 10 21:14:18 raspberry dhcpcd[438]: eth0: hardware address 50:58:96:76:85:6e claims 192.168.1.10
Jan 10 21:14:18 raspberry dhcpcd[438]: eth0: 10 second defence failed for 192.168.1.10
Jan 10 21:14:18 raspberry dhcpcd[438]: eth0: deleting route to 192.168.1./24
Jan 10 21:14:18 raspberry dhcpcd[438]: eth0: deleting default route via 192.168.1.1
Jan 10 21:14:18 raspberry avahi-daemon[410]: Withdrawing address record for 192.168.1.10 on eth0.
Jan 10 21:14:18 raspberry avahi-daemon[410]: Leaving mDNS multicast group on interface eth0.IPv4 with address 192.168.1.10.
Jan 10 21:14:18 raspberry avahi-daemon[410]: Interface eth0.IPv4 no longer relevant for mDNS.
Jan 10 21:14:18 raspberry dhcpcd[438]: eth0: probing address 192.168.1.10/24
Jan 10 21:14:18 raspberry dhcpcd[438]: eth0: hardware address 50:58:96:76:85:6e claims 192.168.1.10
Jan 10 21:14:18 raspberry dhcpcd[438]: eth0: DAD detected 192.168.1.10
Jan 10 21:14:53 raspberry dhcpcd[438]: eth0: Router Advertisement from fe80::e228:6dff:fe95:b5fd

Vor und auch nach diesem Block steht immer dasselbe im SysLog:

Jan 10 20:53:19 raspberry dhcpcd[438]: eth0: Router Advertisement from fe80::xxxx::yyyy::e228::b5fd
Jan 10 20:59:52 raspberry dhcpcd[438]: eth0: Router Advertisement from fe80::xxxx::yyyy::e228::b5fd
Jan 10 21:08:57 raspberry dhcpcd[438]: eth0: Router Advertisement from fe80::xxxx::yyyy::e228::b5fd

Aber nach dieser Uhrzeit sind eben IPS und der Pi nicht mehr erreichbar

Die obere Fehlermeldung sagt, dass die angegebene Macadresse bereits die von dir gewünschte IP benutzt. Daher zieht der Raspberry seinen Wunsch nach dieser IP (bzw. eigentlich den durch die FritzBox vergebenen Zwang zu dieser IP) zurück und schaltet sein Netzwerkinterface aus. Also herausfinden was ist das angegebene Gerät und dessen Konfiguration prüfen.

Hast Du ggf. WLAN und LAN mit der selben IP konfiguriert?
Jürgen

Am RPI? Nein der ist garnicht mit WLAN konfiguriert hängt nur im LAN.

tobiasr
Die obere Fehlermeldung sagt, dass die angegebene Macadresse bereits die von dir gewünschte IP benutzt. Daher zieht der Raspberry seinen Wunsch nach dieser IP (bzw. eigentlich den durch die FritzBox vergebenen Zwang zu dieser IP) zurück und schaltet sein Netzwerkinterface aus. Also herausfinden was ist das angegebene Gerät und dessen Konfiguration prüfen.

Das ist interessant.
Diese Zeile aus dem RPI SysLog hier

Jan 10 21:14:17 raspberry dhcpcd[438]: eth0: hardware address 50:58:96:76:85:6e claims 192.168.1.10

zeigt die MAC Adresse unseres alten Smart TV’s. Dieser wurde vor 5 6 Wochen vom Wohnzimmer ins Schlafzimmer gesetzt und dort ans LAN gehangen. Der Hat in der Fritzbox jetzt aktuell gerade eine andere IP zugewiesen…
Komische Sache, ich habe nun mal für diesen TV die Option „immer gleiche IP Adresse verwenden“ aktiviert. Kann es das schon gewesen sein? Fragt sich nur warum der TV zwischendurch mal eine andere IP haben will?

Das funktioniert allerdings nur wenn ich es per SSH in ausführe. Das müsste ja irgendwie dauerhaft in ein Logfile geschrieben werden, während des Betriebes.

Richtig, du musst entweder eine ssh-Session geöffnet lassen oder den Befehl in einer screen-Session ausführen.

So also nochmal zum Abschluss, seit knapp 2 Wochen habe ich keine Abstürze vom RPI selber gesehen. Es scheint also wohl an dem IP Konflikt gelegen zu haben.
Leider sehe ich wohl noch von IPS selber abstürze, wenn ich zuviel im WF mit Videostreams mache. Zum Beispiel einen über einen längeren Zeitraum ansehen. Das müsste ich aber erst nochmal genau ansehen.

Mmmh, vielleicht hat mein zweites Problem doch noch was mit IPS zu tun?
Ich schreibe seit Monaten stündlich die RPI Ausgabe von /proc/meminfo mit.
Dort lese ich den Wert MemFree aus und schreibe ihn in eine IPS Variable.

Ist mir bisher nicht so aufgefallen, aber dabei entstand folgender Graph:

Die Peaks sind immer die Zeitpunkte, an denen der RPI neugestartet wurde. In den nächsten Tagen nimmt der freie Speicher dann immer ab.
Deute ich hier die Bedeutung von MemFree falsch oder läuft mir mit irgendwas der Speicher voll?

Ich muss das Thema hier nochmal anstoßen. Ursprünglich stürzte ja der Pi, warum auch immer ab.
Nun habe ich es wieder, das IPS alle Paar Tage abschmiert. Gestern Nacht um 1:50 das letzte mal. im Deamon.log vom RPI finde ich das hier zur selben Zeit


Mar 13 01:46:19 raspberry dhcpcd[435]: eth0: Router Advertisement from fe80::e228:6dff:fe95:b5fd
Mar 13 01:51:13 raspberry systemd[1]: session-3.scope: Succeeded.
Mar 13 01:51:23 raspberry systemd[1]: Stopping User Manager for UID 1000...
Mar 13 01:51:23 raspberry systemd[1818]: Stopped target Default.
Mar 13 01:51:23 raspberry systemd[1818]: Stopped target Basic System.
Mar 13 01:51:23 raspberry systemd[1818]: Stopped target Timers.
Mar 13 01:51:23 raspberry systemd[1818]: Stopped target Sockets.
Mar 13 01:51:23 raspberry systemd[1818]: gpg-agent-extra.socket: Succeeded.
Mar 13 01:51:23 raspberry systemd[1818]: Closed GnuPG cryptographic agent and passphrase cache (restricted).
Mar 13 01:51:23 raspberry systemd[1818]: gpg-agent.socket: Succeeded.
Mar 13 01:51:23 raspberry systemd[1818]: Closed GnuPG cryptographic agent and passphrase cache.
Mar 13 01:51:23 raspberry systemd[1818]: dirmngr.socket: Succeeded.
Mar 13 01:51:23 raspberry systemd[1818]: Closed GnuPG network certificate management daemon.
Mar 13 01:51:23 raspberry systemd[1818]: gpg-agent-browser.socket: Succeeded.
Mar 13 01:51:23 raspberry systemd[1818]: Closed GnuPG cryptographic agent and passphrase cache (access for web browsers).
Mar 13 01:51:23 raspberry systemd[1818]: pulseaudio.socket: Succeeded.
Mar 13 01:51:23 raspberry systemd[1818]: Closed Sound System.
Mar 13 01:51:23 raspberry systemd[1818]: Stopped target Paths.
Mar 13 01:51:23 raspberry systemd[1818]: gpg-agent-ssh.socket: Succeeded.
Mar 13 01:51:23 raspberry systemd[1818]: Closed GnuPG cryptographic agent (ssh-agent emulation).
Mar 13 01:51:23 raspberry systemd[1818]: dbus.socket: Succeeded.
Mar 13 01:51:23 raspberry systemd[1818]: Closed D-Bus User Message Bus Socket.
Mar 13 01:51:23 raspberry systemd[1818]: Reached target Shutdown.
Mar 13 01:51:23 raspberry systemd[1818]: systemd-exit.service: Succeeded.
Mar 13 01:51:23 raspberry systemd[1818]: Started Exit the Session.
Mar 13 01:51:23 raspberry systemd[1818]: Reached target Exit the Session.
Mar 13 01:51:23 raspberry systemd[1]: user@1000.service: Succeeded.
Mar 13 01:51:23 raspberry systemd[1]: Stopped User Manager for UID 1000.
Mar 13 01:51:23 raspberry systemd[1]: Stopping User Runtime Directory /run/user/1000...
Mar 13 01:51:23 raspberry systemd[1]: run-user-1000.mount: Succeeded.
Mar 13 01:51:23 raspberry systemd[1]: user-runtime-dir@1000.service: Succeeded.
Mar 13 01:51:23 raspberry systemd[1]: Stopped User Runtime Directory /run/user/1000.
Mar 13 01:51:23 raspberry systemd[1]: Removed slice User Slice of UID 1000.
Mar 13 01:56:11 raspberry dhcpcd[435]: eth0: Router Advertisement from fe80::e228:6dff:fe95:b5fd

Kann mir jemand erklären wo das her kommt oder wie ich weiter vorgehen könnte zur Fehlersuche?

PS: Im Symcon log steht zuletzt übrigens nichts ungewöhnliches:

13/03/21 01:50:33 | 30583 | DEBUG   | VariableManager      | [01_Funktionen_&_Skripte\80_Energieverbrauch\Hausstrom\Verbrauch gestern kWh] = 9.5500000000
13/03/21 01:50:33 | 41426 | DEBUG   | VariableManager      | [01_Funktionen_&_Skripte\80_Energieverbrauch\Hausstrom\Verbrauch diese Woche kWh] = 52.1400000000
13/03/21 01:50:33 | 48335 | DEBUG   | VariableManager      | [01_Funktionen_&_Skripte\80_Energieverbrauch\Hausstrom\Verbrauch letzte Woche kWh] = 82.1100000000
13/03/21 01:50:33 | 22148 | DEBUG   | VariableManager      | [01_Funktionen_&_Skripte\80_Energieverbrauch\Hausstrom\Verbrauch dieser Monat kWh] = 134.2500000000
13/03/21 01:50:33 | 48188 | DEBUG   | VariableManager      | [01_Funktionen_&_Skripte\80_Energieverbrauch\Hausstrom\Verbrauch letzter Monat kWh] = 346.0100000000
13/03/21 01:50:33 | 43495 | DEBUG   | VariableManager      | [01_Funktionen_&_Skripte\80_Energieverbrauch\Wärmepumpenstrom\Zählerstand - Wärmepumpenstrom kWh] = 13289.4000000000

Am besten damit: Debugging für Experten (Raspberry Pi, Linux, SymBox)

paresy

Ich versteh das Vorgehen nicht so ganz
Wenn ich Option B ausführe erscheint die untere Ausgabe. Irgendwann betätige ich im Putty c+Enter und es kommen neue Zeilen wie [New Thread 0x4f3f3980 (LWP 25323)] ins Fenster.
Jetzt schließe ich Putty einfach und öffne beim nächsten Absturz wieder eine neue Verbindung zum pi oder?
Was heißt im nächsten Punkt denn:

Wir wollen nun alle Informationen automatisch in eine
Textdatei schreiben lassen. Dazu folgende Befehle eingeben:


set logging on
thread apply all bt
set logging off

Das Logfile Schreiben aktiviere ich nach dem Absturz oder vorher schon?

pi@raspberry:~ $ sudo gdb --pid $(pidof symcon)
GNU gdb (Raspbian 8.2.1-2) 8.2.1
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "arm-linux-gnueabihf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word".
Attaching to process 25262
[New LWP 25263]
[New LWP 25264]
[New LWP 25265]
[New LWP 25266]
[New LWP 25267]
[New LWP 25268]
[New LWP 25269]
[New LWP 25270]
[New LWP 25271]
[New LWP 25272]
[New LWP 25273]
[New LWP 25274]
[New LWP 25275]
[New LWP 25276]
[New LWP 25277]
[New LWP 25278]
[New LWP 25279]
[New LWP 25280]
[New LWP 25281]
[New LWP 25282]
[New LWP 25283]
[New LWP 25284]
[New LWP 25285]
[New LWP 25286]
[New LWP 25287]
[New LWP 25288]
[New LWP 25289]
[New LWP 25290]
[New LWP 25291]
[New LWP 25292]
[New LWP 25293]
[New LWP 25294]
[New LWP 25295]
[New LWP 25296]
[New LWP 25297]
[New LWP 25298]
[New LWP 25299]
[New LWP 25300]
[New LWP 25301]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/arm-linux-gnueabihf/libthread_db.so.1".
0x0277d304 in std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::push_back(char) ()
(gdb) c
Continuing.
[New Thread 0x55bfe980 (LWP 25310)]
[New Thread 0x54bfe980 (LWP 25311)]
[New Thread 0x543fd980 (LWP 25312)]
[New Thread 0x53bfc980 (LWP 25313)]
[New Thread 0x533fb980 (LWP 25314)]
[New Thread 0x52bfa980 (LWP 25315)]
[New Thread 0x523f9980 (LWP 25316)]
[New Thread 0x51bf8980 (LWP 25317)]
[New Thread 0x513f7980 (LWP 25318)]
[New Thread 0x50bf6980 (LWP 25319)]
[New Thread 0x503f5980 (LWP 25320)]
[New Thread 0x4fbf4980 (LWP 25322)]
[New Thread 0x4f3f3980 (LWP 25323)]

Hi Marcel,

du musst leider die Putty Session so lange offen halten, bis der Absturz passiert. Dann wird wirst du wieder mit (gdb) begrüßt und kannst dann die Kommandos oben ausführen um mehr über den Absturz zu erfahren.

paresy

Hi,

ah ok, dann weiß ich bescheid. Das heißt aber die Anzeigen der „New Threads“ und der „Exited Threads“ sind erstmal normal? Die kommen nämlich in unregelmäßigen Abständen aber schon zahlreich rein. Erst bei einem Absturz sollte eine Meldung einer anderen Art auftauchen?

[New Thread 0x4ac35980 (LWP 25586)]
[New Thread 0x4d43a980 (LWP 25587)]
[New Thread 0x4cc39980 (LWP 25588)]
[New Thread 0x4bc37980 (LWP 25589)]
[New Thread 0x4c438980 (LWP 25590)]
[New Thread 0x4b436980 (LWP 25591)]
[New Thread 0x4a434980 (LWP 25592)]
[New Thread 0x49c33980 (LWP 25593)]
[New Thread 0x49432980 (LWP 25594)]
[Thread 0x4ac35980 (LWP 25586) exited]
[Thread 0x4d43a980 (LWP 25587) exited]
[Thread 0x4cc39980 (LWP 25588) exited]
[Thread 0x4bc37980 (LWP 25589) exited]
[Thread 0x4c438980 (LWP 25590) exited]
[Thread 0x4b436980 (LWP 25591) exited]
[Thread 0x4a434980 (LWP 25592) exited]
[Thread 0x49c33980 (LWP 25593) exited]
[Thread 0x49432980 (LWP 25594) exited]

Korrekt. Das ist ganz normal. Wenn es abstürzt bleibt es stehen und dann wird es spannend :slight_smile:

paresy

OK danke. Ich habs jetzt auf dem Visu PC angeworfen, der läuft eh ständig. Falls es dann stehen bleibt, führ ich mal das logging aus und setz es hier rein…

So nach Wochen konnte ich den Fehler endlich catchen. Anbei die Ausgabe aus dem gdb. Ich habe nach dem ersten Stop nochmal „c+Enter“ betätigt, woraufhin der zweite Fehler erschien. Bis dahin war das WF noch sichtbar, konnte aber nicht bedient werden. Nach einem weiteren „c+Enter“ erschien die bekannte Meldung im WF. ( Zweiter Screenshot )

Unbenannt

Was sagt mir das jetzt? :face_with_raised_eyebrow:

Du musst noch bt + Enter Eingeben. Erst dann wissen mehr! (Also statt dem ersten c + Enter)

Aber: die Initiale Meldung sieht sehr danach aus, dass es ein Fehler im PHP timeout ist. Diesen haben wir zur 5.6 abgeschafft - sodass dieses Problem erledigt sein sollte.

Du kannst alternativ deine php.ini öffnen und das max_executione_time auf z.B. 10000 setzen. das sollte ein guter workaround sein.

paresy

Oh, ja ok das hab ich natürlich nicht gemacht. Auch nicht das Schreiben vom logfile. Hab erst nachher wieder in den link oben geschaut. Mal sehen ob ichs nochmal provozieren kann

Hab dir ne PN geschrieben