Fatal: unable to save snapshot: Access denied (under go test on Windows)

Hi there -

I’m trying to solve a bug in the backrest UI for restic, where Windows backups take 50% longer when run under backrest than when invoked directly on the CLI.

The program works by invoking restic and parsing its stdout status messages. I suspect there is some kind of IO issues causing the slowdown on Windows, but so far I’ve been unable to track it down or isolate the cause.

I decided to change tacks today and create a Benchmark function to invoke the restic backup wrapping code, to at least save some iteration time. However, when running under go test I get a very bizarre Access Denied error and I’m wondering if anyone has ideas:

        Process STDOUT:
        {"message_type":"status","percent_done":0,"total_files":1,"total_bytes":10737418240,"current_files":["/C/backrest/1162000510/10G-data4135267563"]}
        {"message_type":"status","seconds_remaining":4661,"percent_done":0.00006117867305874825,"total_files":1,"total_bytes":10737418240,"bytes_done":656901,"current_files":["/C/backrest/1162000510/10G-data4135267563"]}
        {"message_type":"status","seconds_remaining":1862,"percent_done":0.0001660994254052639,"total_files":1,"total_bytes":10737418240,"bytes_done":1783479,"current_files":["/C/backrest/1162000510/10G-data4135267563"]}
        {"message_type":"status","seconds_remaining":1917,"percent_done":0.0001660994254052639,"total_files":1,"total_bytes":10737418240,"bytes_done":1783479,"current_files":["/C/backrest/1162000510/10G-data4135267563"]}
        {"message_type":"error","error":{},"during":"archival","item":""}
        {"message_type":"error","error":{},"during":"archival","item":""}
        {"message_type":"error","error":{},"during":"archival","item":""}
        {"message_type":"error","error":{},"during":"archival","item":""}
        {"message_type":"status","seconds_remaining":2030,"percent_done":0.0001660994254052639,"total_files":1,"total_bytes":10737418240,"bytes_done":1783479,"error_count":4}
        Fatal: unable to save snapshot: Access is denied.

When I look at the created temporary directories, the repository was init’d successfully and every use has full permission over the directory and its parent.

The internet suggested antivirus can interfere, but I disabled Real-Time Protection in Windows Defender and I’m still having issues. Does anyone have any ideas what might be going on?

Here’s my test code:

func BenchmarkResticBackup(b *testing.B) {
	for i := 0; i < b.N; i++ {
		// stop the timer during test setup
		b.StopTimer()
		repo, err := os.MkdirTemp("C:\\backrest", "")
		if err != nil {
			b.Fatalf("failed to create temp dir: %v", err)
		}
		b.Logf("repo: %s", repo)

		// create a new repo with cache disabled for testing
		binPath, err := resticinstaller.FindOrInstallResticBinary()
		if err != nil {
			b.Fatalf("find restic binary: %v", err)
		}

		r := NewRepo(binPath, repo, WithFlags("--no-cache"), WithEnv("RESTIC_PASSWORD=test"))
		if err := r.Init(context.Background()); err != nil {
			b.Fatalf("failed to init repo: %v", err)
		}

		// create 10G of test data
		dir, err := os.MkdirTemp("C:\\backrest", "")
		if err != nil {
			b.Fatalf("failed to create temp dir: %v", err)
		}
		b.Logf("dir: %s", dir)
		f, err := os.CreateTemp(dir, "10G-data")
		if err != nil {
			b.Fatalf("failed to create file: %v", err)
		}

		// generate and write 10G of data from random
		rr := io.LimitReader(rand.Reader, 10*1024*1024*1024)
		if _, err := io.Copy(f, rr); err != nil {
			b.Fatalf("failed to write 10G of data: %v", err)
		}
		f.Close()

		// make sure permissions are set openly
		if err := RecursiveChmod(dir, 0777); err != nil {
			b.Fatalf("failed to set permissions: %v", err)
		}
		if err := RecursiveChmod(repo, 0777); err != nil {
			b.Fatalf("failed to set permissions: %v", err)
		}

		// start the timer and perform a backup
		b.StartTimer()

		_, err = r.Backup(context.Background(), []string{dir}, func(event *BackupProgressEntry) {
			b.Logf("backup event: %v", event)
		})
		if err != nil {
			b.Fatalf("unexpected error: %v", err)
		}

		// delete test data
		if err := os.RemoveAll(dir); err != nil {
			b.Fatalf("failed to remove test data: %v", err)
		}
		if err := os.RemoveAll(repo); err != nil {
			b.Fatalf("failed to remove repo: %v", err)
		}
	}
}
2 Likes

The log looks like the output from stderr is missing. Judging from the error message, there’s either a problem with writing to the TMPDIR or with writing to the repository.

Which restic version do you use?

Hey thanks for the reply! This is occurring when running tests against restic 0.16.4. I think you are right that stderr isn’t being captured. I’ll look at adding that and see if it offers any hints.

Both the Restic repo and test data directory lives in a temporary directory (os.MkdirTemp.) In this case, that’s somewhere inside %AppData%.

I did find a few users online complaining about “Access denied” errors when interacting with this directory via Go programs, especially when running via go run, so this sounds similar to what I’m seeing with go test. I also don’t see these errors when running under Github CI.

I suspect that there may be some kind of AV / Window Defender interference occurring - although I did disable Windows Defender’s Real-Time Protection, to no avail.

I was busy the last couple days with the total eclipse here, but I’ll take another look at this soon and share what I find.