Browsing in fuse mounted snapshot gives input/output error

[timdeluxe]

I mounted my repository (sftp backend) like this:

# restic mount /mnt
Now serving data at /mnt
Don't forget to umount after quitting!

When i then try to browse through the content i get this:

/mnt # cd snapshots/
/mnt/snapshots # ls -al
total 0
dr-xr-xr-x 1 root root 0 Sep 29 22:32 2015-09-29T22:32:34+02:00
dr-xr-xr-x 1 root root 0 Sep 29 23:34 2015-09-29T23:34:00+02:00
dr-xr-xr-x 1 root root 0 Sep 30 01:33 2015-09-30T01:33:20+02:00
dr-xr-xr-x 1 root root 0 Sep 30 12:07 2015-09-30T12:07:20+02:00
dr-xr-xr-x 1 root root 0 Sep 30 23:50 2015-09-30T23:50:47+02:00
/mnt/snapshots # cd 2015-09-30T23\:50\:47+02\:00/
/mnt/snapshots/2015-09-30T23:50:47+02:00 # ls -al
ls: reading directory .: Input/output error
total 0
/mnt/snapshots/2015-09-30T23:50:47+02:00 #

I could reproduce this on two different servers, with each having a different sftp backend.

[fd0]

Thanks for reporting this bug. Which version of restic are you using on what platform/OS? Please include the output ofrestic version in the bug report.

