Files
app-backup/REMOTE_READBACK.md
T

254 lines
15 KiB
Markdown
Raw Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
# Rücklesefehler am 15.09.2026
## Befund und Grenzen
Lauf: `appbackup_2026-09-15_00-30-51_ed205bcf` auf Gemini.
Die Laufnamen verwenden UTC: 00:30:51 entspricht 02:30:51 MESZ. Das Ende
06:53:01 MESZ und die gemeldeten 15730 Sekunden (4 h 22 min 10 s) passen zusammen.
Der übermittelte Bericht zeigt erfolgreiche lokale Archiverstellung und das
Erreichen der Remote-Rückleseprüfung nach dem Kopierauftrag. Das beweist noch
keine erfolgreiche Offsite-Sicherung. Beim Öffnen von `nextcloud-data.tar.zst`
meldet rclone `not an encrypted file - bad magic string`. Der Crypt-Leser hat
keinen gültigen Dateikopf mit der Signatur `RCLONE\0\0` erhalten. Das ist keine
Diagnose eines beschädigten lokalen zstd-Archivs und auch kein eindeutiger
Nachweis falscher Schlüssel. Quelle:
[Crypt-Dateiformat und Headerprüfung](https://github.com/rclone/rclone/blob/v1.74.3/backend/crypt/cipher.go).
Die Zahlen lassen sich aus dem Bericht nachvollziehen:
- Die 13 Archive ohne `nextcloud-data.tar.zst` ergeben 1.670.479.162 Bytes,
also 1,555755 GiB. rclone erfasst beim Inhaltsvergleich beide Leseströme:
rund 3,111510 GiB, gerundet die angezeigten **3,112 GiB**; das kleine Manifest
verändert diese Rundung nicht.
- **14 passende Dateien** passen zu diesen 13 Archiven plus `manifest.json`.
`COMPLETE` und `UPLOADED` sind bewusst vom Vergleich ausgeschlossen.
- **0 Unterschiede** und **2 Fehler** widersprechen sich nicht: Ein Lesefehler
ist kein erfolgreich festgestellter Inhaltsunterschied. Die Fehlerzählung
belegt nicht zwei beschädigte Dateien.
- Die Statistik passt damit dazu, dass alle übrigen Dateien fertig waren und
das große Nextcloud-Datenarchiv beim Öffnen hängen blieb. „100 %“ ist hier
kein Fortschritt über alle 6,6 GiB Archive. Quelle:
[rclone 1.74.3 Vergleich, Statistik und Fehlerzählung](https://github.com/rclone/rclone/blob/v1.74.3/fs/operations/check.go).
Der konkrete Auslöser bleibt offen: ein falsches/beschädigtes gespeichertes
Objekt oder eine vorübergehend falsche Antwort im Downloadpfad sind mögliche
Erklärungen. Der Bericht enthält keine HTTP-Antwort oder frühen Retry-Meldungen,
mit denen sich das unterscheiden ließe. Ein früherer HTTP-409 vom 10.09. ist
kein Beleg für dieselbe Ursache. SSH bestätigte am 15.09. rclone 1.74.3 auf
Rocky 10.2. Die geschützten Originallogs und Archive waren ohne interaktive
sudo-Anmeldung nicht direkt lesbar. Der Betreiber hat anschließend die ersten
180 Logzeilen und einen gefilterten Auszug über den gesamten Lauf bereitgestellt;
eine erneute OneDrive-Prüfung wurde nicht ausgeführt.
### Ergänzung aus den frühen Logzeilen
Bereits vor dem neuen Snapshot trat ein langer Stillstand beim Rücklesen eines
anderen Satzes auf: `appbackup_2026-09-11_00-38-40_f45e5e2f`.
| Zeit (MESZ) | Beobachtung |
| --- | --- |
| 02:31:04 | Remote-Zugriff vor der Platzbereinigung; für das Snapshot-Budget fehlen rund 6,77 GB. |
| 02:33:40–02:51:40 | Vergleich bleibt bei 3,509 GiB und vermeintlichen 100 % stehen; die angezeigte Rate fällt auf 0 B/s. |
| 02:52:40 | Vergleich läuft weiter; Gesamtmenge steigt, Anzeige fällt auf 72 %. |
| 02:53:43 | 13,431 GiB, 16 passende Dateien, keine Unterschiede; Prüfung erfolgreich. |
| anschließend | Erst jetzt wird die lokale Kopie vom 11.09. entfernt. Vorprüfungen bestehen; danach werden Wartungsmodus und Dienststopps für den neuen Snapshot aktiviert. |
Das bestätigt die Bedeutung der irreführenden Prozentanzeige unabhängig vom
späteren Fehler: Der ältere Satz war bei den ersten 100 % noch nicht fertig
geprüft. Sein erfolgreicher Abschluss belegt außerdem, dass der lange Stillstand
dort vorübergehend war. Der Auszug enthält für diesen alten Satz keinen
Crypt-Headerfehler; dieselbe technische Ursache für beide Vorgänge ist daher
nicht bewiesen. Ein zeitweiliges Problem im Remote-Lesezugriff ist nun eine
stärker gestützte Erklärung. Ein dauerhaft beschädigtes Objekt des neuen Satzes
bleibt trotzdem möglich.
Die Speicherbereinigung hat in diesem Lauf ihre Schutzbedingung eingehalten:
vollständige Offsite-Prüfung vor lokaler Löschung. Während dieser frühen
Wartephase hatte das Backup die Anwendungen noch nicht angehalten. Die neuen
Zeitlimits und Wiederholungen gelten bereits für beide betroffenen Prüfstellen;
dieser zusätzliche Befund erfordert keine weitere Codeänderung.
### Bestätigte Abfolge bis zum Abbruch
Der anschließend bereitgestellte gefilterte Gesamtauszug schließt die Lücke
zwischen Dateikopie und Fehler. Die Zeilennummern beziehen sich auf das Originallog:
| Logzeilen | Bestätigter Schritt |
| --- | --- |
| 248–260 | Wartungsmodus deaktiviert; dovecot, postfix, gitea, php-fpm, httpd und crond.service wieder gestartet. |
| 275 | Vollständiger lokaler Satz unter `/var/backups/app-backup/archives/appbackup_2026-09-15_00-30-51_ed205bcf` erstellt. |
| 276 | Upload von Archiven und Manifest begonnen; Abschlussmarker zurückgehalten. |
| 288 | Upload-Befehl erfolgreich beendet; vollständiges Rücklesen gestartet. |
| 507–512 | Um 06:53:00 MESZ Crypt-Headerfehler für `nextcloud-data.tar.zst`; 14 passende Dateien und Fehlerexit. |
Die lange Remote-Prüfung fand somit nach dem protokollierten Dienstwiederanlauf
statt. Die gesamte Laufzeit von 4 h 22 min ist keine Anwendungsausfallzeit.
Die genaue Dauer der Dienstpause lässt sich aus diesen ungestempelten
Phasenmeldungen nicht ermitteln; der jetzige Dienstzustand wurde nicht abgefragt.
Im gefilterten Auszug erscheint kein vorausgehender Uploadfehler und insbesondere
kein HTTP-409. Der erfolgreiche Kopierauftrag allein belegt weiterhin nicht die
Lesbarkeit des gespeicherten Inhalts. Fehlende Low-Level-/HTTP-Details erlauben
keine Entscheidung zwischen falscher Downloadantwort und fehlerhaftem Objekt.
Eine erneute Inhaltsprüfung des betroffenen Satzes ist der nächste Schritt zur
Eingrenzung; weitere Ausschnitte desselben NOTICE-Logs versprechen dafür wenig.
Der bestehende Codefix bleibt unverändert gültig und das lokale vollständige
Backup wird durch seinen Fehlerpfad erhalten. Sein aktueller Zustand kann mit
der unten beschriebenen lokalen Prüfung bestätigt werden.
Der für den Gesamtauszug verwendete Diagnosebefehl:
```bash
sudo grep -nE 'Remote|ERROR|WARNING|Failed|matching files|differences|Service started|Maintenance mode disabled|Complete local' \
/var/log/app-backup/backup_appbackup_2026-09-15_00-30-51_ed205bcf.log
```
## Was im Code korrigiert wurde
`rclone check` aktiviert in 1.74.3 keine Wiederholung des gesamten Befehls.
`RCLONE_RETRIES=6` bedeutete daher bisher nicht sechs vollständige Rückleseversuche.
Die gemeinsame Leerlauffrist von einer Stunde und 20 Low-Level-Versuche konnten
lange Wartezeiten begünstigen; aus dem Auszug lässt sich die genaue Folge der
Wartezeiten nicht rekonstruieren. Quellen:
[check-Aufruf](https://github.com/rclone/rclone/blob/v1.74.3/cmd/check/check.go),
[Retry-Steuerung](https://github.com/rclone/rclone/blob/v1.74.3/cmd/cmd.go),
[I/O-Leerlauffrist](https://rclone.org/docs/#timeout-duration).
Der neue Wrapper gilt für den vollständigen Backup-Rücklesevergleich und die
Offsite-Prüfung vor einer lokalen Platzbereinigung:
| Einstellung | Default | Bedeutung |
| --- | ---: | --- |
| `RCLONE_CHECK_ATTEMPTS` | 3 | Gesamtzahl vollständiger Versuche, zulässig 1–10 |
| `RCLONE_CHECK_RETRY_DELAY` | 30 | Sekunden Pause, zulässig 0–3600 |
| `RCLONE_CHECK_TIMEOUT` | 300 | Sekunden I/O-Leerlauf, zulässig 1–3600 |
| `RCLONE_CHECK_DEADLINE` | 3600 | Sekunden Prozesslaufzeit je Versuch, zulässig 1–86400 |
| `RCLONE_CHECK_LOW_LEVEL_RETRIES` | 3 | Interne Leseversuche, zulässig 1–20 |
Die neuen Einstellungen sind Ganzzahlen. Sie gelten auch, wenn sie in einer
alten Konfiguration fehlen. Die Prozessfrist verwendet GNU `timeout` und
bezieht Backend-Wartezeiten mit ein. Nach Fristablauf sendet es TERM, nach
weiteren zehn Sekunden nötigenfalls KILL an die Prozessgruppe. Exit 124 wird
als Fristüberschreitung protokolliert; ein durch Signal beendeter Versuch
(einschließlich KILL nach Ablauf der Abbruchfrist) wird nicht erneut gestartet.
Bei drei normalen Fristüberschreitungen beträgt die maximale Prüfzeit ungefähr
3 Stunden plus zwei Pausen und Abbruchfristen. Die systemd-Gesamtfrist bleibt
zusätzlich wirksam. Für größere Sätze oder begrenzte Bandbreite die Frist
passend zum vollständigen Vergleich erhöhen; ein langsamer, aber intakter
Transfer kann sonst korrekt als nicht abgeschlossen abgebrochen werden.
Jeder neue Prozess liest sämtliche ausgewählten Dateien erneut. Ein Fehler
wird erst durch einen späteren **vollständigen** erfolgreichen Vergleich
überwunden. Mehrzeilige Statistiken zeigen aktive Prüfungen; pro Datei erscheint
ein Ergebnis (`=` identisch, `!` Lesefehler, `*` unterschiedlich, `+`/`-` fehlend).
Quelle: [rclone-Prüfberichte](https://rclone.org/commands/rclone_check/).
Bei bleibendem Fehler gibt es keinen neuen Remote-Abschlussmarker, kein lokales
`UPLOADED` und keine nachgelagerte Altersretention. Die lokalen vollständigen
Archive bleiben erhalten. Die bisherige Meldung `Retained work: none` bezog
sich allein auf temporäres Staging; jetzt nennt das Fehlerlog zusätzlich den
erhaltenen lokalen Sicherungssatz. Die Speicherbereinigung entfernt keine
lokale Kopie, deren Offsite-Prüfung scheitert.
Uploads und manuelle `app-restore.sh`-Downloads bleiben beim bisherigen Verfahren.
Die einzelnen Downloads des separaten monatlichen Restore-Tests verwenden seit
dem unten beschriebenen Folgefix ebenfalls begrenzte Versuche. Das Update
repariert weder ein beschädigtes OneDrive-Objekt
noch veröffentlicht es alte fehlgeschlagene Läufe automatisch. Insbesondere
werden keine Crypt-Schlüssel geändert und keine Inhaltsprüfungen abgeschwächt.
## Den betroffenen Satz prüfen
Auf Gemini zunächst den vorhandenen lokalen Satz ohne zusätzliche Archivkopie
prüfen; dabei werden keine Anwendungsdaten verändert:
```bash
sudo /usr/local/sbin/app-restore.sh \
--local-run /var/backups/app-backup/archives/appbackup_2026-09-15_00-30-51_ed205bcf \
--verify-only
```
Eine erneute rein lesende Offsite-Prüfung ist auch ohne Remote-`COMPLETE`
möglich. Der folgende **einmalige Diagnosevergleich** lädt die Inhalte als
Stream, schreibt keine Archive auf Platte und veröffentlicht keinen Marker.
Er nutzt die gemeinsame Standardsperre; bei angepasstem `LOCKFILE` und
`RCLONE_CONFIG` die tatsächlichen Pfade einsetzen. Exit 0 bestätigt nur diesen
Vergleich, Exit 124 einen Timeout. Während laufender Backup-/Restore-/Update-Jobs
wird die Sperre nicht übernommen:
```bash
sudo flock -n /run/app-backup.lock timeout --kill-after=10s 3600s \
rclone --ask-password=false --config /root/.config/rclone/rclone.conf \
check /var/backups/app-backup/archives/appbackup_2026-09-15_00-30-51_ed205bcf \
OneDriveCrypt:gemini/appbackup_2026-09-15_00-30-51_ed205bcf \
--download --exclude /COMPLETE --exclude /UPLOADED \
--timeout 300s --contimeout 30s --low-level-retries 3 \
--stats 1m --stats-log-level NOTICE --combined -
```
Schlägt derselbe Header erneut fehl, den lokalen Satz erhalten und die
vollständigen Logs, betroffene Datei und rclone-Version für die weitere
Provideranalyse verwenden. Ein einzelner weiterer Fehlschlag beweist noch nicht,
dass das gespeicherte Objekt dauerhaft beschädigt ist. Keine Zugangsdaten,
`config show`-Ausgaben oder HTTP-Dumps mit Tokens weitergeben.
## Deployment und Abnahme
Das aus dem Commit gebaute `.run`-Paket mit `.sha256` übertragen und im
Wartungsfenster starten; konkrete Schritte stehen in
[UPDATE_ANLEITUNG.md](UPDATE_ANLEITUNG.md). Der Installer erhält Konfiguration
und Zugangsdaten, erstellt Rollback-Dateien und führt ein neues Backup mit
anschließender separater Restore-Prüfung aus. Dadurch entsteht ein neuer
Sicherungssatz; der oben untersuchte bleibt als fehlgeschlagener Lauf erkennbar.
Für die Abnahme müssen `result.txt` **SUCCESS**, der neue Backupstatus Exit 0
und das Log `Remote backup fully read back and verified` zeigen. Im Rückleselog
müssen alle Dateien erfolgreich geprüft worden sein. Der Backup-Timer wird
erst nach erfolgreicher Update-Abnahme aktiviert. Der konkrete Rollback-Pfad
steht im Update-Ergebnisordner (`rollback-update.sh`); bei einem Rollback
kehren auch die bisherigen Grenzen der Rückleseprüfung zurück.
### Ergebnis des ersten Deployments und Folgefix
Der Betreiber installierte `4f220dbc6447` über den Updateordner
`/var/backups/app-backup-upgrade-vuQRJCvw`. Die Vorbereitung prüfte den Satz
vom 12.09. erfolgreich im ersten Versuch nach rund 13 Minuten, bevor seine lokale
Kopie zur Platzbeschaffung entfernt wurde. Der neue Satz
`appbackup_2026-09-15_09-03-06_20b0f7a6` bestand am 15.09. um 11:32:41 MESZ
die vollständige Rückleseprüfung: 15 passende Dateien, einschließlich
`nextcloud-data.tar.zst`, erster Versuch, 3 min 42,7 s. Um 11:32:50 wurden
Abschlussmarker und Backup-Erfolg bestätigt. Damit ist dieser neue Offsite-Satz
inhaltlich geprüft; das sagt nichts über den Zustand des alten fehlgeschlagenen
Satzes von 00:30 UTC aus.
Die separate Restore-Abnahme scheiterte anschließend beim erneuten Download
der Nextcloud-Daten mit `Command failed: bash`, meldete aber `cleanup OK`.
Metadaten, drei Datenbanken, WordPress und Nextcloud waren bereits bestanden.
Die erste Korrektur begrenzte die `check`-Aufrufe, nicht den eigenen `cat`-Pfad
dieses Tests. Zusätzlich unterdrückte dessen Supervisor die konkrete
Unterprozessfehlermeldung. Die nachträgliche genaue Providerursache ist daher
aus diesem Log nicht rekonstruierbar. Der Folgefix erfasst diesen Downloadpfad
mit Wiederholungen, Zeitlimits und sicheren Diagnosen; siehe
[Restore-Test-Analyse](RESTORE_TEST.md#downloadfehler-bei-der-abnahme-am-15092026).
Regressionstests verwenden echte lokale Crypt-Transfers, tar/zstd und isolierte
MariaDB. Sie prüfen vorübergehende Fehler, echte beschädigte Crypt-Dateiköpfe,
bleibende Fehler, Fristablauf mit Wiederholung, Signalabbruch, erhaltene lokale
Sätze und das Zurückhalten von Abschlussmarkern. systemd und Providerfehler
werden simuliert; ein erfolgreicher lokaler Test belegt keine OneDrive-Abnahme.
Validierung am 15.09.2026:
- `tests/run.sh` im netzlosen Testcontainer: Bash-Syntax und ShellCheck erfolgreich;
106 Tests entdeckt, 101 bestanden, fünf optionale Docker-in-Docker-Tests
ausgelassen. Crypt-Transfers mit rclone 1.60.1-DEV, echte lokale MariaDB ohne TCP.
- Acht gezielte Integrationstests zusätzlich mit der lesend von Gemini kopierten
rclone-1.74.3-Binärdatei: alle bestanden. Darunter vorübergehender Lesefehler,
beschädigter Crypt-Header, Fristablauf mit erneutem Erfolg, dauerhafter Stillstand,
Signalabbruch, gleich große Inhaltsbeschädigung, geschützte Platzbereinigung
sowie Paketinstallation und kombiniertes Rollback.
- Zum Zeitpunkt dieser lokalen Tests war das Produktionssystem noch nicht
verändert. Das nachfolgende Deployment bestand das Backup; die vollständige
Restore-Abnahme scheiterte wie oben beschrieben.