Seltsames im Skript angestossen über udev-Regel

[Tintom]

Prüfe ich die Datenpartitionen auf dem NAS auf mount- und prüf-Vorgänge, so zeigen alle Partitionen ebenfalls das Datum 14.02.2019, allerdings mit unterschiedlichen Uhrzeiten.

Dieses falsche Datum zeigt sich im Terminal auch bei später gesteckten Stick

Code: Alles auswählen

root@NAS-01:~# tune2fs -l /dev/sda6 | egrep -i "Last"
Last mounted on:          /Daten-2
Last mount time:          Thu Feb 14 11:12:20 2019
Last write time:          Thu Feb 14 11:12:20 2019
Last checked:             Thu Feb 14 11:12:17 2019

Diese Werte werden nicht in Echtzeit aktualisiert. Hier mal mein System als Vergleich:
Filesystem created: Tue May 14 08:47:04 2019
Last mount time: Tue Sep 21 07:33:30 2021
Last write time: Tue Sep 21 07:33:29 2021

Das System läuft seit 7:33 Uhr, jedoch haben darauf schon massiv Schreibzugriffe stattgefunden (wie jetzt zum Beispiel )

Damit ist aber immer noch nicht geklärt, warum date nicht richtig arbeitet, wenn der Stick bereits gesteckt ist. Dies ist aber der Sinn der Sache, weil ich nicht unbedingt anwesend bin, wenn das NAS seine Aufgaben ausführen soll.

Ich denke es liegt wirklich an einer falschen/fehlerhaften Initialisierung der Uhrzeit. Als Workaround bis die tatsächliche Ursache gefunden ist würde ich vorschlagen, du schaltest eine Serviceunit von systemd vor das eigentliche Bashskript. In die Serviceunit trägst du dann ein
After=systemd-timesyncd
um sicherzugehen, dass die Systemzeit korrekt gestellt ist, bevor dein Skript startet. Ein Beispiel wie so etwas aussehen kann findest du z.B. hier: https://kinvolk.io/docs/flatcar-contain ... dev-rules/

[halo44]

Ohne auf die letzten Beiträge jetzt einzugehen kann ich mitteilen, dass ich Hinweise gefunden habe.

Zum bewussten Datum 14.02.2019 war noch Stretch stable. Irgendwann habe ich dann auf Buster upgegradet. Und habe dabei offensichtlich irgendwelche Probleme "vererbt".

Ich habe jetzt mal meine Systemsicherungen des NAS durchgesehen und habe hierbei eine Textdatei entdeckt, die ich mittels journalctl erstellt hatte. Diese Datei startet mit einem Eintrag vom bewussten 14.02.2019:

-- Logs begin at Thu 2019-02-14 11:12:02 CET, end at Sat 2020-02-29 19:30:59 CET. --

Diese Datei möchte ich nicht in voller Größe posten, kann aber einige Einträge anlisten, die mit der Problematik zu tun haben könnten. Zunächst hier fsck der Partition sda6. Das Checkdatum steht heute noch - wie gepostet - auf diesem Zeitpunkt.

Feb 14 11:12:08 NAS-01 systemd-fsck[239]: Daten-2: Der Zeitpunkt des letzten Einhängens des Superblocks liegt in der Zukunft.
Feb 14 11:12:08 NAS-01 systemd-fsck[239]: (weniger als ein Tag, wahrscheinlich aufgrund falsch gesetzter Hardware-Uhr)

Noch merkwürdiger die letzte Zeile im Journal vom 14.02.2019:

Feb 14 11:12:12 NAS-01 systemd-timesyncd[312]: System clock time unset or jumped backwards, restoring from recorded timestamp: Fri 2020-02-28 23:59:46 CET

Danach folgt unmittelbar

