borg check crashing

from irc user mlazze:

arch linux running inside virtualbox on a win10 host accessing borg repo via vboxsf (which is known-problematic). borg repo resides on host's ntfs filesystem.

this issue is not about vboxsf being unreliable, but rather about checking whether we can make borg check more robust to not crash here:

~ borg check --debug -p /mnt/z/borg/borg.repo                                                                                                                               
using builtin fallback logging configuration
35 self tests completed in 0.06 seconds
Starting repository check
Upgrading from v1 hints.31692
Rebuilding sparse info for segment 28722
Failed to read committed index ([Errno 2] No such file or directory: '/mnt/z/borg/borg.repo/data/2/28722')
Segment transaction is    31693
Determined transaction is 31693
Found 26881 segments
Local Exceptionts 93.8%
Traceback (most recent call last):
  File "/home/doc/.local/lib/python3.6/site-packages/borg/archiver.py", line 4175, in main
    exit_code = archiver.run(args)
  File "/home/doc/.local/lib/python3.6/site-packages/borg/archiver.py", line 4107, in run
    return set_ec(func(args))
  File "/home/doc/.local/lib/python3.6/site-packages/borg/archiver.py", line 150, in wrapper
    return method(self, args, repository=repository, **kwargs)
  File "/home/doc/.local/lib/python3.6/site-packages/borg/archiver.py", line 304, in do_check
    if not repository.check(repair=args.repair, save_space=args.save_space):
  File "/home/doc/.local/lib/python3.6/site-packages/borg/repository.py", line 904, in check
    objects = list(self.io.iter_objects(segment))
  File "/home/doc/.local/lib/python3.6/site-packages/borg/repository.py", line 1317, in iter_objects
    read_data=read_data)
  File "/home/doc/.local/lib/python3.6/site-packages/borg/repository.py", line 1398, in _read
    data = fd.read(length)
OSError: [Errno 71] Protocol error

Platform: Linux staskij 4.14.10-1-ARCH #1 SMP PREEMPT Fri Dec 29 20:17:35 UTC 2017 x86_64
Linux: arch
Borg: 1.1.4  Python: CPython 3.6.4
PID: 785  CWD: /home/doc
sys.argv: ['/home/doc/.local/bin/borg', 'check', '--debug', '-p', '/mnt/z/borg/borg.repo']
SSH_ORIGINAL_COMMAND: None

#2352 see also there about vboxsf.

For future reference, my problem was a faulty HDD, maybe a faulty sector, as the problem is always at the same % (93.8).

This is what I'm getting from borg check running directly on the Windows host (via WSL):

# borg check --debug -p /mnt/z/borg/borg.repo/
using builtin fallback logging configuration
35 self tests completed in 0.13 seconds
Starting repository check
Upgrading from v1 hints.31692
Rebuilding sparse info for segment 28722
Failed to read committed index ([Errno 2] No such file or directory: '/mnt/z/borg/borg.repo/data/2/28722')
Segment transaction is    31693
Determined transaction is 31693
Found 26881 segments
Local Exceptionts 93.8%
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/borg/archiver.py", line 4175, in main
    exit_code = archiver.run(args)
  File "/usr/lib/python3.6/site-packages/borg/archiver.py", line 4107, in run
    return set_ec(func(args))
  File "/usr/lib/python3.6/site-packages/borg/archiver.py", line 150, in wrapper
    return method(self, args, repository=repository, **kwargs)  File "/usr/lib/python3.6/site-packages/borg/archiver.py", line 304, in do_check
    if not repository.check(repair=args.repair, save_space=args.save_space):
  File "/usr/lib/python3.6/site-packages/borg/repository.py", line 904, in check
    objects = list(self.io.iter_objects(segment))
  File "/usr/lib/python3.6/site-packages/borg/repository.py", line 1317, in iter_objects
    read_data=read_data)
  File "/usr/lib/python3.6/site-packages/borg/repository.py", line 1398, in _read
    data = fd.read(length)
OSError: [Errno 22] Invalid argument

Platform: Linux DOC-PC 4.4.0-43-Microsoft #1-Microsoft Wed Dec 31 14:42:53 PST 2014 x86_64
Linux: arch
Borg: 1.1.4  Python: CPython 3.6.4
PID: 10  CWD: /mnt/c/Users/Doc
sys.argv: ['/usr/sbin/borg', 'check', '--debug', '-p', '/mnt/z/borg/borg.repo/']
SSH_ORIGINAL_COMMAND: None

Thanks for the help

I'm encountering the same exception:

Starting repository check
Local Exceptionts 74.0%                                                                                                                                                                                      
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/dist-packages/borg/archiver.py", line 4175, in main
    exit_code = archiver.run(args)
  File "/usr/local/lib/python3.6/dist-packages/borg/archiver.py", line 4107, in run
    return set_ec(func(args))
  File "/usr/local/lib/python3.6/dist-packages/borg/archiver.py", line 150, in wrapper
    return method(self, args, repository=repository, **kwargs)
  File "/usr/local/lib/python3.6/dist-packages/borg/archiver.py", line 304, in do_check
    if not repository.check(repair=args.repair, save_space=args.save_space):
  File "/usr/local/lib/python3.6/dist-packages/borg/repository.py", line 904, in check
    objects = list(self.io.iter_objects(segment))
  File "/usr/local/lib/python3.6/dist-packages/borg/repository.py", line 1317, in iter_objects
    read_data=read_data)
  File "/usr/local/lib/python3.6/dist-packages/borg/repository.py", line 1398, in _read
    data = fd.read(length)
OSError: [Errno 5] Input/output error

I wouldn't be surprised to find that the disk (which is quite old) has read errors, but I see no relevant issues in dmesg.

While I don't expect Borg to actually fix this, I wonder if it would be useful to catch the OSError and raise an IntegrityError with some pertinent error information such as which segment this occurred in?

For the record, I tested this using the following change to the code in question:

            try:
                data = fd.read(length)
            except OSError:
                raise IntegrityError('Segment entry data read error [segment {}, offset {}]: expected {} bytes'.format(
                    segment, offset, length))

Result:

$ borg check --info --progress --verify-data myrepo
Data integrity error: Segment entry data read error [segment 63449, offset 4354774]: expected 6803909 bytes                                                                                                  
Data integrity error: Segment entry data read error [segment 74330, offset 3553515]: expected 8421581 bytes                                                                                                  
Starting repository index check                                                                                                                                                                              
Completed repository check, errors found.

Borg correctly identifies that the segment files are partly unreadable:

$ ll 6/63449 7/74330
-rw------- 1 jonas jonas 11158692 aug 25  2017 6/63449
-rw------- 1 jonas jonas 11975105 aug 25  2017 7/74330
$ cat 6/63449 7/74330 >/dev/null
cat: 6/63449: Input/output error
cat: 7/74330: Input/output error

I haven't tried running with --repair yet as I want to try to make a copy of the full archive first.

(By the way, when you start an backup archive with a small segment size, but later switch to 200 MB segments, the progress indicator is a bit optimistic as it only counts the number of segments... but that's another issue.)

Maybe follow the hardware checking tips from our docs (recommended for IntegrityErrors, but also somehow applies to IOErrors).

TODO: check that code change, see above.

ideas:

in any case, we must not lose the information given in the original exception
in some cases it might make sense treating it like an integrity error / read error, to be able to finish the check and get the repo into a valid state
in other cases it might be better to fix the hardware / lower sw layers first and retry (instead of throwing away data that could be still read after that fix)