Running now latest master here:
# restic version
debug enabled
restic 0.8.3 (v0.8.3-191-g6d4c40f8) compiled with go1.10.1 on linux/amd64
Using B2 as backend with -o b2.connections=2
.
It’s been runing now for several hours without doing much. It got stuck now in this state for quite a while (bandwidth consumption only changed by a few hundred KB within the last 2h or so):
● restic@moria.service - Backup moria using 'restic'
Loaded: loaded (/etc/systemd/system/restic@.service; static; vendor preset: disabled)
Drop-In: /etc/systemd/system/restic@moria.service.d
└─bandwidth.conf, debug.conf, runtimemax.conf
Active: active (running) since Mon 2018-04-30 08:10:15 CEST; 2h 37min ago
Main PID: 1359 (restic)
IP: 14.9M in, 748.3M out
Tasks: 16 (limit: 4915)
Memory: 4.0G
CGroup: /system.slice/system-restic.slice/restic@moria.service
└─1359 /usr/local/bin/restic backup --limit-upload=1600 --cache-dir=/var/cache/restic/moria --one-file-system --exclude-file=/etc/restic/moria/backup.exclude --excl>
Apr 30 08:10:15 moria systemd[1]: Started Backup moria using 'restic'.
Apr 30 08:10:15 moria restic[1359]: debug log file /var/log/restic/moria/debug.log
Apr 30 08:10:15 moria restic[1359]: debug enabled
Looking at the debug log, it keeps repeating those 806 index checks forever:
2018/04/30 10:58:34 repository/master_index.go:157 repository.(*MasterIndex).FullIndexes 2922 checking 806 indexes
2018/04/30 10:58:34 repository/master_index.go:160 repository.(*MasterIndex).FullIndexes 2922 index 0xc4202b2000 is final
2018/04/30 10:58:34 repository/master_index.go:160 repository.(*MasterIndex).FullIndexes 2922 index 0xc4202b2100 is final
2018/04/30 10:58:34 repository/master_index.go:160 repository.(*MasterIndex).FullIndexes 2922 index 0xc420338000 is final
2018/04/30 10:58:34 repository/master_index.go:160 repository.(*MasterIndex).FullIndexes 2922 index 0xc4202b2180 is final
2018/04/30 10:58:34 repository/master_index.go:160 repository.(*MasterIndex).FullIndexes 2922 index 0xc42029e080 is final
[…]
2018/04/30 10:58:34 repository/master_index.go:160 repository.(*MasterIndex).FullIndexes 2922 index 0xc425d97280 is final
2018/04/30 10:58:34 repository/master_index.go:160 repository.(*MasterIndex).FullIndexes 2922 index 0xc426d0ec00 is final
2018/04/30 10:58:34 repository/master_index.go:160 repository.(*MasterIndex).FullIndexes 2922 index 0xc42a821400 is final
2018/04/30 10:58:34 repository/master_index.go:160 repository.(*MasterIndex).FullIndexes 2922 index 0xc43204a780 is final
2018/04/30 10:58:34 repository/master_index.go:160 repository.(*MasterIndex).FullIndexes 2922 index 0xc436e3d480 is final
2018/04/30 10:58:34 repository/master_index.go:172 repository.(*MasterIndex).FullIndexes 2922 return 0 indexes
Checking, how often this number of indexes was checked seems to confirm this:
# grep 'checking \w\+ indexes' /var/log/private/restic/moria/debug.log | awk '{print $7}' | uniq -c
4 803
31 804
15 805
297 806
…it started with just 4 times checking 803 indexes, checked 15 times 805 indexes but is now ATM stuck at having checked 297 times 806 indexes.
Every now and then, it refreshes locks between the index checks:
2018/04/30 10:58:26 restic/lock.go:77 main.refreshLocks 2876 refreshing locks
2018/04/30 10:58:26 restic/lock.go:223 restic.(*Lock).Refresh 2876 refreshing lock bb149df0
2018/04/30 10:58:26 repository/repository.go:263 repository.(*Repository).SaveJSONUnpacked 2876 save new blob lock
2018/04/30 10:58:26 b2/b2.go:200 b2.(*b2Backend).Save 2876 Save <lock/79e7ca7a8d>, name locks/79e7ca7a8d5c6fcb7d04fb176eca2d528c882a9b2ba8153212801b56c369b882
2018/04/30 10:58:26 b2/b2.go:205 b2.(*b2Backend).Save 2876 saved 140 bytes, err <nil>
2018/04/30 10:58:26 debug/round_tripper_debug.go:77 debug.loggingRoundTripper.RoundTrip 2876 ------------ HTTP REQUEST -----------
POST /b2api/v1/b2_upload_file/0eedcad4d93e4ac76d0d0d1f/c001_v0001038_t0052 HTTP/1.1
Host: pod-000-1038-01.backblaze.com
User-Agent: blazer/0.3.0
Content-Length: 140
Authorization: [REDACTED]
Content-Type: application/octet-stream
X-Blazer-Method: b2_upload_file
X-Blazer-Request-Id: 748
X-Bz-Content-Sha1: 98daf2199fe7b6e1d21f93723464b6c97a1e252b
X-Bz-File-Name: locks/79e7ca7a8d5c6fcb7d04fb176eca2d528c882a9b2ba8153212801b56c369b882
Accept-Encoding: gzip
2018/04/30 10:58:27 debug/round_tripper_debug.go:90 debug.loggingRoundTripper.RoundTrip 2876 ------------ HTTP RESPONSE ----------
HTTP/1.1 200 OK
Content-Length: 469
Cache-Control: max-age=0, no-cache, no-store
Content-Type: application/json;charset=UTF-8
Date: Mon, 30 Apr 2018 08:58:27 GMT
Server: Apache-Coyote/1.1
2018/04/30 10:58:27 repository/repository.go:291 repository.(*Repository).SaveUnpacked 2876 blob <lock/79e7ca7a8d> saved
2018/04/30 10:58:27 cache/backend.go:37 cache.(*Backend).Remove 2876 cache Remove(<lock/bb149df005>)
2018/04/30 10:58:27 b2/b2.go:251 b2.(*b2Backend).Remove 2876 Remove <lock/bb149df005>
2018/04/30 10:58:27 debug/round_tripper_debug.go:77 debug.loggingRoundTripper.RoundTrip 2876 ------------ HTTP REQUEST -----------
GET /file/backup-moria/locks/bb149df00553226eb6012cd61c770a84b30a3c3e6c1982632fdccec90d5cfbb9 HTTP/1.1
Host: f001.backblazeb2.com
User-Agent: blazer/0.3.0
Authorization: [REDACTED]
Range: bytes=0-0
X-Blazer-Method: b2_download_file_by_name
X-Blazer-Request-Id: 749
2018/04/30 10:58:28 debug/round_tripper_debug.go:90 debug.loggingRoundTripper.RoundTrip 2876 ------------ HTTP RESPONSE ----------
HTTP/1.1 206 Partial Content
Content-Length: 1
Accept-Ranges: bytes
Cache-Control: max-age=0, no-cache, no-store
Content-Range: bytes 0-0/140
Content-Type: application/octet-stream
Date: Mon, 30 Apr 2018 08:58:28 GMT
Server: Apache-Coyote/1.1
X-Bz-Content-Sha1: 75be25c4403469417343cdf4be3fd9a1c3f790ff
X-Bz-File-Id: 4_z0eedcad4d93e4ac76d0d0d1f_f107f3a01f630be09_d20180430_m085327_c001_v0001105_t0057
X-Bz-File-Name: locks/bb149df00553226eb6012cd61c770a84b30a3c3e6c1982632fdccec90d5cfbb9
X-Bz-Upload-Timestamp: 1525078407000
2018/04/30 10:58:28 debug/round_tripper_debug.go:77 debug.loggingRoundTripper.RoundTrip 2876 ------------ HTTP REQUEST -----------
POST /b2api/v1/b2_delete_file_version HTTP/1.1
Host: api001.backblazeb2.com
User-Agent: blazer/0.3.0
Content-Length: 180
Authorization: [REDACTED]
X-Blazer-Method: b2_delete_file_version
X-Blazer-Request-Id: 750
Accept-Encoding: gzip
2018/04/30 10:58:29 debug/round_tripper_debug.go:90 debug.loggingRoundTripper.RoundTrip 2876 ------------ HTTP RESPONSE ----------
HTTP/1.1 200 OK
Content-Length: 190
Cache-Control: max-age=0, no-cache, no-store
Content-Type: application/json;charset=UTF-8
Date: Mon, 30 Apr 2018 08:58:29 GMT
Server: Apache-Coyote/1.1
AFAICT it doesn’t seem to be related to the handling of pipes as reported by @wscott:
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
restic 1359 restic cwd DIR 254,0 4096 2 /
restic 1359 restic rtd DIR 254,0 4096 2 /
restic 1359 restic txt REG 254,0 12296224 11542655 /usr/local/bin/restic
restic 1359 restic 0r CHR 1,3 0t0 1030 /dev/null
restic 1359 restic 1u unix 0x00000000b4e60444 0t0 7962977 type=STREAM
restic 1359 restic 2u unix 0x00000000b4e60444 0t0 7962977 type=STREAM
restic 1359 restic 3w REG 254,0 2973061813 7604481 /var/log/private/restic/moria/debug.log
restic 1359 restic 4u a_inode 0,12 0 9886 [eventpoll]
restic 1359 restic 5r DIR 254,0 4096 3407873 /home
restic 1359 restic 6r DIR 254,0 12288 3407876 /home/elias
restic 1359 restic 7r DIR 254,0 4096 3409850 /home/elias/.steam
restic 1359 restic 10u REG 254,0 1234794 7602370 /var/log/private/restic/moria/restic-temp-pack-723406626 (deleted)
restic 1359 restic 13u REG 254,0 669728 7602414 /var/log/private/restic/moria/restic-temp-pack-360908825 (deleted)
restic 1359 restic 17u REG 254,0 102050 7602186 /var/log/private/restic/moria/restic-temp-pack-382709872 (deleted)