search

borgbackup / borg

Deduplicating archiver with compression and authenticated encryption.
https://www.borgbackup.org/
Other
11.17k stars 742 forks source link

Borg Crashes with I/O Error but only as Cronjob #4076

Closed ZoidbergZulu closed 6 years ago

ZoidbergZulu commented 6 years ago

Have you checked borgbackup docs, FAQ, and open Github issues?

Yes, as far as I could

Is this a BUG / ISSUE report or a QUESTION?

Potential Issue (?)

System information. For client/server mode post info for both machines.

Server Gentoo Linux with all updates installed Linux nibbler 4.14.65-gentoo #1 SMP

Your borg version (borg -V).

borg 1.1.6

I have tried 1.1.7 and latest snapshot as well

Operating system (distribution) and version.

Gentoo Linux with Kernel 4.14.65

Hardware / network configuration, and filesystems used.

Backup on USB HDD

How much data is handled by borg?

About 1.5 TB

Full borg commandline that lead to the problem (leave away excludes and passwords)

/usr/bin/borg prune /mnt/backup/borg --keep-daily 7 --keep-weekly 8 --keep-monthly 12 --keep-yearly 2 --prefix '{hostname}-' --remote-path borg1 --umask 77 --debug --stats --list

Describe the problem you're observing.

Borg crashes with I/O Error but ONLY when run as Cron Job. Running the same script as root in the shell works perfectly fine.

As Cron Job, I get the following Error:

security: repository checks ok, allowing access
Synchronizing chunks cache...
Archives: 26, w/ cached Idx: 16, w/ outdated Idx: 0, w/o cached Idx: 10.
Reading cached archive chunk index for nibbler-documents-2017-11-30T12:42:24 ...
Local Exception
Traceback (most recent call last):
  File "/usr/lib64/python3.6/site-packages/borg/archiver.py", line 4299, in main
    exit_code = archiver.run(args)
  File "/usr/lib64/python3.6/site-packages/borg/archiver.py", line 4231, in run
    return set_ec(func(args))
  File "/usr/lib64/python3.6/site-packages/borg/archiver.py", line 151, in wrapper
    return method(self, args, repository=repository, **kwargs)
  File "/usr/lib64/python3.6/site-packages/borg/archiver.py", line 1370, in do_prune
    with Cache(repository, key, manifest, lock_wait=self.lock_wait) as cache:
  File "/usr/lib64/python3.6/site-packages/borg/cache.py", line 378, in __new__
    return local()
  File "/usr/lib64/python3.6/site-packages/borg/cache.py", line 372, in local
    lock_wait=lock_wait, cache_mode=cache_mode)
  File "/usr/lib64/python3.6/site-packages/borg/cache.py", line 465, in __init__
    self.sync()
  File "/usr/lib64/python3.6/site-packages/borg/cache.py", line 849, in sync
    self.chunks = create_master_idx(self.chunks)
  File "/usr/lib64/python3.6/site-packages/borg/cache.py", line 795, in create_master_idx
    archive_chunk_idx = read_archive_index(archive_id, archive_name)
  File "/usr/lib64/python3.6/site-packages/borg/cache.py", line 738, in read_archive_index
    archive_chunk_idx = ChunkIndex.read(fd, permit_compact=True)
  File "src/borg/hashindex.pyx", line 109, in borg.hashindex.IndexBase.read (src/borg/hashindex.c:1974)
  File "src/borg/hashindex.pyx", line 94, in borg.hashindex.IndexBase.__cinit__ (src/borg/hashindex.c:1679)
  File "/usr/lib64/python3.6/site-packages/borg/crypto/file_integrity.py", line 32, in read
    return self.fd.read(n)
  File "/usr/lib64/python3.6/site-packages/borg/crypto/file_integrity.py", line 82, in read
    data = super().read(n)
  File "/usr/lib64/python3.6/site-packages/borg/crypto/file_integrity.py", line 32, in read
    return self.fd.read(n)
OSError: [Errno 5] Input/output error

Platform: Linux nibbler 4.14.65-gentoo #1 SMP Fri Aug 24 22:08:26 CEST 2018 x86_64
Linux: Gentoo Base System 2.4.1 
Borg: 1.2.0.dev661+g3e560411  Python: CPython 3.6.5
PID: 29674  CWD: /
sys.argv: ['/usr/lib/python-exec/python3.6/borg', 'prune', '/mnt/backup/borg', '--keep-daily', '7', '--keep-weekly', '8', '--keep-monthly', '12', '--keep-yearly', '2', '--prefix', '{hostname}-', '--remote-path', 'borg1', '--umask', '77', '--debug', '--stats', '--list']
SSH_ORIGINAL_COMMAND: None

