log: create initial trace2 logger

Create a general 'TraceLogger' interface and (for now) a sole implementation
in the 'Trace2' struct. There are two main components of this commit: the
Trace2 logger itself, and how it's used in the CLIs built in this
repository.

The Trace2 logger is built around the 'zap' structured logger. As of right
now, it does not log anything other than 'start', 'exit', and 'atexit' (and
only through the 'WithLogger()' wrapper described later). The logs include:

* 'event': the event type; it takes over the 'message' field of the 'zap'
  logging functions, mostly for the sake of simplicity (those functions
  require a message, and every trace2 log has an 'event').
* 'sid': a UUID generated by the 'uuid.NewUUID()' function, propagated
  through the call stack via the 'context.Context'.
* 'time': the UTC timestamp of the log generation; this is automatically
  provided by a 'zap' logger, but requires a custom formatter to provide the
  timestamp in UTC.
* 't_abs': the time (in seconds) since the start of the program
  (technically, when the 'log' package is loaded and the 'globalStartTime'
  is initialized).
* 'file' and 'line': the filename and line number where the relevant trace2
  log function was called.
* 'thread': hardcoded to 'main', but may be updated in the future to give
  unique names to goroutines.

From a user's perspective, the logger is configured by the
'GIT_TRACE2_EVENT' environment variable. Its behavior matches what is
described in Git [1], but it is currently missing support for open file
handles 2-9 and Unix Domain Sockets.

To use the trace2 logger, create the 'main()' function wrapper
'WithLogger()'. This function creates an instance of a 'TraceLogger', logs
the program start, defers a "cleanup" logging function to write out the
'exit'/'atexit' logs, then runs the wrapped function.

[1] https://git-scm.com/docs/git-config#Documentation/git-config.txt-trace2eventTarget

Signed-off-by: Victoria Dye <[email protected]>

Author: vdye

cmd/git-bundle-server/main.go

