Scan error finishes backup prematurely

Getting Help
1

Hi there,

I have a seaweedfs filesystem, which has a “broken” file (named ?W?B?0!?\u0001). I am not sure what is going on there, since I can’t even read it correctly, if I ls the folder, everything else is shown, also this happens:

ls: cannot access '/opt/aptly/.aptly/?W?B?0!?'$'\001': No such file or directory

There are other directories in the same level, which are full of “normal” files. But that broken file causes restic to fail early with an error like:

{"message_type":"status","seconds_elapsed":7,"percent_done":0,"total_files":1}
{"message_type":"error","error":{},"during":"archival","item":"/opt/aptly/.aptly"}
{"message_type":"error","error":{"Op":"lstat","Path":"/opt/aptly/.aptly/?W?B?0!?\u0001","Err":2},"during":"scan","item":"/opt/aptly/.aptly/?W?B?0!?\u0001"}
{"message_type":"summary","files_new":0,"files_changed":0,"files_unmodified":1,"dirs_new":0,"dirs_changed":2,"dirs_unmodified":1,"data_blobs":0,"tree_blobs":3,"data_added":1365,"total_files_processed":1,"total_bytes_processed":0,"total_duration":8.128964209,"snapshot_id":"91367277"}

I was expecting it to skip that file, continue backing up others and end up with a “some files can’t be read” warning at the end & get return code 3. But restic seems to have a real error here and reporting back total_files_processed:1 (despite creating the snapshot with only few empty folders leading up to that file).

So my questions are:

  • Is this expected or shall I file an issue?
  • Is there a way to tell “skip unreadable/broken/weird files” to the backup command?

Thanks!

2

Which command line and restic version did you use?
The scan error from the log shouldn’t be able to cause the backup command to exit, things must go wrong somewhere else. Could you create a debug log to get some more information on what’s going on?

You could try to exclude the weird files from the backup. But nevertheless restic should continue to backup files.

3 
restic backup --files-from /etc/folders_to_backup --exclude-file /etc/folders_to_backup_exclude --json --cache-dir /opt/restic_local_cache --cleanup-cache --tag type:file_backup

Version is 0.12.0. I’ve already excluded that file. I’ll try to create a debug log.

4

Here is the relevant part, I can attach full log if needed:

