This is subtle. A combination od fast client disk (read: SSD) with lots
of files and fast network connection to restic-server would suddenly
start getting lots of "dial tcp: connect: cannot assign requested
address" errors during backup stage. Further inspection revealed that
client machine was plagued with TCP sockets in TIME_WAIT state. When
ephemeral port range was finally exhausted, no more sockets could be
opened, so restic would freak out.
To understand the magnitude of this problem, with ~18k ports and default
timeout of 60 seconds, it means more than 300 HTTP connections per
seconds were created and teared down. Yeah, restic-server is that
fast. :)
As it turns out, this behavior was product of 2 subtle issues:
1) The body of HTTP response wasn't read completely with io.ReadFull()
at the end of the Load() function. This deactivated HTTP keepalive,
so already open connections were not reused, but closed instead, and
new ones opened for every new request. io.Copy(ioutil.Discard,
resp.Body) before resp.Body.Close() remedies this.
2) Even with the above fix, somehow having MaxIdleConnsPerHost at its
default value of 2 wasn't enough to stop reconnecting. It is hard to
understand why this would be so detrimental, it could even be some
subtle Go runtime bug. Anyhow, setting this value to match the
connection limit, as set by connLimit global variable, finally nails
this ugly bug.
I fixed several other places where the response body wasn't read in
full (or at all). For example, json.NewDecoder() is also known not to
read the whole body of response.
Unfortunately, this is not over yet. :( The check command is firing up
to 40 simultaneous connections to the restic-server. Then, once again,
MaxIdleConnsPerHost is too low to support keepalive, and sockets in the
TIME_WAIT state pile up. But, as this kind of concurrency absolutely
kill the poor disk on the server side, this is a completely different
bug then.
$ bin/restic forget /d 7 /w 4 /m 12
argument "/d" is not a snapshot ID, ignoring
argument "7" is not a snapshot ID, ignoring
argument "/w" is not a snapshot ID, ignoring
argument "4" is not a snapshot ID, ignoring
argument "/m" is not a snapshot ID, ignoring
cound not find a snapshot for ID "12", ignoring
Equivalent to rsync's "-x" option.
Notes to the naming:
"--exclude-other-filesystems"
is used by Duplicity,
"--one-file-system"
is used rsync and tar.
This latter should be more familiar to the user.
The fuse code kept adding snapshots to the top-level dir "snapshots". In
addition, snapshots with the same timestamp (same second) were not added
correctly, they will now be suffixed by an incrementing counter, e.g.:
dr-xr-xr-x 1 fd0 users 0 Sep 18 15:01 2016-09-18T15:01:44+02:00
dr-xr-xr-x 1 fd0 users 0 Sep 18 15:01 2016-09-18T15:01:48+02:00
dr-xr-xr-x 1 fd0 users 0 Sep 18 15:01 2016-09-18T15:01:48+02:00-1
Closes #624
This code is introduced to watch for issue #529, in which two users
describe that restic failed encoding a time in a node to JSON with the
error message:
panic: json: error calling MarshalJSON for type *restic.Node: json: error calling MarshalJSON for type time.Time: Time.MarshalJSON: year outside of range [0,9999]
The error message now is:
panic: Marshal: json: error calling MarshalJSON for type *restic.Node: node /home/fd0/shared/work/restic/restic/.git/hooks/applypatch-msg.sample has invalid ModTime year -1: -0001-01-02 03:04:05.000000006 +0053 LMT
This closes #606, which fails because several snapshots are created with
exactly the same timestamp, and the code checks that for each snapshot
there is a dir in the fuse mount. This fails for colliding timestamps,
so we now add a suffix "-1", "-2" etc for each duplicate timestamp.
Sample:
counting files in repo
building new index for repo
[0:00] 100.00% 22 / 22 packs
repository contains 22 packs (1377 blobs) with 90.610 MiB bytes
processed 1377 blobs: 0 duplicate blobs, 0B duplicate
load all snapshots
find data that is still in use for 1 snapshots
[0:00] 100.00% 1 / 1 snapshots
found 409 of 1377 data blobs still in use, removing 968 blobs
will delete 10 packs and rewrite 10 packs, this frees 64.232 MiB
creating new index
[0:00] 100.00% 7 / 7 packs
saved new index as df467c6e
done
Closes #581
