check: survive I/O errors while reading repository objects

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

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
 +++++++++++++++++
 

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(

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
         +++++++++++++++++
 

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:

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(