Retry restore-test downloads safely and expose bounded diagnostics

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

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()