check: survive I/O errors while reading repository objects

docs/changes.rst

@@ -197,6 +197,13 @@ Fixes:
     packs, #9443
   - --find-lost-archives reuses the archive metadata ids found by --verify-data, #8478
   - --repair rebuilds a corrupt index only once, in the archives phase, #10434
+  - 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
 - extract --continue: skip complete dirs, count skipped files in --progress, #6857
 - create: back up automounted directories, #6652
 - security: same local repo dir via another path is not a relocation, #8188

docs/internals/frontends.rst

@@ -877,6 +877,10 @@ Errors
         Repository {} needs its key to access the store object {}, but no key was set.
     Repository.LegacyRepository rc: 29 traceback: no
         {} looks like a borg 1.x repository, use --from-borg1 to access it (e.g. with borg transfer).
+    Repository.RepairUnsafe rc: 34 traceback: no
+        Not repairing: {} repository object(s) could not be read. Fix the underlying problem, then check again.
+    Repository.StoreReadError rc: 35 traceback: no
+        Error reading {} from the repository: {}. Check the storage hardware / filesystem.
 
     MandatoryFeatureUnsupported rc: 25 traceback: no
         Unsupported repository feature(s) {}. A newer version of Borg is required to access this repository.

docs/usage/check.rst.inc

@@ -210,6 +210,24 @@ would report them as lost. After a ``--repair`` that stored or deleted chunks, b
 packs the repair wrote, makes the chunk index match them and stores it; that always runs to
 completion, also after a Ctrl-C.
 
+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
 +++++++++++++++++
 

src/borg/archive.py

@@ -2607,7 +2607,8 @@ def verify_data(self):
         verified = 0  # chunks actually verified
         defect_chunks = []
         archive_meta_ids = set()
-        untrusted_pack_ids = set()  # ids of the packs that are missing or hold a defect chunk
+        untrusted_pack_ids = set()  # ids of the packs that are missing, unreadable or hold a defect chunk
+        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"
         )
@@ -2652,6 +2653,21 @@ def verify_data(self):
                 for missing_id in chunk_ids:
                     logger.debug("chunk %s: pack %s is missing.", bin_to_hex(missing_id), bin_to_hex(pack_id))
                 pi.show(increase=lost)
+            except Repository.StoreReadError as err:
+                # the pack could not be read (I/O error), and like above, get_many() raises before any chunk
+                # of this pack was read. 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
+                untrusted_pack_ids.add(pack_id)  # like a missing pack: its objects may be unreadable
+                unreadable = len(chunk_ids)
+                errors += unreadable
+                unreadable_chunks += unreadable
+                verified += unreadable  # they are not read, but they are accounted for, like a failed read
+                logger.error("%s, %d chunks could not be verified.", err, unreadable)
+                for unreadable_id in chunk_ids:
+                    logger.debug("chunk %s: pack %s could not be read.", bin_to_hex(unreadable_id), bin_to_hex(pack_id))
+                pi.show(increase=unreadable)
             # this pack is done: drop it, the cache would else keep PACK_READER_CACHE_SIZE whole packs
             # of which none is read again, and the retries below must really re-read from the store.
             self.repository.clear_pack_cache()
@@ -2684,6 +2700,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, and removes it from self.chunks, so rebuild_archives
@@ -2717,18 +2738,23 @@ def verify_data(self):
         if not sig_int:
             # the ids of an interrupted pass are incomplete.
             self.archive_meta_ids = archive_meta_ids
+        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,
             )
@@ -2818,13 +2844,19 @@ def check_archive_meta(chunk_id):
             """Load the archive metadata object chunk_id. If it has no archives directory entry, create one
             (with --repair) or log that it would create one.
             """
-            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
                 return
+            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
+                return
             if meta["type"] != ROBJ_ARCHIVE_META:
                 return  # should never happen
             try:
@@ -2879,6 +2911,11 @@ def check_archive_meta(chunk_id):
                     logger.error("Skipping corrupted chunk: %s", exc)
                     self.error_found = True
                     continue
+                except Repository.StoreReadError as exc:
+                    # see check_archive_meta.
+                    logger.error("Skipping unreadable chunk: %s", exc)
+                    self.error_found = True
+                    continue
                 if meta["type"] != ROBJ_ARCHIVE_META:
                     continue
             check_archive_meta(chunk_id)
@@ -3123,6 +3160,9 @@ def robust_item_ids():
                 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)
@@ -3131,7 +3171,7 @@ def robust_item_ids():
             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)
         if deadline is not None:
             # archives without an ok record first, then the least recently checked ones, so that
@@ -3170,10 +3210,11 @@ def check_order(info):
                     formatted = formatter.format_item(info, jsonline=False)
                     # the formatter uses defaults for keys like {comment} if it has no archive metadata.
                     metadata_missing = bool(formatter.used_call_keys) and formatter.archive is None
