fix skip frames

armadaproject · d80tb7 · Jan 20, 2025 · Jan 2, 2025 · Jan 3, 2025 · Jan 3, 2025
commit 951ab70b58bfce5c8a8ac96e798af469d19bd499
diff --git a/go.mod b/go.mod
@@ -160,7 +160,8 @@ require (
 	github.com/lucasb-eyer/go-colorful v1.2.0 // indirect
 	github.com/magiconair/properties v1.8.7 // indirect
 	github.com/mailru/easyjson v0.7.7 // indirect
-	github.com/mattn/go-isatty v0.0.18 // indirect
+	github.com/mattn/go-colorable v0.1.13 // indirect
+	github.com/mattn/go-isatty v0.0.19 // indirect
 	github.com/mattn/go-runewidth v0.0.15 // indirect
 	github.com/microcosm-cc/bluemonday v1.0.25 // indirect
 	github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd // indirect
@@ -180,6 +181,7 @@ require (
 	github.com/prometheus/client_model v0.6.1 // indirect
 	github.com/prometheus/procfs v0.15.1 // indirect
 	github.com/rivo/uniseg v0.4.2 // indirect
+	github.com/rs/zerolog v1.33.0 // indirect
 	github.com/sagikazarmark/locafero v0.6.0 // indirect
 	github.com/sagikazarmark/slog-shim v0.1.0 // indirect
 	github.com/sirupsen/logrus v1.9.3 // indirect

diff --git a/go.sum b/go.sum
@@ -114,6 +114,7 @@ github.com/containerd/log v0.1.0 h1:TCJt7ioM2cr/tfR8GPbGf9/VRAX8D2B4PjzCpfX540I=
 github.com/containerd/log v0.1.0/go.mod h1:VRRf09a7mHDIRezVKTRCrOq78v577GXq3bSa3EhrzVo=
 github.com/coreos/go-oidc v2.2.1+incompatible h1:mh48q/BqXqgjVHpy2ZY7WnWAbenxRjsz9N1i1YxjHAk=
 github.com/coreos/go-oidc v2.2.1+incompatible/go.mod h1:CgnwVTmzoESiwO9qyAFEMiHoZ1nMCKZlZ9V6mm3/LKc=
+github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
 github.com/cpuguy83/dockercfg v0.3.1 h1:/FpZ+JaygUR/lZP2NlFI2DVfrOEMAIKP5wWEJdoYe9E=
 github.com/cpuguy83/dockercfg v0.3.1/go.mod h1:sugsbF4//dDlL/i+S+rtpIWp+5h0BHJHfjj5/jFyUJc=
 github.com/cpuguy83/go-md2man/v2 v2.0.4/go.mod h1:tgQtvFlXSQOSOSIRvRPT7W67SCa46tRHOmNcaadrF8o=
@@ -209,6 +210,7 @@ github.com/gobwas/glob v0.2.3 h1:A4xDbljILXROh+kObIiy5kIaPYD8e96x1tgBhUI5J+Y=
 github.com/gobwas/glob v0.2.3/go.mod h1:d3Ez4x06l9bZtSvzIay5+Yzi0fmZzPgnTbPcKjJAkT8=
 github.com/godbus/dbus v0.0.0-20190726142602-4481cbc300e2 h1:ZpnhV/YsD2/4cESfV5+Hoeu/iUR3ruzNvZ+yQfO03a0=
 github.com/godbus/dbus v0.0.0-20190726142602-4481cbc300e2/go.mod h1:bBOAhwG1umN6/6ZUMtDFBMQR8jRg9O75tm9K00oMsK4=
+github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
 github.com/gogo/googleapis v0.0.0-20180223154316-0cd9801be74a h1:dR8+Q0uO5S2ZBcs2IH6VBKYwSxPo2vYCYq0ot0mu7xA=
 github.com/gogo/googleapis v0.0.0-20180223154316-0cd9801be74a/go.mod h1:gf4bu3Q80BeJ6H1S1vYPm8/ELATdvryBaNFGgqEef3s=
 github.com/gogo/protobuf v1.3.2 h1:Ov1cvc58UF3b5XjBnZv7+opcTcQFZebYjWzi34vdm4Q=
@@ -393,8 +395,13 @@ github.com/mailru/easyjson v0.7.7 h1:UGYAvKxe3sBsEDzO8ZeWOSlIQfWFlxbzLZe7hwFURr0
 github.com/mailru/easyjson v0.7.7/go.mod h1:xzfreul335JAWq5oZzymOObrkdz5UnU4kGfJJLY9Nlc=
 github.com/matryer/is v1.4.0 h1:sosSmIWwkYITGrxZ25ULNDeKiMNzFSr4V/eqBQP0PeE=
 github.com/matryer/is v1.4.0/go.mod h1:8I/i5uYgLzgsgEloJE1U6xx5HkBQpAZvepWuujKwMRU=
+github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA=
+github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg=
+github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM=
 github.com/mattn/go-isatty v0.0.18 h1:DOKFKCQ7FNG2L1rbrmstDN4QVRdS89Nkh85u68Uwp98=
 github.com/mattn/go-isatty v0.0.18/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
+github.com/mattn/go-isatty v0.0.19 h1:JITubQf0MOLdlGRuRq+jtsDlekdYPia9ZFsB8h/APPA=
+github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
 github.com/mattn/go-runewidth v0.0.9/go.mod h1:H031xJmbD/WCDINGzjvQ9THkh0rPKHF+m2gUSrubnMI=
 github.com/mattn/go-runewidth v0.0.12/go.mod h1:RAqKPSqVFrSLVXbA8x7dzmKdmGzieGRCM46jaSJTDAk=
 github.com/mattn/go-runewidth v0.0.15 h1:UNAjwbU9l54TA3KzvqLGxwWjHmMgBUVhBiTjelZgg3U=
@@ -503,6 +510,9 @@ github.com/rogpeppe/fastuuid v1.2.0/go.mod h1:jVj6XXZzXRy/MSR5jhDC/2q6DgLz+nrA6L
 github.com/rogpeppe/go-internal v1.3.0/go.mod h1:M8bDsm7K2OlrFYOpmOWEs/qY81heoFRclV5y23lUDJ4=
 github.com/rogpeppe/go-internal v1.11.0 h1:cWPaGQEPrBb5/AsnsZesgZZ9yb1OQ+GOISoDNXVBh4M=
 github.com/rogpeppe/go-internal v1.11.0/go.mod h1:ddIwULY96R17DhadqLgMfk9H9tvdUzkipdSkR5nkCZA=
+github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
+github.com/rs/zerolog v1.33.0 h1:1cU2KZkvPxNyfgEmhHAz/1A9Bz+llsdYzklWFzgp0r8=
+github.com/rs/zerolog v1.33.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss=
 github.com/russross/blackfriday/v2 v2.1.0/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM=
 github.com/sagikazarmark/locafero v0.6.0 h1:ON7AQg37yzcRPU69mt7gwhFEBwxI6P9T4Qu3N51bwOk=
 github.com/sagikazarmark/locafero v0.6.0/go.mod h1:77OmuIc6VTraTXKXIs/uvUxKGUXjE1GbemJYHqdNjX0=
@@ -727,7 +737,9 @@ golang.org/x/sys v0.0.0-20210819135213-f52c844e1c1c/go.mod h1:oPkhp1MJrh7nUepCBc
 golang.org/x/sys v0.0.0-20220520151302-bc2c85ada10a/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.26.0 h1:KHjCJyddX0LoSTb3J+vWpupP9p0oznkqVk/IfjymZbo=
 golang.org/x/sys v0.26.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
 golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=

diff --git a/internal/common/armadacontext/armada_context.go b/internal/common/armadacontext/armada_context.go
@@ -75,15 +75,15 @@ func (ctx *Context) Fatalf(format string, args ...interface{}) {
 func Background() *Context {
 	return &Context{
 		Context: context.Background(),
-		logger:  logging.StdLogger().WithCallerSkip(1),
+		logger:  logging.StdLogger(),
 	}
 }
 
 // TODO creates an empty context with a default logger.  It is analogous to context.TODO()
 func TODO() *Context {
 	return &Context{
 		Context: context.TODO(),
-		logger:  logging.StdLogger().WithCallerSkip(1),
+		logger:  logging.StdLogger(),
 	}
 }
 
@@ -93,7 +93,7 @@ func FromGrpcCtx(ctx context.Context) *Context {
 	if ok {
 		return armadaCtx
 	}
-	logger := logging.StdLogger().WithCallerSkip(1).
+	logger := logging.StdLogger().
 		WithField("user", ctx.Value("user")).
 		WithField("requestId", ctx.Value("requestId"))
 	return New(ctx, logger)
@@ -108,7 +108,7 @@ func New(ctx context.Context, log *logging.Logger) *Context {
 }
 
 func (ctx *Context) Logger() *logging.Logger {
-	return ctx.logger.WithCallerSkip(-1)
+	return ctx.logger.WithCallerSkip(logging.StdSkipFrames - 1)
 }
 
 // WithCancel returns a copy of parent with a new Done channel. It is analogous to context.WithCancel()

diff --git a/internal/common/logging/application.go b/internal/common/logging/application.go
@@ -2,98 +2,116 @@ package logging
 
 import (
 	"fmt"
+	"io"
 	"os"
-	"strings"
+	"time"
 
 	"github.com/pkg/errors"
-	"go.uber.org/zap"
-	"go.uber.org/zap/zapcore"
+	"github.com/rs/zerolog"
 	"gopkg.in/natefinch/lumberjack.v2"
+
+	"path/filepath"
 	"sigs.k8s.io/yaml"
+	"strconv"
+	"strings"
 )
 
 var (
 	defaultLogConfigPath = "config/logging.yaml"
 	logConfigPathEnvVar  = "ARMADA_LOG_CONFIG"
+	logTimestampFormat   = "2006-01-02T15:04:05.999Z07:00"
 )
 
-// MustConfigureApplicationLogging sets up logging suitable for an application.  Logging configuration is loaded from
+// MustConfigureApplicationLogging sets up logging suitable for an application. Logging configuration is loaded from
 // a filepath given by the ARMADA_LOG_CONFIG environmental variable or from config/logging.yaml if this var is unset.
-// Note that this function will immediately shut do the application if it fails.
+// Note that this function will immediately shut down the application if it fails.
 func MustConfigureApplicationLogging() {
 	err := ConfigureApplicationLogging()
 	if err != nil {
-		_, _ = fmt.Fprintln(os.Stderr, "Error initialising logging"+err.Error())
+		_, _ = fmt.Fprintln(os.Stderr, "Error initializing logging: "+err.Error())
 		os.Exit(1)
 	}
 }
 
-// ConfigureApplicationLogging sets up logging suitable for an application.  Logging configuration is loaded from
+// ConfigureApplicationLogging sets up logging suitable for an application. Logging configuration is loaded from
 // a filepath given by the ARMADA_LOG_CONFIG environmental variable or from config/logging.yaml if this var is unset.
 func ConfigureApplicationLogging() error {
-	configPath := getEnv(logConfigPathEnvVar, defaultLogConfigPath)
 
+	// Set some global logging properties
+	zerolog.TimeFieldFormat = time.RFC3339Nano
+	zerolog.CallerMarshalFunc = shortCallerEncoder
+
+	// Load config file
+	configPath := getEnv(logConfigPathEnvVar, defaultLogConfigPath)
 	logConfig, err := readConfig(configPath)
 	if err != nil {
 		return err
 	}
 
-	encoderConfig := zapcore.EncoderConfig{
-		TimeKey:          "ts",
-		LevelKey:         "level",
-		NameKey:          "logger",
-		CallerKey:        "caller",
-		FunctionKey:      zapcore.OmitKey,
-		MessageKey:       "msg",
-		StacktraceKey:    "stacktrace",
-		LineEnding:       zapcore.DefaultLineEnding,
-		EncodeLevel:      zapcore.CapitalLevelEncoder,
-		EncodeTime:       zapcore.ISO8601TimeEncoder,
-		EncodeDuration:   zapcore.SecondsDurationEncoder,
-		EncodeCaller:     shortCallerEncoder,
-		ConsoleSeparator: " ",
-	}
-
-	var cores []zapcore.Core
-
 	// Console logging
-	consoleEncoder, err := createEncoder(logConfig.Console.Format, encoderConfig)
-	if err != nil {
-		return errors.Wrap(err, "error creating console logger")
-	}
-	consoleLevel, err := parseLogLevel(logConfig.Console.Level)
+	var writers []io.Writer
+	consoleLogger, err := createConsoleLogger(logConfig)
 	if err != nil {
-		return errors.Wrap(err, "error creating console logger")
+		return err
 	}
-	cores = append(cores, zapcore.NewCore(consoleEncoder, zapcore.AddSync(os.Stdout), consoleLevel))
+	writers = append(writers, consoleLogger)
 
 	// File logging
 	if logConfig.File.Enabled {
-		fileEncoder, err := createEncoder(logConfig.File.Format, encoderConfig)
+		fileLogger, err := createFileLogger(logConfig)
 		if err != nil {
-			return errors.Wrap(err, "error creating file logger")
+			return err
 		}
-		w := zapcore.AddSync(&lumberjack.Logger{
+		writers = append(writers, fileLogger)
+	}
+
+	// Combine loggers
+	multiWriter := zerolog.MultiLevelWriter(writers...)
+	logger := zerolog.New(multiWriter).With().Timestamp().Logger()
+
+	// Set our new logger to be the default
+	ReplaceStdLogger(FromZerolog(logger))
+	return nil
+}
+
+func createFileLogger(logConfig Config) (*FilteredLevelWriter, error) {
+	level, err := zerolog.ParseLevel(logConfig.Console.Level)
+	if err != nil {
+		return nil, err
+	}
+
+	return &FilteredLevelWriter{
+		level: level,
+		writer: &lumberjack.Logger{
 			Filename:   "app.log",
 			MaxSize:    logConfig.File.Rotation.MaxSizeMb,
 			MaxBackups: logConfig.File.Rotation.MaxBackups,
-			MaxAge:     logConfig.File.Rotation.MaxAgeDays, // days
+			MaxAge:     logConfig.File.Rotation.MaxAgeDays,
 			Compress:   logConfig.File.Rotation.Compress,
-		})
-		fileLevel, err := parseLogLevel(logConfig.Console.Level)
-		if err != nil {
-			return errors.Wrap(err, "error creating file logger")
-		}
-		cores = append(cores, zapcore.NewCore(fileEncoder, w, fileLevel))
-	}
-
-	core := zapcore.NewTee(cores...)
+		},
+	}, nil
+}
 
-	// Create logger
-	l := zap.New(core, zap.AddCaller()).WithOptions(zap.AddCallerSkip(2))
-	ReplaceStdLogger(FromZap(l))
+func createConsoleLogger(logConfig Config) (*FilteredLevelWriter, error) {
+	level, err := zerolog.ParseLevel(logConfig.Console.Level)
+	if err != nil {
+		return nil, err
+	}
 
-	return nil
+	return &FilteredLevelWriter{
+		level: level,
+		writer: zerolog.ConsoleWriter{
+			Out:        os.Stdout,
+			TimeFormat: logTimestampFormat,
+			FormatLevel: func(i interface{}) string {
+				return strings.ToUpper(fmt.Sprintf("%s", i))
+			},
+			FormatCaller: func(i interface{}) string {
+				return filepath.Base(fmt.Sprintf("%s", i))
+			},
+			NoColor: true,
+		},
+	}, nil
 }
 
 func readConfig(configFilePath string) (Config, error) {
@@ -114,27 +132,16 @@ func readConfig(configFilePath string) (Config, error) {
 	return config, nil
 }
 
-func createEncoder(format string, encoderConfig zapcore.EncoderConfig) (zapcore.Encoder, error) {
-	switch strings.ToLower(format) {
-	case "json":
-		return zapcore.NewJSONEncoder(encoderConfig), nil
-	case "text":
-		return zapcore.NewConsoleEncoder(encoderConfig), nil
-	default:
-		return nil, errors.Errorf("unknown format: %s", format)
-	}
-}
-
-// ShortCallerEncoder serializes a caller in to just file:line format.
-func shortCallerEncoder(caller zapcore.EntryCaller, enc zapcore.PrimitiveArrayEncoder) {
-	trimmed := caller.TrimmedPath()
-	lastSlash := strings.LastIndexByte(trimmed, '/')
-	if lastSlash != -1 && lastSlash != len(trimmed)-1 {
-		fileName := trimmed[lastSlash+1:]
-		enc.AppendString(fileName)
-	} else {
-		enc.AppendString(trimmed)
+func shortCallerEncoder(_ uintptr, file string, line int) string {
+	short := file
+	for i := len(file) - 1; i > 0; i-- {
+		if file[i] == '/' {
+			short = file[i+1:]
+			break
+		}
 	}
+	file = short
+	return file + ":" + strconv.Itoa(line)
 }
 
 func getEnv(key, defaultValue string) string {
@@ -143,3 +150,22 @@ func getEnv(key, defaultValue string) string {
 	}
 	return defaultValue
 }
+
+type FilteredLevelWriter struct {
+	writer io.Writer
+	level  zerolog.Level
+}
+
+// Write writes to the underlying Writer.
+func (w *FilteredLevelWriter) Write(p []byte) (int, error) {
+	return w.writer.Write(p)
+}
+
+// WriteLevel calls WriteLevel of the underlying Writer only if the level is equal
+// or above the Level.
+func (w *FilteredLevelWriter) WriteLevel(level zerolog.Level, p []byte) (int, error) {
+	if level >= w.level {
+		return w.writer.Write(p)
+	}
+	return len(p), nil
+}
diff --git a/internal/common/logging/global.go b/internal/common/logging/global.go
@@ -1,21 +1,21 @@
 package logging
 
 import (
+	"github.com/rs/zerolog"
 	"os"
-
-	"go.uber.org/zap"
-	"go.uber.org/zap/zapcore"
+	"time"
 )
 
 // The global Logger.  Comes configured with some sensible defaults for e.g. unit tests, but applications should
 // generally configure their own logging config via ReplaceStdLogger
 var (
-	stdLogger = &Logger{underlying: createDefaultLogger()}
+	StdSkipFrames = 4
+	stdLogger     = createDefaultLogger()
 )
 
 // ReplaceStdLogger Replaces the global logger.  This should be called once at app startup!
 func ReplaceStdLogger(l *Logger) {
-	stdLogger = l
+	stdLogger = l.WithCallerSkip(StdSkipFrames)
 }
 
 // StdLogger Returns the default logger
@@ -98,16 +98,19 @@ func WithStacktrace(err error) *Logger {
 	return stdLogger.WithStacktrace(err)
 }
 
-// Default logging options
-func createDefaultLogger() *zap.SugaredLogger {
-	pe := zap.NewProductionEncoderConfig()
-	pe.EncodeTime = zapcore.ISO8601TimeEncoder
-	pe.ConsoleSeparator = " "
-	pe.EncodeLevel = zapcore.CapitalLevelEncoder
-	consoleEncoder := zapcore.NewConsoleEncoder(pe)
-	core := zapcore.NewCore(consoleEncoder, zapcore.AddSync(os.Stdout), zapcore.DebugLevel)
-	return zap.
-		New(core, zap.AddCaller()).
-		WithOptions(zap.AddCallerSkip(2)).
-		Sugar()
+// createDefaultLogger returns a new Logger configured with default settings using zerolog.
+func createDefaultLogger() *Logger {
+	consoleWriter := zerolog.ConsoleWriter{
+		Out:        os.Stdout,
+		TimeFormat: time.RFC3339,
+		NoColor:    true,
+	}
+	zerologLogger := zerolog.New(consoleWriter).
+		Level(zerolog.InfoLevel).
+		With().
+		CallerWithSkipFrameCount(StdSkipFrames).
+		Timestamp().
+		Logger()
+
+	return FromZerolog(zerologLogger)
 }