/etc/borgmatic/config.yaml: Running command for on-error hook
/etc/borgmatic/config.yaml: Hook command: echo "`date` - Error while creating a backup."
Sun Sep  9 04:03:03 CEST 2018 - Error while creating a backup.
Command '('borg', 'prune', '/mnt/backup/borg', '--keep-daily', '7', '--keep-weekly', '8', '--keep-monthly', '12', '--keep-yearly', '2', '--prefix', '{hostname}-', '--remote-path', 'borg1', '--umask', '77', '--debug', '--stats', '--list')' returned non-zero exit status 2.

The external HDD is in good state, SMART has not recognized any errors and self-testing works fine.

Can you reproduce the problem? If so, describe how. If not, describe troubleshooting steps you took before opening the issue.

YES: Everytime the Backup is run as Cron, it fails. Everytime, the cron script is executed by root it works.

Include any warning/errors/backtraces from the system logs

ThomasWaldmann commented 6 years ago

Output of mount for the repo disk (check both for a cron-run and for your manual-as-root runs whether it makes a difference)? Filesystem in repo disk?

ZoidbergZulu commented 6 years ago

The repo disk mounts cleanly at all times. e2fsck runs without errors. I have tried both scenarios with disk mounted already and disk mounted before running borg via cron. I just can't get my head around this: Even IF my HDD has an issue, why does the same command work when ran manually that fails in a cron job...

ThomasWaldmann commented 6 years ago

Do you run borg as root from your cronjob?

Check the environment inside the cronjob vs. your environment when being root. PATH?

Multiple borg versions installed?

ZoidbergZulu commented 6 years ago

Yes, it's part of cron.daily, which is run by root in crontab. PATH should not really play a role since I use absolute paths, i.e. /usr/bin/borg. Or am I mistaken here?

The package manager would not allow for different borg versions in parallel.

Any suggestions would be sincerely appreciated...

ThomasWaldmann commented 6 years ago

OK, good.

Just noticed that the problem is in the cache, not in the repo.

So, please post smartctl -a /dev/sdx output for the disk that has the borg cache (usually $HOME/.cache/borg). What fs is that? Run fsck on it.

ZoidbergZulu commented 6 years ago

Wow... this was unexpected - my SSD (roof FS) might be broken after all: tunefs failed with a bad superblock error: tune2fs: Bad magic number in super-block while trying to open /dev/sda

All Smart Selftest checked out fine however....

SMART Self-test log structure revision number 1
Num  Test_Description    Status                  Remaining  LifeTime(hours)  LBA_of_first_error
# 1  Extended offline    Completed without error       00%       355         -
# 2  Extended offline    Completed without error       00%       347         -
# 3  Extended offline    Completed without error       00%       339         -
# 4  Short offline       Completed without error       00%       331         -
# 5  Short offline       Completed without error       00%       331         -
# 6  Extended offline    Completed without error       00%       331         -

Thanks a lot, ThomasWaldmann - I will further investigate but it appears to be an FS or even hardware issue...

ThomasWaldmann commented 6 years ago

Can you show the complete smartctl output?

ZoidbergZulu commented 6 years ago

Here you go:

smartctl 6.6 2017-11-05 r4594 [x86_64-linux-4.14.65-gentoo] (local build)
Copyright (C) 2002-17, Bruce Allen, Christian Franke, www.smartmontools.org

=== START OF INFORMATION SECTION ===
Model Family:     Intel 540 Series SSDs
Device Model:     INTEL SSDSC2KW240H6
Serial Number:    
LU WWN Device Id: 5 5cd2e4 14e8f000d
Firmware Version: LSF036C
User Capacity:    240,057,409,536 bytes [240 GB]
Sector Size:      512 bytes logical/physical
Rotation Rate:    Solid State Device
Form Factor:      2.5 inches
Device is:        In smartctl database [for details use: -P show]
ATA Version is:   ACS-3 (minor revision not indicated)
SATA Version is:  SATA 3.2, 6.0 Gb/s (current: 6.0 Gb/s)
Local Time is:    Sun Sep 16 18:06:26 2018 CEST
SMART support is: Available - device has SMART capability.
SMART support is: Enabled

=== START OF READ SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED

General SMART Values:
Offline data collection status:  (0x02) Offline data collection activity
                                        was completed without error.
                                        Auto Offline Data Collection: Disabled.
Self-test execution status:      (   0) The previous self-test routine completed
                                        without error or no self-test has ever
                                        been run.
Total time to complete Offline
data collection:                (    0) seconds.
Offline data collection
capabilities:                    (0x53) SMART execute Offline immediate.
                                        Auto Offline data collection on/off support.
                                        Suspend Offline collection upon new
                                        command.
                                        No Offline surface scan supported.
                                        Self-test supported.
                                        No Conveyance Self-test supported.
                                        Selective Self-test supported.
SMART capabilities:            (0x0003) Saves SMART data before entering
                                        power-saving mode.
                                        Supports SMART auto save timer.
Error logging capability:        (0x01) Error logging supported.
                                        General Purpose Logging supported.
