Repro and fix for zero-sized snapshot bug (#641)

* server: repro for zero-sized snapshot bug

As described in https://kopia.discourse.group/t/kopia-0-7-0-not-backing-up-any-files-repro-needed/136/5

* server: fixed zero-sized snapshots after repository is connected via API

The root cause was that source manager was inheriting HTTP call context
which was immediately closed after the 'connect' RPC returned thus
silently killing all uploads.

internal/server/api_sources.go

@@ -9,7 +9,6 @@
 
 	"github.com/pkg/errors"
 
-	"github.com/kopia/kopia/internal/ctxutil"
 	"github.com/kopia/kopia/internal/serverapi"
 	"github.com/kopia/kopia/repo"
 	"github.com/kopia/kopia/snapshot"
@@ -104,7 +103,7 @@ func (s *Server) handleSourcesCreate(ctx context.Context, r *http.Request, body
 		sm := newSourceManager(sourceInfo, s)
 		s.sourceManagers[sourceInfo] = sm
 
-		go sm.run(ctxutil.Detach(ctx))
+		go sm.run(ctx)
 	}
 	s.mu.Unlock()
 	s.mu.RLock()

internal/server/source_manager.go

@@ -7,6 +7,7 @@
 
 	"github.com/kopia/kopia/fs/localfs"
 	"github.com/kopia/kopia/internal/clock"
+	"github.com/kopia/kopia/internal/ctxutil"
 	"github.com/kopia/kopia/internal/serverapi"
 	"github.com/kopia/kopia/snapshot"
 	"github.com/kopia/kopia/snapshot/policy"
@@ -89,6 +90,9 @@ func (s *sourceManager) setUploader(u *snapshotfs.Uploader) {
 }
 
 func (s *sourceManager) run(ctx context.Context) {
+	// make sure we run in a detached context, which ignores outside cancelation and deadline.
+	ctx = ctxutil.Detach(ctx)
+
 	s.setStatus("INITIALIZING")
 	defer s.setStatus("STOPPED")
 

tests/end_to_end_test/server_start_test.go

@@ -185,7 +185,7 @@ func TestServerStart(t *testing.T) {
 	waitForSnapshotCount(ctx, t, cli, &snapshot.SourceInfo{Host: "fake-hostname", UserName: "fake-username", Path: sharedTestDataDir3}, 1)
 }
 
-func TestServerStartWithoutInitialRepository(t *testing.T) {
+func TestServerCreateAndConnectViaAPI(t *testing.T) {
 	t.Parallel()
 
 	ctx := testlogging.Context(t)
@@ -248,6 +248,81 @@ func TestServerStartWithoutInitialRepository(t *testing.T) {
 	verifyServerConnected(t, cli, true)
 }
 
+func TestConnectToExistingRepositoryViaAPI(t *testing.T) {
+	t.Parallel()
+
+	ctx := testlogging.Context(t)
+
+	e := testenv.NewCLITest(t)
+	e.RunAndExpectSuccess(t, "repo", "create", "filesystem", "--path", e.RepoDir, "--override-hostname=fake-hostname", "--override-username=fake-username")
+	e.RunAndExpectSuccess(t, "snapshot", "create", sharedTestDataDir1)
+	e.RunAndExpectSuccess(t, "snapshot", "create", sharedTestDataDir1)
+	e.RunAndExpectSuccess(t, "repo", "disconnect")
+
+	var sp serverParameters
+
+	connInfo := blob.ConnectionInfo{
+		Type: "filesystem",
+		Config: filesystem.Options{
+			Path: e.RepoDir,
+		},
+	}
+
+	// at this point repository is not connected, start the server
+	e.RunAndProcessStderr(t, sp.ProcessOutput, "server", "start", "--ui", "--address=localhost:0", "--random-password", "--tls-generate-cert", "--auto-shutdown=180s", "--override-hostname=fake-hostname", "--override-username=fake-username")
+	t.Logf("detected server parameters %#v", sp)
+
+	cli, err := apiclient.NewKopiaAPIClient(apiclient.Options{
+		BaseURL:                             sp.baseURL,
+		Username:                            "kopia",
+		Password:                            sp.password,
+		TrustedServerCertificateFingerprint: sp.sha256Fingerprint,
+	})
+	if err != nil {
+		t.Fatalf("unable to create API apiclient")
+	}
+
+	defer serverapi.Shutdown(ctx, cli)
+
+	waitUntilServerStarted(ctx, t, cli)
+	verifyServerConnected(t, cli, false)
+
+	if err = serverapi.ConnectToRepository(ctx, cli, &serverapi.ConnectRepositoryRequest{
+		Password: testenv.TestRepoPassword,
+		Storage:  connInfo,
+	}); err != nil {
+		t.Fatalf("connect error: %v", err)
+	}
+
+	verifyServerConnected(t, cli, true)
+
+	si := snapshot.SourceInfo{Host: "fake-hostname", UserName: "fake-username", Path: sharedTestDataDir1}
+
+	uploadMatchingSnapshots(t, cli, &si)
+
+	snaps := waitForSnapshotCount(ctx, t, cli, &si, 3)
+
+	// we're reproducing the bug described in, after connecting to repo via API, next snapshot size becomes zero.
+	// https://kopia.discourse.group/t/kopia-0-7-0-not-backing-up-any-files-repro-needed/136/6?u=jkowalski
+	minSize := snaps[0].Summary.TotalFileSize
+	maxSize := snaps[0].Summary.TotalFileSize
+
+	for _, sn := range snaps {
+		v := sn.Summary.TotalFileSize
+		if v < minSize {
+			minSize = v
+		}
+
+		if v > maxSize {
+			maxSize = v
+		}
+	}
+
+	if minSize != maxSize {
+		t.Errorf("snapshots don't have consistent size: min %v max %v", minSize, maxSize)
+	}
+}
+
 func verifyServerConnected(t *testing.T, cli *apiclient.KopiaAPIClient, want bool) *serverapi.StatusResponse {
 	t.Helper()
 
@@ -263,9 +338,11 @@ func verifyServerConnected(t *testing.T, cli *apiclient.KopiaAPIClient, want boo
 	return st
 }
 
-func waitForSnapshotCount(ctx context.Context, t *testing.T, cli *apiclient.KopiaAPIClient, match *snapshot.SourceInfo, want int) {
+func waitForSnapshotCount(ctx context.Context, t *testing.T, cli *apiclient.KopiaAPIClient, match *snapshot.SourceInfo, want int) []*serverapi.Snapshot {
 	t.Helper()
 
+	var result []*serverapi.Snapshot
+
 	err := retry.PeriodicallyNoValue(ctx, 1*time.Second, 180, "wait for snapshots", func() error {
 		snapshots, err := serverapi.ListSnapshots(testlogging.Context(t), cli, match)
 		if err != nil {
@@ -276,11 +353,15 @@ func waitForSnapshotCount(ctx context.Context, t *testing.T, cli *apiclient.Kopi
 			return errors.Errorf("unexpected number of snapshots %v, want %v", got, want)
 		}
 
+		result = snapshots.Snapshots
+
 		return nil
 	}, retry.Always)
 	if err != nil {
 		t.Fatal(err)
 	}
+
+	return result
 }
 
 func uploadMatchingSnapshots(t *testing.T, cli *apiclient.KopiaAPIClient, match *snapshot.SourceInfo) {

tests/testenv/cli_test_env.go

@@ -24,7 +24,9 @@
 )
 
 const (
-	repoPassword        = "qWQPJ2hiiLgWRRCr"
+	// TestRepoPassword is a password for repositories created in tests.
+	TestRepoPassword = "qWQPJ2hiiLgWRRCr"
+
 	maxOutputLinesToLog = 40
 )
 
@@ -93,7 +95,7 @@ func NewCLITest(t *testing.T) *CLITest {
 		fixedArgs: fixedArgs,
 		LogsDir:   logsDir,
 		Environment: []string{
-			"KOPIA_PASSWORD=" + repoPassword,
+			"KOPIA_PASSWORD=" + TestRepoPassword,
 			"KOPIA_ADVANCED_COMMANDS=enabled",
 		},
 	}