2021/05/14 14:08:36 cache/file.go:106   cache.(*Cache).Save     163     Save to cache: <data/6e5760e7db>
2021/05/14 14:08:36 cache/file.go:89    cache.(*Cache).saveWriter       163     Save to cache: <data/6e5760e7db>
2021/05/14 14:08:36 s3/s3.go:346        s3.(*Backend).openReader.func1  163     Close()
2021/05/14 14:08:36 cache/file.go:44    cache.(*Cache).load     163     Load from cache: <data/6e5760e7db>
2021/05/14 14:08:36 restic/readerat.go:41       restic.ReadAt   163     ReadAt(<data/6e5760e7db>) ReadFull returned 408 bytes
2021/05/14 14:08:36 archiver/archiver.go:551    archiver.(*Archiver).SaveTree   163     /opt (1 nodes), parent Tree<1 nodes>
2021/05/14 14:08:36 repository/repository.go:726        repository.(*Repository).LoadTree       163     load tree ac08ce34ba4f8123618661bef2425f7028ffb9ac740578a3ee88684d2523fee8
2021/05/14 14:08:36 repository/repository.go:156        repository.(*Repository).LoadBlob       163     load tree with id ac08ce34ba4f8123618661bef2425f7028ffb9ac740578a3ee88684d2523fee8 (buf len 0, cap 0)
2021/05/14 14:08:36 repository/repository.go:170        repository.(*Repository).LoadBlob       163     blob tree/ac08ce34ba4f8123618661bef2425f7028ffb9ac740578a3ee88684d2523fee8 found: <Blob (tree) ac08ce34, offset 4067293, length 45>
2021/05/14 14:08:36 restic/readerat.go:30       restic.ReadAt   163     ReadAt(<data/2735e8e3ac>) at 4067293, len 45
2021/05/14 14:08:36 cache/backend.go:164        cache.(*Backend).Load   163     Load(<data/2735e8e3ac>, 45, 4067293) from cache
2021/05/14 14:08:36 cache/file.go:44    cache.(*Cache).load     163     Load from cache: <data/2735e8e3ac>
2021/05/14 14:08:36 restic/readerat.go:41       restic.ReadAt   163     ReadAt(<data/2735e8e3ac>) ReadFull returned 45 bytes
2021/05/14 14:08:36 archiver/archiver.go:551    archiver.(*Archiver).SaveTree   163     /opt/aptly (1 nodes), parent Tree<0 nodes>
2021/05/14 14:08:36 archiver/archiver.go:353    archiver.(*Archiver).Save       163     /opt/aptly/.aptly target "/opt/aptly/.aptly", previous <nil>
2021/05/14 14:08:36 archiver/archiver.go:457    archiver.(*Archiver).Save       163       /opt/aptly/.aptly dir
2021/05/14 14:08:36 archiver/archiver.go:233    archiver.(*Archiver).SaveDir    163     /opt/aptly/.aptly /opt/aptly/.aptly
2021/05/14 14:08:36 restic/node.go:624  restic.(*Node).fillExtendedAttributes   163     fillExtendedAttributes(/opt/aptly/.aptly) [] Listxattr: xattr.list /opt/aptly/.aptly : no such file or directory
2021/05/14 14:08:36 archiver/archiver.go:475    archiver.(*Archiver).Save       163     SaveDir for /opt/aptly/.aptly returned error: NodeFromFileInfo: Listxattr: xattr.list /opt/aptly/.aptly : no such file or directory
2021/05/14 14:08:36 archiver/archiver.go:162    archiver.(*Archiver).error      163     item /opt/aptly/.aptly: error was filtered by handler, before: "NodeFromFileInfo: Listxattr: xattr.list /opt/aptly/.aptly : no such file or directory", after: <nil>
2021/05/14 14:08:36 archiver/archiver.go:641    archiver.(*Archiver).SaveTree   163     waiting on 0 nodes
2021/05/14 14:08:36 archiver/archiver.go:616    archiver.(*Archiver).SaveTree   163     /opt, saved subtree Tree<0 nodes> as ac08ce34
2021/05/14 14:08:36 archiver/archiver.go:623    archiver.(*Archiver).SaveTree   163     /opt, dir node data loaded from /opt/aptly
2021/05/14 14:08:36 restic/node.go:624  restic.(*Node).fillExtendedAttributes   163     fillExtendedAttributes(/opt/aptly) [] <nil>
2021/05/14 14:08:36 archiver/archiver.go:641    archiver.(*Archiver).SaveTree   163     waiting on 0 nodes
2021/05/14 14:08:36 archiver/archiver.go:616    archiver.(*Archiver).SaveTree   163     /, saved subtree Tree<1 nodes> as a8c551b9
2021/05/14 14:08:36 archiver/archiver.go:623    archiver.(*Archiver).SaveTree   163     /, dir node data loaded from /opt
2021/05/14 14:08:36 restic/node.go:624  restic.(*Node).fillExtendedAttributes   163     fillExtendedAttributes(/opt) [] <nil>
2021/05/14 14:08:36 archiver/archiver.go:641    archiver.(*Archiver).SaveTree   163     waiting on 0 nodes
2021/05/14 14:08:36 archiver/archiver.go:815    archiver.(*Archiver).Snapshot   1       err is <nil>
2021/05/14 14:08:36 repository/repository.go:355        repository.(*Repository).FlushPacks     1       manually flushing 0 packs
2021/05/14 14:08:36 repository/repository.go:355        repository.(*Repository).FlushPacks     1       manually flushing 0 packs
2021/05/14 14:08:36 repository/master_index.go:201      repository.(*MasterIndex).FinalizeNotFinalIndexes       1       return 0 indexes
2021/05/14 14:08:36 repository/repository.go:293        repository.(*Repository).SaveJSONUnpacked       1       save new blob snapshot
2021/05/14 14:08:36 cache/backend.go:57 cache.(*Backend).Save   1       Save(<snapshot/28331e873a>): auto-store in the cache
2021/05/14 14:08:36 s3/s3.go:260        s3.(*Backend).Save      1       Save <snapshot/28331e873a>
2021/05/14 14:08:36 s3/s3.go:274        s3.(*Backend).Save      1       PutObject(admin-update, snapshots/28331e873a76702510702f19fb443527eadd00ec548d350f475beeaa5a15a745, 387)
2021/05/14 14:08:36 debug/round_tripper_debug.go:82     debug.loggingRoundTripper.RoundTrip     1       ------------  HTTP REQUEST -------

I’d like to note that this is a mounted FUSE filesystem.

Now if I’ve excluded that broken file. But including any other folder which is neighbor of it, fails backup command with:

Fatal: unable to save snapshot: NodeFromFileInfo: Listxattr: xattr.list /opt/aptly/.aptly : no such file or directory

Due to .aptly folder can’t even properly list its files apparently.

5

Now I’m confused. Does the debug log show a successful or a failed backup run? Judging from archiver.(*Archiver).Snapshot 1 err is <nil> that backup run did not fail with the unable to save snapshot error.

