Show periodic rclone progress and remote verification phases

2026-09-10 16:04:09 +02:00
1 parent ff152c7f0f
commit fe50bb42a1
@@ -52,6 +52,23 @@ flowchart TD

 `ENABLE_UPLOAD=false` beendet den Datenpfad nach dem vollständigen lokalen Satz und führt nur lokale Retention aus. Dies ist kein Offsite-Backup.

+Upload und Remote-Prüfung melden ihre Phase ausdrücklich. Mit
+`RCLONE_STATS_INTERVAL="1m"`, `--stats-one-line` und `--stats-log-level NOTICE`
+erscheinen periodische rclone-Statistiken auch ohne ausführliches Debug-Logging.
+Sie gehen nach stderr; Marker und Dateilisten auf stdout bleiben maschinell
+auswertbar. Alte Konfigurationen erhalten den Intervallstandard automatisch.
+Eine Anpassung wirkt erst beim nächsten rclone-Prozess. Die bestehende
+I/O-Leerlauffrist `RCLONE_TIMEOUT="1h"` ist keine Gesamtlaufzeitbegrenzung.
+
+Beim Betreiberlauf am 10.09.2026 ab 15:30 Uhr wurden die geschützte Kopierphase,
+Dienstwiederaufnahme und ein vollständiger lokaler Satz bestätigt. Danach meldete
+rclone 1.74.3 HTTP 409 `resourceModified` bei einem OneDrive-Objekt. Die Ursache
+und der Abschluss der Remote-Prüfung sind noch offen. Der Fehler darf nicht mit
+einer fehlgeschlagenen lokalen Kopie gleichgesetzt werden. Die Unterscheidung
+zwischen HTTP-Wiederholungen und Wiederholung des gesamten Kopierauftrags sowie
+die Diagnose eines stillen Journals stehen in der
+[Update-Anleitung](UPDATE_ANLEITUNG.md#onedrive-http-409-resourcemodified-und-stilles-journal).
+
 Dateikopien erhalten mit `rsync -aHAX --numeric-ids` Eigentümer, Modus, Symlinks, Hardlinks innerhalb einer Komponente, ACLs und Extended Attributes. Tar erhält diese Metadaten einschließlich SELinux. Plattform-/Dateisystemunterstützung ist Voraussetzung. Externe Symlink-Ziele werden nicht automatisch gesichert; absolute Symlinks als einzelne Einträge bleiben erhalten. Geräte, FIFOs und andere Spezialdateien werden von der Archivprüfung abgelehnt. Zusätzliche Pfade sind deshalb Datenverzeichnisse, kein Ersatz für ein vollständiges Systemimage.

 Vor jedem Backup und bei `--check` prüft rsync das Auflisten der Quellwurzel sowie
@@ -415,8 +432,11 @@ Reproduzierbar mit `tests/Dockerfile` und `tests/run.sh`. Der Container bekommt

 Verifikation am 10.09.2026: **52 Testfälle erfolgreich** — 50 im vollständigen Durchlauf, anschließend beide zusätzlichen Abbruchtests für Kopie und Upload auf dem ergänzten Stand. Shell-Syntax und ShellCheck abschließend ohne Befund. Testumgebung: Debian 13.6, MariaDB 11.8.6, rclone 1.60.1-DEV (Distributionspaket), ShellCheck 0.10.0. Diese Versionsangaben beschreiben die Testumgebung, keine Empfehlung für die Produktivversion.

+Für die anschließende Ergänzung der Upload-Statistiken wurden drei betroffene Tests erneut erfolgreich ausgeführt: echter gedrosselter Crypt-Upload samt Remote-Restore, fehlgeschlagene Rückleseprüfung ohne Remote-Abschlussmarker und TERM während eines Uploads mit gestoppt bleibendem Timer. Shell-Syntax und ShellCheck bestanden ebenfalls erneut. Der vollständige 52-Fälle-Umfang wurde für diese Protokollergänzung nicht nochmals durchlaufen.
+
 Geprüfte Fälle umfassen:

+- Periodische NOTICE-Statistiken bei gedrosseltem echten Crypt-Upload, erfolgreicher Rückleseprüfung und Remote-Restore; die Statistik verändert den maschinell gelesenen Abschlussmarker nicht.
 - Fremde Startversuche während realer rsync-Kopien werden durch das systemd-Testmodell übersprungen; zuvor inaktive Writer bleiben nach dem Lauf inaktiv.
 - Aktive sowie zwischenzeitlich gestartete und wieder gestoppte Writer verhindern die Veröffentlichung eines vollständigen Satzes.
 - Nicht geladene Startsperre, Erhalt vorhandener Maskierungen und fehlgeschlagene Sperrfreigabe mit erhaltener Wiederanlaufdatei.
@@ -50,6 +50,7 @@ Details und geprüfte Grenzen stehen in der Update-Anleitung.
 - Fehler bei Dump, rsync, Kompression und Rückleseprüfung brechen den Lauf ab.
 - Wartungsmodus und Dienststopps umfassen Datenbankdump **und** Dateikopie. Danach endet die Ausfallzeit; Kompression und Upload laufen aus dem Staging.
 - Vorübergehende systemd-Startsperren verhindern die erneute Aktivierung konfigurierter Writer während der Kopie. Zustands- und Zeitstempelprüfungen brechen bei erkannten Neustarts vor Veröffentlichung ab. Eigene Sperren werden beim Wiederanlauf entfernt; bestehende Maskierungen bleiben erhalten.
+- Upload und Rückleseprüfung melden ihre Phase und standardmäßig jede Minute rclone-Statistiken im Journal (`RCLONE_STATS_INTERVAL`). Ein laufender Auftrag ist erst nach erfolgreicher Remote-Prüfung abgenommen.
 - Vollständige Sicherungssätze mit SHA-256-Manifest, Archivprüfung und zuletzt hochgeladenem `COMPLETE`-Marker.
 - Retention löscht nur vollständige neue Sicherungssätze und behält mindestens `RETENTION_KEEP_LAST` Läufe. Alte Sicherungen werden nicht automatisch gelöscht.
 - Private Arbeitsverzeichnisse, gemeinsame Sperre für Backup/Restore/Update und Wiederanlaufhinweise nach Abbrüchen.
@@ -354,6 +354,46 @@ und die Dienstzustände prüfen; insbesondere ein Stop-Timeout ist kein Nachweis
 für eine erfolgreiche Wiederaufnahme. Die Änderung wirkt für neue Aufträge,
 nicht nachträglich für einen bereits gestarteten alten Worker.

+## OneDrive: HTTP 409 resourceModified und stilles Journal
+
+Der Lauf auf Gemini vom 10.09.2026 ab 15:30 Uhr hat die geschützte Kopierphase
+und Dienstwiederaufnahme erfolgreich abgeschlossen. Um 15:46:11 meldete rclone
+1.74.3 bei `wordpress.tar.zst` HTTP 409 `resourceModified`; das deutet auf einen
+Versions-/eTag-Konflikt am OneDrive-Objekt. Der konkrete Auslöser ist anhand
+dieser Meldung nicht bestimmt. Der lokale Satz bleibt erhalten; eine erfolgreiche
+Offsite-Abnahme ist damit noch nicht belegt.
+
+HTTP 409 ist in dieser rclone-Version nicht in der allgemeinen Liste unmittelbar
+wiederholter OneDrive-HTTP-Fehler enthalten. `--low-level-retries 20` bedeutet daher
+nicht, dass genau dieser Fehler sofort 20-mal versucht wird. Die standardmäßig
+bis zu sechs Versuche über `--retries` betreffen den übergeordneten Kopierauftrag;
+andere Dateiübertragungen können vor dessen Wiederholung noch laufen. Bei als
+fatal oder nicht wiederholbar eingestuften Fehlern kann rclone früher abbrechen.
+Quelle: [rclone 1.74.3 OneDrive-Code](https://github.com/rclone/rclone/blob/v1.74.3/backend/onedrive/onedrive.go),
+[Wiederholungen](https://rclone.org/docs/#retries-int).
+
+Die bisherigen Aufträge zeigten normale Fortschrittsstatistiken nicht an:
+rclone meldet sie standardmäßig auf INFO, die normale Logschwelle ist NOTICE.
+Das aktuelle Paket setzt `--stats-log-level NOTICE --stats-one-line` mit
+`RCLONE_STATS_INTERVAL="1m"` und meldet die Phasen Upload, Rücklesen und
+Freigabe des Abschlussmarkers. Statistiken gehen nach stderr, damit maschinell
+gelesene Marker und Dateilisten auf stdout unverändert bleiben.
+Quelle: [rclone-Statistiken](https://rclone.org/docs/#stats-log-level-loglevel).
+
+`RCLONE_TIMEOUT="1h"` ist die bestehende I/O-Leerlauffrist, keine Gesamtlaufzeit
+und kein Versprechen einer Meldung pro Minute. `RUNNING` und der systemd-Zustand
+`activating/start` bei der oneshot-Unit belegen keinen Datenfortschritt. Bei einem
+stillen alten Auftrag Prozesszustand und TCP-Zähler mit `ps`/`ss` prüfen;
+steigende Zähler belegen Netzwerkverkehr, aber noch keinen erfolgreichen Upload.
+Quelle: [I/O-Leerlauffrist](https://rclone.org/docs/#timeout-duration).
+
+Eine neue Paketdatei oder geänderte Config ergänzt keine Statistiken im bereits
+laufenden rclone-Prozess. Keinen zweiten Upload parallel starten und den
+vorhandenen lokalen Satz nicht löschen. Ein einzelner 409-Fehler begründet keine
+Abschwächung der Prüfungen durch `--ignore-existing`/`--size-only`.
+Entscheidend bleiben erfolgreiches Rücklesen,
+Manifest-/Archivprüfung und `SUCCESS` in der Ergebnisdatei des konkreten Auftrags.
+
 ## Paket reproduzieren

 Aus einem sauberen, eingecheckten Repository:
@@ -371,6 +411,8 @@ Das ausführbare Paket ausschließlich über euren vertrauenswürdigen Kanal bez
 ## Verifikation der Lieferung

 52 Testfälle erfolgreich: vollständiger Durchlauf mit 50 Tests, anschließend die zwei zusätzlichen Abbruchtests für Kopie und Upload. ShellCheck und Shell-Syntaxprüfung abschließend erfolgreich.
+Für die danach ergänzten Upload-Statistiken bestanden drei gezielt wiederholte Tests: gedrosselter echter Crypt-Upload mit Remote-Restore, fehlgeschlagene Rückleseprüfung ohne Abschlussmarker und TERM während des Uploads. ShellCheck und Shell-Syntax bestanden erneut; kein erneuter vollständiger Durchlauf für diese Protokollergänzung.
+
 Die Tests enthalten echte MariaDB-Dumps/Imports und lokale rclone-Crypt-Roundtrips;
 systemd/occ und die systemd-run-Übergabe sind simuliert. Das Übergabemodell
 berücksichtigt jetzt das Warten auf den oneshot-Startauftrag: Der Regressionstest
@@ -29,6 +29,8 @@ RCLONE_LOW_LEVEL_RETRIES=20
 RCLONE_RETRIES_SLEEP="30s"
 RCLONE_TIMEOUT="1h"
 RCLONE_CONTIMEOUT="30s"
+# Periodic transfer/check statistics in journald, including otherwise quiet uploads.
+RCLONE_STATS_INTERVAL="1m"
 RCLONE_TRANSFERS=2
 RCLONE_CHECKERS=4
 # OneDrive chunks must be multiples of 320 KiB; 80 MiB satisfies this.
@@ -32,6 +32,7 @@ load_config() {
  : "${RCLONE_REMOTE_BASE:=}" "${RCLONE_CONFIG:=/root/.config/rclone/rclone.conf}"
  : "${RCLONE_RETRIES:=6}" "${RCLONE_LOW_LEVEL_RETRIES:=20}"
  : "${RCLONE_RETRIES_SLEEP:=30s}" "${RCLONE_TIMEOUT:=1h}" "${RCLONE_CONTIMEOUT:=30s}"
+  : "${RCLONE_STATS_INTERVAL:=1m}"
  : "${RCLONE_TRANSFERS:=2}" "${RCLONE_CHECKERS:=4}" "${RCLONE_ONEDRIVE_CHUNK_SIZE:=80Mi}"
  : "${RCLONE_BWLIMIT:=0}" "${ENABLE_MAIL_REPORT:=true}" "${MAIL_TO:=johannes}"
  : "${ENABLE_WORDPRESS:=false}" "${ENABLE_NEXTCLOUD:=false}" "${ENABLE_NEXTCLOUD_DATA:=true}"
@@ -260,10 +261,13 @@ check_remote() {
    --crypt-directory-name-encryption=true --crypt-no-data-encryption=false
    --retries "$RCLONE_RETRIES" --low-level-retries "$RCLONE_LOW_LEVEL_RETRIES"
    --retries-sleep "$RCLONE_RETRIES_SLEEP" --timeout "$RCLONE_TIMEOUT" --contimeout "$RCLONE_CONTIMEOUT"
+    --stats "$RCLONE_STATS_INTERVAL" --stats-one-line --stats-log-level NOTICE
    --transfers "$RCLONE_TRANSFERS" --checkers "$RCLONE_CHECKERS" --onedrive-chunk-size "$RCLONE_ONEDRIVE_CHUNK_SIZE"
    --bwlimit "$RCLONE_BWLIMIT")
  rc lsd "${name}:" --max-depth 1 >/dev/null
 }
+# Statistics go to stderr, leaving stdout intact for manifests/markers captured
+# by callers. NOTICE makes periodic progress visible without verbose HTTP logs.
 rc() { "$RCLONE_BIN" "${RCLONE_ARGS[@]}" "$@"; }

 # Exclusions are rooted so a nested directory named data is not accidentally lost.
@@ -949,9 +949,18 @@ if '--no-block' not in args:

    def test_real_crypt_upload_readback_remote_restore(self):
        self.crypt_config()
+        # Exercise periodic stderr statistics during a real throttled crypt
+        # transfer; they must not contaminate captured COMPLETE-marker stdout.
+        (self.wp/'statistics-test.bin').write_bytes(os.urandom(512*1024))
+        with self.config.open('a') as f:
+            f.write('RCLONE_STATS_INTERVAL="100ms"\nRCLONE_BWLIMIT="256k"\n')
        run=self.backup()
        self.assertTrue((run/'UPLOADED').is_file())
        self.assertFalse(list((self.base/'encrypted').rglob('wordpress.tar.zst')))
+        log=next((self.base/'logs').glob('backup_*.log')).read_text()
+        self.assertIn('NOTICE:',log)
+        self.assertIn('Remote upload started',log)
+        self.assertIn('Remote readback passed',log)
        self.run_script('app-restore.sh','--remote-run',run.name,'--verify-only')

    def test_failed_readback_does_not_publish_remote_marker(self):
@@ -98,8 +98,11 @@ echo "-- Complete local backup: $RUN_DIR"
 if [[ $ENABLE_UPLOAD == true ]]; then
  remote_run="${RCLONE_REMOTE_BASE%/}/$RUN_ID"
  # Upload COMPLETE last. An interrupted upload cannot look like a valid set.
+  echo '-- Remote upload started (archives and manifest; completion marker withheld)'
  rc copy "$RUN_DIR" "$remote_run" --exclude /COMPLETE --exclude /UPLOADED --immutable
+  echo '-- Remote upload finished; reading all uploaded files back for verification'
  rc check "$RUN_DIR" "$remote_run" --download --exclude /COMPLETE --exclude /UPLOADED
+  echo '-- Remote readback passed; publishing completion marker'
  rc copyto "$RUN_DIR/COMPLETE" "$remote_run/COMPLETE" --immutable
  marker=$(rc cat "$remote_run/COMPLETE")
  [[ $marker == "$(cat "$RUN_DIR/COMPLETE")" ]] || die 'Remote completion marker mismatch'
@@ -45,7 +45,9 @@ mkdir -m 700 "$INPUT"
 if [[ -n $REMOTE_RUN ]]; then
  [[ $REMOTE_RUN =~ ^[a-zA-Z0-9][a-zA-Z0-9_-]+$ && $REMOTE_RUN == "$ARCHIVE_PREFIX"_* ]] || die 'Unsafe remote run name'
  check_remote
+  echo "-- Downloading remote backup for restore verification: $REMOTE_RUN"
  rc copy "${RCLONE_REMOTE_BASE%/}/$REMOTE_RUN" "$INPUT"
+  echo '-- Remote backup downloaded; validating manifest, hashes and archives'
 else
  [[ -d $LOCAL_RUN && ! -L $LOCAL_RUN ]] || die 'Local run must be an existing directory'
  # Resolve overlap separately: archive sources are allowed under WORKDIR, but