Feb 28 23:59:47 NAS-01 kernel: audit: type=1400 audit(1582930786.476:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/evince" pid=319 comm="apparmor_parser"

In diesen Fehlern vermute ich die Ursache des Problems. Am 14.02.2019 ist etwas beschädigt worden, was beim Upgrade von Stretch zu Buster übernommen wurde und heute noch im System ist.

Ein weiteres Suchen scheint mir nicht erfolgversprechend, da mir auch nicht mehr präsent ist, was damals wirklich geschah.

Mein NAS tut, was es soll, weil ich für meine Aufgabe eine andere Lösung gefunden habe. Auch die ursprüngliche udev-Regel mit anderem Programm für die Datumsbestimmung ist eine weitere Möglichkeit.

Ich bedanke mich bei allen, die bei der "Fehlersuche" geholfen haben.

Gruss H.

[uname]

Ich denke die richtige Stelle hast du immer noch nicht gefunden.

Das Datum springt vom 14. Februar 2019 auf den 28. Februar 2020, was noch weit entfernt von heute ist.
Zudem wird eine Sekunde später (auch noch im Jahr 2020) etwas über apparmor und evince dokumentiert, was ich persönlich mindestens auf einen NAS nicht verstehe. Braucht man auf einen NAS ein PDF-Viewer? Du kannst ihn ja mal deinstallieren bzw. deinstalliere auch gleich AppArmor, da es dir bzgl. der Betrachtung scheinbar ja sowieso nicht wichtig genug ist. Vielleicht wurde dein NAS ja gehackt.

Falls du dich weiter mit "Zeit" beschäftigen willst, habe ich vor ein paar Tagen ein nettes Video zu "Zeit" und "Mathematik" gesehen. Vielleicht das richtige Thema am Tag der Tagundnachtgleiche. https://www.youtube.com/watch?v=G7az86ahy0M

[halo44]

Ich denke die richtige Stelle hast du immer noch nicht gefunden ...

Also habe ich im gefundenen Journal weiter gesucht und bin auch fündig geworden. Zunächst fand ich diese Einträge

Feb 29 00:00:01 NAS-01 exim[920]: 2020-02-29 00:00:01 1j75eZ-00012k-5b spool file write error while delivering: No space left on device
Feb 29 00:00:01 NAS-01 exim[920]: write failed on panic log: length=102 result=-1 errno=28 (No space left on device)
Feb 29 19:30:09 NAS-01 logrotate[918]: gzip: stdout: No space left on device
Feb 29 19:30:39 NAS-01 anacron[986]: 2020-02-29 19:30:39 failed to write to main log: length=79 result=-1 errno=28 (No space left on device)
Feb 29 19:30:39 NAS-01 exim[1299]: 2020-02-29 19:30:39 failed to write to main log: length=79 result=-1 errno=28 (No space left on device)
Feb 29 19:30:39 NAS-01 exim[1299]: write failed on panic log: length=104 result=-1 errno=28 (No space left on device)

Das kam mir irgendwie bekannt vor und in meinen Betriebssystem-Dokumentationen fand ich eine Notiz, die ich hier in Auszügen poste:

Am 29.02.2020 stellte ich fest, dass am Vorabend die Sicherung der Datenpartitionen auf das NAS nicht durchgeführt wurde.

Ich konnte mich über ssh auf die Konsole des NAS einloggen, allerdings ließ sich das Journal nicht auswerten, es folgte die Meldung
"system.journal is truncated, ignoring file". Das Journal war defekt und ließ sich weder auslesen, reparieren noch kürzen.

Auf der Konsole zeigte df -h dass das Rootverzeichnis / zu 100% gefüllt war. Weiter fanden sich in /var/log/syslog.1 (14 GB)
und /var/log/daemon.log.1 (22 G) unmäßig viele Einträge den Dienst qcontrol betreffend: NAS-01 qcontrol[420]: (PIC 0x0) unknown command from PIC

Ich habe schließlich diese Dateien und das Verzeichnis Journal in /var/log gelöscht, wieder angelegt und das NAS neu gestartet.

Dann habe ich das Journal in eine Textdatei geschrieben und diese zum Desktoprechner übertragen, um sie dort auszuwerten.

Obwohl ich ja das Journal vor dem Neustart gelöscht hatte, begann dieses mit einem Bootvorgang vom 14.02.2019 11:12:02, endete dann aber
10 Sekunden später mit der Meldung "System clock time unset or jumped backwards, restoring from recorded timestamp: Fri 2020-02-28 23:59:46 CET".

Hier ist offensichtlich wegen Speichermangels einiges durcheinander geraten und hat auch den Neustart überlebt.

Nur zur Ergänzung evince ist nicht installiert, apparmor schon. Ob ich das brauche, weiss ich nicht sicher. Ich habe sicher einige Software auf dem NAS, die ich eigentlich nicht benötige.

Das NAS sichert täglich mit dirvish meine Datenpartitionen vom Desktoprechner. Gelegentlich speichere ich dort Videos, die ich über minidlna aufs TV ausgebe.

Gruss H.