Seltsames im Skript angestossen über udev-Regel

[halo44]

Also die Dateien sind an einigen Stellen unterschiedlich, allerdings zeigt sich wohl der entscheidende Unterschied in der 5.Zeile vor dem Ende der Datei.

In der Terminal-Ausgabe:

write(1, "Mo 20. Sep 15:53:00 CEST 2021\n", 30) = 30

In der Skript-Ausgabe:

write(1, "Thu Feb 14 11:12:09 CET 2019\n", 29) = 29

Wird die komplette Ausgabe trotzdem noch benötigt?

Gruss H.

[halo44]

Weiter oben hat schon jemand geschrieben: Kannst du bitte einmal die Ausgabe von timedatectl (aus dem Terminal, nicht durch udev-Skript) posten?

Das zeigt im NAS-Terminal jetzt

Code: Alles auswählen

               Local time: Mo 2021-09-20 17:17:06 CEST
           Universal time: Mo 2021-09-20 15:17:06 UTC
                 RTC time: Mo 2021-09-20 15:17:06
                Time zone: Europe/Berlin (CEST, +0200)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no

Gruss H.

[reox]

Wird die komplette Ausgabe trotzdem noch benötigt?

Gruss H.

Der interessante teil ist wohl, was der unterschied von clock_gettime ist
aber poste mal bitte alles, das sollte ja auch nicht lang sein!

[halo44]

Hier die beiden Ausgaben, zunächst die Terminal-Ausgabe 41473

Dann die Ausgabe im Skript 41474 wobei diese Datei als Erstellungsdatum ebenfalls den 14.02.2019 trägt.

Gruss H.

[reox]

das ist echt oarg, tatsächlich liefert das ein anderes datum zurück:

Code: Alles auswählen

clock_gettime(CLOCK_REALTIME, {tv_sec=1550139129, tv_nsec=265725895}) = 0

Da kann ich mir überhaupt keinen reim drauf machen... wieso sollte das einmal tatsächlich das richtige datum liefern und mal nicht?!
offenbar wird auf der konsole noch /usr/lib/locale/locale-archive gelesen - was das für einen Unterschied macht versteh ich nicht - weil dann solte es ja mit LANG=C auch das resultat geben...
Auf die schnelle hab ich einen bug gefunden der so ähnlich klingt: https://git.kernel.org/pub/scm/linux/ke ... 2c3baa3ae4
evt ist das auch sowas und das lesen der datei verhindert, dass der Wert verwendet wird.

Kannst du probieren einen neueren Kernel zu verwenden? ggf ist das Problem im Kernel schon gelöst

[Tintom]

Hier die beiden Ausgaben, zunächst die Terminal-Ausgabe 41473

Dann die Ausgabe im Skript 41474 wobei diese Datei als Erstellungsdatum ebenfalls den 14.02.2019 trägt.

Gruss H.

Eine ganz banale Vermutung von mir: Du schreibst, du startest das System bei allen Änderungen neu. Kann es sein, dass das System die Uhrzeit beim Neustart vergisst (Batterie leer?)?
Nach dem Neustart beginnt das System zeitlich beim Urknall, hier also der 14.02. Diese Uhrzeit wird zunächst als Basis für die Systemzeit genommen. Während des Bootvorgangs wird dein udev-Skript abgearbeitet, wahrscheinlich jedoch bevor systemd-timesyncd sich die aktuelle Zeit aus dem Internet geholt hat. Sobald du dich eingeloggt hast, hat sich das System bereits eine Uhrzeit besorgt (siehe Ausgabe von timedatectl).

Was passiert, wenn du die Udev-Regel ausführst (d.h. den Stick einsteckst) nachdem du dich angemeldet hast und das System sich zeitlich synchronisiert hat (mit timedatectl vorher prüfen!)? Ändert das etwas?

[reox]

Dann müssten aber die Sekunden weitergezählt werden und wenn ich das richtig verstehe, kommt dort immer der selbe TImestamp zurück - oder nicht?

[halo44]

... Eine ganz banale Vermutung von mir: Du schreibst, du startest das System bei allen Änderungen neu. Kann es sein, dass das System die Uhrzeit beim Neustart vergisst (Batterie leer?)?
Nach dem Neustart beginnt das System zeitlich beim Urknall, hier also der 14.02. Diese Uhrzeit wird zunächst als Basis für die Systemzeit genommen. Während des Bootvorgangs wird dein udev-Skript abgearbeitet, wahrscheinlich jedoch bevor systemd-timesyncd sich die aktuelle Zeit aus dem Internet geholt hat. Sobald du dich eingeloggt hast, hat sich das System bereits eine Uhrzeit besorgt (siehe Ausgabe von timedatectl).

Was passiert, wenn du die Udev-Regel ausführst (d.h. den Stick einsteckst) nachdem du dich angemeldet hast und das System sich zeitlich synchronisiert hat (mit timedatectl vorher prüfen!)? Ändert das etwas?

Dass die Batterie leer ist, kann ich ausschließen. Ich schalte mein NAS spätabends per Cronjob aus. Hierbei vermittle ich dem NAS, dass es am nächsten Tag um 17:05 Uhr neu starten soll:

Code: Alles auswählen

echo `date '+%s' -d 'tomorrow 17:05:00'` > /sys/class/rtc/rtc0/wakealarm

Sollte die Batterie leer sein, wüsste mein NAS nicht wann es so weit ist.

Entscheidend aber ist, dass der USB-Stick beim Start des NAS bereits gesteckt ist. Stecke ich ihn erst nach vollständigen Start arbeitet date richtig, heute also

Code: Alles auswählen

Tue Sep 21 13:31:00 CEST 2021

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.

Auch noch dieser Hinweis, gestern 20.09.21 um 15:11:30 schrieb ich

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

Alles sehr seltsam.

Gruss H.

[uname]

Ich würde mal folgendes annehmen.

- die Batterie ist nicht leer
- beim Neustart bzw. im Schlafmodus wird die korrekte Uhrzeit verwendet
- dann wird sie beim Starten irgendwie falsch initialisiert
- jetzt läuft udev durch
- während des Starts wird sie dann wieder korrekt gesetzt

Vielleicht kann man irgendwie die Reihenfolge beim Boot ändern.
Oder wirklich statt "date" einen anderen Befehl verwenden siehe weiter oben.

[reox]

Aber dann sollte ein einfacher Test das klären können:

* das NAS aufdrehen
* verifizieren, dass auf der konsole das richtige datum mit `date` daherkommt
* dann den stick anstecken der die UDEV rule auslöst
* verifizieren, dass dort nicht der 14.02. ist

Heißt das auch, du hast die udev regel immer mit einem systemstart getestet?

[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.