feat(log): Introduce Trace log level (#412)

* feat: add trace level to logger
* fix: rework new trace logger implementation to build on tags

Now building 2 different types of the Logger interface depending on a build tag
Added implementations for printing the log level properly
Moved the default log level back to Debug
Removed tests that tried to test new trace functionality on a test file without the build tag

---------

Co-authored-by: serkan.begar <serkan.begar@1nce.com>

core/silentzap/levelencoder.go

@@ -0,0 +1,25 @@
+package silentzap
+
+import (
+	"fmt"
+
+	"go.uber.org/zap/zapcore"
+)
+
+func capitalLevelEncoder(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) {
+	if l == logLevels["Trace"] {
+		enc.AppendString("TRACE")
+		return
+	}
+
+	zapcore.CapitalLevelEncoder(l, enc)
+}
+
+func capitalColorLevelEncoder(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) {
+	if l == logLevels["Trace"] {
+		enc.AppendString(fmt.Sprintf("\x1b[36m%s\x1b[0m", "TRACE")) // Cyan colored TRACE
+		return
+	}
+
+	zapcore.CapitalColorLevelEncoder(l, enc)
+}

core/silentzap/levels_standard.go

@@ -0,0 +1,6 @@
+//go:build !tracelog
+
+package silentzap
+
+// allowedLevels returns allowed levels for the standard logger.
+const allowedLevels = `*"Debug" | "Info" | "Warn" | "Error" | "DPanic" | "Panic" | "Fatal"`

core/silentzap/levels_trace.go

@@ -0,0 +1,6 @@
+//go:build tracelog
+
+package silentzap
+
+// allowedLevels returns allowed levels for the trace logger.
+const allowedLevels = `"Trace" | *"Debug" | "Info" | "Warn" | "Error" | "DPanic" | "Panic" | "Fatal"`

core/silentzap/logger.go

@@ -35,6 +35,7 @@ var (
 	keyLevel, _ = tag.NewKey("level")
 
 	logLevels = map[string]zapcore.Level{
+		"Trace":  zap.DebugLevel - 1, // does not exist in zap by default
 		"Debug":  zap.DebugLevel,
 		"Info":   zap.InfoLevel,
 		"Warn":   zap.WarnLevel,
@@ -85,9 +86,11 @@ func getSilentLogger(
 		output = "json"
 	}
 
-	encoder := zapcore.CapitalLevelEncoder
+	// Capital encoder with trace addition
+	encoder := capitalLevelEncoder
 	if config.ColoredOutput {
-		encoder = zapcore.CapitalColorLevelEncoder
+		// Capital color encoder with trace addition
+		encoder = capitalColorLevelEncoder
 	}
 
 	cfg := makeZapConfig(level, config.DevelopmentMode, samplingConfig, output, encoder)
@@ -170,6 +173,40 @@ func (l *SilentLogger) record(level string) {
 	stats.Record(ctx, logCount.M(1))
 }
 
+// Trace logs a message at trace level
+func (l *SilentLogger) Trace(args ...interface{}) {
+	l.record("Trace")
+
+	logContext := l.loggingRegistry.Get(l.traceID)
+	if logContext.isWritingAllowed() {
+		l.writeLog(func(zl *zap.Logger, msg string, fields ...zapcore.Field) {
+			zl.Log(logLevels["Trace"], msg, fields...)
+		}, fmt.Sprint(args...))
+
+		return
+	}
+
+	checkedEntry := l.Logger.Check(logLevels["Trace"], fmt.Sprint(args...))
+	logContext.store(checkedEntry)
+}
+
+// Debugf logs a message at debug level with format string
+func (l *SilentLogger) Tracef(log string, args ...interface{}) {
+	l.record("Trace")
+
+	logContext := l.loggingRegistry.Get(l.traceID)
+	if logContext.isWritingAllowed() {
+		l.writeLog(func(zl *zap.Logger, msg string, fields ...zapcore.Field) {
+			zl.Log(logLevels["Trace"], msg, fields...)
+		}, fmt.Sprintf(log, args...))
+
+		return
+	}
+
+	checkedEntry := l.Logger.Check(logLevels["Trace"], fmt.Sprintf(log, args...))
+	logContext.store(checkedEntry)
+}
+
 // Debug logs a message at debug level
 func (l *SilentLogger) Debug(args ...interface{}) {
 	l.record("Debug")

core/silentzap/module.go

@@ -2,6 +2,7 @@ package silentzap
 
 import (
 	"context"
+	"fmt"
 
 	"flamingo.me/dingo"
 
@@ -48,16 +49,16 @@ func (subscriber *shutdownEventSubscriber) Notify(_ context.Context, event flami
 // CueConfig Schema
 func (m *Module) CueConfig() string {
 	// language=cue
-	return `
+	return fmt.Sprintf(`
 core zap: {
-	loglevel: *"Debug" | "Info" | "Warn" | "Error" | "DPanic" | "Panic" | "Fatal"
+	loglevel: %s
 	sampling: {
 		enabled: bool | *true
 		initial: int | *100 
 		thereafter: int | *100
 	}
 }
-`
+`, allowedLevels)
 }
 
 // FlamingoLegacyConfigAlias mapping

core/zap/levelencoder.go

@@ -0,0 +1,25 @@
+package zap
+
+import (
+	"fmt"
+
+	"go.uber.org/zap/zapcore"
+)
+
+func capitalLevelEncoder(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) {
+	if l == logLevels["Trace"] {
+		enc.AppendString("TRACE")
+		return
+	}
+
+	zapcore.CapitalLevelEncoder(l, enc)
+}
+
+func capitalColorLevelEncoder(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) {
+	if l == logLevels["Trace"] {
+		enc.AppendString(fmt.Sprintf("\x1b[36m%s\x1b[0m", "TRACE")) // Cyan colored TRACE
+		return
+	}
+
+	zapcore.CapitalColorLevelEncoder(l, enc)
+}

core/zap/levels_standard.go

@@ -0,0 +1,6 @@
+//go:build !tracelog
+
+package zap
+
+// allowedLevels returns allowed levels for the standard logger.
+const allowedLevels = `*"Debug" | "Info" | "Warn" | "Error" | "DPanic" | "Panic" | "Fatal"`

core/zap/levels_trace.go

@@ -0,0 +1,6 @@
+//go:build tracelog
+
+package zap
+
+// allowedLevels returns allowed levels for the trace logger.
+const allowedLevels = `"Trace" | *"Debug" | "Info" | "Warn" | "Error" | "DPanic" | "Panic" | "Fatal"`

core/zap/logger.go

@@ -94,6 +94,22 @@ func (l *Logger) record(level string) {
 	stats.Record(ctx, logCount.M(1))
 }
 
+// Trace logs a message at debug level
+func (l *Logger) Trace(args ...interface{}) {
+	l.record("Trace")
+	l.writeLog(func(zl *zap.Logger, msg string, fields ...zapcore.Field) {
+		zl.Log(logLevels["Trace"], msg, fields...)
+	}, fmt.Sprint(args...))
+}
+
+// Tracef logs a message at trace level with format string
+func (l *Logger) Tracef(log string, args ...interface{}) {
+	l.record("Trace")
+	l.writeLog(func(zl *zap.Logger, msg string, fields ...zapcore.Field) {
+		zl.Log(logLevels["Trace"], msg, fields...)
+	}, fmt.Sprintf(log, args...))
+}
+
 // Debug logs a message at debug level
 func (l *Logger) Debug(args ...interface{}) {
 	l.record("Debug")

core/zap/logger_test.go

@@ -295,6 +295,30 @@ func TestLogger_WithFields(t *testing.T) {
 	}
 }
 
+func TestLogger_Trace(t *testing.T) {
+	t.Parallel()
+
+	core, observedLogs := observer.New(uberZap.DebugLevel - 1) // trace level
+	l := zap.NewLogger(uberZap.New(core, uberZap.WithFatalHook(zapcore.WriteThenNoop)))
+
+	l.Trace("test")
+
+	require.Equal(t, observedLogs.Len(), 1)
+	assert.Equal(t, "test", observedLogs.All()[0].Message)
+}
+
+func TestLogger_Tracef(t *testing.T) {
+	t.Parallel()
+
+	core, observedLogs := observer.New(uberZap.DebugLevel - 1) // trace level
+	l := zap.NewLogger(uberZap.New(core, uberZap.WithFatalHook(zapcore.WriteThenNoop)))
+
+	l.Tracef("test %s", "logger")
+
+	require.Equal(t, observedLogs.Len(), 1)
+	assert.Equal(t, "test logger", observedLogs.All()[0].Message)
+}
+
 func TestLogger_Debug(t *testing.T) {
 	t.Parallel()
 

core/zap/module.go

@@ -2,6 +2,7 @@ package zap
 
 import (
 	"context"
+	"fmt"
 
 	"flamingo.me/dingo"
 	"flamingo.me/flamingo/v3/framework/config"
@@ -31,6 +32,7 @@ type (
 )
 
 var logLevels = map[string]zapcore.Level{
+	"Trace":  zap.DebugLevel - 1, // does not exist in zap by default
 	"Debug":  zap.DebugLevel,
 	"Info":   zap.InfoLevel,
 	"Warn":   zap.WarnLevel,
@@ -101,9 +103,11 @@ func (m *Module) createLoggerInstance() *Logger {
 		output = "json"
 	}
 
-	encoder := zapcore.CapitalLevelEncoder
+	// Capital encoder with trace addition
+	encoder := capitalLevelEncoder
 	if m.coloredOutput {
-		encoder = zapcore.CapitalColorLevelEncoder
+		// Capital color encoder with trace addition
+		encoder = capitalColorLevelEncoder
 	}
 
 	cfg := zap.Config{
@@ -167,9 +171,9 @@ func (subscriber *shutdownEventSubscriber) Notify(_ context.Context, event flami
 // CueConfig Schema
 func (m *Module) CueConfig() string {
 	// language=cue
-	return `
+	return fmt.Sprintf(`
 core: zap: {
-	loglevel: *"Debug" | "Info" | "Warn" | "Error" | "DPanic" | "Panic" | "Fatal"
+	loglevel: %s
 	sampling: {
 		enabled: bool | *true
 		initial: int | *100 
@@ -183,7 +187,7 @@ core: zap: {
 		[string]: string
 	}
 }
-`
+`, allowedLevels)
 }
 
 // FlamingoLegacyConfigAlias mapping

framework/flamingo/log.go

@@ -41,25 +41,6 @@ const (
 type (
 	// LogKey is a logging key constant
 	LogKey string
-
-	// Logger defines a standard Flamingo logger interfaces
-	Logger interface {
-		WithContext(ctx context.Context) Logger
-
-		Debug(args ...interface{})
-		Info(args ...interface{})
-		Warn(args ...interface{})
-		Error(args ...interface{})
-		Fatal(args ...interface{})
-		Panic(args ...interface{})
-
-		Debugf(log string, args ...interface{})
-
-		WithField(key LogKey, value interface{}) Logger
-		WithFields(fields map[LogKey]interface{}) Logger
-
-		Flush()
-	}
 )
 
 func LogFunc(l Logger, fields map[LogKey]any) func(f func(l Logger, args ...any), args ...any) {
@@ -120,6 +101,27 @@ func (l *StdLogger) Panic(args ...interface{}) {
 	l.Logger.Panic(args...)
 }
 
+// Trace logs output
+func (l *StdLogger) Trace(args ...interface{}) {
+	args = append([]any{"trace: "}, args...)
+	if isLoggerNil(l) {
+		log.Print(args...)
+		return
+	}
+
+	l.Logger.Print(args...)
+}
+
+// Tracef outputs the formatted trace string
+func (l *StdLogger) Tracef(f string, args ...interface{}) {
+	if isLoggerNil(l) {
+		log.Print(args...)
+		return
+	}
+
+	l.Logger.Printf(f, args...)
+}
+
 // Debug logs output
 func (l *StdLogger) Debug(args ...interface{}) {
 	args = append([]any{"debug: "}, args...)
@@ -218,6 +220,12 @@ func (n NullLogger) WithField(_ LogKey, _ interface{}) Logger { return n }
 // WithFields null-implementation
 func (n NullLogger) WithFields(_ map[LogKey]interface{}) Logger { return n }
 
+// Trace null-implementation
+func (NullLogger) Trace(_ ...interface{}) {}
+
+// Tracef null-implementation
+func (NullLogger) Tracef(_ string, _ ...interface{}) {}
+
 // Debug null-implementation
 func (NullLogger) Debug(_ ...interface{}) {}
 

framework/flamingo/log_standard.go

@@ -0,0 +1,28 @@
+//go:build !tracelog
+
+package flamingo
+
+import (
+	"context"
+)
+
+type (
+	// Logger defines the standard Flamingo logger interface
+	Logger interface {
+		WithContext(ctx context.Context) Logger
+
+		Debug(args ...interface{})
+		Info(args ...interface{})
+		Warn(args ...interface{})
+		Error(args ...interface{})
+		Fatal(args ...interface{})
+		Panic(args ...interface{})
+
+		Debugf(log string, args ...interface{})
+
+		WithField(key LogKey, value interface{}) Logger
+		WithFields(fields map[LogKey]interface{}) Logger
+
+		Flush()
+	}
+)

framework/flamingo/log_test.go

@@ -42,6 +42,7 @@ func ExampleLogger() {
 	logger.Info("my", "log", "args")
 	logger.Warn("my", "log", "args")
 	logger.Debug("my", "log", "args")
+	// logger.Trace("my", "log", "args") // this is possible with build tag `tracelog`
 
 	fmt.Println(recorder.String())
 
@@ -69,6 +70,7 @@ func ExampleLogFunc() {
 	logFunc(flamingo.Logger.Info, "my", "log", "args")
 	logFunc(flamingo.Logger.Warn, "my", "log", "args")
 	logFunc(flamingo.Logger.Debug, "my", "log", "args")
+	// logFunc(flamingo.Logger.Trace, "my", "log", "args") // this is possible with build tag `tracelog`
 	// if we do not give the level, it will be Info
 	logFunc(nil, "my", "log", "args")
 
@@ -106,6 +108,7 @@ func ExampleLogFuncWithContext() {
 	logFunc(ctx, flamingo.Logger.Info, "my", "log", "args")
 	logFunc(ctx, flamingo.Logger.Warn, "my", "log", "args")
 	logFunc(ctx, flamingo.Logger.Debug, "my", "log", "args")
+	// logFunc(ctx, flamingo.Logger.Trace, "my", "log", "args") // this is possible with build tag `tracelog`
 	// if we do not give the level, it will be Info
 	logFunc(ctx, nil, "my", "log", "args")