Repository: kopia/kopia

Issue:
Rclone backups are not working
I just upgraded to 0.22.1 and all of my rclone backups throw errors.

unable to create policy getter: unable to get policies: unable to get parent policies: unable to find manifest for source source@computer.name:D:\Folder: unable to load manifest contents: error refreshing indexes: mutable parameters: unable to read format blob: error getting kopia.repository blob: error flushing dir cache: RC error: Post "https://127.0.0.1:54298/vfs/forget": dial tcp 127.0.0.1:54298: connectex: Connection refused.

And my home computer throws;
08:56:13.119 got error Put "https://127.0.0.1:35637/pf7/978/8177ee69380dd2fc9b1aa00b306-sd0f9b9be92911fae13b.f-5811583191278177141": dial tcp 127.0.0.1:35637: connect: connection refused when WriteTemporaryFileAndCreateParentDirs (#7), sleeping for 1.70859375s before retrying

or 

09:01:50.288 async write error: unable to write content chunk 58 of FILE:CFETVNMWFM.sqlite: mutable parameters: unable to read format blob: error getting kopia.repository blob: error flushing dir cache: RC error: Post "https://127.0.0.1:33133/vfs/forget": dial tcp 127.0.0.1:33133: connect: connection refused: mutable parameters: unable to read format blob: error getting kopia.repository blob: error flushing dir cache: RC error: Post "https://127.0.0.1:33133/vfs/forget": dial tcp 127.0.0.1:33133: connect: connection refused

or

{"path":".","error":"unable to process directory \"Folder\": error writing dir manifest: Duplicati: unable to write directory: unable to write content chunk 0 of DIR:Folder: mutable parameters: unable to read format blob: error getting kopia.repository blob: error flushing dir cache: RC error: Post \"https://127.0.0.1:33133/vfs/forget\": dial tcp 127.0.0.1:33133: connect: connection refused: mutable parameters: unable to read format blob: error getting kopia.repository blob: error flushing dir cache: RC error: Post \"https://127.0.0.1:33133/vfs/forget\": dial tcp 127.0.0.1:33133: connect: connection refused","dur":"14m35.628483408s"}

Hints from issue comments:
@milindpatel63: I'm having the same issue.
Running v0.22.1 in docker.
Snapshot logs show multiple of these errors,
```
16:53:49.588 got error Put "https://127.0.0.1:36239/se8/af0/15a92150fb41da878541c877b3e-s8bb704a2ca44938213b.f-8554497933529558087": dial tcp 127.0.0.1:36239: connect: connection refused when WriteTemporaryFileAndCreateParentDirs (#9), sleeping for 3.844335937s before retrying
```@basldfalksjdf: Did this start in 0.22.0 or 0.22.1?@dantesbr: Same here.

`Error: unable to create policy getter: unable to get policies: unable to get parent policies: unable to find manifest for source source@computer:/rootfs/etc: unable to load manifest contents: error refreshing indexes: mutable parameters: unable to read format blob: error getting kopia.repository blob: error flushing dir cache: RC error: Post "https://127.0.0.1:34339/vfs/forget": dial tcp 127.0.0.1:34339: connect: connection refused.`

this issue started in 0.22.1; 0.22.0 was working fine.

@headcrushed: > Did this start in 0.22.0 or 0.22.1?

0.22.1, it was working yesterday.@basldfalksjdf: Hmmm. Alright. If anyone can figure out the regression introduced by 0.22.1 that broke rclone integration, feel free to submit a PR. Otherwise, pinging the main devs to see if they can spot the problem @jkowalski @julio-lopez 

My guess is, this is being caused by https://github.com/kopia/kopia/issues/5003

Solution patch:
diff --git a/repo/blob/rclone/rclone_storage.go b/repo/blob/rclone/rclone_storage.go
index 77d2a435..b59bed2b 100644
--- a/repo/blob/rclone/rclone_storage.go
+++ b/repo/blob/rclone/rclone_storage.go
@@ -339,7 +339,7 @@ func New(ctx context.Context, opt *Options, isCreate bool) (blob.Storage, error)
 		"--vfs-write-back=0s", // disable write-back, critical for correctness
 	)
 
-	r.cmd = exec.CommandContext(ctx, rcloneExe, arguments...) //nolint:gosec
+	r.cmd = exec.CommandContext(context.WithoutCancel(ctx), rcloneExe, arguments...) //nolint:gosec
 	r.cmd.Env = append(r.cmd.Env, opt.RCloneEnv...)
 
 	// https://github.com/kopia/kopia/issues/1934
