Restore inconsistent timestamps permissions

[kitone]

What does this PR change? What problem does it solve?

Fix inconsistent timestamps/permissions during restore in some case

Was the change discussed in an issue or in the forum before?

#1212

Checklist

• I have read the Contribution Guidelines
• I have enabled maintainer edits for this PR
• I have added tests for all changes in this PR
• I have added documentation for the changes (in the manual)
• There's a new file in changelog/unreleased/ that describes the changes for our users (template here)
• I have run gofmt on the code in all commits
• All commit messages are formatted in the same style as the other commits in the repo
• I'm done, this Pull Request is ready for review

Information

The current implementation of restore code using two pass does not restore the metadata of all elements.

I will use a simplified reproductible script to reduce the log/debug
you can find the complet reproductible script (thanks to @deviantintegral) there #1212 (comment)

About the change :

• The first commit extend and add test case to check Mode and ModTime
• The second add log information because it was pretty hard to debug treeVisitor proc functions and understand what happenning.
• The fix make the simplified and complet reproductible script work, but introduce a bad behaviour, trying to restore metadata on a file/dir not selected for restore.
  ignoring error for /test/bar: UtimesNano: no such file or directory

The simplified script, show that metadata on the root directory isn't restored

#!/bin/bash

export DEBUG_LOG=restic-debug.log

check_equal_permission()
{
  echo "Comparing permissions on $1 to $2..."
  (test $(stat -f %p $1) -eq $(stat -f %p $2) && echo "Passed!") || (echo "#### Comparison failed." && ls -ld $1 && ls -ld $2)
  echo ""
}

check_equal_modified()
{
  echo "Comparing modified dates on $1 to $2..."
  (test $(stat -f %m $1) -eq $(stat -f %m $2) && echo "Passed!") || (echo "#### Comparison failed." && ls -ld $1 && ls -ld $2)
  echo ""
}

check_file()
{
  check_equal_permission $1 $2
  check_equal_modified $1 $2
}

rm restic-debug.log
mkdir -p test/{dir1,dir2}
mkdir -p test/dir1/dir3/
chmod 700 test/dir1
chmod 700 test/dir1/dir3
touch -t 201901010000 test/{dir1,dir2}/{file1,file2} test/{dir1,dir2} test test/dir1/dir3/file3
restic --password-command='echo pass' -r repo init
restic --password-command='echo pass' -r repo backup test

rm restic-debug.log

restic --password-command='echo pass' -r repo restore latest --include 'file1' --target restored
check_file test restored/test

rm -rf test repo restored

The logs show that leaveDir is never executed, this is why the metadata of the root directory and in some case isn't restored.

