From 3d16f33f24c0ac27472fa644ce6672dfcc673a1d Mon Sep 17 00:00:00 2001 From: Johannes Rest Date: Tue, 15 Sep 2026 12:57:59 +0200 Subject: [PATCH] Retry restore-test downloads safely and expose bounded diagnostics --- Dokumentation.md | 6 +- README.md | 3 + REMOTE_READBACK.md | 33 ++++++- RESTORE_TEST.md | 92 ++++++++++++++++++ UPDATE_ANLEITUNG.md | 21 +++++ etc/app-backup/app-backup.conf | 3 +- lib/restore-test-remote.sh | 5 + lib/restore_test.py | 147 +++++++++++++++++++++++++---- tests/test_restore_test.py | 127 +++++++++++++++++++++++++ usr-local-sbin/app-restore-test.sh | 2 + 10 files changed, 417 insertions(+), 22 deletions(-) diff --git a/Dokumentation.md b/Dokumentation.md index 5c1a65e..1c1eb66 100644 --- a/Dokumentation.md +++ b/Dokumentation.md @@ -222,8 +222,10 @@ Die sechs Gesamtversuche gelten nicht pauschal für jeden rclone-Befehl: jedoch Wiederholungen fehlgeschlagener Datei-Leseoperationen. Deshalb verwendet app-backup jetzt einen eigenen begrenzten Wrapper nur für vollständige Rücklesevergleiche (Backup und Platzbereinigung). Er greift auch mit alten -Konfigurationen. Die einzelnen Restore-Downloads und Uploads behalten ihre -bisherigen Einstellungen. Ein verbleibender Prüffehler beendet das Backup +Konfigurationen. Uploads und manuelle `app-restore.sh`-Downloads behalten ihre +bisherigen Einstellungen. Der separate monatliche Restore-Test verwendet seit +dem Folgefix ebenfalls begrenzte Downloads; siehe [RESTORE_TEST.md](RESTORE_TEST.md). +Ein verbleibender Prüffehler beendet das Backup sichtbar. Quellen: [Kopierversuche](https://github.com/rclone/rclone/blob/v1.74.3/cmd/cmd.go), [Check-Aufruf](https://github.com/rclone/rclone/blob/v1.74.3/cmd/check/check.go), diff --git a/README.md b/README.md index 26cdd5f..f8c56a1 100644 --- a/README.md +++ b/README.md @@ -7,6 +7,9 @@ Die vollständige Analyse, Architektur, Konfiguration, Betriebsanleitung und ver Der [Vorfall vom 15.09.2026 und die korrigierte Rückleseprüfung](REMOTE_READBACK.md) sind dokumentiert: begrenzte vollständige Prüfanläufe, eigene Zeitlimits, sichtbare Dateiergebnisse und eindeutiger Hinweis auf erhaltene lokale Archive. +Die anschließende Restore-Abnahme verwendet jetzt ebenfalls begrenzte Downloads +mit Wiederholungen und sicheren Fehlerdetails; siehe +[Restore-Test: Downloadfehler](RESTORE_TEST.md#downloadfehler-bei-der-abnahme-am-15092026). Neu: [Monatlicher Offsite-Restore-Test](RESTORE_TEST.md) mit vollständiger Prüfung aller Komponenten, isoliertem MariaDB-Import und Bereinigung auch bei Fehlern. diff --git a/REMOTE_READBACK.md b/REMOTE_READBACK.md index cc71fc8..d15440e 100644 --- a/REMOTE_READBACK.md +++ b/REMOTE_READBACK.md @@ -151,8 +151,10 @@ 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, einzelne Restore-Downloads und deren Einstellungen bleiben beim -bisherigen Verfahren. Das Update repariert weder ein beschädigtes OneDrive-Objekt +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. @@ -207,6 +209,29 @@ 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 @@ -223,4 +248,6 @@ Validierung am 15.09.2026: beschädigter Crypt-Header, Fristablauf mit erneutem Erfolg, dauerhafter Stillstand, Signalabbruch, gleich große Inhaltsbeschädigung, geschützte Platzbereinigung sowie Paketinstallation und kombiniertes Rollback. -- Das Produktionssystem wurde nicht verändert; die OneDrive-Abnahme steht aus. +- 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. diff --git a/RESTORE_TEST.md b/RESTORE_TEST.md index 4e898bb..7bb8838 100644 --- a/RESTORE_TEST.md +++ b/RESTORE_TEST.md @@ -6,6 +6,82 @@ entschlüsselt, validiert und in ein privates Testverzeichnis entpackt. SQL-Dump werden zusätzlich in eine isolierte MariaDB importiert und mit `mariadb-check` geprüft. Produktive Anwendungen werden dabei nicht angehalten oder überschrieben. +## Downloadfehler bei der Abnahme am 15.09.2026 + +Das Update `4f220dbc6447` erzeugte den Satz +`appbackup_2026-09-15_09-03-06_20b0f7a6`. Sein Upload und der vollständige +Bytevergleich aller 15 Dateien bestanden, auch für die rund 5 GiB große +`nextcloud-data.tar.zst`. Der Abschlussmarker wurde bestätigt. Anschließend +bestand der separate Restore-Test Metadaten, drei Datenbanken, WordPress und +Nextcloud; beim erneuten Abruf der Nextcloud-Daten folgte `Command failed: bash`. +Der Test meldete `FAIL; cleanup OK`, das gesamte Update deshalb `FAILED`. + +Der Fehler ist dem Shell-Aufruf für den Komponentendownload einschließlich +Remote-Vorprüfung zuzuordnen: Tar-Prüfung und Entpacken würden einen anderen +Programmnamen melden; Fehler der separaten Platzbeschaffung werden bereits +mit einer eigenen Meldung versehen. Der Supervisor verwarf jedoch stderr +und nannte weder Exit-Code noch genaue Phase. Ob diesmal Crypt-Header, Timeout, +HTTP-Fehler oder eine andere Bridge-Ursache vorlag, ist damit **nicht mehr aus +diesem Log rekonstruierbar**. Ein erneuter `bad magic string` ist nicht belegt. + +Die erste Korrektur erfasste `rclone check`, aber nicht diesen eigenen +`rclone cat`-Pfad. Auch `cat` wiederholt den gesamten Befehl in rclone 1.74.3 +nicht automatisch über `--retries`. +Quelle: [rclone-1.74.3-cat-Aufruf](https://github.com/rclone/rclone/blob/v1.74.3/cmd/cat/cat.go). + +### Korrigierter Ablauf + +Der Restore-Test verwendet für seine lesenden Remote-Aufrufe jetzt dieselben +Konfigurationswerte wie die Backup-Rückleseprüfung: + +- `RCLONE_CHECK_ATTEMPTS=3`: höchstens drei Versuche je Metadatenabruf/Download. +- `RCLONE_CHECK_DEADLINE=3600`: maximal eine Stunde je Versuch einschließlich + Remote-Vorprüfung. Der Python-Supervisor beendet die eigene Prozessgruppe bei + Überschreitung mit TERM, nötigenfalls nach fünf Sekunden mit KILL. +- `RCLONE_CHECK_TIMEOUT=300` und `RCLONE_CHECK_LOW_LEVEL_RETRIES=3`: kürzere + rclone-Leerlauffrist und begrenzte interne Versuche, auch bei der Vorprüfung. +- `RCLONE_CHECK_RETRY_DELAY=30`: Pause zwischen fehlgeschlagenen Versuchen. + Die Gesamtfrist `RESTORE_TEST_TIMEOUT` und die Speicherüberwachung bleiben + während Downloads und Wartepausen wirksam. Die Fristen addieren sich nicht + zu einer unbegrenzten Verlängerung des gesamten Restore-Tests. + +Bei einer Wiederholung wird die angefangene Archivdatei auf null gekürzt und +vollständig neu geladen; es wird niemals an Teilbytes angehängt. Metadaten +werden je Versuch in einem neuen begrenzten Puffer gelesen. Erst ein erfolgreich +beendeter Download mit passender Größe und SHA-256 darf zur Archivprüfung und +zum Entpacken gelangen. Größenüberschreitungen, Prüfsummenfehler, Speichergrenzen, +Gesamtfrist und Signalabbrüche lösen keine Download-Wiederholung aus. +Die Platzbereinigung wird nicht als Remote-Leseoperation wiederholt. + +Jede Komponente meldet und speichert nun ihre konkrete Phase: Download, +Prüfsumme, Archivprüfung, Platzabschätzung, Entpacken, DB-Import/-Prüfung und +Bereinigung. Während eines Remote-Aufrufs erscheint etwa jede Minute +ein Fortschrittsbericht mit gelesenen Bytes und verstrichener Zeit, auch bei +Stillstand. Nicht erfolgreiche Prozesse nennen Exit-Code oder Fristablauf. + +Remote-stderr wird parallel zum Archivstrom gelesen und ausschließlich in feste +Fehlerklassen übersetzt, etwa `crypt-header`, `io-timeout`, `tls`, `dns`, +`connection`, `http-429` oder `http-503`. Die Auswertung hat einen begrenzten +Textpuffer; große stderr-Ausgaben können die Download-Pipe nicht blockieren. +Es werden keine rohen URLs, Tokens, Header, Dateiinhalte oder Providertexte +übernommen. Unbekannte Meldungen erscheinen als `unclassified remote error`. +Diese Klassifizierung ist ein Diagnosehinweis, kein Beweis der Providerursache. +DB- und sonstige Tool-stderr-Ausgaben bleiben vollständig unterdrückt, da sie +SQL-Inhalte enthalten können. Phase und Exit-Code bleiben trotzdem sichtbar. + +Ein bleibender Fehler erhält den bereits verifizierten Backup-Satz und den +vorherigen Restore-Erfolgsnachweis, meldet die betroffene Komponente als `FAIL` +und bereinigt die Testdaten. Nach fehlgeschlagener Update-Abnahme bleiben +Backup- und Restore-Test-Timer gestoppt. Das neue Paket erneut im Wartungsfenster +installieren; es führt ein neues Backup samt vollständiger Restore-Abnahme aus. +Erst die neue `result.txt` mit `SUCCESS` bestätigt die gesamte Abnahme. +[Installationsschritte](UPDATE_ANLEITUNG.md). + +Der vorhandene erfolgreiche Backup-Satz darf alternativ nach Installation des +Fixes mit `app-restore-test.sh --remote-run` erneut geprüft werden. Dabei bleibt +die Altersgrenze aktiv. Ein solcher Einzeltest setzt nicht nachträglich das +alte Update-Ergebnis auf SUCCESS und aktiviert keine Update-Timer. + ## Speicherbedarf und Bereinigung Wegen des knappen Speichers auf Gemini läuft immer nur **eine Komponente**: @@ -221,6 +297,22 @@ Technische Referenzen: [Docker run](https://docs.docker.com/reference/cli/docker ## Entwicklung und lokale Verifikation +Der Folgefix vom 15.09.2026 bestand alle **33 Restore-Test-Fälle** mit der von +Gemini kopierten rclone-1.74.3-Binärdatei und dem echten lokalen +`mariadb:10.11`-Image. Geprüft wurden auch Teil-Downloads/Metadaten mit erneutem +Erfolg, dauerhaft fehlgeschlagene Downloads, Fristablauf, Signalabbruch, +Gesamtfrist während einer Retry-Pause und zu große Antworten. Große stderr- +Ausgaben blockierten nicht; synthetische Tokens und SQL-Inhalte erschienen +weder im Log noch im Status oder Bericht. Die Testcontainer und Testdaten waren +anschließend entfernt. Diese lokalen Tests ersetzen nicht die erneute +OneDrive-/Rocky-Abnahme auf Gemini. + +Die vollständige Basissuite `tests/run.sh` bestand ebenfalls: Bash-Syntax, +ShellCheck und 111 erfolgreiche Tests; fünf optionale Docker-Fälle waren in +diesem netzlosen Basistest ausgelassen und wurden im oben genannten echten +MariaDB-Lauf bestanden. Insgesamt sind damit alle **116 unterschiedlichen +Tests** erfolgreich abgedeckt, einschließlich Paketinstallation und Rollback. + Am 12.09.2026 bestanden **100 unterschiedliche Tests**: 71 Backup-/Restore-/ Installer-Regressionstests, 23 Restore-Test-Fälle mit dem offiziellen lokalen MariaDB-10.11-Image und 6 gezielte Scratch-/Recovery-Schutzprüfungen. ShellCheck diff --git a/UPDATE_ANLEITUNG.md b/UPDATE_ANLEITUNG.md index 9034a8b..aa736e3 100644 --- a/UPDATE_ANLEITUNG.md +++ b/UPDATE_ANLEITUNG.md @@ -1,5 +1,26 @@ # Automatisches Update-Paket +## Nachtrag vom 15.09.2026: Restore-Abnahme nach erfolgreichem Backup + +Das Paket `4f220dbc6447` bestand auf Gemini das neue Backup einschließlich +vollständiger Remote-Rückleseprüfung. Danach scheiterte der separate Restore-Test +bei `nextcloud-data` mit `Command failed: bash`; seine Bereinigung war erfolgreich. +Die erste Korrektur erfasste diesen eigenen Downloadpfad noch nicht. + +Das aktuelle Paket begrenzt und wiederholt auch die Restore-Test-Downloads. +Es meldet die genaue Komponente/Phase, Exit-Code, empfangene Bytes und sichere +Fehlerklassen. Angefangene Downloads werden vor Wiederholung auf null gekürzt. +Details und Grenzen stehen in [RESTORE_TEST.md](RESTORE_TEST.md). + +Bei diesem Updatefehler bleibt das erfolgreich erstellte Backup erhalten, +das Paket ist installiert, Backup- und Restore-Test-Timer bleiben jedoch gestoppt. +Das korrigierte Paket wie unten per SCP übertragen und im Wartungsfenster normal +starten. Es erstellt ein neues Abnahmebackup und prüft dieses vollständig. +Ein bereits aktivierter Restore-Test benötigt keine weitere Aktivierungsoption. +Erst `SUCCESS` in der **neuen** `result.txt` bestätigt die gesamte Update-Abnahme +und die Timer-Aktivierung; die alte Fehlerdatei bleibt ein historischer Nachweis. +Rollback ist für die erneute Paketinstallation nicht erforderlich. + ## Korrektur vom 15.09.2026: hängende Rückleseprüfung Das aktuelle Paket ergänzt drei vollständige Rückleseversuche mit eigenen diff --git a/etc/app-backup/app-backup.conf b/etc/app-backup/app-backup.conf index 81c5d3b..bba4e1b 100644 --- a/etc/app-backup/app-backup.conf +++ b/etc/app-backup/app-backup.conf @@ -31,7 +31,8 @@ RCLONE_TIMEOUT="1h" RCLONE_CONTIMEOUT="30s" # Periodic transfer/check statistics in journald, including otherwise quiet uploads. RCLONE_STATS_INTERVAL="1m" -# Full readback attempts, independent of upload retries. All times are seconds. +# Readback policy: full comparisons and individual monthly restore-test reads. +# Independent of upload retries. All times are seconds. # Deadline includes backend waits; raise it for larger/slower full comparisons. RCLONE_CHECK_ATTEMPTS=3 RCLONE_CHECK_RETRY_DELAY=30 diff --git a/lib/restore-test-remote.sh b/lib/restore-test-remote.sh index 3f07b32..54fe71a 100644 --- a/lib/restore-test-remote.sh +++ b/lib/restore-test-remote.sh @@ -19,6 +19,11 @@ if [[ ${1:-} == space ]]; then ensure_space "$WORKDIR" "$2" exit 0 fi +# These reads belong to verification, not upload. Apply the shorter read I/O +# policy even during crypt preflight. The Python parent owns deadlines/retries +# and resets partial output before retry; retrying cat here could append bytes. +RCLONE_TIMEOUT="${RCLONE_CHECK_TIMEOUT}s" +RCLONE_LOW_LEVEL_RETRIES=$RCLONE_CHECK_LOW_LEVEL_RETRIES check_remote >&2 # rclone is restricted to read operations here, including metadata reads. case ${1:-} in lsf|cat) rc "$@" ;; *) die 'Unsupported restore-test remote operation' ;; esac diff --git a/lib/restore_test.py b/lib/restore_test.py index 2d07f24..88a199e 100644 --- a/lib/restore_test.py +++ b/lib/restore_test.py @@ -36,6 +36,53 @@ class TestError(Exception): pass +class CommandError(TestError): + """Only process failures/timeouts are retryable; disk and size guards are not.""" + def __init__(self, operation, code, total, diagnostics='unclassified', timed_out=False): + self.code = code + self.timed_out = timed_out + reason = 'deadline exceeded' if timed_out else f'exit {code}' + super().__init__(f'{operation} failed ({reason}; received {total} bytes; {diagnostics})') + + +class RemoteDiagnostics: + """Classify stderr without retaining URLs, tokens, filenames or raw payloads. + + A denylist cannot reliably redact provider messages. Emit only fixed labels + and HTTP status numbers, draining both pipes to avoid a full-stderr deadlock. + SQL/tool stderr outside the remote bridge stays suppressed. + """ + PATTERNS = { + 'crypt-header': ('bad magic string', 'too short to be encrypted', 'truncated block header'), + 'crypt-authentication': ('failed to authenticate decrypted block',), + 'io-timeout': ('i/o timeout', 'context deadline exceeded', 'timed out'), + 'dns': ('no such host', 'temporary failure in name resolution'), + 'connection': ('connection reset', 'connection refused', 'unexpected eof'), + 'tls': ('x509:', 'tls handshake'), + 'throttled': ('too many requests', 'activitylimitreached', 'throttled'), + 'not-found': ('object not found', 'directory not found'), + 'authentication': ('unauthorized', 'invalid_grant', 'invalid token'), + 'local-space': ('no space left on device',), + 'configuration': ('unsupported rclone', 'invalid remote', 'config file not found', 'crypt remote required'), + } + + def __init__(self): + self.tail = '' + self.labels = set() + + def feed(self, chunk): + text = self.tail + chunk.decode(errors='replace').lower() + for label, patterns in self.PATTERNS.items(): + if any(pattern in text for pattern in patterns): + self.labels.add(label) + for code in re.findall(r'(?:http(?:/\d(?:\.\d)?)?\s+|status(?: code)?[\s:=]+)([45]\d\d)\b', text): + self.labels.add('http-' + code) + self.tail = text[-256:] + + def summary(self): + return ', '.join(sorted(self.labels)) or 'unclassified remote error (raw details suppressed)' + + def atomic_json(path, data): temp = path.with_suffix('.tmp') temp.write_text(json.dumps(data, ensure_ascii=True, indent=2) + '\n') @@ -161,27 +208,40 @@ class Rehearsal: if self.args.max_work_gb and self.used + additional > self.args.max_work_gb * GIB: raise TestError('Restore-test disk budget exceeded') - def command(self, command, *, capture=0, output=None, limit=None, stdin=None, timeout=120): + def command(self, command, *, capture=0, output=None, limit=None, stdin=None, timeout=120, + operation=None, remote_diagnostics=False): """Bound stdout and runtime, monitor disk, reap children even on interruption. - stderr is intentionally not copied: DB errors can contain restored data. - Errors identify the failed operation without logging SQL or credentials. + Only the remote bridge gets classified stderr; raw stderr is never logged. """ result = bytearray() total = 0 + operation = operation or Path(command[0]).name + diagnostics = RemoteDiagnostics() + started = time.monotonic() + next_progress = started + 60 end = time.monotonic() + timeout proc = subprocess.Popen(command, stdin=stdin or subprocess.DEVNULL, stdout=subprocess.PIPE if capture or output is not None else subprocess.DEVNULL, - stderr=subprocess.DEVNULL, start_new_session=True) + stderr=subprocess.PIPE if remote_diagnostics else subprocess.DEVNULL, + start_new_session=True) selector = selectors.DefaultSelector() if proc.stdout: - selector.register(proc.stdout, selectors.EVENT_READ) + selector.register(proc.stdout, selectors.EVENT_READ, 'stdout') + if proc.stderr: + selector.register(proc.stderr, selectors.EVENT_READ, 'stderr') try: self.remember_child(proc) while selector.get_map() or proc.poll() is None: self.disk() + if remote_diagnostics and time.monotonic() >= next_progress: + self.log.info('%s progress: %s/%s bytes, elapsed %ss', operation, total, + limit if limit is not None else 'metadata', int(time.monotonic()-started)) + next_progress = time.monotonic() + 60 if time.monotonic() >= end: - raise TestError('Timed out: ' + Path(command[0]).name) + raise CommandError(operation, None, total, + diagnostics.summary() if remote_diagnostics else 'tool details suppressed', + timed_out=True) if not selector.get_map(): time.sleep(0.1) continue @@ -190,6 +250,9 @@ class Rehearsal: if not chunk: selector.unregister(key.fileobj) continue + if key.data == 'stderr': + diagnostics.feed(chunk) + continue total += len(chunk) if total > (limit if limit is not None else capture): raise TestError('Remote output exceeds expected size') @@ -198,8 +261,10 @@ class Rehearsal: output.write(chunk) else: result.extend(chunk) - if proc.wait() != 0: - raise TestError('Command failed: ' + Path(command[0]).name) + code = proc.wait() + if code != 0: + raise CommandError(operation, code, total, + diagnostics.summary() if remote_diagnostics else 'tool details suppressed') return bytes(result) finally: selector.close() @@ -212,11 +277,38 @@ class Rehearsal: proc.wait() if proc.stdout: proc.stdout.close() + if proc.stderr: + proc.stderr.close() (self.root / 'child.json').unlink(missing_ok=True) def remote(self, *args, **kwargs): - return self.command(['bash', self.args.remote_check, self.args.config, *args], - timeout=self.args.timeout, **kwargs) + command = ['bash', self.args.remote_check, self.args.config, *args] + # Space recovery can delete eligible local copies and has its own checks; + # it must not be replayed as though it were a read-only cat/lsf request. + if args[0] == 'space': + return self.command(command, timeout=self.args.timeout, operation='Space recovery', **kwargs) + for attempt in range(1, self.args.remote_attempts + 1): + self.disk() + output = kwargs.get('output') + if output is not None: + # Reuse one file, never append an aborted cat stream to a retry. + output.seek(0) + output.truncate() + self.log.info('Remote %s attempt %s/%s (deadline %ss)', args[0], attempt, + self.args.remote_attempts, self.args.remote_deadline) + try: + return self.command(command, timeout=self.args.remote_deadline, + operation='Remote ' + args[0], remote_diagnostics=True, **kwargs) + except CommandError as exc: + self.log.warning('%s', exc) + if (attempt == self.args.remote_attempts or + (exc.code is not None and (exc.code < 0 or exc.code >= 128))): + raise + # Keep disk/overall time and signal handling active during backoff. + end = time.monotonic() + self.args.remote_retry_delay + while time.monotonic() < end: + self.disk() + time.sleep(min(0.2, max(0, end-time.monotonic()))) def cleanup(self): self.stop_orphan() @@ -372,41 +464,55 @@ exec mariadbd --no-defaults --user=root --datadir=/var/lib/mysql/db --socket=/va self.state['components'].append(component) self.save() self.log.info('Component %s: download, verify, extract', item['label']) + self.phase(component, 'download') self.disk(additional=item['size'], force=True) archive = self.scratch / item['file'] with archive.open('wb') as output: self.remote('cat', self.args.remote.rstrip('/') + '/' + self.state['run'] + '/' + item['file'], output=output, limit=item['size']) + self.phase(component, 'checksum') if archive.stat().st_size != item['size'] or backup_set.digest(archive) != item['sha256']: raise TestError('Archive checksum/size mismatch: ' + item['label']) # Run shared validation as a monitored child, so even corrupt streams # and metadata-heavy archives cannot bypass the total timeout. + self.phase(component, 'archive validation') self.command([sys.executable, str(Path(__file__).with_name('backup_set.py')), - 'tar', str(archive), item['root']], timeout=self.args.timeout) + 'tar', str(archive), item['root']], timeout=self.args.timeout, operation='Archive validation') + self.phase(component, 'space estimate') unpacked, entries = self.expand_size(archive) self.disk(additional=unpacked, force=True) extracted = self.scratch / 'extracted' extracted.mkdir(mode=0o700) + self.phase(component, 'extract') self.command(['tar', '--extract', '--file', str(archive), '--acls', '--xattrs', '--selinux', - '--numeric-owner', '--same-owner', '-C', str(extracted)], timeout=self.args.timeout) + '--numeric-owner', '--same-owner', '-C', str(extracted)], timeout=self.args.timeout, + operation='Archive extraction') # The compressed input is no longer needed; free it BEFORE DB import. archive.unlink() component.update(extracted_bytes=unpacked, entries=entries) if item['label'].startswith('db-'): + self.phase(component, 'database import/check') sql = extracted / item['root'] if not sql.is_file() or sql.is_symlink() or not sql.stat().st_size: raise TestError('SQL dump missing or empty') self.disk(additional=512*1024*1024, force=True) component['tables'] = self.database(sql) + self.phase(component, 'cleanup') self.monitor = False self.cleanup() self.scratch.mkdir(mode=0o700) self.monitor = True component['status'] = 'SUCCESS' + component['phase'] = 'complete' self.save() self.log.info('Component %s: SUCCESS; files and test DB removed', item['label']) self.state['status'] = 'SUCCESS' + def phase(self, component, phase): + component['phase'] = phase + self.save() + self.log.info('Component %s: %s', component['label'], phase) + def report(self): fqdn = socket.getfqdn() host = self.args.hostname or fqdn @@ -421,7 +527,7 @@ exec mariadbd --no-defaults --user=root --datadir=/var/lib/mysql/db --socket=/va f"Bereinigung: {state['cleanup']}", f"Fehler: {state['error']}", '', 'Komponenten:'] for c in state['components']: body.append(f"{c['label']}: {c['status']}; Archiv {c['archive_bytes']} Bytes; " - f"Einträge {c.get('entries', '?')}; Tabellen {c.get('tables', '-')}") + f"Einträge {c.get('entries', '?')}; Tabellen {c.get('tables', '-')}; Phase {c.get('phase', '?')}") body.extend(['', 'Dateien entpackt; enthaltene DB-Dumps isoliert importiert und Tabellen geprüft.', 'Dies ist kein Start-/Funktionstest der produktiven Anwendungen.']) message.set_content('\n'.join(body)) @@ -480,11 +586,16 @@ def main(): parser.add_argument('--expected', action='append', default=[]) for key in ('max-age-hours', 'timeout', 'mail-timeout'): parser.add_argument('--' + key, type=int, required=True) + parser.add_argument('--remote-attempts', type=int, default=3) + parser.add_argument('--remote-deadline', type=int, default=3600) + parser.add_argument('--remote-retry-delay', type=int, default=30) for key in ('max-work-gb', 'min-free-gb'): parser.add_argument('--' + key, type=float, required=True) args = parser.parse_args() if not (0 <= args.max_work_gb <= 100000 and 0 <= args.min_free_gb <= 100000 and - 1 <= args.max_age_hours <= 8760 and 1 <= args.timeout <= 86400 and 1 <= args.mail_timeout <= 300): + 1 <= args.max_age_hours <= 8760 and 1 <= args.timeout <= 86400 and 1 <= args.mail_timeout <= 300 and + 1 <= args.remote_attempts <= 10 and 1 <= args.remote_deadline <= 86400 and + 0 <= args.remote_retry_delay <= 3600): parser.error('Invalid restore-test limits') if os.geteuid() != 0: parser.error('Run as root via app-restore-test.sh') @@ -549,8 +660,12 @@ def main(): test.scratch.mkdir(mode=0o700) test.execute() except Exception as exc: - test.state.update(status='FAIL', error=str(exc)) - test.log.error('Restore-test failed: %s', exc) + context = '' + if test.state['components'] and test.state['components'][-1]['status'] == 'RUNNING': + current = test.state['components'][-1] + context = f"Component {current['label']} / {current.get('phase', '?')}: " + test.state.update(status='FAIL', error=context + str(exc)) + test.log.error('Restore-test failed: %s', test.state['error']) return test.finish() diff --git a/tests/test_restore_test.py b/tests/test_restore_test.py index b9fa3f6..1f63561 100644 --- a/tests/test_restore_test.py +++ b/tests/test_restore_test.py @@ -12,6 +12,7 @@ import sys import tarfile import tempfile import time +from types import SimpleNamespace import unittest from email.parser import BytesParser from email import policy @@ -54,6 +55,7 @@ RCLONE_CONFIG="{self.crypt}" RCLONE_REMOTE_BASE="crypt:sets" RCLONE_RETRIES=1 RCLONE_LOW_LEVEL_RETRIES=1 +RCLONE_CHECK_RETRY_DELAY=0 RESTORE_TEST_MIN_FREE_GB=0 RESTORE_TEST_MAX_WORK_GB=1 RESTORE_TEST_TIMEOUT=30 @@ -154,6 +156,131 @@ MAIL_SENDMAIL_BIN="{self.sendmail}" self.assertEqual(self.state()['status'],'FAIL') self.clean() + def download_failure(self, mode, target='wordpress.tar.gz'): + # Real crypt transfers surround injected stream failures. stderr includes + # a fake credential to prove that diagnostics never copy raw messages. + wrapper = self.base/'test-rclone' + counter = self.base/'attempts' + wrapper.write_text(f'''#!/usr/bin/env python3 +import os, pathlib, subprocess, sys, time +args = sys.argv[1:] +if 'cat' in args and any(a.endswith('/' + {target!r}) for a in args): + counter = pathlib.Path({str(counter)!r}) + attempt = int(counter.read_text()) + 1 if counter.exists() else 1 + counter.write_text(str(attempt)) + assert args[args.index('--timeout')+1] == '300s', args + assert args[args.index('--low-level-retries')+1] == '3', args + mode = {mode!r} + if mode == 'signal': sys.exit(143) + if mode == 'oversize': + sys.stdout.buffer.write(b'x'*1048576) + sys.exit(0) + if mode == 'hang' or (mode == 'hang-once' and attempt == 1): + sys.stdout.buffer.write(b'partial') + sys.stdout.buffer.flush() + time.sleep(20) + if mode in ('always-fail', 'stderr-flood') or (mode == 'fail-once' and attempt == 1): + # Larger than the pipe capacity; the supervisor must drain stderr concurrently. + sys.stderr.write(('https://example.invalid/?token=SECRET-DO-NOT-LOG HTTP 503 bad magic string\\n') * (2000 if mode == 'stderr-flood' else 1)) + sys.stdout.buffer.write(b'partial') + sys.exit(5) +os.execv('/usr/bin/rclone', ['/usr/bin/rclone', *args]) +''') + wrapper.chmod(0o700) + with self.config.open('a') as f: f.write(f'RCLONE_BIN="{wrapper}"\n') + return counter + + def test_partial_download_restarts_cleanly_and_checks_real_content(self): + counter = self.download_failure('fail-once') + output = self.execute() + self.assertEqual(counter.read_text(),'2') + self.assertIn('crypt-header',output) + self.assertIn('http-503',output) + self.assertIn('exit 5',output) + self.assertNotIn('SECRET-DO-NOT-LOG',output) + self.assertEqual(self.state()['status'],'SUCCESS') + self.assertTrue(all(c['phase']=='complete' for c in self.state()['components'])) + self.clean() + + def test_partial_metadata_read_is_not_appended_on_retry(self): + counter = self.download_failure('fail-once', 'manifest.json') + self.execute() + self.assertEqual(counter.read_text(),'2') + self.assertEqual(self.state()['status'],'SUCCESS') + self.clean() + + def test_database_stderr_stays_private_with_operation_and_exit_code(self): + rehearsal = restore_test.Rehearsal(SimpleNamespace(workdir=str(self.work), mode='run', timeout=10)) + with self.assertRaises(restore_test.CommandError) as result: + rehearsal.command([sys.executable, '-c', "import sys; sys.stderr.write('SQL-SECRET'); sys.exit(2)"], + operation='Database import') + self.assertIn('Database import failed (exit 2', str(result.exception)) + self.assertNotIn('SQL-SECRET', str(result.exception)) + self.assertNotIn('SQL-SECRET', (self.root/'restore-test.log').read_text()) + self.clean() + + def test_persistent_download_error_reports_phase_and_preserves_previous_success(self): + self.execute() + previous = (self.root/'last-success.json').read_bytes() + counter = self.download_failure('always-fail') + output = self.execute(ok=False) + self.assertEqual(counter.read_text(),'3') + self.assertIn('Component wordpress / download: Remote cat failed (exit 5',output) + self.assertIn('crypt-header',self.state()['error']) + self.assertEqual((self.root/'last-success.json').read_bytes(),previous) + for path in ['state.json','restore-test.log','report.eml']: + self.assertNotIn('SECRET-DO-NOT-LOG',(self.root/path).read_text()) + self.clean() + + def test_remote_stderr_flood_does_not_deadlock_or_leak(self): + counter = self.download_failure('stderr-flood') + output = self.execute(ok=False) + self.assertEqual(counter.read_text(),'3') + self.assertIn('http-503',output) + self.assertNotIn('SECRET-DO-NOT-LOG',output) + self.assertLess(len(output),12000) + self.clean() + + def test_stalled_download_retries_from_empty_file(self): + counter = self.download_failure('hang-once') + with self.config.open('a') as f: f.write('RCLONE_CHECK_DEADLINE=2\n') + output = self.execute() + self.assertIn('deadline exceeded',output) + self.assertEqual(counter.read_text(),'2') + self.clean() + + def test_stalled_download_exhausts_attempts_and_cleans(self): + counter = self.download_failure('hang') + with self.config.open('a') as f: f.write('RCLONE_CHECK_DEADLINE=2\nRCLONE_CHECK_ATTEMPTS=2\n') + self.execute(ok=False) + self.assertEqual(counter.read_text(),'2') + self.assertIn('deadline exceeded',self.state()['error']) + self.assertEqual(self.state()['cleanup'],'OK') + self.clean() + + def test_download_signal_does_not_retry(self): + counter = self.download_failure('signal') + self.execute(ok=False) + self.assertEqual(counter.read_text(),'1') + self.assertIn('exit 143',self.state()['error']) + self.clean() + + def test_oversized_download_does_not_retry(self): + counter = self.download_failure('oversize') + self.execute(ok=False) + self.assertEqual(counter.read_text(),'1') + self.assertIn('exceeds expected size',self.state()['error']) + self.clean() + + def test_global_timeout_stops_download_retry_backoff(self): + counter = self.download_failure('always-fail') + with self.config.open('a') as f: + f.write('RESTORE_TEST_TIMEOUT=5\nRCLONE_CHECK_RETRY_DELAY=10\n') + self.execute(ok=False) + self.assertEqual(counter.read_text(),'1') + self.assertIn('time limit exceeded',self.state()['error']) + self.clean() + def test_disk_budget_refuses_work_and_cleans(self): with self.config.open('a') as f: f.write('RESTORE_TEST_MAX_WORK_GB=0.000001\n') self.execute(ok=False) diff --git a/usr-local-sbin/app-restore-test.sh b/usr-local-sbin/app-restore-test.sh index 8bc86fd..02098d3 100755 --- a/usr-local-sbin/app-restore-test.sh +++ b/usr-local-sbin/app-restore-test.sh @@ -31,6 +31,8 @@ args=("$MODE" --workdir "$WORKDIR" --prefix "$ARCHIVE_PREFIX" --remote "$RCLONE_ --run "$REMOTE_RUN" --max-age-hours "$RESTORE_TEST_MAX_AGE_HOURS" --max-work-gb "$RESTORE_TEST_MAX_WORK_GB" --min-free-gb "$RESTORE_TEST_MIN_FREE_GB" --timeout "$RESTORE_TEST_TIMEOUT" --image "$RESTORE_TEST_DB_IMAGE" + --remote-attempts "$RCLONE_CHECK_ATTEMPTS" --remote-retry-delay "$RCLONE_CHECK_RETRY_DELAY" + --remote-deadline "$RCLONE_CHECK_DEADLINE" --hostname "$MAIL_HOSTNAME" --to "$MAIL_TO" --sender "$MAIL_FROM" --sendmail "$MAIL_SENDMAIL_BIN" --mail-timeout "$MAIL_SEND_TIMEOUT" --mail "$ENABLE_MAIL_REPORT") if [[ $MODE != cleanup ]]; then