diff --git a/repo/blob/sftp/sftp_storage.go b/repo/blob/sftp/sftp_storage.go
index b1ebfd54..a4d2cb52 100644
--- a/repo/blob/sftp/sftp_storage.go
+++ b/repo/blob/sftp/sftp_storage.go
@@ -553,7 +553,9 @@ func New(ctx context.Context, opts *Options, isCreate bool) (blob.Storage, error
 
 	impl.rec = connection.NewReconnector(impl)
 
-	conn, err := impl.rec.GetOrOpenConnection(ctx)
+	// removing cancelation from ctx since ctx is likely to be canceled after
+	// New returns, causing the initial connection to be closed and not reused
+	conn, err := impl.rec.GetOrOpenConnection(context.WithoutCancel(ctx))
 	if err != nil {
 		return nil, errors.Wrap(err, "unable to open SFTP storage")
 	}



Test patch:
diff --git a/internal/testutil/dockertestutil.go b/internal/testutil/dockertestutil.go
index 8b22acda..6b69d8ae 100644
--- a/internal/testutil/dockertestutil.go
+++ b/internal/testutil/dockertestutil.go
@@ -50,7 +50,7 @@ func RunContainerAndKillOnCloseOrSkip(t *testing.T, args ...string) string {
 
 	t.Cleanup(func() {
 		// t.Context() is canceled by the time cleanup executes, so it cannot be used here
-		runDockerAndGetOutputOrSkip(context.Background(), t, "kill", containerID)
+		runDockerAndGetOutputOrSkip(context.WithoutCancel(t.Context()), t, "kill", containerID)
 	})
 
 	return containerID
diff --git a/repo/blob/rclone/rclone_storage_test.go b/repo/blob/rclone/rclone_storage_test.go
index 7bb6ae79..50b3bc81 100644
--- a/repo/blob/rclone/rclone_storage_test.go
+++ b/repo/blob/rclone/rclone_storage_test.go
@@ -62,6 +62,38 @@ func mustGetRcloneExeOrSkip(t *testing.T) string {
 	return rcloneExe
 }
 
+func TestRCloneStorageCancelContext(t *testing.T) {
+	t.Parallel()
+	testutil.ProviderTest(t)
+
+	rcloneExe := mustGetRcloneExeOrSkip(t)
+	dataDir := testutil.TempDirectory(t)
+	ctx := testlogging.Context(t)
+
+	// use context that gets canceled after opening storage to ensure it's not used beyond New().
+	newCtx, cancel := context.WithCancel(ctx)
+	st, err := rclone.New(newCtx, &rclone.Options{
+		// pass local file as remote path.
+		RemotePath: dataDir,
+		RCloneExe:  rcloneExe,
+	}, true)
+
+	cancel()
+
+	require.NoError(t, err, "unable to connect to rclone backend")
+	require.NotNil(t, st, "unable to connect to rclone backend")
+
+	t.Cleanup(func() {
+		st.Close(testlogging.ContextForCleanup(t))
+	})
+
+	var tmp gather.WriteBuffer
+	defer tmp.Close()
+
+	err = st.GetBlob(ctx, blob.ID(uuid.New().String()), 0, -1, &tmp)
+	require.ErrorIs(t, err, blob.ErrBlobNotFound, "unexpected error when downloading non-existent blob")
+}
+
 func TestRCloneStorage(t *testing.T) {
 	t.Parallel()
 	testutil.ProviderTest(t)
@@ -72,8 +104,8 @@ func TestRCloneStorage(t *testing.T) {
 	dataDir := testutil.TempDirectory(t)
 
 	// use context that gets canceled after opening storage to ensure it's not used beyond New().
-	newctx, cancel := context.WithCancel(ctx)
-	st, err := rclone.New(newctx, &rclone.Options{
+	newCtx, cancel := context.WithCancel(ctx)
+	st, err := rclone.New(newCtx, &rclone.Options{
 		// pass local file as remote path.
 		RemotePath: dataDir,
 		RCloneExe:  rcloneExe,
diff --git a/repo/blob/sftp/sftp_storage_test.go b/repo/blob/sftp/sftp_storage_test.go
index 002a13aa..306473ca 100644
--- a/repo/blob/sftp/sftp_storage_test.go
+++ b/repo/blob/sftp/sftp_storage_test.go
@@ -212,8 +212,9 @@ func TestSFTPStorageValid(t *testing.T) {
 
 	t.Run("PasswordCreds", func(t *testing.T) {
 		ctx := testlogging.Context(t)
+		newctx, cancel := context.WithCancel(ctx)
 
-		st, err := createSFTPStorage(ctx, t, sftp.Options{
+		st, err := createSFTPStorage(newctx, t, sftp.Options{
 			Path:           "/upload2",
 			Host:           host,
 			Username:       sftpUsernameWithPasswordAuth,
@@ -226,6 +227,8 @@ func TestSFTPStorageValid(t *testing.T) {
 			t.Fatalf("unable to connect to SSH: %v", err)
 		}
 
+		cancel()
+
 		deleteBlobs(ctx, t, st)
 
 		blobtesting.VerifyStorage(ctx, t, st, blob.PutOptions{})