gitaly-git2go: Pass through correlation ID from requestgit2go_logging

Adds some basic sub-command logging.

2 files changed, 25 insertions, 4 deletions

diff --git a/cmd/gitaly-git2go-v14/main.go b/cmd/gitaly-git2go-v14/main.go
index 809c9f657..3f403c9d4 100644
--- a/cmd/gitaly-git2go-v14/main.go
+++ b/cmd/gitaly-git2go-v14/main.go
@@ -15,6 +15,7 @@ import (
 	"github.com/sirupsen/logrus"
 	"gitlab.com/gitlab-org/gitaly/v14/internal/git2go"
 	glog "gitlab.com/gitlab-org/gitaly/v14/internal/log"
+	"gitlab.com/gitlab-org/labkit/correlation"
 )
 
 type subcmd interface {
@@ -59,15 +60,25 @@ func main() {
 	decoder := gob.NewDecoder(os.Stdin)
 	encoder := gob.NewEncoder(os.Stdout)
 
-	var logFormat, logLevel string
+	var logFormat, logLevel, correlationID string
 
 	flags := flag.NewFlagSet(git2go.BinaryName, flag.PanicOnError)
 	flags.StringVar(&logFormat, "log-format", "", "logging format")
 	flags.StringVar(&logLevel, "log-level", "", "logging level")
+	flags.StringVar(&correlationID, "correlation-id", "", "correlation ID used for request tracing")
 	_ = flags.Parse(os.Args[1:])
 
+	if correlationID == "" {
+		correlationID = correlation.SafeRandomID()
+	}
+
 	configureLogging(logFormat, logLevel)
-	logger := glog.Default().WithField("command.name", git2go.BinaryName)
+
+	ctx := correlation.ContextWithCorrelation(context.Background(), correlationID)
+	logger := glog.Default().WithFields(logrus.Fields{
+		"command.name":   git2go.BinaryName,
+		"correlation_id": correlationID,
+	})
 
 	if flags.NArg() < 1 {
 		fatalf(logger, encoder, "missing subcommand")
@@ -91,9 +102,14 @@ func main() {
 		fatalf(logger, encoder, "enable fsync: %s", err)
 	}
 
-	ctx := ctxlogrus.ToContext(context.Background(), logger.WithField("subcommand", subcmd))
+	subcmdLogger := logger.WithField("command.subcommand", subcmdFlags.Name())
+	subcmdLogger.Infof("starting %s command", subcmdFlags.Name())
 
+	ctx = ctxlogrus.ToContext(ctx, subcmdLogger)
 	if err := subcmd.Run(ctx, decoder, encoder); err != nil {
+		subcmdLogger.WithError(err).Errorf("%s command failed", subcmdFlags.Name())
 		fatalf(logger, encoder, "%s: %s", subcmdFlags.Name(), err)
 	}
+
+	subcmdLogger.Infof("%s command finished", subcmdFlags.Name())
 }
diff --git a/internal/git2go/executor.go b/internal/git2go/executor.go
index b903eb217..45ed5e8c1 100644
--- a/internal/git2go/executor.go
+++ b/internal/git2go/executor.go
@@ -18,6 +18,7 @@ import (
 	"gitlab.com/gitlab-org/gitaly/v14/internal/gitaly/storage"
 	glog "gitlab.com/gitlab-org/gitaly/v14/internal/log"
 	"gitlab.com/gitlab-org/gitaly/v14/internal/version"
+	"gitlab.com/gitlab-org/labkit/correlation"
 )
 
 var (
@@ -61,7 +62,11 @@ func (b *Executor) run(ctx context.Context, repo repository.GitRepo, stdin io.Re
 	// https://pkg.go.dev/github.com/sirupsen/logrus#readme-thread-safety
 	log := glog.Default().Logger.Out
 
-	args = append([]string{"-log-format", b.logFormat, "-log-level", b.logLevel}, args...)
+	args = append([]string{
+		"-log-format", b.logFormat,
+		"-log-level", b.logLevel,
+		"-correlation-id", correlation.ExtractFromContext(ctx),
+	}, args...)
 
 	var stdout bytes.Buffer
 	cmd, err := command.New(ctx, exec.Command(b.binaryPath, args...), stdin, &stdout, log, env...)