// first tree pass: create directories and collect all files to restore
err = res.traverseTree(ctx, dst, string(filepath.Separator), *res.sn.Tree, treeVisitor{
  enterDir: func(node *restic.Node, target, location string) error {
    debug.Log("first pass, enterDir: mkdir %q, leaveDir should restore metadata", location)
    // create dir with default permissions
    // #leaveDir restores dir metadata after visiting all children
    return fs.MkdirAll(target, 0700)
  },

  visitNode: func(node *restic.Node, target, location string) error {
    debug.Log("first pass, visitNode: mkdir %q, leaveDir on second pass should restore metadata", location)
    // create parent dir with default permissions
    // second pass #leaveDir restores dir metadata after visiting/restoring all children
    err := fs.MkdirAll(filepath.Dir(target), 0700)

I guess, also because we use MkdirAll, so when we pass on "/test/dir1" but restoring with ---include 'file1' childMayBeSelected is equal to true, but the leaveDir is only executed on selectedForRestore

restorer/restorer.go:93	  restorer.(*Restorer).traverseTree	SelectFilter returned false true for "/test"

if selectedForRestore {
  err = sanitizeError(visitor.leaveDir(node, nodeTarget, nodeLocation))
  if err != nil {
    return err
  }
}

restorer/restorer.go:208	restorer.(*Restorer).RestoreTo	first pass for "/Users/kitone/Downloads/restic_kitone/issues_1212/restored"
restorer/restorer.go:53	  restorer.(*Restorer).traverseTree	/Users/kitone/Downloads/restic_kitone/issues_1212/restored / cfd11f1ffa1ce50693db112af06c4df85ba92ec5dd3a5a18247c81e7a067c774
restorer/restorer.go:93	  restorer.(*Restorer).traverseTree	SelectFilter returned false true for "/test"
restorer/restorer.go:53	  restorer.(*Restorer).traverseTree	/Users/kitone/Downloads/restic_kitone/issues_1212/restored/test /test d6c3f48a1e21c0032e57790081a46f6aa25de05e307fae94c2859d3bc1670c33
restorer/restorer.go:93	  restorer.(*Restorer).traverseTree	SelectFilter returned false true for "/test/dir1"
restorer/restorer.go:53	  restorer.(*Restorer).traverseTree	/Users/kitone/Downloads/restic_kitone/issues_1212/restored/test/dir1 /test/dir1 5adbd0033dc689a2195d61fb22b8ef6e8be43ba473528bb7e8c3fd8e0e4e2083
restorer/restorer.go:93	  restorer.(*Restorer).traverseTree	SelectFilter returned false true for "/test/dir1/dir3"
restorer/restorer.go:53	  restorer.(*Restorer).traverseTree	/Users/kitone/Downloads/restic_kitone/issues_1212/restored/test/dir1/dir3 /test/dir1/dir3 ab6863baeb85cbe416e25baefd0f11622a69712323c986a027dfe4a85cf1852d
restorer/restorer.go:93	  restorer.(*Restorer).traverseTree	SelectFilter returned false false for "/test/dir1/dir3/file3"
restorer/restorer.go:93	  restorer.(*Restorer).traverseTree	SelectFilter returned true false for "/test/dir1/file1"
restorer/restorer.go:220	restorer.(*Restorer).RestoreTo.func2	first pass, visitNode: mkdir "/test/dir1/file1", leaveDir on second pass should restore metadata
restorer/restorer.go:93	  restorer.(*Restorer).traverseTree	SelectFilter returned false false for "/test/dir1/file2"
restorer/restorer.go:93	  restorer.(*Restorer).traverseTree	SelectFilter returned false true for "/test/dir2"
restorer/restorer.go:53	  restorer.(*Restorer).traverseTree	/Users/kitone/Downloads/restic_kitone/issues_1212/restored/test/dir2 /test/dir2 81891851485d83cf6cf8e605bf3ea3487a9951cbfb2e58696db5fb326373ddd5
restorer/restorer.go:93	  restorer.(*Restorer).traverseTree	SelectFilter returned true false for "/test/dir2/file1"
restorer/restorer.go:220	restorer.(*Restorer).RestoreTo.func2	first pass, visitNode: mkdir "/test/dir2/file1", leaveDir on second pass should restore metadata
restorer/restorer.go:93	  restorer.(*Restorer).traverseTree	SelectFilter returned false false for "/test/dir2/file2"

restorer/restorer.go:261	restorer.(*Restorer).RestoreTo	second pass for "/Users/kitone/Downloads/restic_kitone/issues_1212/restored"
restorer/restorer.go:53	  restorer.(*Restorer).traverseTree	/Users/kitone/Downloads/restic_kitone/issues_1212/restored / cfd11f1ffa1ce50693db112af06c4df85ba92ec5dd3a5a18247c81e7a067c774
restorer/restorer.go:93	  restorer.(*Restorer).traverseTree	SelectFilter returned false true for "/test"
restorer/restorer.go:53	  restorer.(*Restorer).traverseTree	/Users/kitone/Downloads/restic_kitone/issues_1212/restored/test /test d6c3f48a1e21c0032e57790081a46f6aa25de05e307fae94c2859d3bc1670c33
restorer/restorer.go:93	  restorer.(*Restorer).traverseTree	SelectFilter returned false true for "/test/dir1"
restorer/restorer.go:53	  restorer.(*Restorer).traverseTree	/Users/kitone/Downloads/restic_kitone/issues_1212/restored/test/dir1 /test/dir1 5adbd0033dc689a2195d61fb22b8ef6e8be43ba473528bb7e8c3fd8e0e4e2083
restorer/restorer.go:93	  restorer.(*Restorer).traverseTree	SelectFilter returned false true for "/test/dir1/dir3"
restorer/restorer.go:53	  restorer.(*Restorer).traverseTree	/Users/kitone/Downloads/restic_kitone/issues_1212/restored/test/dir1/dir3 /test/dir1/dir3 ab6863baeb85cbe416e25baefd0f11622a69712323c986a027dfe4a85cf1852d
restorer/restorer.go:93	  restorer.(*Restorer).traverseTree	SelectFilter returned false false for "/test/dir1/dir3/file3"
restorer/restorer.go:93	  restorer.(*Restorer).traverseTree	SelectFilter returned true false for "/test/dir1/file1"
restorer/restorer.go:270	restorer.(*Restorer).RestoreTo.func5	second pass, visitNode: restore node "/test/dir1/file1"
restorer/restorer.go:158	restorer.(*Restorer).restoreNodeMetadataTo	restoreNodeMetadata file1 /Users/kitone/Downloads/restic_kitone/issues_1212/restored/test/dir1/file1 /test/dir1/file1
restorer/restorer.go:93	  restorer.(*Restorer).traverseTree	SelectFilter returned false false for "/test/dir1/file2"
restorer/restorer.go:93	  restorer.(*Restorer).traverseTree	SelectFilter returned false true for "/test/dir2"
restorer/restorer.go:53	  restorer.(*Restorer).traverseTree	/Users/kitone/Downloads/restic_kitone/issues_1212/restored/test/dir2 /test/dir2 81891851485d83cf6cf8e605bf3ea3487a9951cbfb2e58696db5fb326373ddd5
restorer/restorer.go:93	  restorer.(*Restorer).traverseTree	SelectFilter returned true false for "/test/dir2/file1"
restorer/restorer.go:270	restorer.(*Restorer).RestoreTo.func5	second pass, visitNode: restore node "/test/dir2/file1"
restorer/restorer.go:158	restorer.(*Restorer).restoreNodeMetadataTo	restoreNodeMetadata file1 /Users/kitone/Downloads/restic_kitone/issues_1212/restored/test/dir2/file1 /test/dir2/file1
restorer/restorer.go:93	  restorer.(*Restorer).traverseTree	SelectFilter returned false false for "/test/dir2/file2"

The solution is to keep track of restored child status so parent and root directory not selected by filter will also restore metadata when traversing the tree.

[kitone]

I have push a proper solution that doesn't have side effect of trying to restore unwanted directory.

This broke a test case, causing leaveDir call more that one time, but I'm not sure to understand this test...

--- FAIL: TestRestorerTraverseTree (0.01s)
    --- FAIL: TestRestorerTraverseTree/#04 (0.00s)
        testing.go:30: using low-security KDF parameters for test
        config.go:65: disabling check of the chunker polynomial
        restorer_test.go:506: step 1, leaveDir(/dir): expected no more than 1 function calls

[kitone]

Continuous integration fail on windows, I have try to fix it without success. Would love little help, I don't understand why this fail on windows.

[MichaelEischer]

@kitone My guess would be that res.SelectFilter doesn't work on Windows. item and dstpath are assembled using filepath.Join which uses \ as path separator on Windows. You could try whether filepath.ToSlash solves the problem.

[kitone]

@MichaelEischer thank you! You right, ToSlash fix the select filter on windows.
The test was still falling to set the permission on windows but after checking the doc https://golang.org/pkg/os/#Chmod I think my test was to specific to unix, so I move the test into restorer_unix_test.go file instead.

I will try to add a simple test case for windows.

[kitone]

integration for unix and windows are green.

I guess we could merge both new case into restorer_test.go using filepath.ToSlash(item) in SelectFilter and use 0555 | os.ModeDir and os.FileMode(0444) also for unix, test should work.

Let me know if you think it's better to do that or let this separate for more specific test for the future.

[MichaelEischer]

The fix itself looks good to me. The debug logging could be a bit less verbose (see comment) and the test implementation has to be unified between Unix and Windows. And this PR also needs a changelog entry.

[MichaelEischer]

LGTM. Thanks for quickly fixing all our comments :-) .
I've rebased the branch to the current master and renamed the changelog file to issue-1212.