restic backup hangs indefinitely after a few hundred MBs upload #1526
Description
Output of restic version
debug enabled
restic 0.8.1 (v0.8.1-15-g2bc4d200)
compiled with go1.9.2 on linux/amd64
How did you run restic exactly?
Using the following systemd unit:
[Unit]
Description=Backup %I using 'restic'
ConditionFileNotEmpty=/etc/restic/%i/restic.env
ConditionPathExists=/etc/restic/%i/backup.exclude
[Service]
ExecStart=/usr/local/bin/restic backup --limit-upload=1600 --cache-dir=/var/cache/restic/%i --one-file-system --exclude-file=/etc/restic/%i/backup.exclude --exclude=/var/cache/* --exclude=/tmp/* --exclude=/var/tmp/* --exclude=/home/*/.cache/* --exclude=/run/* /
Type=simple
EnvironmentFile=/etc/restic/%i/restic.env
DynamicUser=yes
PrivateTmp=no
PrivateDevices=yes
CacheDirectory=restic/%i
CacheDirectoryMode=0700
ConfigurationDirectory=restic/%i
ConfigurationDirectoryMode=0700
LogsDirectory=restic/%i
SystemCallFilter=@basic-io @default @file-system @io-event @network-io @process @signal getrandom ioctl sched_getaffinity
AmbientCapabilities=CAP_DAC_READ_SEARCH
IPAccounting=yes
IOSchedulingClass=idle
CPUSchedulingPolicy=idle/etc/restic/moria/restic.env:
RESTIC_PASSWORD=##redacted##
RESTIC_REPOSITORY=b2:backup-moria
B2_ACCOUNT_ID=##redacted##
B2_ACCOUNT_KEY=##redacted##
DEBUG_LOG=/var/log/private/restic/moria/debug.log
TMPDIR=/var/log/private/restic/moria
What backend/server/service did you use to store the repository?
Backblaze B2
Expected behavior
I'd expect restic backup to continue its operation until it has finished uploading the snapshot.
Actual behavior
After I already uploaded around ~100GB to B2 throughout the last ~10 days, I restarted it yesterday once I had sufficient upstream available again.
It stopped uploading after around 100MB and looking at the process using strace indicated it was simply hanging at a futex() call, not uploading anything or indicating any other kind of activity.
I retried it several times since then, each time it uploaded between ~100MB to ~750MB when it started hanging again, so I created a debug build, made sure it writes a debug.log and could reproduce it again.
Steps to reproduce the behavior
- Initialize a new B2 repo
- Start uploading a large-ish backup (here ~177GB)
- Stop & resume the
restic backup …process after around ~100GB
Output of strace -f -p $(pidof restic):
strace: Process 8193 attached with 18 threads
[pid 8477] futex(0xc420a47990, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid 8408] futex(0xc4206f4810, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid 8400] futex(0xf3f960, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 8399] futex(0xc420029290, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid 8234] futex(0xc4206f4110, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid 8232] futex(0xf3f960, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 8231] futex(0xf3f960, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 8210] futex(0xc420053610, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid 8202] futex(0xc420052810, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid 8201] futex(0xc420242f10, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid 8200] futex(0xc420242b90, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid 8198] futex(0xc420052490, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid 8197] futex(0xf57640, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid 8196] futex(0xc420028810, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid 8195] futex(0xc420028490, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid 8233] futex(0xf3f960, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 8199] futex(0xc420029990, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid 8193] futex(0xf38550, FUTEX_WAIT, 0, NULL
Last lines of debug.log:
2018/01/04 15:34:48 repository/index.go:142 repository.(*Index).Lookup 44757 id ca88dd0c not found
2018/01/04 15:34:48 repository/index.go:142 repository.(*Index).Lookup 44757 id ca88dd0c not found
2018/01/04 15:34:48 repository/index.go:142 repository.(*Index).Lookup 44757 id ca88dd0c not found
2018/01/04 15:34:48 repository/index.go:142 repository.(*Index).Lookup 44757 id ca88dd0c not found
2018/01/04 15:34:48 repository/index.go:142 repository.(*Index).Lookup 44757 id ca88dd0c not found
2018/01/04 15:34:48 repository/index.go:142 repository.(*Index).Lookup 44757 id ca88dd0c not found
2018/01/04 15:34:48 repository/master_index.go:39 repository.(*MasterIndex).Lookup 44757 id ca88dd0c not found in any index
2018/01/04 15:34:48 repository/repository.go:209 repository.(*Repository).SaveAndEncrypt 44757 save id ca88dd0c (data, 8388608 bytes)
2018/01/04 15:34:48 repository/packer_manager.go:65 repository.(*packerManager).findPacker 44757 create new pack
2018/01/04 15:34:48 repository/packer_manager.go:93 repository.(*Repository).savePacker 44757 save packer for data with 1 blobs (8388640 bytes)
2018/01/04 15:34:48 debug/round_tripper_debug.go:90 debug.loggingRoundTripper.RoundTrip 43911 ------------ HTTP RESPONSE ----------
HTTP/1.1 200 OK
Content-Length: 289
Cache-Control: max-age=0, no-cache, no-store
Content-Type: application/json;charset=UTF-8
Date: Thu, 04 Jan 2018 14:34:48 GMT
Server: Apache-Coyote/1.1
2018/01/04 15:34:48 debug/round_tripper_debug.go:77 debug.loggingRoundTripper.RoundTrip 43911 ------------ HTTP REQUEST -----------
POST /b2api/v1/b2_upload_file/0eedcad4d93e4ac76d0d0d1f/c001_v0001038_t0022 HTTP/1.1
Host: pod-000-1038-08.backblaze.com
User-Agent: blazer/0.2.1
Content-Length: 8388753
Authorization: ##redacted##
Content-Type: application/octet-stream
X-Blazer-Method: b2_upload_file
X-Blazer-Request-Id: 577
X-Bz-Content-Sha1: hex_digits_at_end
X-Bz-File-Name: data/66/66005186f523a43986d7b7dc84d3ade24b19a5fa2831b9694d1b5d78a6bdf015
Accept-Encoding: gzip
2018/01/04 15:34:53 debug/round_tripper_debug.go:90 debug.loggingRoundTripper.RoundTrip 43809 ------------ HTTP RESPONSE ----------
HTTP/1.1 200 OK
Content-Length: 475
Cache-Control: max-age=0, no-cache, no-store
Content-Type: application/json;charset=UTF-8
Date: Thu, 04 Jan 2018 14:34:53 GMT
Server: Apache-Coyote/1.1
Do you have any idea what may have caused this?
Possibly some deadlock in the B2 code, but I don't really have a clue.
Do you have an idea how to solve the issue?
No
Did restic help you or made you happy in any way?
restic is finally a backup tool which feels done right without being overly complex/complicated.
Easy to setup & use and encourages to practice a good "backup hygiene".