Short self-test routine
recommended polling time:        (   2) minutes.
Extended self-test routine
recommended polling time:        (  15) minutes.
SCT capabilities:              (0x0039) SCT Status supported.
                                        SCT Error Recovery Control supported.
                                        SCT Feature Control supported.
                                        SCT Data Table supported.

SMART Attributes Data Structure revision number: 1
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  5 Reallocated_Sector_Ct   0x0032   100   100   000    Old_age   Always       -       47
  9 Power_On_Hours_and_Msec 0x0032   100   100   000    Old_age   Always       -       356h+00m+00.000s
 12 Power_Cycle_Count       0x0032   100   100   000    Old_age   Always       -       12
170 Available_Reservd_Space 0x0033   099   099   010    Pre-fail  Always       -       0
171 Program_Fail_Count      0x0032   100   100   010    Old_age   Always       -       0
172 Erase_Fail_Count        0x0032   100   100   010    Old_age   Always       -       0
174 Unexpect_Power_Loss_Ct  0x0032   100   100   000    Old_age   Always       -       4
183 SATA_Downshift_Count    0x0032   100   100   000    Old_age   Always       -       0
184 End-to-End_Error        0x0033   100   100   090    Pre-fail  Always       -       0
187 Uncorrectable_Error_Cnt 0x0032   100   100   000    Old_age   Always       -       75
190 Airflow_Temperature_Cel 0x0032   033   043   000    Old_age   Always       -       33 (Min/Max 29/43)
192 Power-Off_Retract_Count 0x0032   100   100   000    Old_age   Always       -       4
199 UDMA_CRC_Error_Count    0x0032   100   100   000    Old_age   Always       -       0
225 Host_Writes_32MiB       0x0032   100   100   000    Old_age   Always       -       23728
226 Workld_Media_Wear_Indic 0x0032   100   100   000    Old_age   Always       -       0
227 Workld_Host_Reads_Perc  0x0032   100   100   000    Old_age   Always       -       0
228 Workload_Minutes        0x0032   100   100   000    Old_age   Always       -       0
232 Available_Reservd_Space 0x0033   099   099   010    Pre-fail  Always       -       0
233 Media_Wearout_Indicator 0x0032   100   100   000    Old_age   Always       -       0
241 Total_LBAs_Written      0x0032   100   100   000    Old_age   Always       -       23728
242 Total_LBAs_Read         0x0032   100   100   000    Old_age   Always       -       72479
249 NAND_Writes_1GiB        0x0032   100   100   000    Old_age   Always       -       339
252 Unknown_Attribute       0x0032   100   100   000    Old_age   Always       -       3

SMART Error Log Version: 1
No Errors Logged

SMART Self-test log structure revision number 1
Num  Test_Description    Status                  Remaining  LifeTime(hours)  LBA_of_first_error
# 1  Extended offline    Completed without error       00%       355         -
# 2  Extended offline    Completed without error       00%       347         -
# 3  Extended offline    Completed without error       00%       339         -
# 4  Short offline       Completed without error       00%       331         -
# 5  Short offline       Completed without error       00%       331         -
# 6  Extended offline    Completed without error       00%       331         -
# 7  Extended offline    Completed: read failure       80%       331         0
# 8  Extended offline    Completed: read failure       80%       331         0
# 9  Extended offline    Completed: read failure       80%       331         0
#10  Extended offline    Completed: read failure       80%       331         0
#11  Extended offline    Completed: read failure       80%       331         0
#12  Extended offline    Completed: read failure       80%       331         0
#13  Extended offline    Completed: read failure       80%       331         0
#14  Extended offline    Completed: read failure       80%       331         0
#15  Extended offline    Completed: read failure       80%       331         0
#16  Extended offline    Completed: read failure       80%       331         0
#17  Extended offline    Completed: read failure       80%       331         0
#18  Extended offline    Completed: read failure       80%       331         0
#19  Extended offline    Completed: read failure       80%       331         0
#20  Extended offline    Completed: read failure       80%       331         0
#21  Extended offline    Completed: read failure       80%       330         0
15 of 15 failed self-tests are outdated by newer successful extended offline self-test # 1

SMART Selective self-test log data structure revision number 1
 SPAN         MIN_LBA         MAX_LBA  CURRENT_TEST_STATUS
    1  70403103932424  70403103932424  Not_testing
    2  70403103932424  70403103932424  Not_testing
    3  70403103932424  70403103932424  Not_testing
    4  70403103932424  70403103932424  Not_testing
    5  70403103932424  70403103932424  Not_testing
Selective self-test flags (0x4008):
  After scanning selected spans, do NOT read-scan remainder of disk.
If Selective self-test is pending on power-up, resume after 0 minute delay.
ThomasWaldmann commented 6 years ago

That looks bad (5, 187 and also the tests at 331 hours) - guess you should send it in for warranty.

ZoidbergZulu commented 6 years ago

Alright, thanks for your great support here. The issue is obviously closed.