-                except (Repository.ObjectNotFound, IntegrityErrorBase):
+                except (Repository.ObjectNotFound, IntegrityErrorBase, Repository.StoreReadError):
                     metadata_missing = True
                 if metadata_missing:
-                    # keys like {comment} need the archive metadata, which is damaged or missing here.
+                    # 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})")
@@ -3187,9 +3228,18 @@ def check_order(info):
                         logger.error(f"Would delete broken archive {info.name} {archive_id_hex}.")
                     record_result(archive_id, found_before)
                     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.
+                    # no result is recorded for it, so a later check verifies it again.
+                    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
@@ -3207,15 +3257,24 @@ def check_order(info):
                 items_buffer = ChunkBuffer(self.key)
                 items_buffer.write_chunk = add_callback
                 complete = False
-                for item in robust_iterator(archive):
-                    if sig_int and not self.repair:
-                        # without --repair the archive is only read, so the check also stops within it.
-                        break
-                    if "chunks" in item:
-                        verify_file_chunks(info.name, item)
-                    items_buffer.add(item)
-                else:
-                    complete = True
+                try:
+                    for item in robust_iterator(archive):
+                        if sig_int and not self.repair:
+                            # without --repair the archive is only read, so the check also stops within it.
+                            break
+                        if "chunks" in item:
+                            verify_file_chunks(info.name, item)
+                        items_buffer.add(item)
+                    else:
+                        complete = True
+                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(

src/borg/archiver/check_cmd.py

@@ -300,6 +300,24 @@ def build_parser_check(self, subparsers, common_parser, mid_common_parser):
         packs the repair wrote, makes the chunk index match them and stores it; that always runs to
         completion, also after a Ctrl-C.
 
+        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
         +++++++++++++++++
 

src/borg/cache.py

@@ -907,8 +907,9 @@ def build_chunkindex_from_repo(
     # read completely, and never write to the repo.
     # write_immediately: store the index (all of it, deleting all other fragments) before returning it. The
     # callers hold an exclusive lock (borg compact, borg repo-compress, borg check --repair).
-    # a corrupt fragment raises CorruptChunkIndexFragment: a corrupt index aborts the command. Only with
-    # write_immediately (the index is rewritten anyway), the index is rebuilt from the packs instead.
+    # a corrupt fragment raises CorruptChunkIndexFragment, an unreadable one Repository.StoreReadError: an
+    # unusable index aborts the command. Only with write_immediately (the index is rewritten anyway), the
+    # index is rebuilt from the packs instead.
     # validate: a repo object validator or None, passed to PackReader.iter_headers. With a validator,
     # the rebuild skips the objects that fail it; without one, a corrupt object header raises CorruptPack.
     # on_drop: a callable or None, passed to PackReader.iter_headers, called once per byte range the
@@ -949,7 +950,7 @@ def build_chunkindex_from_repo(
                 break
             chunks = ChunkIndex()  # we'll merge all fragments into this
             complete = True
-            corrupt_fragment = None
+            unusable_fragment = None  # the error of a fragment that is corrupt or could not be read
             msgid = "cache.merge_chunkindex_fragments"
             show_percent = progress_wanted()
             if show_percent:
@@ -961,8 +962,9 @@ def build_chunkindex_from_repo(
                     pi.show()
                     try:
                         chunks_to_merge = read_chunkindex_from_repo(repository, hash)
-                    except CorruptChunkIndexFragment as err:
-                        corrupt_fragment = err
+                    except (CorruptChunkIndexFragment, Repository.StoreReadError) as err:
+                        # a corrupt fragment, or one that could not be read (I/O error, refs #3509).
+                        unusable_fragment = err
                         break
                     if chunks_to_merge is None:
                         logger.debug(f"chunk index fragment {hash} vanished, restarting the merge...")
@@ -977,13 +979,17 @@ def build_chunkindex_from_repo(
                         pi.show(current=len(hashes))  # finish at 100%
             finally:
                 pi.finish()
-            if corrupt_fragment is not None:
-                # retrying would re-read the same corrupt fragment. abort, unless the index gets rewritten
+            if unusable_fragment is not None:
+                # retrying would re-read the same unusable fragment. abort, unless the index gets rewritten
                 # anyway: then rebuild the whole index from the packs.
                 chunks.clear()
                 if not write_immediately:
-                    raise corrupt_fragment
-                logger.warning(f"{corrupt_fragment.args[0]} is corrupt, rebuilding the chunk index from the packs.")
+                    raise unusable_fragment
+                if isinstance(unusable_fragment, CorruptChunkIndexFragment):
+                    problem = f"{unusable_fragment.args[0]} is corrupt"
+                else:
+                    problem = f"chunk index fragment {hash} could not be read: {unusable_fragment}"
+                logger.warning(f"{problem}, rebuilding the chunk index from the packs.")
                 break
             if complete:
                 if len(hashes) > 1 and write_immediately: