|
| 1 | +package log |
| 2 | + |
| 3 | +import ( |
| 4 | + "context" |
| 5 | + "fmt" |
| 6 | + "os" |
| 7 | + "path" |
| 8 | + "path/filepath" |
| 9 | + "runtime" |
| 10 | + "strconv" |
| 11 | + "time" |
| 12 | + |
| 13 | + "github.com/google/uuid" |
| 14 | + "go.uber.org/zap" |
| 15 | + "go.uber.org/zap/zapcore" |
| 16 | +) |
| 17 | + |
| 18 | +// Trace2 environment variables |
| 19 | +const ( |
| 20 | + // TODO: handle GIT_TRACE2 by adding a separate output config (see zapcore |
| 21 | + // "AdvancedConfiguration" example: |
| 22 | + // https://pkg.go.dev/go.uber.org/zap#example-package-AdvancedConfiguration) |
| 23 | + trace2Event string = "GIT_TRACE2_EVENT" |
| 24 | +) |
| 25 | + |
| 26 | +// Global start time |
| 27 | +var globalStart = time.Now().UTC() |
| 28 | + |
| 29 | +const trace2TimeFormat string = "2006-01-02T15:04:05.999999Z" |
| 30 | + |
| 31 | +type ctxKey int |
| 32 | + |
| 33 | +const ( |
| 34 | + sidId ctxKey = iota |
| 35 | +) |
| 36 | + |
| 37 | +type Trace2 struct { |
| 38 | + logger *zap.Logger |
| 39 | +} |
| 40 | + |
| 41 | +func getTrace2OutputPaths(envKey string) []string { |
| 42 | + tr2Output := os.Getenv(envKey) |
| 43 | + |
| 44 | + // Configure the output |
| 45 | + if tr2, err := strconv.Atoi(tr2Output); err == nil { |
| 46 | + // Handle numeric values |
| 47 | + if tr2 == 1 { |
| 48 | + return []string{"stderr"} |
| 49 | + } |
| 50 | + // TODO: handle file handles 2-9 and unix sockets |
| 51 | + } else if tr2Output != "" { |
| 52 | + // Assume we received a path |
| 53 | + fileInfo, err := os.Stat(tr2Output) |
| 54 | + if err == nil && fileInfo.IsDir() { |
| 55 | + // If the path is an existing directory, generate a filename |
| 56 | + return []string{ |
| 57 | + filepath.Join(tr2Output, fmt.Sprintf("trace2_%s.txt", globalStart.Format(trace2TimeFormat))), |
| 58 | + } |
| 59 | + } else { |
| 60 | + // Create leading directories |
| 61 | + parentDir := path.Dir(tr2Output) |
| 62 | + os.MkdirAll(parentDir, 0o755) |
| 63 | + return []string{tr2Output} |
| 64 | + } |
| 65 | + } |
| 66 | + |
| 67 | + return []string{} |
| 68 | +} |
| 69 | + |
| 70 | +func createTrace2ZapLogger() *zap.Logger { |
| 71 | + loggerConfig := zap.NewProductionConfig() |
| 72 | + |
| 73 | + // Configure the output for GIT_TRACE2_EVENT |
| 74 | + loggerConfig.OutputPaths = getTrace2OutputPaths(trace2Event) |
| 75 | + loggerConfig.Level = zap.NewAtomicLevelAt(zap.DebugLevel) |
| 76 | + |
| 77 | + // Encode UTC time |
| 78 | + loggerConfig.EncoderConfig.TimeKey = "time" |
| 79 | + loggerConfig.EncoderConfig.EncodeTime = zapcore.TimeEncoder( |
| 80 | + func(t time.Time, enc zapcore.PrimitiveArrayEncoder) { |
| 81 | + enc.AppendString(t.Format(trace2TimeFormat)) |
| 82 | + }, |
| 83 | + ) |
| 84 | + |
| 85 | + // Re-purpose the "message" to represent the (always-present) "event" key |
| 86 | + loggerConfig.EncoderConfig.MessageKey = "event" |
| 87 | + |
| 88 | + // Don't print the log level |
| 89 | + loggerConfig.EncoderConfig.LevelKey = "" |
| 90 | + |
| 91 | + // Disable caller info, we'll customize those fields manually |
| 92 | + logger, _ := loggerConfig.Build(zap.WithCaller(false)) |
| 93 | + return logger |
| 94 | +} |
| 95 | + |
| 96 | +func NewTrace2() traceLoggerInternal { |
| 97 | + return &Trace2{ |
| 98 | + logger: createTrace2ZapLogger(), |
| 99 | + } |
| 100 | +} |
| 101 | + |
| 102 | +type fieldList []zap.Field |
| 103 | + |
| 104 | +func (l fieldList) withTime() fieldList { |
| 105 | + return append(l, zap.Float64("t_abs", time.Since(globalStart).Seconds())) |
| 106 | +} |
| 107 | + |
| 108 | +func (l fieldList) with(f ...zap.Field) fieldList { |
| 109 | + return append(l, f...) |
| 110 | +} |
| 111 | + |
| 112 | +func (t *Trace2) sharedFields(ctx context.Context) (context.Context, fieldList) { |
| 113 | + fields := fieldList{} |
| 114 | + |
| 115 | + // Get the session ID |
| 116 | + var sid uuid.UUID |
| 117 | + haveSid := false |
| 118 | + sidAny := ctx.Value(sidId) |
| 119 | + if sidAny != nil { |
| 120 | + sid, haveSid = sidAny.(uuid.UUID) |
| 121 | + } |
| 122 | + if !haveSid { |
| 123 | + sid = uuid.New() |
| 124 | + ctx = context.WithValue(ctx, sidId, sid) |
| 125 | + } |
| 126 | + fields = append(fields, zap.String("sid", sid.String())) |
| 127 | + |
| 128 | + // Hardcode the thread to "main" because Go doesn't like to share its |
| 129 | + // internal info about threading. |
| 130 | + fields = append(fields, zap.String("thread", "main")) |
| 131 | + |
| 132 | + // Get the caller of the function in trace2.go |
| 133 | + // Skip up two levels: |
| 134 | + // 0: this function |
| 135 | + // 1: the caller of this function (StartTrace, LogEvent, etc.) |
| 136 | + // 2: the function calling this trace2 library |
| 137 | + _, fileName, lineNum, ok := runtime.Caller(2) |
| 138 | + if ok { |
| 139 | + fields = append(fields, |
| 140 | + zap.String("file", filepath.Base(fileName)), |
| 141 | + zap.Int("line", lineNum), |
| 142 | + ) |
| 143 | + } |
| 144 | + |
| 145 | + return ctx, fields |
| 146 | +} |
| 147 | + |
| 148 | +func (t *Trace2) logStart(ctx context.Context) context.Context { |
| 149 | + ctx, sharedFields := t.sharedFields(ctx) |
| 150 | + |
| 151 | + t.logger.Info("start", sharedFields.withTime().with( |
| 152 | + zap.Strings("argv", os.Args), |
| 153 | + )...) |
| 154 | + |
| 155 | + return ctx |
| 156 | +} |
| 157 | + |
| 158 | +func (t *Trace2) logExit(ctx context.Context, exitCode int) { |
| 159 | + _, sharedFields := t.sharedFields(ctx) |
| 160 | + fields := sharedFields.with( |
| 161 | + zap.Int("code", exitCode), |
| 162 | + ) |
| 163 | + t.logger.Info("exit", fields.withTime()...) |
| 164 | + t.logger.Info("atexit", fields.withTime()...) |
| 165 | + |
| 166 | + t.logger.Sync() |
| 167 | +} |
0 commit comments