diff options
author | James Fargher <proglottis@gmail.com> | 2022-04-04 03:30:40 +0300 |
---|---|---|
committer | James Fargher <proglottis@gmail.com> | 2022-04-04 03:30:40 +0300 |
commit | fc158823aa4e499001354081435ca2bad3ab8aca (patch) | |
tree | 0cb5b2aeb080d74c34a9ec718a1ef668acb86ca1 | |
parent | 10cd56699856b8b648aff3bec0c43257b3e98e51 (diff) | |
parent | bc3116c963558e9989dd35e86a947ed5f1078642 (diff) |
Merge branch 'git2go_logging' into 'master'
Add logging to gitaly-git2go
Closes #3229
See merge request gitlab-org/gitaly!4426
-rw-r--r-- | cmd/gitaly-git2go-v14/main.go | 70 | ||||
-rw-r--r-- | internal/git2go/executor.go | 29 |
2 files changed, 73 insertions, 26 deletions
diff --git a/cmd/gitaly-git2go-v14/main.go b/cmd/gitaly-git2go-v14/main.go index 1bbdf6e20..3f403c9d4 100644 --- a/cmd/gitaly-git2go-v14/main.go +++ b/cmd/gitaly-git2go-v14/main.go @@ -10,8 +10,12 @@ import ( "fmt" "os" + "github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus/ctxlogrus" git "github.com/libgit2/git2go/v33" + "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 { @@ -31,51 +35,81 @@ var subcommands = map[string]subcmd{ "submodule": &submoduleSubcommand{}, } -func fatalf(encoder *gob.Encoder, format string, args ...interface{}) { - // Once logging has been implemented these encoding errors can be logged. - // Until then these will be ignored as we can no longer use stderr. - // https://gitlab.com/gitlab-org/gitaly/-/issues/3229 - _ = encoder.Encode(git2go.Result{ +func fatalf(logger logrus.FieldLogger, encoder *gob.Encoder, format string, args ...interface{}) { + err := encoder.Encode(git2go.Result{ Err: git2go.SerializableError(fmt.Errorf(format, args...)), }) + if err != nil { + logger.WithError(err).Error("encode to gob failed") + } // An exit code of 1 would indicate an error over stderr. Since our errors // are encoded over gob, we need to exit cleanly os.Exit(0) } +func configureLogging(format, level string) { + // Gitaly logging by default goes to stdout, which would interfere with gob + // encoding. + for _, l := range glog.Loggers { + l.Out = os.Stderr + } + glog.Configure(glog.Loggers, format, level) +} + func main() { decoder := gob.NewDecoder(os.Stdin) encoder := gob.NewEncoder(os.Stdout) - flags := flag.NewFlagSet(git2go.BinaryName, flag.ContinueOnError) + 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 err := flags.Parse(os.Args); err != nil { - fatalf(encoder, "parsing flags: %s", err) + if correlationID == "" { + correlationID = correlation.SafeRandomID() } - if flags.NArg() < 2 { - fatalf(encoder, "missing subcommand") + configureLogging(logFormat, logLevel) + + 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") } - subcmd, ok := subcommands[flags.Arg(1)] + subcmd, ok := subcommands[flags.Arg(0)] if !ok { - fatalf(encoder, "unknown subcommand: %q", flags.Arg(0)) + fatalf(logger, encoder, "unknown subcommand: %q", flags.Arg(0)) } subcmdFlags := subcmd.Flags() - if err := subcmdFlags.Parse(flags.Args()[2:]); err != nil { - fatalf(encoder, "parsing flags of %q: %s", subcmdFlags.Name(), err) + if err := subcmdFlags.Parse(flags.Args()[1:]); err != nil { + fatalf(logger, encoder, "parsing flags of %q: %s", subcmdFlags.Name(), err) } if subcmdFlags.NArg() != 0 { - fatalf(encoder, "%s: trailing arguments", subcmdFlags.Name()) + fatalf(logger, encoder, "%s: trailing arguments", subcmdFlags.Name()) } if err := git.EnableFsyncGitDir(true); err != nil { - fatalf(encoder, "enable fsync: %s", err) + fatalf(logger, encoder, "enable fsync: %s", err) } - if err := subcmd.Run(context.Background(), decoder, encoder); err != nil { - fatalf(encoder, "%s: %s", subcmdFlags.Name(), err) + 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 35b62b682..45ed5e8c1 100644 --- a/internal/git2go/executor.go +++ b/internal/git2go/executor.go @@ -16,7 +16,9 @@ import ( "gitlab.com/gitlab-org/gitaly/v14/internal/git/repository" "gitlab.com/gitlab-org/gitaly/v14/internal/gitaly/config" "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 ( @@ -29,9 +31,10 @@ var ( // Executor executes gitaly-git2go. type Executor struct { - binaryPath string - gitCmdFactory git.CommandFactory - locator storage.Locator + binaryPath string + gitCmdFactory git.CommandFactory + locator storage.Locator + logFormat, logLevel string } // NewExecutor returns a new gitaly-git2go executor using binaries as configured in the given @@ -41,6 +44,8 @@ func NewExecutor(cfg config.Cfg, gitCmdFactory git.CommandFactory, locator stora binaryPath: filepath.Join(cfg.BinDir, BinaryName), gitCmdFactory: gitCmdFactory, locator: locator, + logFormat: cfg.Logging.Format, + logLevel: cfg.Logging.Level, } } @@ -52,16 +57,24 @@ func (b *Executor) run(ctx context.Context, repo repository.GitRepo, stdin io.Re env := alternates.Env(repoPath, repo.GetGitObjectDirectory(), repo.GetGitAlternateObjectDirectories()) - var stderr, stdout bytes.Buffer - cmd, err := command.New(ctx, exec.Command(b.binaryPath, args...), stdin, &stdout, &stderr, env...) + // Pass the log output directly to gitaly-git2go. No need to reinterpret + // these logs as long as the destination is an append-only file. See + // 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, + "-correlation-id", correlation.ExtractFromContext(ctx), + }, args...) + + var stdout bytes.Buffer + cmd, err := command.New(ctx, exec.Command(b.binaryPath, args...), stdin, &stdout, log, env...) if err != nil { return nil, err } if err := cmd.Wait(); err != nil { - if _, ok := err.(*exec.ExitError); ok { - return nil, fmt.Errorf("%s", stderr.String()) - } return nil, err } |