From c9c8d27c8db2096bf32e3eff052ddfb387b25f00 Mon Sep 17 00:00:00 2001 From: Jarek Kowalski Date: Wed, 23 Sep 2020 20:15:36 -0700 Subject: [PATCH] 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 | 3 +- internal/server/source_manager.go | 4 + tests/end_to_end_test/server_start_test.go | 85 +++++++++++++++++++++- tests/testenv/cli_test_env.go | 6 +- 4 files changed, 92 insertions(+), 6 deletions(-) diff --git a/internal/server/api_sources.go b/internal/server/api_sources.go index d61467467..fb13322e2 100644 --- a/internal/server/api_sources.go +++ b/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() diff --git a/internal/server/source_manager.go b/internal/server/source_manager.go index 1c1ff6b0b..1a3294975 100644 --- a/internal/server/source_manager.go +++ b/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") diff --git a/tests/end_to_end_test/server_start_test.go b/tests/end_to_end_test/server_start_test.go index deb982ed9..b50206e42 100644 --- a/tests/end_to_end_test/server_start_test.go +++ b/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) { diff --git a/tests/testenv/cli_test_env.go b/tests/testenv/cli_test_env.go index 935d44e02..3309d635f 100644 --- a/tests/testenv/cli_test_env.go +++ b/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", }, }