@@ -6,6 +6,7 @@ import (
 	"os"
 
 	"github.com/github/git-bundle-server/internal/argparse"
+	tracelog "github.com/github/git-bundle-server/internal/log"
 )
 
 func all() []argparse.Subcommand {
@@ -21,19 +22,19 @@ func all() []argparse.Subcommand {
 }
 
 func main() {
-	ctx := context.Background()
+	tracelog.WithTraceLogger(context.Background(), func(ctx context.Context, logger tracelog.TraceLogger) {
+		cmds := all()
 
-	cmds := all()
+		parser := argparse.NewArgParser("git-bundle-server <command> [<options>]")
+		parser.SetIsTopLevel(true)
+		for _, cmd := range cmds {
+			parser.Subcommand(cmd)
+		}
+		parser.Parse(ctx, os.Args[1:])
 
-	parser := argparse.NewArgParser("git-bundle-server <command> [<options>]")
-	parser.SetIsTopLevel(true)
-	for _, cmd := range cmds {
-		parser.Subcommand(cmd)
-	}
-	parser.Parse(ctx, os.Args[1:])
-
-	err := parser.InvokeSubcommand(ctx)
-	if err != nil {
-		log.Fatal("Failed with error: ", err)
-	}
+		err := parser.InvokeSubcommand(ctx)
+		if err != nil {
+			log.Fatalf("Failed with error: %s", err)
+		}
+	})
 }

cmd/git-bundle-web-server/main.go

@@ -8,35 +8,37 @@ import (
 
 	"github.com/github/git-bundle-server/cmd/utils"
 	"github.com/github/git-bundle-server/internal/argparse"
+	"github.com/github/git-bundle-server/internal/log"
 )
 
 func main() {
-	ctx := context.Background()
+	log.WithTraceLogger(context.Background(), func(ctx context.Context, logger log.TraceLogger) {
+		parser := argparse.NewArgParser("git-bundle-web-server [--port <port>] [--cert <filename> --key <filename>]")
+		flags, validate := utils.WebServerFlags(parser)
+		flags.VisitAll(func(f *flag.Flag) {
+			parser.Var(f.Value, f.Name, f.Usage)
+		})
 
-	parser := argparse.NewArgParser("git-bundle-web-server [--port <port>] [--cert <filename> --key <filename>]")
-	flags, validate := utils.WebServerFlags(parser)
-	flags.VisitAll(func(f *flag.Flag) {
-		parser.Var(f.Value, f.Name, f.Usage)
-	})
-	parser.Parse(ctx, os.Args[1:])
-	validate(ctx)
+		parser.Parse(ctx, os.Args[1:])
+		validate(ctx)
 
-	// Get the flag values
-	port := utils.GetFlagValue[string](parser, "port")
-	cert := utils.GetFlagValue[string](parser, "cert")
-	key := utils.GetFlagValue[string](parser, "key")
+		// Get the flag values
+		port := utils.GetFlagValue[string](parser, "port")
+		cert := utils.GetFlagValue[string](parser, "cert")
+		key := utils.GetFlagValue[string](parser, "key")
 
-	// Configure the server
-	bundleServer := NewBundleWebServer(port, cert, key)
+		// Configure the server
+		bundleServer := NewBundleWebServer(port, cert, key)
 
-	// Start the server asynchronously
-	bundleServer.StartServerAsync(ctx)
+		// Start the server asynchronously
+		bundleServer.StartServerAsync(ctx)
 
-	// Intercept interrupt signals
-	bundleServer.HandleSignalsAsync(ctx)
+		// Intercept interrupt signals
+		bundleServer.HandleSignalsAsync(ctx)
 
-	// Wait for server to shut down
-	bundleServer.Wait()
+		// Wait for server to shut down
+		bundleServer.Wait()
 
-	fmt.Println("Shutdown complete")
+		fmt.Println("Shutdown complete")
+	})
 }

go.mod

@@ -2,11 +2,17 @@ module github.com/github/git-bundle-server
 
 go 1.19
 
-require github.com/stretchr/testify v1.8.1
+require (
+	github.com/google/uuid v1.3.0
+	github.com/stretchr/testify v1.8.1
+	go.uber.org/zap v1.24.0
+)
 
 require (
 	github.com/davecgh/go-spew v1.1.1 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
 	github.com/stretchr/objx v0.5.0 // indirect
+	go.uber.org/atomic v1.10.0 // indirect
+	go.uber.org/multierr v1.9.0 // indirect
 	gopkg.in/yaml.v3 v3.0.1 // indirect
 )

go.sum

@@ -1,6 +1,10 @@
+github.com/benbjohnson/clock v1.1.0 h1:Q92kusRqC1XV2MjkWETPvjJVqKetz1OzxZB7mHJLju8=
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
+github.com/google/uuid v1.3.0 h1:t6JiXgmwXMjEs8VusXIJk2BXHsn+wx8BZdTaoZ5fu7I=
+github.com/google/uuid v1.3.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo=
+github.com/pkg/errors v0.8.1 h1:iURUrRGxPUNPdy5/HRSm+Yj6okJ6UtLINN0Q9M4+h3I=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
@@ -11,6 +15,13 @@ github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/
 github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU=
 github.com/stretchr/testify v1.8.1 h1:w7B6lhMri9wdJUVmEZPGGhZzrYTPvgJArz7wNPgYKsk=
 github.com/stretchr/testify v1.8.1/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4=
+go.uber.org/atomic v1.10.0 h1:9qC72Qh0+3MqyJbAn8YU5xVq1frD8bn3JtD2oXtafVQ=
+go.uber.org/atomic v1.10.0/go.mod h1:LUxbIzbOniOlMKjJjyPfpl4v+PKK2cNJn91OQbhoJI0=
+go.uber.org/goleak v1.1.11 h1:wy28qYRKZgnJTxGxvye5/wgWr1EKjmUDGYox5mGlRlI=
+go.uber.org/multierr v1.9.0 h1:7fIwc/ZtS0q++VgcfqFDxSBZVv/Xo49/SYnDFupUwlI=
+go.uber.org/multierr v1.9.0/go.mod h1:X2jQV1h+kxSjClGpnseKVIxpmcjrj7MNnI0bnlfKTVQ=
+go.uber.org/zap v1.24.0 h1:FiJd5l1UOLj0wCgbSE0rwwXHzEdAZS6hiiSnxJN/D60=
+go.uber.org/zap v1.24.0/go.mod h1:2kMP+WWQ8aoFoedH3T2sq6iJ2yDWpHbP0f6MQbS9Gkg=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=

internal/log/logger.go

@@ -0,0 +1,38 @@
+package log
+
+import (
+	"context"
+	"os"
+)
+
+type TraceLogger interface{}
+
+type traceLoggerInternal interface {
+	// Internal setup/teardown functions
+	logStart(ctx context.Context) context.Context
+	logExit(ctx context.Context, exitCode int)
+
+	TraceLogger
+}
+
+func WithTraceLogger(
+	ctx context.Context,
+	mainFunc func(context.Context, TraceLogger),
+) {
+	logger := NewTrace2()
+
+	// Set up the program-level context
+	ctx = logger.logStart(ctx)
+	defer func() {
+		if recover() != nil {
+			// Panicking - exit with error
+			logger.logExit(ctx, 1)
+			os.Exit(1)
+		} else {
+			// Just log the exit (but don't os.Exit()) so we can exit normally
+			logger.logExit(ctx, 0)
+		}
+	}()
+
+	mainFunc(ctx, logger)
+}

internal/log/trace2.go

@@ -0,0 +1,167 @@
+package log
+
+import (
+	"context"
+	"fmt"
+	"os"
+	"path"
+	"path/filepath"
+	"runtime"
+	"strconv"
+	"time"
+
+	"github.com/google/uuid"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+)
+
+// Trace2 environment variables
+const (
+	// TODO: handle GIT_TRACE2 by adding a separate output config (see zapcore
+	// "AdvancedConfiguration" example:
+	// https://pkg.go.dev/go.uber.org/zap#example-package-AdvancedConfiguration)
+	trace2Event string = "GIT_TRACE2_EVENT"
+)
+
+// Global start time
+var globalStart = time.Now().UTC()
+
+const trace2TimeFormat string = "2006-01-02T15:04:05.999999Z"
+
+type ctxKey int
+
+const (
+	sidId ctxKey = iota
+)
+
+type Trace2 struct {
+	logger *zap.Logger
+}
+
+func getTrace2OutputPaths(envKey string) []string {
+	tr2Output := os.Getenv(envKey)
+
+	// Configure the output
+	if tr2, err := strconv.Atoi(tr2Output); err == nil {
+		// Handle numeric values
+		if tr2 == 1 {
+			return []string{"stderr"}
+		}
+		// TODO: handle file handles 2-9 and unix sockets
+	} else if tr2Output != "" {
+		// Assume we received a path
+		fileInfo, err := os.Stat(tr2Output)
+		if err == nil && fileInfo.IsDir() {
+			// If the path is an existing directory, generate a filename
+			return []string{
+				filepath.Join(tr2Output, fmt.Sprintf("trace2_%s.txt", globalStart.Format(trace2TimeFormat))),
+			}
+		} else {
+			// Create leading directories
+			parentDir := path.Dir(tr2Output)
+			os.MkdirAll(parentDir, 0o755)
+			return []string{tr2Output}
+		}
+	}
+
+	return []string{}
+}
+
+func createTrace2ZapLogger() *zap.Logger {
+	loggerConfig := zap.NewProductionConfig()
+
+	// Configure the output for GIT_TRACE2_EVENT
+	loggerConfig.OutputPaths = getTrace2OutputPaths(trace2Event)
+	loggerConfig.Level = zap.NewAtomicLevelAt(zap.DebugLevel)
+
+	// Encode UTC time
+	loggerConfig.EncoderConfig.TimeKey = "time"
+	loggerConfig.EncoderConfig.EncodeTime = zapcore.TimeEncoder(
+		func(t time.Time, enc zapcore.PrimitiveArrayEncoder) {
+			enc.AppendString(t.Format(trace2TimeFormat))
+		},
+	)
+
+	// Re-purpose the "message" to represent the (always-present) "event" key
+	loggerConfig.EncoderConfig.MessageKey = "event"
+
+	// Don't print the log level
+	loggerConfig.EncoderConfig.LevelKey = ""
+
+	// Disable caller info, we'll customize those fields manually
+	logger, _ := loggerConfig.Build(zap.WithCaller(false))
+	return logger
+}
+
+func NewTrace2() traceLoggerInternal {
+	return &Trace2{
+		logger: createTrace2ZapLogger(),
+	}
+}
+
+type fieldList []zap.Field
+
+func (l fieldList) withTime() fieldList {
+	return append(l, zap.Float64("t_abs", time.Since(globalStart).Seconds()))
+}
+
+func (l fieldList) with(f ...zap.Field) fieldList {
+	return append(l, f...)
+}
+
+func (t *Trace2) sharedFields(ctx context.Context) (context.Context, fieldList) {
+	fields := fieldList{}
+
+	// Get the session ID
+	var sid uuid.UUID
+	haveSid := false
+	sidAny := ctx.Value(sidId)
+	if sidAny != nil {
+		sid, haveSid = sidAny.(uuid.UUID)
+	}
+	if !haveSid {
+		sid = uuid.New()
+		ctx = context.WithValue(ctx, sidId, sid)
+	}
+	fields = append(fields, zap.String("sid", sid.String()))
+
+	// Hardcode the thread to "main" because Go doesn't like to share its
+	// internal info about threading.
+	fields = append(fields, zap.String("thread", "main"))
+
+	// Get the caller of the function in trace2.go
+	// Skip up two levels:
+	// 0: this function
+	// 1: the caller of this function (StartTrace, LogEvent, etc.)
+	// 2: the function calling this trace2 library
+	_, fileName, lineNum, ok := runtime.Caller(2)
+	if ok {
+		fields = append(fields,
+			zap.String("file", filepath.Base(fileName)),
+			zap.Int("line", lineNum),
+		)
+	}
+
+	return ctx, fields
+}
+
+func (t *Trace2) logStart(ctx context.Context) context.Context {
+	ctx, sharedFields := t.sharedFields(ctx)
+
+	t.logger.Info("start", sharedFields.withTime().with(
+		zap.Strings("argv", os.Args),
+	)...)
+
+	return ctx
+}
+
+func (t *Trace2) logExit(ctx context.Context, exitCode int) {
+	_, sharedFields := t.sharedFields(ctx)
+	fields := sharedFields.with(
+		zap.Int("code", exitCode),
+	)
+	t.logger.Info("exit", fields.withTime()...)
+	t.logger.Info("atexit", fields.withTime()...)
+
+	t.logger.Sync()
+}