You can help us a lot (especially if it's reproducable) by compiling restic with debug support using go run build.go -tags debug and then running:

$ DEBUG_LOG=/tmp/log restic mount /mnt

This instructs restic to write extensive debug information to the file /tmp/log. Be aware that this logfile may contain sensitive data such as file and directory names. Please have a look around in the debug log file, maybe you can see what the underlying error is.

[timdeluxe]

My version is:

restic 0.1.0 (v0.1.0-39-ge738d35)
compiled at 2015-09-29 00:51:45 with go1.5.1

And i use Debian, yesterday it was still wheezy, now it is jessie (8.2) - the issue didn't change with the upgrade:

# cat /etc/debian_version
8.2
# uname -a
Linux xxxxxxxxx.de 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt11-1+deb8u4 (2015-09-19) x86_64 GNU/Linux

Here the debug log:

2015/10/01 12:25:07 [    restic]   1 main.go: 24 main []string{"./restic", "mount", "/mnt"}
2015/10/01 12:25:08 [Repo.LoadIndex]   1 repository.go:506 Loading index
2015/10/01 12:25:08 [     LoadIndex]  35 repository.go:543 Loading index 1a5bed0f
2015/10/01 12:25:08 [     LoadIndex]  15 repository.go:543 Loading index 1dbd9029
2015/10/01 12:25:08 [     LoadIndex]  16 repository.go:543 Loading index 267b9594
2015/10/01 12:25:08 [     LoadIndex]  18 repository.go:543 Loading index 92ba511d
2015/10/01 12:25:08 [     LoadIndex]  19 repository.go:543 Loading index d849f2df
2015/10/01 12:25:08 [     LoadIndex]  20 repository.go:543 Loading index fe3df7a5
2015/10/01 12:25:08 [Index.DecodeIndex]  16 index.go:309 Start decoding index
2015/10/01 12:25:08 [Index.DecodeIndex]  16 index.go:325 done
2015/10/01 12:25:08 [      Index.Merge]   1 index.go:128 Merge index with 0xc8200b0610
2015/10/01 12:25:08 [      Index.Merge]   1 index.go:139 done merging index
2015/10/01 12:25:08 [Index.DecodeIndex]  18 index.go:309 Start decoding index
2015/10/01 12:25:08 [Index.DecodeIndex]  18 index.go:325 done
2015/10/01 12:25:08 [      Index.Merge]   1 index.go:128 Merge index with 0xc820145140
2015/10/01 12:25:08 [      Index.Merge]   1 index.go:139 done merging index
2015/10/01 12:25:08 [Index.DecodeIndex]  20 index.go:309 Start decoding index
2015/10/01 12:25:08 [Index.DecodeIndex]  20 index.go:325 done
2015/10/01 12:25:08 [Index.DecodeIndex]  35 index.go:309 Start decoding index
2015/10/01 12:25:08 [      Index.Merge]   1 index.go:128 Merge index with 0xc82035c450
2015/10/01 12:25:08 [      Index.Merge]   1 index.go:139 done merging index
2015/10/01 12:25:08 [Index.DecodeIndex]  35 index.go:325 done
2015/10/01 12:25:08 [      Index.Merge]   1 index.go:128 Merge index with 0xc82415bb60
2015/10/01 12:25:08 [      Index.Merge]   1 index.go:139 done merging index
2015/10/01 12:25:09 [Index.DecodeIndex]  15 index.go:309 Start decoding index
2015/10/01 12:25:11 [Index.DecodeIndex]  15 index.go:325 done
2015/10/01 12:25:11 [      Index.Merge]   1 index.go:128 Merge index with 0xc820263f70
2015/10/01 12:25:11 [      Index.Merge]   1 index.go:139 done merging index
2015/10/01 12:25:11 [Index.DecodeIndex]  19 index.go:309 Start decoding index
2015/10/01 12:25:13 [Index.DecodeIndex]  19 index.go:325 done
2015/10/01 12:25:13 [      Index.Merge]   1 index.go:128 Merge index with 0xc8221c5b20
2015/10/01 12:25:13 [      Index.Merge]   1 index.go:139 done merging index
2015/10/01 12:25:15 [     Index.Lookup]  40 index.go: 98 id 5729617f found in pack fed115d2 at 1574248, length 328
2015/10/01 12:25:20 [        unlockAll]   1 lock.go:111 unlocking 0 locks

And by the way, when i doing "umount /mnt" in another shell, because restic tells me to umount cleanly i get this (last line):

debug log file /tmp/log
debug enabled
Now serving data at /mnt
Don't forget to umount after quitting!
error in cleanup handler: exit status 1: fusermount: failed to unmount /mnt: Invalid argument

And the restic mount command doesn't come back to shell until it is umounted - but i think that is normal behaivour?

[fd0]

I'm not able to reproduce the issue, do you maybe have a hint what's different for you? do you have unusual files or file types backed up? Could you try to reproduce this with a backup of a dummy directory and provide instructions on how to build that?

[timdeluxe]

uhm, well, i backup nearly my whole server with it. This means there are a lot of files and file types of course (symlinks, sockets, etc.).

For file types i made some tests: I tried a small dir with sockets, symlinks and even /dev (i think instructions are not needed, okay?). I made a backup of it and mounted and changed into that snapshot dir. All that worked fine!

So maybe it has to do with the amount of files (or better said elements) organized by a snapshot?
If you tell me, how to get useful statistics with restic (list? dump?), i can provide you that...

[fd0]

How did you call restic for the backup exactly?

[timdeluxe]

For the (successful) tests just "restic backup /foo/bar".

For my whole backup:

export RESTIC_REPOSITORY=sftp://xxxx@yyyyyy.zzz/data
export RESTIC_PASSWORD=XXXXXXXXXXXX

restic backup \
--exclude=/dev \
--exclude=/initrd \
--exclude=/media \
--exclude=/mnt \
--exclude=/proc \
--exclude=/src \
--exclude=/sys \
--exclude=/tmp \
--exclude=/var/tmp \
--exclude=/var/run \
--exclude=/var/spool \
--exclude=/dev/log \
--exclude="*.mp3" \
--exclude=ibdata \
/

[fd0]

Is there something unusual in / that got into the backup?

[timdeluxe]

I have no idea. It is a typical Debian system with apache, mysql, php(-fpm), postfix, dovecot, proftpd, some java apps and the usual system daemons (systemd, ntp, logcheck, sshd, etc. pp.).

I don't know how i could identify something "unusual" out of...

 # find / | wc -l
1011991

...files. :(

[fd0]

From what I can see in your bug report, the fuse mount fails when opening the root-directory of the snapshot, so I suspect it's something in the root path...

[timdeluxe]

I see nothing suspicious, do you?

# ls -al /
total 261K
drwxr-xr-x  26 root root 4.0K Oct  1 23:57 .
drwxr-xr-x  26 root root 4.0K Oct  1 23:57 ..
drwxr-xr-x   2 root root 128K Oct 14 22:13 backup
drwx------   2 root root 4.0K Sep 30 23:01 backup_restic
drwxr-xr-x   2 root root 4.0K Oct  1 23:47 bin
drwxr-xr-x   4 root root 1.0K Oct 14 21:35 boot
drwxr-xr-x  19 root root 3.4K Oct 10 18:26 dev
drwxr-xr-x 118 root root  12K Oct 14 21:35 etc
drwxr-xr-x   4 root root 4.0K Sep 29 23:28 home
lrwxrwxrwx   1 root root   31 Oct  1 23:57 initrd.img -> /boot/initrd.img-3.16.0-4-amd64
lrwxrwxrwx   1 root root   30 Nov 14  2012 initrd.img.old -> /boot/initrd.img-3.2.0-4-amd64
-rw-r-----   1 root root  618 Oct  1  2014 installimage.conf
-rw-r-----   1 root root  11K Oct  1  2014 installimage.debug
drwxr-xr-x   9 root root 4.0K Jan 26  2015 kunden
drwxr-xr-x  18 root root 4.0K Oct  1 23:48 lib
drwxr-xr-x   2 root root 4.0K Oct  1 23:29 lib64
-rw-------   1 root root   83 Nov 29  2014 log_path
drwx------   2 root root  16K Sep 12  2012 lost+found
drwxr-xr-x   3 root root 4.0K Sep 12  2012 media
drwxr-xr-x   2 root root 4.0K Oct  1 23:17 mnt
drwxr-xr-x   2 root root 4.0K Sep 12  2012 opt
drwxr-xr-x   3 root root 4.0K Feb  9  2015 path
dr-xr-xr-x 302 root root    0 Oct 10 15:09 proc
drwx------  10 root root 4.0K Oct 14 22:36 root
drwxr-xr-x  28 root root 1020 Oct 14 23:40 run
drwxr-xr-x   2 root root  12K Oct  1 23:48 sbin
drwxr-xr-x   3 root root 4.0K Nov 27  2014 srv
dr-xr-xr-x  13 root root    0 Oct 14 23:44 sys
drwxrwxrwt   9 root root 4.0K Oct 14 23:40 tmp
drwxr-xr-x  11 root root 4.0K Oct  1 23:45 usr
drwxr-xr-x  13 root root 4.0K Nov 29  2014 var
lrwxrwxrwx   1 root root   27 Oct  1 23:57 vmlinuz -> boot/vmlinuz-3.16.0-4-amd64
lrwxrwxrwx   1 root root   26 Nov 14  2012 vmlinuz.old -> boot/vmlinuz-3.2.0-4-amd64

[fd0]

This looks perfectly normal (unfortunately), I'll have to think about how to debug this further.

[Intensity]

How about, generally, bisecting to hone in on the problematic file(s)?

[fd0]

Good idea, but this needs to be reproduceable for someone who is able to bisect. And for the bisect to be successfull it would need a revision that actually worked in that situation.

[Intensity]

I was suggesting that the original poster do the bisection - maybe deciding to back up each top-level directory independently would lead to some/most of those cases working, and then one or two that do not.

[fd0]

That's a good idea. @timdeluxe could you try creating a backup of each of the files/dirs in /, and then check whether you experience the error again?

You could start with something like this: for item in /*; do restic backup $item; done

[timdeluxe]

sure, i did it.

Interesting outcome - every single dir is working fine. I had to cancel /proc and /sys (restic ran into errors there), but i am excluding that in my normal backup, as you can see here: #313 (comment)

Here you see the output of my test. It pretty much explains itself. At 12:07 it was my regular backup by cron - everything else was the test:

/mnt/snapshots # ls -al 2015-11-04*
2015-11-04T12:07:36+01:00:
ls: reading directory 2015-11-04T12:07:36+01:00: Input/output error
total 0

2015-11-04T23:30:34+01:00:
total 0
drwxr-xr-x 1 root root 0 Sep 30 01:26 backup

2015-11-04T23:30:43+01:00:
total 0
drwxr-xr-x 1 root root 0 Oct  1 00:33 bin

2015-11-04T23:30:54+01:00:
total 0
drwxr-xr-x 1 root root 0 Oct 14 21:35 boot

2015-11-04T23:31:05+01:00:
total 0
drwxr-xr-x 1 root root 0 Oct 20 11:09 dev

2015-11-04T23:31:15+01:00:
total 0
drwxr-xr-x 1 root root 0 Oct 14 21:35 etc

2015-11-04T23:31:26+01:00:
total 0
drwx------ 1 root root 0 Oct 14 21:49 help

2015-11-04T23:31:35+01:00:
total 0
drwxr-xr-x 1 root root 0 Mar 16  2012 home

2015-11-04T23:31:45+01:00:
total 0
lrwxrwxrwx 1 root root 0 Oct  1 00:37 initrd.img -> /boot/initrd.img-3.16.0-4-amd64

2015-11-04T23:31:54+01:00:
total 0
lrwxrwxrwx 1 root root 0 Jun 29  2013 initrd.img.old -> /boot/initrd.img-3.2.0-4-amd64

2015-11-04T23:32:03+01:00:
total 0
-rw-r----- 1 root root 537 Mar 14  2012 installimage.conf

2015-11-04T23:32:13+01:00:
total 0
-rw-r----- 1 root root 7.6K Mar 14  2012 installimage.debug

2015-11-04T23:32:24+01:00:
total 0
drwxr-xr-x 1 root root 0 Oct  1 00:33 lib

2015-11-04T23:32:53+01:00:
total 0
drwxr-xr-x 1 root root 0 Oct  1 00:23 lib64

2015-11-04T23:33:03+01:00:
total 0
drwx------ 1 root root 0 Feb  9  2011 lost+found

2015-11-04T23:33:12+01:00:
total 0
drwxr-xr-x 1 root root 0 Feb  9  2011 media

2015-11-04T23:33:21+01:00:
total 0
drwxr-xr-x 1 root root 0 Oct  1 00:23 mnt

2015-11-04T23:33:40+01:00:
total 0
drwxr-xr-x 1 root root 0 Feb  9  2011 opt

2015-11-04T23:45:08+01:00:
total 0
drwx------ 1 root root 0 Oct 14 22:07 root

2015-11-04T23:45:17+01:00:
total 0
drwxr-xr-x 1 root root 0 Oct 29 20:56 run

2015-11-04T23:45:27+01:00:
total 0
drwxr-xr-x 1 root root 0 Oct  1 00:33 sbin

2015-11-04T23:45:37+01:00:
total 0
drwxr-xr-x 1 root root 0 Feb  9  2011 srv

2015-11-04T23:46:06+01:00:
total 0
drwxrwxrwx 1 root root 0 Nov  4 23:45 tmp

2015-11-04T23:46:19+01:00:
total 0
drwxr-xr-x 1 root root 0 Jun 29  2013 usr

2015-11-04T23:47:38+01:00:
total 0
drwxr-xr-x 1 root root 0 Jun 29  2013 var

2015-11-04T23:56:22+01:00:
total 0
lrwxrwxrwx 1 root root 0 Oct  1 00:37 vmlinuz -> boot/vmlinuz-3.16.0-4-amd64

2015-11-04T23:56:31+01:00:
total 0
lrwxrwxrwx 1 root root 0 Jun 29  2013 vmlinuz.old -> boot/vmlinuz-3.2.0-4-amd64
/mnt/snapshots #

Any other idea?

[fd0]

Did you do the mount as root? If not, try browsing the directry with the same user account. Fuse restricts the access root has on mounts of regular users...

[timdeluxe]

All backups and mounts and browsing are done by root - if you would do the backup with another user, i couldn't do the "full" backup, because access will be denied on much stuff...

The next thing i can try to do is to exclude more and more directories to find the point where it starts to work - it will take some time, which i currently miss - i hope i am able to do it on the weekend...

[fd0]

If you do everything as the same user (root) it should work...

[fd0]

We've recently fixed a bug in the fuse mount (it failed to work properly with empty files) that might be the cause for the issue you reported. Could you please try again?

I'm closing this issue for now, please feel free to add a comment, so we can reopen it if the problem persists.

[timdeluxe]

Sorry for being quiet for ages.
Today i updated to the latest go version and to the latest restic version.
I also have rebuild the index.

Now the mount works excellent. I don't get the reported error anymore.

Thanks a lot!

[fd0]

Thanks for taking the time to leave feedback!

[kgraefe]

I just ran into the same issue with restic 0.7.3 and 0.8.0 when using the following script to backup my fritzbox config:

export RESTIC_REPOSITORY="$FRITZBOX_RESTIC_REPOSITORY"
export RESTIC_PASSWORD="$FRITZBOX_RESTIC_PASSWORD"

CURL="curl --silent --insecure"

# Login
challenge=$( \
    $CURL https://fritz.box/login_sid.lua \
    | sed 's/.*<Challenge>\([a-z0-9]*\)<.*/\1/' \
)
response="$challenge-$( \
    echo -n "$challenge-$FRITZBOX_LOGIN_PASSWORD" \
    | iconv -t UTF-16LE | md5sum -b | cut -d' ' -f1 \
)"
data="response=$response&username=$FRITZBOX_LOGIN_USER"
session=$( \
    $CURL --data $data https://fritz.box/login_sid.lua \
    | sed 's/.*<SID>\([a-z0-9]*\)<.*/\1/' \
)

# Do backup
$CURL \
    --form sid=$session \
    --form ImportExportPassword=$FRITZBOX_RESTIC_PASSWORD \
    --form ConfigExport= https://fritz.box/cgi-bin/firmwarecfg \
| restic backup \
    --hostname fritz.box --tag config \
    --stdin --stdin-filename /config/fritzbox.export

# Logout
data="sid=$session&logout=1"
$CURL --data $data https://fritz.box/login_sid.lua -o /dev/null

This is on a fresh repository so there shouldn't be any files besides /config/fritzbox.export in there.

Since the Fritzbox export files are encrypted as well, I might even be able to share the restic repo with you. (I have to double-check that.)

[kgraefe]

I am on Debian too:

# cat /etc/debian_version
9.3
# uname -a
Linux xxx 4.14.0-00028-gbd8e8ab5145a #8 SMP Thu Nov 16 10:32:35 CET 2017 armv7l GNU/Linux

[fd0]

Oh, interesting. The filename is not supposed to contain slashes, that is the error. Can you create a new issue about it? Thanks!