improve logging in ReplicateRepository

ReplicateRepository currently does not add a lot of context to the
errors when returning them. This makes it difficult to identify
which command failed. This commit improves the situation by adding
context to the returned errors.

5 files changed, 35 insertions, 25 deletions

diff --git a/changelogs/unreleased/smh-improve-logging.yml b/changelogs/unreleased/smh-improve-logging.yml
new file mode 100644
index 000000000..3a520b241
--- /dev/null
+++ b/changelogs/unreleased/smh-improve-logging.yml
@@ -0,0 +1,5 @@
+---
+title: Improve logging in ReplicateRepository
+merge_request: 2767
+author:
+type: other
diff --git a/internal/gitaly/service/remote/fetch_internal_remote.go b/internal/gitaly/service/remote/fetch_internal_remote.go
index fe0d7bdd5..5a1391427 100644
--- a/internal/gitaly/service/remote/fetch_internal_remote.go
+++ b/internal/gitaly/service/remote/fetch_internal_remote.go
@@ -28,22 +28,24 @@ func (s *server) FetchInternalRemote(ctx context.Context, req *gitalypb.FetchInt
 
 	env, err := gitalyssh.UploadPackEnv(ctx, &gitalypb.SSHUploadPackRequest{Repository: req.RemoteRepository})
 	if err != nil {
-		return nil, err
+		return nil, fmt.Errorf("upload pack environment: %w", err)
 	}
 
+	stderr := &bytes.Buffer{}
 	cmd, err := git.SafeCmdWithEnv(ctx, env, req.Repository, nil,
 		git.SubCmd{
 			Name:  "fetch",
 			Flags: []git.Option{git.Flag{Name: "--prune"}},
 			Args:  []string{gitalyssh.GitalyInternalURL, mirrorRefSpec},
 		},
+		git.WithStderr(stderr),
 	)
 	if err != nil {
-		return nil, err
+		return nil, fmt.Errorf("create git fetch: %w", err)
 	}
 	if err := cmd.Wait(); err != nil {
 		// Design quirk: if the fetch fails, this RPC returns Result: false, but no error.
-		ctxlogrus.Extract(ctx).WithError(err).Warn("git fetch failed")
+		ctxlogrus.Extract(ctx).WithError(err).WithField("stderr", stderr.String()).Warn("git fetch failed")
 		return &gitalypb.FetchInternalRemoteResponse{Result: false}, nil
 	}
 
diff --git a/internal/gitaly/service/repository/create.go b/internal/gitaly/service/repository/create.go
index 7f56fca8e..b9fc42d3a 100644
--- a/internal/gitaly/service/repository/create.go
+++ b/internal/gitaly/service/repository/create.go
@@ -1,6 +1,7 @@
 package repository
 
 import (
+	"bytes"
 	"context"
 	"os"
 
@@ -12,14 +13,15 @@ import (
 func (s *server) CreateRepository(ctx context.Context, req *gitalypb.CreateRepositoryRequest) (*gitalypb.CreateRepositoryResponse, error) {
 	diskPath, err := s.locator.GetPath(req.GetRepository())
 	if err != nil {
-		return nil, helper.ErrInvalidArgument(err)
+		return nil, helper.ErrInvalidArgumentf("locate repository: %w", err)
 	}
 
 	if err := os.MkdirAll(diskPath, 0770); err != nil {
-		return nil, helper.ErrInternal(err)
+		return nil, helper.ErrInternalf("create directories: %w", err)
 	}
 
-	cmd, err := git.SafeCmdWithoutRepo(ctx, git.CmdStream{}, nil,
+	stderr := &bytes.Buffer{}
+	cmd, err := git.SafeCmdWithoutRepo(ctx, git.CmdStream{Err: stderr}, nil,
 		git.SubCmd{
 			Name: "init",
 			Flags: []git.Option{
@@ -30,11 +32,11 @@ func (s *server) CreateRepository(ctx context.Context, req *gitalypb.CreateRepos
 		},
 	)
 	if err != nil {
-		return nil, helper.ErrInternal(err)
+		return nil, helper.ErrInternalf("create git init: %w", err)
 	}
 
 	if err := cmd.Wait(); err != nil {
-		return nil, helper.ErrInternal(err)
+		return nil, helper.ErrInternalf("git init stderr: %q, err: %w", stderr, err)
 	}
 
 	return &gitalypb.CreateRepositoryResponse{}, nil
diff --git a/internal/gitaly/service/repository/replicate.go b/internal/gitaly/service/repository/replicate.go
index 7d65fef49..489504ce7 100644
--- a/internal/gitaly/service/repository/replicate.go
+++ b/internal/gitaly/service/repository/replicate.go
@@ -1,6 +1,7 @@
 package repository
 
 import (
+	"bytes"
 	"context"
 	"errors"
 	"fmt"
@@ -101,23 +102,23 @@ func (s *server) create(ctx context.Context, in *gitalypb.ReplicateRepositoryReq
 func (s *server) createFromSnapshot(ctx context.Context, in *gitalypb.ReplicateRepositoryRequest) error {
 	tempRepo, tempPath, err := tempdir.NewAsRepository(ctx, in.GetRepository(), s.locator)
 	if err != nil {
-		return err
+		return fmt.Errorf("create temporary directory: %w", err)
 	}
 
 	if _, err := s.CreateRepository(ctx, &gitalypb.CreateRepositoryRequest{
 		Repository: tempRepo,
 	}); err != nil {
-		return err
+		return fmt.Errorf("create repository: %w", err)
 	}
 
 	repoClient, err := s.newRepoClient(ctx, in.GetSource().GetStorageName())
 	if err != nil {
-		return err
+		return fmt.Errorf("new client: %w", err)
 	}
 
 	stream, err := repoClient.GetSnapshot(ctx, &gitalypb.GetSnapshotRequest{Repository: in.GetSource()})
 	if err != nil {
-		return err
+		return fmt.Errorf("get snapshot: %w", err)
 	}
 
 	snapshotReader := streamio.NewReader(func() ([]byte, error) {
@@ -125,26 +126,27 @@ func (s *server) createFromSnapshot(ctx context.Context, in *gitalypb.ReplicateR
 		return resp.GetData(), err
 	})
 
-	cmd, err := command.New(ctx, exec.Command("tar", "-C", tempPath, "-xvf", "-"), snapshotReader, nil, nil)
+	stderr := &bytes.Buffer{}
+	cmd, err := command.New(ctx, exec.Command("tar", "-C", tempPath, "-xvf", "-"), snapshotReader, nil, stderr)
 	if err != nil {
-		return err
+		return fmt.Errorf("create tar command: %w", err)
 	}
 
 	if err = cmd.Wait(); err != nil {
-		return err
+		return fmt.Errorf("wait for tar, stderr: %q, err: %w", stderr, err)
 	}
 
 	targetPath, err := s.locator.GetPath(in.GetRepository())
 	if err != nil {
-		return err
+		return fmt.Errorf("locate repository: %w", err)
 	}
 
 	if err = os.MkdirAll(filepath.Dir(targetPath), 0755); err != nil {
-		return err
+		return fmt.Errorf("create parent directories: %w", err)
 	}
 
 	if err := os.Rename(tempPath, targetPath); err != nil {
-		return err
+		return fmt.Errorf("move temporary directory to target path: %w", err)
 	}
 
 	return nil
@@ -153,7 +155,7 @@ func (s *server) createFromSnapshot(ctx context.Context, in *gitalypb.ReplicateR
 func (s *server) syncRepository(ctx context.Context, in *gitalypb.ReplicateRepositoryRequest) error {
 	remoteClient, err := s.newRemoteClient(ctx)
 	if err != nil {
-		return err
+		return fmt.Errorf("new client: %w", err)
 	}
 
 	resp, err := remoteClient.FetchInternalRemote(ctx, &gitalypb.FetchInternalRemoteRequest{
@@ -161,7 +163,7 @@ func (s *server) syncRepository(ctx context.Context, in *gitalypb.ReplicateRepos
 		RemoteRepository: in.GetSource(),
 	})
 	if err != nil {
-		return err
+		return fmt.Errorf("fetch internal remote: %w", err)
 	}
 
 	if !resp.Result {
diff --git a/internal/gitaly/service/repository/snapshot.go b/internal/gitaly/service/repository/snapshot.go
index 55e77be85..87a563479 100644
--- a/internal/gitaly/service/repository/snapshot.go
+++ b/internal/gitaly/service/repository/snapshot.go
@@ -67,7 +67,7 @@ func (s *server) GetSnapshot(in *gitalypb.GetSnapshotRequest, stream gitalypb.Re
 	builder.FileIfExist("shallow")
 
 	if err := s.addAlternateFiles(stream.Context(), in.GetRepository(), builder); err != nil {
-		return helper.ErrInternal(err)
+		return helper.ErrInternalf("add alternates: %w", err)
 	}
 
 	if err := builder.Close(); err != nil {
@@ -80,12 +80,12 @@ func (s *server) GetSnapshot(in *gitalypb.GetSnapshotRequest, stream gitalypb.Re
 func (s *server) addAlternateFiles(ctx context.Context, repository *gitalypb.Repository, builder *archive.TarBuilder) error {
 	storageRoot, err := s.locator.GetStorageByName(repository.GetStorageName())
 	if err != nil {
-		return err
+		return fmt.Errorf("get storage path: %w", err)
 	}
 
 	repoPath, err := s.locator.GetRepoPath(repository)
 	if err != nil {
-		return err
+		return fmt.Errorf("get repo path: %w", err)
 	}
 
 	altObjDirs, err := git.AlternateObjectDirectories(ctx, storageRoot, repoPath)
@@ -105,14 +105,13 @@ func (s *server) addAlternateFiles(ctx context.Context, repository *gitalypb.Rep
 
 func walkAndAddToBuilder(alternateObjDir string, builder *archive.TarBuilder) error {
 	matchWalker := archive.NewMatchWalker(objectFiles, func(path string, info os.FileInfo, err error) error {
-		fmt.Printf("walking down %v\n", path)
 		if err != nil {
 			return fmt.Errorf("error walking %v: %v", path, err)
 		}
 
 		relPath, err := filepath.Rel(alternateObjDir, path)
 		if err != nil {
-			return err
+			return fmt.Errorf("alternative object directory path: %w", err)
 		}
 
 		file, err := os.Open(path)