diff --git a/docs/changes.rst b/docs/changes.rst index 4df2950d0b..d10180d2e6 100644 --- a/docs/changes.rst +++ b/docs/changes.rst @@ -167,6 +167,13 @@ Version 2.0.0b24 (not released yet) Fixes: +- check: do not crash with a traceback when a repository object can not be read + (I/O error, e.g. failing disk or flaky network filesystem). The affected object + is reported, the check continues and fails at the end. Such an object is not + recorded as corrupt (a later check verifies it again), ``--repair`` refuses to + repair around it and ``--verify-data`` no longer deletes chunks it could not + read. Other commands stop with the read error instead of working with a + partially readable repository, #3509 - shell completions: complete local repository directories for ``-r`` / ``--repo`` and ``--other-repo``, #3086 - shell completions: use the command borg was invoked as, e.g. ``borg2``. A borg diff --git a/docs/usage/check.rst.inc b/docs/usage/check.rst.inc index 98e3098fca..0c6eb05019 100644 --- a/docs/usage/check.rst.inc +++ b/docs/usage/check.rst.inc @@ -190,6 +190,24 @@ packs, and, if the key must be recovered, scans chunks for it. These phases do n respond to SIGINT, so on a large repository a Ctrl-C during them may appear to have no effect until they finish. +Unreadable repository objects ++++++++++++++++++++++++++++++ + +A repository object that cannot be read at all (an I/O error from a failing disk, a +flaky network filesystem, ...) is different from a corrupt one: Borg never saw its +content, so it cannot tell whether the object is fine. Such an object is reported and +the check continues, so one run lists everything that is affected; the check then +fails. The object is not remembered as corrupt, so a later check verifies it again. + +Because the data may well be readable again once the underlying problem is fixed, +``--repair`` refuses to repair while there are unreadable objects, and +``--verify-data`` leaves chunks it could not read in place instead of deleting them. +Fix the storage hardware, filesystem or network first, then run the check again. + +Only ``borg check`` goes on like this. Other commands stop with the read error rather +than work with a partially readable repository - e.g. ``borg prune`` would otherwise +see an archive whose metadata it could not read as undated and thus as the oldest one. + About repair mode +++++++++++++++++ diff --git a/src/borg/archive.py b/src/borg/archive.py index 5c7f2f2ddc..5b3bc377d8 100644 --- a/src/borg/archive.py +++ b/src/borg/archive.py @@ -2236,6 +2236,7 @@ def verify_data(self): errors = 0 verified = 0 # chunks actually verified defect_chunks = [] + unreadable_chunks = 0 # chunks we could not even read, refs #3509 pi = ProgressIndicatorPercent( total=chunks_count, msg="Verifying data %6.2f%%", step=0.01, msgid="check.verify_data" ) @@ -2246,6 +2247,13 @@ def verify_data(self): verified += 1 try: encrypted_data = self.repository.get(chunk_id) + except Repository.StoreReadError as err: + # unreadable, not defect: we did not see the content, so we must not conclude it is + # bad and delete it - it may read fine once the hardware/fs problem is fixed, refs #3509. + self.error_found = True + errors += 1 + unreadable_chunks += 1 + logger.error("chunk %s: %s", bin_to_hex(chunk_id), err) except (Repository.ObjectNotFound, IntegrityErrorBase) as err: self.error_found = True errors += 1 @@ -2285,6 +2293,11 @@ def verify_data(self): ro_type=ROBJ_DONTCARE, assert_id_place="verify_data", ) + except Repository.StoreReadError as err: + # the retry did not fail on the content, it failed to read at all: keep the + # chunk, the read may well succeed again later, refs #3509. + unreadable_chunks += 1 + logger.error("chunk %s not deleted, could not be re-read: %s", bin_to_hex(defect_chunk), err) except IntegrityErrorBase: # failed twice -> remove this defect chunk. delete rewrites its pack without it, # keeping the other chunks. update_index=False: finish() rebuilds the index from @@ -2299,18 +2312,23 @@ def verify_data(self): logger.warning("Found defect chunks. Run with --repair to remove them.") for defect_chunk in defect_chunks: logger.debug("chunk %s is defect.", bin_to_hex(defect_chunk)) + if unreadable_chunks: + logger.error( + "%d chunk(s) could not be read and were left untouched. This usually means a hardware, " + "filesystem or network problem - fix that first, then run the check again.", + unreadable_chunks, + ) log = logger.error if errors else logger.info if sig_int: log( - "Interrupted cryptographic data integrity verification, " - "verified %d of %d chunks with %d integrity errors.", + "Interrupted cryptographic data integrity verification, verified %d of %d chunks with %d error(s).", verified, chunks_count, errors, ) else: log( - "Finished cryptographic data integrity verification, verified %d chunks with %d integrity errors.", + "Finished cryptographic data integrity verification, verified %d chunks with %d error(s).", verified, errors, ) @@ -2352,23 +2370,33 @@ def valid_archive(obj): if sig_int: break pi.show() - cdata = self.repository.get(chunk_id, read_data=False) # only get metadata try: + cdata = self.repository.get(chunk_id, read_data=False) # only get metadata meta = self.repo_objs.parse_meta(chunk_id, cdata, ro_type=ROBJ_DONTCARE) except IntegrityErrorBase as exc: logger.error("Skipping corrupted chunk: %s", exc) self.error_found = True continue + except Repository.StoreReadError as exc: + # unreadable, not corrupt: this scan only looks for archive metadata, so skipping + # such a chunk can at worst miss a lost archive - it never drops data, refs #3509. + logger.error("Skipping unreadable chunk: %s", exc) + self.error_found = True + continue if meta["type"] != ROBJ_ARCHIVE_META: continue # now we know it is an archive metadata chunk, load the full object from the repo: - cdata = self.repository.get(chunk_id) try: + cdata = self.repository.get(chunk_id) meta, data = self.repo_objs.parse(chunk_id, cdata, ro_type=ROBJ_DONTCARE) except IntegrityErrorBase as exc: logger.error("Skipping corrupted chunk: %s", exc) self.error_found = True continue + except Repository.StoreReadError as exc: + logger.error("Skipping unreadable chunk: %s", exc) + self.error_found = True + continue if meta["type"] != ROBJ_ARCHIVE_META: continue # should never happen try: @@ -2578,6 +2606,9 @@ def valid_item(obj): newest=newest, older=older, newer=newer, + # an archive whose metadata we can not read gets a placeholder entry here, so the + # other archives still get checked; the loop below reports it, refs #3509. + tolerate_read_errors=True, ) if match and not archive_infos: logger.warning("--match-archives %s does not match any archives", match) @@ -2586,7 +2617,7 @@ def valid_item(obj): if last and len(archive_infos) < last: logger.warning("--last %d archives: only found %d archives", last, len(archive_infos)) else: - archive_infos = self.manifest.archives.list(sort_by=sort_by) + archive_infos = self.manifest.archives.list(sort_by=sort_by, tolerate_read_errors=True) num_archives = len(archive_infos) formatter = ArchiveFormatter(self.format, self.repository, self.manifest, self.key) @@ -2605,9 +2636,10 @@ def valid_item(obj): archive_id, archive_id_hex = info.id, bin_to_hex(info.id) try: formatted = formatter.format_item(info, jsonline=False) - except (Archive.DoesNotExist, Repository.ObjectNotFound, IntegrityErrorBase): - # keys like {comment} need the archive metadata, which is damaged or missing here. - # use the values from the archive directory entry, they are always available. + except (Archive.DoesNotExist, Repository.ObjectNotFound, IntegrityErrorBase, Repository.StoreReadError): + # keys like {comment} need the archive metadata, which is damaged, missing or + # unreadable here. use the values from the archive directory entry, they are + # always available. formatted = f"{info.name} {OutputTimestamp(info.ts)} {archive_id_hex}" logger.info(f"Analyzing archive {formatted} ({i + 1}/{num_archives})") if archive_id not in self.chunks: @@ -2619,9 +2651,17 @@ def valid_item(obj): else: logger.error(f"Would delete broken archive {info.name} {archive_id_hex}.") continue - cdata = self.repository.get(archive_id) try: + cdata = self.repository.get(archive_id) _, data = self.repo_objs.parse(archive_id, cdata, ro_type=ROBJ_ARCHIVE_META) + except Repository.StoreReadError as err: + # unreadable, not corrupt: we did not see the metadata, so we can not tell + # whether this archive is fine - and must not "repair" it away, refs #3509. + logger.error(f"Archive metadata block {archive_id_hex} could not be read: {err}") + self.error_found = True + if self.repair: + raise + continue except IntegrityErrorBase as integrity_error: logger.error(f"Archive metadata block {archive_id_hex} is corrupted: {integrity_error}") self.error_found = True @@ -2637,10 +2677,19 @@ def valid_item(obj): raise Exception("Unknown archive metadata version") items_buffer = ChunkBuffer(self.key) items_buffer.write_chunk = add_callback - for item in robust_iterator(archive): - if "chunks" in item: - verify_file_chunks(info.name, item) - items_buffer.add(item) + try: + for item in robust_iterator(archive): + if "chunks" in item: + verify_file_chunks(info.name, item) + items_buffer.add(item) + except Repository.StoreReadError as err: + # part of the item metadata stream could not be read (see above): rewriting the + # archive from what we did read would drop the rest of it, refs #3509. + logger.error(f"Archive {info.name} {archive_id_hex} could not be read fully: {err}") + self.error_found = True + if self.repair: + raise + continue items_buffer.flush(flush=True) if self.repair: archive.item_ptrs = archive_put_items( diff --git a/src/borg/archiver/check_cmd.py b/src/borg/archiver/check_cmd.py index d6aedb8517..2b751e44a1 100644 --- a/src/borg/archiver/check_cmd.py +++ b/src/borg/archiver/check_cmd.py @@ -204,6 +204,24 @@ def build_parser_check(self, subparsers, common_parser, mid_common_parser): respond to SIGINT, so on a large repository a Ctrl-C during them may appear to have no effect until they finish. + Unreadable repository objects + +++++++++++++++++++++++++++++ + + A repository object that cannot be read at all (an I/O error from a failing disk, a + flaky network filesystem, ...) is different from a corrupt one: Borg never saw its + content, so it cannot tell whether the object is fine. Such an object is reported and + the check continues, so one run lists everything that is affected; the check then + fails. The object is not remembered as corrupt, so a later check verifies it again. + + Because the data may well be readable again once the underlying problem is fixed, + ``--repair`` refuses to repair while there are unreadable objects, and + ``--verify-data`` leaves chunks it could not read in place instead of deleting them. + Fix the storage hardware, filesystem or network first, then run the check again. + + Only ``borg check`` goes on like this. Other commands stop with the read error rather + than work with a partially readable repository - e.g. ``borg prune`` would otherwise + see an archive whose metadata it could not read as undated and thus as the oldest one. + About repair mode +++++++++++++++++ diff --git a/src/borg/cache.py b/src/borg/cache.py index c49277d745..615b9f9356 100644 --- a/src/borg/cache.py +++ b/src/borg/cache.py @@ -891,12 +891,17 @@ def build_chunkindex_from_repo( break chunks = ChunkIndex() # we'll merge all fragments into this complete = True - corrupt_fragment = None + unusable_fragment = None # message about a fragment that is corrupt or could not be read for hash in hashes: try: chunks_to_merge = read_chunkindex_from_repo(repository, hash) except CorruptChunkIndexFragment as err: - corrupt_fragment = err + unusable_fragment = f"{err} is corrupt" + break + except Repository.StoreReadError as err: + # the fragment could not be read (I/O error, refs #3509). retrying would just hit + # the same error, so give up on the fragments and rebuild from the packs instead. + unusable_fragment = f"chunk index fragment {hash} could not be read: {err}" break if chunks_to_merge is None: logger.debug(f"chunk index fragment {hash} vanished, restarting the merge...") @@ -906,13 +911,13 @@ def build_chunkindex_from_repo( for k, v in chunks_to_merge.items(): chunks[k] = v chunks_to_merge.clear() - if corrupt_fragment is not None: - # retrying would re-read the same corrupt fragment; rebuild the whole index from + if unusable_fragment is not None: + # retrying would re-read the same unusable fragment; rebuild the whole index from # the packs instead (or return None in fragments_only mode). chunks.clear() if fragments_only: return None - logger.warning(f"{corrupt_fragment} is corrupt, rebuilding the chunk index from the packs.") + logger.warning(f"{unusable_fragment}, rebuilding the chunk index from the packs.") break if complete: if len(hashes) > 1 and write_immediately: diff --git a/src/borg/manifest.py b/src/borg/manifest.py index d25070d8f4..5d0f04cee7 100644 --- a/src/borg/manifest.py +++ b/src/borg/manifest.py @@ -151,12 +151,28 @@ def ids(self, *, deleted=False): info = ItemInfo(*info) # RPC does not give us a NamedTuple yield hex_to_bin(info.name) - def _get_archive_meta(self, id: bytes) -> dict: + def _get_archive_meta(self, id: bytes, *, tolerate_read_errors: bool = False) -> dict: # get all metadata directly from the ArchiveItem in the repo. from .repository import Repository try: cdata = self.repository.get(id) + except Repository.StoreReadError: + # the archive metadata could not be read at all (I/O error, refs #3509). only borg check + # opts into a placeholder here, so it can go on and check the other archives. everybody + # else must not act on a repository it can not fully read: the placeholder's 1970 + # timestamp would e.g. make prune treat the archive as the oldest one. + if not tolerate_read_errors: + raise + metadata = dict( + id=id, + name="archive-metadata-could-not-be-read", + time="1970-01-01T00:00:00.000000", + exists=False, # we have the pointer, but we could not read the archive item + username="", + hostname="", + tags=(), + ) except Repository.ObjectNotFound: metadata = dict( id=id, @@ -201,13 +217,13 @@ def _get_archive_meta(self, id: bytes) -> dict: ) return metadata - def _infos(self, *, deleted=False): + def _infos(self, *, deleted=False, tolerate_read_errors=False): # yield the infos of all archives for id in self.ids(deleted=deleted): - yield self._get_archive_meta(id) + yield self._get_archive_meta(id, tolerate_read_errors=tolerate_read_errors) - def _info_tuples(self, *, deleted=False): - for info in self._infos(deleted=deleted): + def _info_tuples(self, *, deleted=False, tolerate_read_errors=False): + for info in self._infos(deleted=deleted, tolerate_read_errors=tolerate_read_errors): yield ArchiveInfo( name=info["name"], id=info["id"], @@ -217,8 +233,8 @@ def _info_tuples(self, *, deleted=False): host=info["hostname"], ) - def _matching_info_tuples(self, match_patterns, match_end, *, deleted=False): - archive_infos = list(self._info_tuples(deleted=deleted)) + def _matching_info_tuples(self, match_patterns, match_end, *, deleted=False, tolerate_read_errors=False): + archive_infos = list(self._info_tuples(deleted=deleted, tolerate_read_errors=tolerate_read_errors)) if match_patterns: assert isinstance(match_patterns, list), f"match_pattern is a {type(match_patterns)}" for match in match_patterns: @@ -376,6 +392,7 @@ def list( oldest=None, newest=None, deleted=False, + tolerate_read_errors=False, ): """ Return list of ArchiveInfo instances according to the parameters. @@ -397,7 +414,9 @@ def list( if isinstance(sort_by, (str, bytes)): raise TypeError("sort_by must be a sequence of str") - archive_infos = self._matching_info_tuples(match, match_end, deleted=deleted) + archive_infos = self._matching_info_tuples( + match, match_end, deleted=deleted, tolerate_read_errors=tolerate_read_errors + ) if any([oldest, newest, older, newer]): archive_infos = filter_archives_by_date( diff --git a/src/borg/repository.py b/src/borg/repository.py index a007f7561f..47304c7237 100644 --- a/src/borg/repository.py +++ b/src/borg/repository.py @@ -359,13 +359,22 @@ def read(self, offset, size): # in-memory pack: return a memoryview into pack_contents. store: range-read bytes. if self.pack_contents is not None: return memoryview(self.pack_contents)[offset : offset + size] - return self.store.load(self.key, offset=offset, size=size) + try: + return self.store.load(self.key, offset=offset, size=size) + except OSError as exc: + # the pack exists, but reading it failed (bad disk, flaky network fs, ...). that is + # neither "object missing" nor "content corrupt", so it gets its own error class: + # callers must not react to it by dropping data, refs #3509. + raise Repository.StoreReadError(f"pack {bin_to_hex(self.pack_id)}", exc) from exc def size(self): """Return the pack size in bytes; for a store-backed pack this is one metadata lookup.""" if self.pack_contents is not None: return len(self.pack_contents) - return self.store.info(self.key).size + try: + return self.store.info(self.key).size + except OSError as exc: + raise Repository.StoreReadError(f"pack {bin_to_hex(self.pack_id)}", exc) from exc def iter_headers(self): """Yield (chunk_id, offset, size) for each object by walking the fixed object headers. @@ -656,6 +665,18 @@ class PermissionDenied(Error): exit_mcode = 24 + class RepairUnsafe(Error): + """Not repairing: {} repository object(s) could not be read. Fix the underlying problem, then check again.""" + + exit_mcode = 26 + + class StoreReadError(Error): + """Error reading {} from the repository: {}. Check the storage hardware / filesystem.""" + + exit_mcode = 25 + + # the underlying I/O error (bad disk, flaky network fs, ...) is kept as __cause__, refs #3509. + # Whole packs kept in memory for reads; the least recently used is evicted first. # Memory use is this count times the pack size. PACK_READER_CACHE_SIZE = 3 @@ -1033,12 +1054,19 @@ def check(self, repair=False, max_duration=0, max_age=0, repo_only=False): """ def verify(namespace, name): + """Return True if the object is intact, False if it is corrupt, None if it could not be read.""" # name is the sha256 of the object's content, so it is intact iff store.hash() matches. key = f"{namespace}/{name}" try: ok = self.store.hash(key) == name except StoreObjectNotFound: return True # vanished since store.list(); not an error + except OSError as exc: + # reading failed (bad disk, flaky network fs, ...), so we do not know whether the + # object is intact. report it and go on: one unreadable object must not abort the + # whole check, and the result must not be recorded as "corrupt", refs #3509. + logger.error(f"Store object {key} could not be read: {exc}") + return None if not ok: logger.error(f"Store object {key} is corrupted: content does not match its name (sha256).") return ok @@ -1048,6 +1076,10 @@ def store_list(namespace): return list(self.store.list(namespace)) except StoreObjectNotFound: return [] # namespace does not exist + except OSError as exc: + # without a listing we do not know what to check, so this one is fatal - but it + # ends the check with a clear message instead of a traceback, refs #3509. + raise self.StoreReadError(f"the {namespace}/ listing", exc) from exc partial = bool(max_duration) assert not (repair and partial) @@ -1068,6 +1100,9 @@ def store_list(namespace): t_last_checkpoint = t_start index_files = index_errors = 0 pack_files = pack_errors = pack_skipped = 0 + # objects that could not be read at all (I/O errors, refs #3509) - counted apart from + # corruption: "unreadable" is a different diagnosis and is often transient/fixable. + read_errors = 0 missing_pack_ids = [] # packs referenced by the index but absent from packs/ (refs #9898) index_repaired = False packs_scanned = False @@ -1087,7 +1122,10 @@ def store_list(namespace): self._lock_refresh() index_pi.show(increase=1) index_files += 1 - if not verify("index", info.name): + result = verify("index", info.name) + if result is None: + read_errors += 1 + elif not result: index_errors += 1 if index_infos: index_pi.show(current=len(index_infos)) # finish at 100% @@ -1173,9 +1211,14 @@ def recorded_ts(info): continue pack_files += 1 ok = verify("packs", info.name) - if not ok: - pack_errors += 1 - tracker.record(pack_id, ok) + if ok is None: + # unreadable: we did not learn anything about this pack, so do not record a + # result for it - a later check re-verifies it (unrecorded packs come first). + read_errors += 1 + else: + if not ok: + pack_errors += 1 + tracker.record(pack_id, ok) now = time.monotonic() # a checkpoint rewrites the whole table (41 bytes per pack), so keep the interval long. if now > t_last_checkpoint + 30 * 60: @@ -1194,7 +1237,9 @@ def recorded_ts(info): # rebuild only if the index was the sole problem and every pack was verified intact this # run: sig_int breaks the loop early, so "no pack errors" must be paired with "all packs # scanned" (pack_files == len(pack_infos)) to not rebuild from unverified packs. - if index_errors and pack_errors == 0 and not sig_int and pack_files == len(pack_infos): + # read_errors == 0 for the same reason: an unreadable pack was not verified either, and + # rebuilding the index from packs we could not read would drop their chunks, refs #3509. + if index_errors and pack_errors == 0 and read_errors == 0 and not sig_int and pack_files == len(pack_infos): # the exclusive check lock keeps the pack set fixed, so re-listing packs/ inside # build_chunkindex_from_repo matches this verification. write_immediately persists the # index and drops the corrupt fragments. @@ -1211,6 +1256,13 @@ def recorded_ts(info): if pack_skipped: summary += f" Reused {pack_skipped} recent pack check result(s)." logger.info(summary) + if read_errors: + logger.error( + f"{read_errors} store object(s) could not be read, so they could not be checked. " + "This usually means a hardware, filesystem or network problem - see the " + '"Data integrity" section of the docs. The repository was not modified; fix the ' + "underlying problem, then run the check again." + ) if missing_pack_ids: # one id per line (the list can be long). logger.error(f"{len(missing_pack_ids)} pack(s) referenced by the index are missing:") @@ -1230,14 +1282,17 @@ def recorded_ts(info): logger.error(f"Found {len(corrupt_ids)} corrupt pack(s):") for pack_id in corrupt_ids: logger.error(f"Corrupt pack: {bin_to_hex(pack_id)}") - # fail if this run found errors, or any pack is recorded corrupt. - problems = objs_errors != 0 or bool(corrupt_ids) + # fail if this run found errors or could not read some objects, or any pack is recorded corrupt. + problems = objs_errors != 0 or read_errors != 0 or bool(corrupt_ids) # On Ctrl-C the check stopped early, so the summary only covers the packs seen so far. done, so_far = ("Interrupted", " so far") if sig_int else ("Finished", "") if not problems: logger.info(f"{done} {mode} repository check, no problems found{so_far}.") elif not repair: logger.error(f"{done} {mode} repository check, errors found{so_far}.") + elif read_errors: + # repair mode, but unreadable objects stop us below - so report like a read-only check. + logger.error(f"{done} {mode} repository check, errors found{so_far}.") elif index_repaired and not (pack_errors or corrupt_ids or missing_pack_ids): # the index was the only problem and it has been rebuilt from the packs. logger.info(f"{done} {mode} repository check, repaired{so_far}.") @@ -1263,6 +1318,10 @@ def recorded_ts(info): if repair: if index_errors and not index_repaired: return False + if read_errors: + # we do not know what is in those objects, so repairing around them could throw away + # data that reads fine again once the underlying problem is fixed, refs #3509. + raise self.RepairUnsafe(read_errors) return not (repo_only and (pack_errors or corrupt_ids or missing_pack_ids)) return not problems @@ -1355,7 +1414,11 @@ def _cached_pack_reader(self, pack_id): reader = self._pack_cache.get(pack_id) if reader is None: key = "packs/" + bin_to_hex(pack_id) - reader = PackReader(pack_id=pack_id, pack_contents=self.store.load(key)) + try: + pack_contents = self.store.load(key) + except OSError as exc: + raise self.StoreReadError(f"pack {bin_to_hex(pack_id)}", exc) from exc + reader = PackReader(pack_id=pack_id, pack_contents=pack_contents) self._pack_cache[pack_id] = reader return reader @@ -1380,6 +1443,7 @@ def get_many(self, ids, read_data=True, raise_missing=True): raise self.PackNotFound(id_, entry.pack_id, str(self._location)) from None yield None else: + # the pack is in memory here, so read() only slices it and can not raise OSError. yield reader.read(entry.obj_offset, entry.obj_size) def put(self, id, data): @@ -1757,10 +1821,15 @@ def store_list(self, name, *, deleted=False): return list(self.store.list(name, deleted=deleted)) except StoreObjectNotFound: return [] + except OSError as exc: + raise self.StoreReadError(f"the {name}/ listing", exc) from exc def store_load(self, name, *, size=None, offset=0): self._lock_refresh() - return self.store.load(name, size=size, offset=offset) + try: + return self.store.load(name, size=size, offset=offset) + except OSError as exc: + raise self.StoreReadError(name, exc) from exc def store_store(self, name, value): self._lock_refresh() diff --git a/src/borg/testsuite/archiver/check_cmd_test.py b/src/borg/testsuite/archiver/check_cmd_test.py index 34a9ee5cb3..19d5300c31 100644 --- a/src/borg/testsuite/archiver/check_cmd_test.py +++ b/src/borg/testsuite/archiver/check_cmd_test.py @@ -1,4 +1,5 @@ from datetime import datetime, timezone, timedelta +import errno from pathlib import Path import re import shutil @@ -8,7 +9,7 @@ from ...archive import ArchiveChecker, ChunkBuffer from ...constants import * # NOQA -from ...helpers import bin_to_hex, msgpack, CommandError, Error, IntegrityError, sig_int +from ...helpers import bin_to_hex, hex_to_bin, msgpack, CommandError, Error, IntegrityError, sig_int from ...manifest import Archives, Manifest from ...repository import PackTracker, Repository from ..repository_test import fchunk, corrupt_chunk_on_disk @@ -894,3 +895,329 @@ def test_empty_repository(archivers, request): for info in repository.store_list("packs"): repository.store_delete("packs/" + info.name) cmd(archiver, "check", exit_code=1) + + +def make_store_reads_fail(monkeypatch, should_fail, *, after=0): + """Make matching posixfs reads fail with an OSError, like failing storage does. + + should_fail(name, offset, size) decides per read; offset/size are None for the operations that + do not take a range (hash, info, list). The first matching reads still succeed, which + models storage that starts failing (or fails only sometimes) rather than being dead from the + start. + + Patches the backend rather than using file permissions, so this also works when the tests run + as root and does not depend on the platform's permission semantics. Returns a dict whose + "failing" entry switches the failures off again (monkeypatch.undo() must not be used here, it + would also revert the autouse clean_env fixture). + """ + from borgstore.backends.posixfs import PosixFS + + state = {"failing": True, "hits": 0} + orig = {name: getattr(PosixFS, name) for name in ("hash", "load", "info", "list")} + + def check(name, offset=None, size=None): + if not (state["failing"] and should_fail(name, offset, size)): + return + state["hits"] += 1 + if state["hits"] > after: + raise OSError(errno.EIO, "Input/output error", name) + + def failing_hash(self, name, algorithm="sha256"): + check(name) + return orig["hash"](self, name, algorithm=algorithm) + + def failing_load(self, name, *, size=None, offset=0): + check(name, offset, size) + return orig["load"](self, name, size=size, offset=offset) + + def failing_info(self, name): + check(name) + return orig["info"](self, name) + + def failing_list(self, name): + check(name) + return orig["list"](self, name) + + monkeypatch.setattr(PosixFS, "hash", failing_hash) + monkeypatch.setattr(PosixFS, "load", failing_load) + monkeypatch.setattr(PosixFS, "info", failing_info) + monkeypatch.setattr(PosixFS, "list", failing_list) + return state + + +def object_name(name): + """Return the object's own name, without the nesting levels borgstore puts in front of it.""" + # the backend gets the name including those levels, e.g. packs/d0/d0a6... for packs/d0a6... + return name.rsplit("/", 1)[-1] + + +def make_pack_unreadable(monkeypatch, pack_name): + """Make every read of the pack packs/ fail.""" + return make_store_reads_fail(monkeypatch, lambda name, offset, size: object_name(name) == pack_name) + + +def make_namespace_listing_fail(monkeypatch, namespace): + """Make listing the given store namespace fail.""" + return make_store_reads_fail(monkeypatch, lambda name, offset, size: name.split("/")[0] == namespace) + + +def some_pack_name(archiver): + """Return the name of one of the repository's pack files.""" + with Repository(archiver.repository_location, exclusive=True) as repository: + return sorted(info.name for info in repository.store_list("packs"))[0] + + +def pack_name_of(archiver, chunk_id): + """Return the name of the pack file holding chunk_id.""" + with Repository(archiver.repository_location, exclusive=True) as repository: + return bin_to_hex(repository.chunks[chunk_id].pack_id) + + +def file_content_chunk_id(archiver, archive_name="archive1"): + """Return the id of a file content chunk of the given archive.""" + archive, repository = open_archive(archiver.repository_path, archive_name) + with repository: + for item in archive.iter_items(): + if item.path.endswith(src_file): + return item.chunks[-1].id + raise AssertionError(f"{src_file} not found in {archive_name}") + + +def test_check_unreadable_pack(archivers, request, monkeypatch): + # an I/O error while reading a pack must not crash the check with a traceback: it is reported, + # the check goes on and fails at the end, refs #3509. + archiver = request.getfixturevalue(archivers) + if archiver.get_kind() != "local": + pytest.skip("only works locally, patches objects") + check_cmd_setup(archiver) + cmd(archiver, "check", exit_code=0) + pack_name = some_pack_name(archiver) + make_pack_unreadable(monkeypatch, pack_name) + + output = cmd(archiver, "check", "-v", "--repository-only", exit_code=1) + assert f"Store object packs/{pack_name} could not be read" in output + assert "Input/output error" in output + # the check did not stop at the unreadable pack ... + assert "Finished checking packs." in output + assert "store object(s) could not be read" in output + # ... and it did not claim the pack is corrupt (we never saw its content). + assert "is corrupted" not in output + assert "Corrupt pack" not in output + + +def test_check_unreadable_pack_not_recorded(archivers, request, monkeypatch): + # a pack we could not read gets no result recorded, so a later check verifies it again instead + # of remembering it as corrupt, refs #3509. + archiver = request.getfixturevalue(archivers) + if archiver.get_kind() != "local": + pytest.skip("only works locally, patches objects") + check_cmd_setup(archiver) + pack_name = some_pack_name(archiver) + state = make_pack_unreadable(monkeypatch, pack_name) + cmd(archiver, "check", "--repository-only", exit_code=1) + with Repository(archiver.repository_location, exclusive=True) as repository: + tracker = PackTracker.load(repository.store) + assert tracker.get(hex_to_bin(pack_name)) is None + assert tracker.corrupt_ids() == [] + # once the pack reads fine again, the check passes without any manual cleanup. + state["failing"] = False + cmd(archiver, "check", exit_code=0) + + +def test_check_repair_refuses_unreadable_pack(archivers, request, monkeypatch): + # --repair must not repair around an unreadable pack: its chunks may well be readable again + # once the underlying problem is fixed, refs #3509. + archiver = request.getfixturevalue(archivers) + if archiver.get_kind() != "local": + pytest.skip("only works locally, patches objects") + check_cmd_setup(archiver) + pack_name = some_pack_name(archiver) + make_pack_unreadable(monkeypatch, pack_name) + with pytest.raises(Repository.RepairUnsafe): # local (not forked): the Error propagates + cmd(archiver, "check", "--repair") + + +def test_check_verify_data_unreadable_pack_keeps_chunks(archivers, request, monkeypatch): + # --verify-data deletes chunks whose content is defect, but must keep chunks it could not read + # at all, refs #3509. + archiver = request.getfixturevalue(archivers) + if archiver.get_kind() != "local": + pytest.skip("only works locally, patches objects") + check_cmd_setup(archiver) + # target the pack holding file content, so --verify-data is what reads it. + pack_name = pack_name_of(archiver, file_content_chunk_id(archiver)) + with Repository(archiver.repository_location, exclusive=True) as repository: + chunks_before = sorted(chunk_id for chunk_id, _ in repository.chunks.iteritems()) + state = make_pack_unreadable(monkeypatch, pack_name) + + output = cmd(archiver, "check", "--archives-only", "--verify-data", exit_code=1) + assert "could not be read and were left untouched" in output + + state["failing"] = False + with Repository(archiver.repository_location, exclusive=True) as repository: + chunks_after = sorted(chunk_id for chunk_id, _ in repository.chunks.iteritems()) + assert chunks_after == chunks_before # nothing was thrown away + + +def test_check_unreadable_archive_metadata_pack(archivers, request, monkeypatch): + # the pack holding an archive's metadata is unreadable: listing the archives must not die, the + # affected archive is reported and the other archives still get checked, refs #3509. + archiver = request.getfixturevalue(archivers) + if archiver.get_kind() != "local": + pytest.skip("only works locally, patches objects") + check_cmd_setup(archiver) + archive, repository = open_archive(archiver.repository_path, "archive1") + with repository: + archive_id = archive.id + pack_name = pack_name_of(archiver, archive_id) + make_pack_unreadable(monkeypatch, pack_name) + + output = cmd(archiver, "check", "--archives-only", exit_code=1) + assert f"Archive metadata block {bin_to_hex(archive_id)} could not be read" in output + assert "Input/output error" in output + assert "Archive consistency check complete, problems found." in output + + +def test_unreadable_archive_metadata_pack_does_not_fake_an_archive(archivers, request, monkeypatch): + # outside of borg check, an unreadable archive metadata object must not turn into a placeholder + # entry: acting on a repository we can not fully read (e.g. prune, which would see the + # placeholder's 1970 timestamp) is how transient I/O errors become data loss, refs #3509. + archiver = request.getfixturevalue(archivers) + if archiver.get_kind() != "local": + pytest.skip("only works locally, patches objects") + check_cmd_setup(archiver) + archive, repository = open_archive(archiver.repository_path, "archive1") + with repository: + archive_id = archive.id + make_pack_unreadable(monkeypatch, pack_name_of(archiver, archive_id)) + with pytest.raises(Repository.StoreReadError): # local (not forked): the Error propagates + cmd(archiver, "repo-list") + + +def test_check_unreadable_packs_listing(archivers, request, monkeypatch): + # without a listing we do not know what to check, so this one is fatal - but it must end the + # check with a clear message instead of a traceback, refs #3509. + archiver = request.getfixturevalue(archivers) + if archiver.get_kind() != "local": + pytest.skip("only works locally, patches objects") + check_cmd_setup(archiver) + make_namespace_listing_fail(monkeypatch, "packs") + with pytest.raises(Repository.StoreReadError): # local (not forked): the Error propagates + cmd(archiver, "check", "--repository-only") + + +def test_check_unreadable_index_object(archivers, request, monkeypatch): + # an unreadable index object is reported and the check goes on to the packs. the missing-pack + # cross-check needs the index too, so it is skipped rather than reporting bogus results, #3509. + archiver = request.getfixturevalue(archivers) + if archiver.get_kind() != "local": + pytest.skip("only works locally, patches objects") + check_cmd_setup(archiver) + with Repository(archiver.repository_location, exclusive=True) as repository: + index_name = sorted(info.name for info in repository.store_list("index"))[0] + make_store_reads_fail(monkeypatch, lambda name, offset, size: object_name(name) == index_name) + + output = cmd(archiver, "check", "-v", "--repository-only", exit_code=1) + assert f"Store object index/{index_name} could not be read" in output + assert "skipping missing-pack detection" in output + assert "Finished checking packs." in output # the packs were checked anyway + assert "store object(s) could not be read" in output + + +def test_check_repair_unreadable_pack_aborts_index_rebuild(archivers, request, monkeypatch): + # --repair rebuilds the chunk index from the packs' object headers. an unreadable pack stops + # that with a clear error: an index rebuilt without its objects would drop them, refs #3509. + archiver = request.getfixturevalue(archivers) + if archiver.get_kind() != "local": + pytest.skip("only works locally, patches objects") + check_cmd_setup(archiver) + make_pack_unreadable(monkeypatch, some_pack_name(archiver)) + with pytest.raises(Repository.StoreReadError): # local (not forked): the Error propagates + cmd(archiver, "check", "--archives-only", "--repair") + + +def test_verify_data_repair_keeps_a_chunk_that_fails_to_re_read(archivers, request, monkeypatch): + # --verify-data --repair deletes a chunk only after its content failed to verify twice. if the + # second read fails outright, we did not see the content again, so the chunk must stay: this is + # exactly how a flaky disk would otherwise talk borg into throwing data away, refs #3509. + archiver = request.getfixturevalue(archivers) + if archiver.get_kind() != "local": + pytest.skip("only works locally, patches objects") + check_cmd_setup(archiver) + chunk_id = file_content_chunk_id(archiver) + with Repository(archiver.repository_location, exclusive=True) as repository: + entry = repository.chunks[chunk_id] + corrupt_chunk_on_disk(repository, chunk_id) + pack_name = bin_to_hex(entry.pack_id) + # fail reads of exactly this object, and only from the second one on (a bad spot in the pack + # that the first read still got through): the first read returns the corrupted content, so the + # chunk lands in the defect list, and the re-read that would confirm it fails. matching on the + # object's full range leaves the pack's header scan (a short read at the same offset) working, + # so rebuilding the chunk index from the packs still succeeds. + make_store_reads_fail( + monkeypatch, + lambda name, offset, size: ( + object_name(name) == pack_name and offset == entry.obj_offset and size == entry.obj_size + ), + after=1, + ) + + output = cmd(archiver, "check", "--repair", "--verify-data", "--archives-only", exit_code=0) + assert "not deleted, could not be re-read" in output + with Repository(archiver.repository_location, exclusive=True) as repository: + assert chunk_id in repository.chunks # the chunk is still there + + +def test_find_lost_archives_skips_unreadable_chunk(archivers, request, monkeypatch): + # the --find-lost-archives scan only looks for archive metadata, so skipping an unreadable + # chunk can at worst miss a lost archive - it never drops data, refs #3509. + archiver = request.getfixturevalue(archivers) + if archiver.get_kind() != "local": + pytest.skip("only works locally, patches objects") + check_cmd_setup(archiver) + make_pack_unreadable(monkeypatch, pack_name_of(archiver, file_content_chunk_id(archiver))) + + output = cmd(archiver, "check", "--archives-only", "--find-lost-archives", exit_code=1) + assert "Skipping unreadable chunk" in output + + +def test_unreadable_archives_listing_is_not_an_empty_repository(archivers, request, monkeypatch): + # a namespace listing that fails must not look like "the namespace is empty" - that would make + # e.g. repo-list report a repository with no archives at all, refs #3509. + archiver = request.getfixturevalue(archivers) + if archiver.get_kind() != "local": + pytest.skip("only works locally, patches objects") + check_cmd_setup(archiver) + make_namespace_listing_fail(monkeypatch, "archives") + with pytest.raises(Repository.StoreReadError): # local (not forked): the Error propagates + cmd(archiver, "repo-list") + + +def test_check_repair_stops_at_unreadable_archive_metadata(archivers, request, monkeypatch): + # a bad spot inside an otherwise readable pack: the chunk index still rebuilds from the pack's + # headers, so --repair gets as far as the archive itself - and must stop there rather than + # rewrite the archive around metadata it never read, refs #3509. + archiver = request.getfixturevalue(archivers) + if archiver.get_kind() != "local": + pytest.skip("only works locally, patches objects") + check_cmd_setup(archiver) + archive, repository = open_archive(archiver.repository_path, "archive1") + with repository: + archive_id = archive.id + entry = repository.chunks[archive_id] + pack_name = bin_to_hex(entry.pack_id) + # fail reads of the archive metadata object only; the short header reads at the same offset + # (and every other object in the pack) keep working. + state = make_store_reads_fail( + monkeypatch, + lambda name, offset, size: ( + object_name(name) == pack_name and offset == entry.obj_offset and size == entry.obj_size + ), + ) + with pytest.raises(Repository.StoreReadError): # local (not forked): the Error propagates + cmd(archiver, "check", "--archives-only", "--repair") + + # the archive is untouched: once it reads again, it is still there and still checks out. + state["failing"] = False + assert "archive1" in cmd(archiver, "repo-list") + cmd(archiver, "check", exit_code=0) diff --git a/src/borg/testsuite/archives_test.py b/src/borg/testsuite/archives_test.py index 59c4d33896..8c4ec2920e 100644 --- a/src/borg/testsuite/archives_test.py +++ b/src/borg/testsuite/archives_test.py @@ -53,13 +53,15 @@ def _archiveinfo(name, id_, ts=TS, *, username="", hostname="", tags=()): def _stub_matching_info_tuples(infos): ar, _, _ = _archives() - ar._matching_info_tuples = Mock(side_effect=lambda match_patterns, match_end, deleted=False: list(infos)) + ar._matching_info_tuples = Mock( + side_effect=lambda match_patterns, match_end, deleted=False, tolerate_read_errors=False: list(infos) + ) return ar def _stub_info_tuples(infos): ar, _, _ = _archives() - ar._info_tuples = Mock(side_effect=lambda deleted=False: iter(infos)) + ar._info_tuples = Mock(side_effect=lambda deleted=False, tolerate_read_errors=False: iter(infos)) return ar @@ -438,9 +440,9 @@ def test_list_date_filter(): def test_list_deleted_passes_flag(): ar, _, _ = _archives() - ar._info_tuples = Mock(side_effect=lambda deleted=False: iter([])) + ar._info_tuples = Mock(side_effect=lambda deleted=False, tolerate_read_errors=False: iter([])) ar.list(deleted=True) - ar._info_tuples.assert_called_once_with(deleted=True) + ar._info_tuples.assert_called_once_with(deleted=True, tolerate_read_errors=False) def test_list_match_name(): @@ -537,9 +539,10 @@ def test_get_one_multiple_matches_raises(): def test_get_one_deleted_passes_flag(): i1 = _archiveinfo("a", _id(1)) ar, _, _ = _archives() - ar._info_tuples = Mock(side_effect=lambda deleted=False: iter([i1])) + ar._info_tuples = Mock(side_effect=lambda deleted=False, tolerate_read_errors=False: iter([i1])) ar.get_one(["a"], deleted=True) - ar._info_tuples.assert_called_once_with(deleted=True) + # get_one never opts into tolerance: it must not return a placeholder for an unreadable archive. + ar._info_tuples.assert_called_once_with(deleted=True, tolerate_read_errors=False) def test_list_considering_raises_if_name_set():