There’s also something strange going on with that FUSE filesystem:

no such file or directory is simply the wrong errno to return here. If the file systems doesn’t support xattrs then it should be no supported (or maybe no data) or alternatively just return an empty list of xattrs.

Could you post the relevant part of debug logs which cause restic to fail with cannot access '/opt/aptly/.aptly/?W?B?0!?'$'\001' and Listxattr: xattr.list /opt/aptly/.aptly : no such file or directory?

6

Alright I understood the confusion, here is what happened.

Here is the problematic folder:

~> ls -la /opt/aptly/.aptly
ls: /opt/aptly/.aptly: No such file or directory
ls: cannot access '/opt/aptly/.aptly/?W?B?0!?'$'\001': No such file or directory
total 1017
lrwxrwx--- 1 root  root        0 May  4 19:23  db -> /opt/aptly/.db/
drwx------ 1 aptly aptly       0 May  3 09:31  db.bak/
-rw-r----- 1 aptly aptly 1040194 Apr 23 14:25  LOG
drwxrwxr-x 1 aptly aptly       0 Mar 23 15:48  pool/
drwxrwxr-x 1 aptly aptly       0 Mar 24 10:28  public/
-????????? ? ?     ?           ?            ? '?W?B?0!?'$'\001'

I was originally trying to backup this folder (/opt/aptly/.aptly) with an empty folder named /backup, which gave following warning at the end:

{"message_type":"error","error":{"Op":"lstat","Path":"/opt/aptly/.aptly/?W?B?0!?\u0001","Err":2},"during":"scan","item":"/opt/aptly/.aptly/?W?B?0!?\u0001"}
{"message_type":"error","error":{},"during":"archival","item":"/opt/aptly/.aptly"}
Warning: failed to read all source data during backup

And it created the snapshot with only 3 empty folders:

~> restic ls 484279c6
repository d7957d1e opened successfully, password is correct
snapshot 484279c6 of [/opt/aptly/.aptly /backup] filtered by [] at 2021-05-12 05:45:55.761556724 +0000 UTC):
/backup
/opt
/opt/aptly

It just ignored TB-big /opt/aptly/.aptly/pool subfolder for example.

Then I tried to backup that pool subfolder, thus bypassing the “broken” file. The warning you see ( Fatal: unable to save snapshot: NodeFromFileInfo: Listxattr: xattr.list /opt/aptly/.aptly : no such file or directory) was from this second try. This time it didn’t create a snapshot.

While trying to reproduce the issue with debug log, I again tried to backup main folder, but this time it didn’t create the broken snapshot also. I didn’t understand why, I’ve tried with latest master’s debug-enabled build, might be some changes included. Here is the full log:
http://ix.io/3mSB

Thanks

7

The relevant part from the logfile is the following:


2021/05/14 14:14:13 archiver/archiver.go:616	archiver.(*Archiver).SaveTree	157	/opt/aptly, saved subtree Tree<1 nodes> as e6539b18
2021/05/14 14:14:13 archiver/archiver.go:623	archiver.(*Archiver).SaveTree	157	/opt/aptly, dir node data loaded from /opt/aptly/.aptly
2021/05/14 14:14:13 restic/node.go:624	restic.(*Node).fillExtendedAttributes	157	fillExtendedAttributes(/opt/aptly/.aptly) [] Listxattr: xattr.list /opt/aptly/.aptly : no such file or directory
2021/05/14 14:14:13 archiver/archiver.go:815	archiver.(*Archiver).Snapshot	1	err is NodeFromFileInfo: Listxattr: xattr.list /opt/aptly/.aptly : no such file or directory
2021/05/14 14:14:13 archiver/archiver.go:818	archiver.(*Archiver).Snapshot	1	error while saving tree: NodeFromFileInfo: Listxattr: xattr.list /opt/aptly/.aptly : no such file or directory

The error gets returned here:

restic does not include folders in the backup for which it fails to retrieve the metadata. As unfortunately /opt/aptly/.aptly is seriously broken in that regard, this causes the backup operation to fail right at that point. Just specifying a subfolder won’t work either: restic arranges all backup paths in a virtual tree and then backs up the files specified by these paths. For intermediate directories, for /opt/aptly/.aptly this would be /opt/aptly/.aptly, /opt/aptly and /opt (I’m not completely sure about /), restic must also be able to retrieve the directory metadata.

As a slightly hacky workaround you could use bind mounts to make the data available at a different location without requiring restic to traverse the broken folders.

On the restic side we could let restic backup files/folders despite failing to retrieve extended attributes. That might be worth discussing in a Github issue. But the cleanest solution would be to fix the filesystem.

1 Like