Add uuid to log messages

FerretDB · AlekSi · Oct 12, 2022 · Oct 10, 2022 · Oct 10, 2022 · Oct 11, 2022
commit e57fa5d2d5b3ee5671cb744b495078116021c96f
@@ -290,7 +290,8 @@ func main() {
 	if cli.Debug {
 		level = zap.DebugLevel
 	}
-	logging.Setup(level)
+
+	logging.Setup(level, "")
 	logger := zap.S()
 
 	ctx, cancel := context.WithTimeout(context.Background(), time.Minute)

@@ -43,10 +43,15 @@ var cli struct {
 	ListenAddr string `default:"127.0.0.1:27017"      help:"Listen address."`
 	ProxyAddr  string `default:"127.0.0.1:37017"      help:"Proxy address."`
 	DebugAddr  string `default:"127.0.0.1:8088"       help:"Debug address."`
-	LogLevel   string `default:"${default_log_level}" help:"${help_log_level}"`
 	StateDir   string `default:"."                    help:"Process state directory."`
 	Mode       string `default:"${default_mode}"      help:"${help_mode}"             enum:"${enum_mode}"`
-	Handler    string `default:"pg"                   help:"${help_handler}"`
+
+	Log struct {
+		Level string `default:"${default_log_level}" help:"${help_log_level}"`
+		UUID  bool   `default:"false"                help:"Add instance UUID to log messages."`
+	} `embed:"" prefix:"log-"`
+
+	Handler string `default:"pg" help:"${help_handler}"`
 
 	PostgresURL string `default:"postgres://postgres@127.0.0.1:5432/ferretdb" help:"PostgreSQL URL for 'pg' handler."`
 
@@ -64,20 +69,23 @@ var cli struct {
 // Additional variables for the kong parsers.
 var (
 	logLevels = []string{
-		zapcore.DebugLevel.String(),
-		zapcore.InfoLevel.String(),
-		zapcore.WarnLevel.String(),
-		zapcore.ErrorLevel.String(),
+		zap.DebugLevel.String(),
+		zap.InfoLevel.String(),
+		zap.WarnLevel.String(),
+		zap.ErrorLevel.String(),
 	}
 
 	kongOptions = []kong.Option{
 		kong.Vars{
-			"default_log_level": zapcore.DebugLevel.String(),
+			"default_log_level": zap.DebugLevel.String(),
 			"default_mode":      clientconn.AllModes[0],
 
-			"help_log_level": fmt.Sprintf("Log level: '%s'.", strings.Join(logLevels, "', '")),
-			"help_mode":      fmt.Sprintf("Operation mode: '%s'.", strings.Join(clientconn.AllModes, "', '")),
-			"help_handler":   fmt.Sprintf("Backend handler: '%s'.", strings.Join(registry.Handlers(), "', '")),
+			"help_log_level": fmt.Sprintf(
+				"Log level: '%s'. Debug level also enables development mode.",
+				strings.Join(logLevels, "', '"),
+			),
+			"help_mode":    fmt.Sprintf("Operation mode: '%s'.", strings.Join(clientconn.AllModes, "', '")),
+			"help_handler": fmt.Sprintf("Backend handler: '%s'.", strings.Join(registry.Handlers(), "', '")),
 
 			"enum_mode": strings.Join(clientconn.AllModes, ","),
 		},
@@ -101,13 +109,6 @@ func main() {
 
 // run sets up environment based on provided flags and runs FerretDB.
 func run() {
-	level, err := zapcore.ParseLevel(cli.LogLevel)
-	if err != nil {
-		log.Fatal(err)
-	}
-	logging.Setup(level)
-	logger := zap.L()
-
 	info := version.Get()
 
 	if cli.Version {
@@ -120,30 +121,44 @@ func run() {
 
 	stateFile, err := filepath.Abs(filepath.Join(cli.StateDir, "state.json"))
 	if err != nil {
-		logger.Fatal("Failed to get path for state file", zap.Error(err))
+		log.Fatalf("Failed to get path for state file: %s.", err)
 	}
-	logger.Debug("State file", zap.String("filename", stateFile))
 
 	p, err := state.NewProvider(stateFile)
 	if err != nil {
-		logger.Fatal("Failed to create state provider", zap.Error(err))
+		log.Fatalf("Failed to create state provider: %s.", err)
 	}
 
 	s, err := p.Get()
 	if err != nil {
-		logger.Fatal("Failed to get state", zap.Error(err))
+		log.Fatalf("Failed to get state: %s.", err)
+	}
+
+	level, err := zapcore.ParseLevel(cli.Log.Level)
+	if err != nil {
+		log.Fatal(err)
 	}
 
-	startFields := []zap.Field{
+	logUUID := s.UUID
+	startupFields := []zap.Field{
 		zap.String("version", info.Version),
 		zap.String("commit", info.Commit),
 		zap.String("branch", info.Branch),
 		zap.Bool("dirty", info.Dirty),
 		zap.Bool("debug", info.Debug),
 		zap.Reflect("buildEnvironment", info.BuildEnvironment.Map()),
-		zap.String("uuid", s.UUID),
 	}
-	logger.Info("Starting FerretDB "+info.Version+"...", startFields...)
+
+	// don't add UUID to all messages, but log it once at startup
+	if !cli.Log.UUID {
+		logUUID = ""
+		startupFields = append(startupFields, zap.String("uuid", s.UUID))
+	}
+
+	logging.Setup(level, logUUID)
+	logger := zap.L()
+
+	logger.Info("Starting FerretDB "+info.Version+"...", startupFields...)
 
 	ctx, stop := notifyAppTermination(context.Background())
 	go func() {

diff --git a/cmd/fuzztool/fuzztool.go b/cmd/fuzztool/fuzztool.go
@@ -199,10 +199,10 @@ var cli struct {
 func main() {
 	ctx := kong.Parse(&cli)
 
-	logging.Setup(zap.InfoLevel)
+	logging.Setup(zap.InfoLevel, "")
 
 	if cli.Debug {
-		logging.Setup(zap.DebugLevel)
+		logging.Setup(zap.DebugLevel, "")
 	}
 
 	logger := zap.S()

diff --git a/ferretdb/ferretdb.go b/ferretdb/ferretdb.go
@@ -22,7 +22,6 @@ import (
 	"net/url"
 
 	"go.uber.org/zap"
-	"go.uber.org/zap/zapcore"
 
 	"github.com/FerretDB/FerretDB/internal/clientconn"
 	"github.com/FerretDB/FerretDB/internal/handlers/registry"
@@ -122,6 +121,6 @@ var logger *zap.Logger
 // Initialize the global logger there to avoid creating too many issues for zap users that initialize it in their
 // `main()` functions. It is still not a full solution; eventually, we should remove the usage of the global logger.
 func init() {
-	logging.Setup(zapcore.FatalLevel)
+	logging.Setup(zap.FatalLevel, "")
 	logger = zap.L()
 }
@@ -186,7 +186,7 @@ func setupClient(tb testing.TB, ctx context.Context, port int) *mongo.Client {
 // startup initializes things that should be initialized only once.
 func startup() {
 	startupOnce.Do(func() {
-		logging.Setup(zap.DebugLevel)
+		logging.Setup(zap.DebugLevel, "")
 
 		go debug.RunHandler(context.Background(), "127.0.0.1:0", zap.L().Named("debug"))
 

diff --git a/internal/handlers/pg/msg_getlog.go b/internal/handlers/pg/msg_getlog.go
@@ -21,7 +21,7 @@ import (
 	"strings"
 	"time"
 
-	"go.uber.org/zap/zapcore"
+	"go.uber.org/zap"
 
 	"github.com/FerretDB/FerretDB/internal/handlers/common"
 	"github.com/FerretDB/FerretDB/internal/types"
@@ -72,7 +72,7 @@ func (h *Handler) MsgGetLog(ctx context.Context, msg *wire.OpMsg) (*wire.OpMsg,
 		))
 
 	case "global":
-		log, err := logging.RecentEntries.GetArray(zapcore.DebugLevel)
+		log, err := logging.RecentEntries.GetArray(zap.DebugLevel)
 		if err != nil {
 			return nil, lazyerrors.Error(err)
 		}

diff --git a/internal/handlers/tigris/msg_getlog.go b/internal/handlers/tigris/msg_getlog.go
@@ -20,7 +20,7 @@ import (
 	"fmt"
 	"time"
 
-	"go.uber.org/zap/zapcore"
+	"go.uber.org/zap"
 
 	"github.com/FerretDB/FerretDB/internal/handlers/common"
 	"github.com/FerretDB/FerretDB/internal/types"
@@ -71,7 +71,7 @@ func (h *Handler) MsgGetLog(ctx context.Context, msg *wire.OpMsg) (*wire.OpMsg,
 		))
 
 	case "global":
-		log, err := logging.RecentEntries.GetArray(zapcore.DebugLevel)
+		log, err := logging.RecentEntries.GetArray(zap.DebugLevel)
 		if err != nil {
 			return nil, lazyerrors.Error(err)
 		}

diff --git a/internal/util/logging/buffer.go b/internal/util/logging/buffer.go
@@ -28,7 +28,7 @@ import (
 
 // RecentEntries implements zap logging entries interception
 // and stores the last 1024 entries in circular buffer in memory.
-var RecentEntries *circularBuffer
+var RecentEntries = NewCircularBuffer(1024)
 
 // circularBuffer is a storage of log records in memory.
 type circularBuffer struct {

diff --git a/internal/util/logging/buffer_test.go b/internal/util/logging/buffer_test.go
@@ -102,14 +102,14 @@ func TestCircularBuffer(t *testing.T) {
 		tc := tc
 		t.Run(name, func(t *testing.T) {
 			logram.append(&tc.inLog)
-			actual := logram.get(zapcore.DebugLevel)
+			actual := logram.get(zap.DebugLevel)
 			for i, exp := range tc.expected {
 				assert.Equal(t, exp, *actual[i])
 			}
 		})
 	}
 
-	Setup(zap.DebugLevel)
+	Setup(zap.DebugLevel, "")
 	logger := zap.L()
 	for n, tc := range []struct {
 		addMsg   string
@@ -131,7 +131,7 @@ func TestCircularBuffer(t *testing.T) {
 		tc := tc
 		t.Run(name, func(t *testing.T) {
 			logger.Info(tc.addMsg)
-			actual := RecentEntries.get(zapcore.DebugLevel)
+			actual := RecentEntries.get(zap.DebugLevel)
 			for i, exp := range tc.expected {
 				assert.Equal(t, exp, actual[i].Message)
 			}

diff --git a/internal/util/logging/logging.go b/internal/util/logging/logging.go
@@ -23,43 +23,46 @@ import (
 )
 
 // Setup initializes logging with a given level.
-func Setup(level zapcore.Level) {
-	var config zap.Config
-	if level <= zapcore.DebugLevel {
-		config = zap.Config{
-			Level:             zap.NewAtomicLevelAt(level),
-			Development:       true,
-			DisableCaller:     false,
-			DisableStacktrace: false,
-			Sampling:          nil,
-			Encoding:          "console",
-			EncoderConfig:     zap.NewDevelopmentEncoderConfig(),
-			OutputPaths:       []string{"stderr"},
-			ErrorOutputPaths:  []string{"stderr"},
-			InitialFields:     nil,
-		}
-	} else {
-		config = zap.Config{
-			Level:             zap.NewAtomicLevelAt(level),
-			Development:       false,
-			DisableCaller:     false,
-			DisableStacktrace: false,
-			Sampling:          nil,
-			Encoding:          "console",
-			EncoderConfig:     zap.NewDevelopmentEncoderConfig(),
-			OutputPaths:       []string{"stderr"},
-			ErrorOutputPaths:  []string{"stderr"},
-			InitialFields:     nil,
-		}
+func Setup(level zapcore.Level, uuid string) {
+	config := zap.Config{
+		Level:             zap.NewAtomicLevelAt(level),
+		Development:       false,
+		DisableCaller:     false,
+		DisableStacktrace: false,
+		Sampling:          nil,
+		Encoding:          "console",
+		EncoderConfig: zapcore.EncoderConfig{
+			TimeKey:        "T",
+			LevelKey:       "L",
+			NameKey:        "N",
+			CallerKey:      "C",
+			FunctionKey:    zapcore.OmitKey,
+			MessageKey:     "M",
+			StacktraceKey:  "S",
+			LineEnding:     zapcore.DefaultLineEnding,
+			EncodeLevel:    zapcore.CapitalLevelEncoder,
+			EncodeTime:     zapcore.ISO8601TimeEncoder,
+			EncodeDuration: zapcore.StringDurationEncoder,
+			EncodeCaller:   zapcore.ShortCallerEncoder,
+		},
+		OutputPaths:      []string{"stderr"},
+		ErrorOutputPaths: []string{"stderr"},
+		InitialFields:    nil,
+	}
+
+	if level == zap.DebugLevel {
+		config.Development = true
+	}
+
+	if uuid != "" {
+		config.InitialFields = map[string]any{"uuid": uuid}
 	}
 
 	logger, err := config.Build()
 	if err != nil {
 		log.Fatal(err)
 	}
 
-	RecentEntries = NewCircularBuffer(1024)
-
 	logger = logger.WithOptions(zap.Hooks(func(entry zapcore.Entry) error {
 		RecentEntries.append(&entry)
 		return nil