Add UUID to log messages (#1208)

Refs #1209.
FerretDB · Oct 11, 2022 · 470940b · 470940b · vercel · Oct 11, 2022
1 parent 51eeb82
commit 470940b
Show file tree

Hide file tree

Showing 20 changed files with 313 additions and 100 deletions.
diff --git a/.gitignore b/.gitignore
@@ -22,6 +22,9 @@ node_modules/
 # test coverage results, generated files like commit.txt, etc.
 *.txt
 
+# runtime state
+state.json
+
 # for now
 testdata/fuzz/
 records/

diff --git a/Taskfile.yml b/Taskfile.yml
@@ -232,18 +232,18 @@ tasks:
     desc: "Run FerretDB"
     deps: [build-testcover]
     cmds:
-      - bin/ferretdb-testcover{{exeExt}} -test.coverprofile=cover.txt -- --test-record=records --mode=diff-normal --listen-addr=:27017
+      - bin/ferretdb-testcover{{exeExt}} -test.coverprofile=cover.txt -- --test-records-dir=records --mode=diff-normal --listen-addr=:27017
 
   run-tigris:
     deps: [build-testcover]
     cmds:
-      - bin/ferretdb-testcover{{exeExt}} -test.coverprofile=cover.txt -- --test-record=records --mode=diff-normal --listen-addr=:27017 --handler=tigris
+      - bin/ferretdb-testcover{{exeExt}} -test.coverprofile=cover.txt -- --test-records-dir=records --mode=diff-normal --listen-addr=:27017 --handler=tigris
 
   run-proxy:
     desc: "Run FerretDB in diff-proxy mode"
     deps: [build-testcover]
     cmds:
-      - bin/ferretdb-testcover{{exeExt}} -test.coverprofile=cover.txt -- --test-record=records --mode=diff-proxy --listen-addr=:27017
+      - bin/ferretdb-testcover{{exeExt}} -test.coverprofile=cover.txt -- --test-records-dir=records --mode=diff-proxy --listen-addr=:27017
 
   lint:
     desc: "Run linters"

diff --git a/cmd/envtool/main.go b/cmd/envtool/main.go
@@ -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)

diff --git a/cmd/ferretdb/main.go b/cmd/ferretdb/main.go
@@ -19,6 +19,7 @@ import (
 	"fmt"
 	"log"
 	"os"
+	"path/filepath"
 	"strings"
 	"time"
 
@@ -27,54 +28,68 @@ import (
 	"github.com/prometheus/common/expfmt"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
-	"golang.org/x/exp/slices"
 
 	"github.com/FerretDB/FerretDB/internal/clientconn"
 	"github.com/FerretDB/FerretDB/internal/handlers/registry"
 	"github.com/FerretDB/FerretDB/internal/util/debug"
 	"github.com/FerretDB/FerretDB/internal/util/logging"
+	"github.com/FerretDB/FerretDB/internal/util/state"
 	"github.com/FerretDB/FerretDB/internal/util/version"
 )
 
 // The cli struct represents all command-line commands, fields and flags.
 // It's used for parsing the user input.
 var cli struct {
-	Version bool `default:"false" help:"Print version to stdout (full version, commit, branch, dirty flag) and exit."`
+	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."`
+	StateDir   string `default:"."                    help:"Process state directory."`
+	Mode       string `default:"${default_mode}"      help:"${help_mode}"             enum:"${enum_mode}"`
 
-	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."`
-	Mode       string `default:"${default_mode}" help:"${help_mode}."`
-	TestRecord string `default:"" help:"Directory of record files with binary data coming from connected clients."`
+	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}."`
+	Handler string `default:"pg" help:"${help_handler}"`
 
-	PostgresURL string `name:"postgresql-url" default:"postgres://postgres@127.0.0.1:5432/ferretdb" help:"PostgreSQL URL."`
+	PostgresURL string `default:"postgres://postgres@127.0.0.1:5432/ferretdb" help:"PostgreSQL URL for 'pg' handler."`
 
-	LogLevel string `default:"${default_logLevel}" help:"${help_logLevel}."`
+	// Put flags for other handlers there, between --postgres-url and --version in the help output.
+	kong.Plugins
 
-	TestConnTimeout time.Duration `default:"0" help:"Test: set connection timeout."`
+	Version bool `default:"false" help:"Print version to stdout and exit."`
 
-	kong.Plugins
+	Test struct {
+		ConnTimeout time.Duration `default:"0" help:"Testing flag: client connection timeout."`
+		RecordsDir  string        `default:""  help:"Testing flag: directory for record files."`
+	} `embed:"" prefix:"test-"`
 }
 
 // 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_logLevel": zapcore.DebugLevel.String(),
-			"default_mode":     string(clientconn.AllModes[0]),
-			"help_handler":     "Backend handler: " + strings.Join(registry.Handlers(), ", "),
-			"help_logLevel":    "Log level: " + strings.Join(logLevels, ", "),
-			"help_mode":        fmt.Sprintf("Operation mode: %v", clientconn.AllModes),
+			"default_log_level": zap.DebugLevel.String(),
+			"default_mode":      clientconn.AllModes[0],
+
+			"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, ","),
 		},
+		kong.DefaultEnvars("FERRETDB"),
 	}
 )
 
@@ -94,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 {
@@ -111,20 +119,47 @@ func run() {
 		return
 	}
 
-	startFields := []zap.Field{
+	stateFile, err := filepath.Abs(filepath.Join(cli.StateDir, "state.json"))
+	if err != nil {
+		log.Fatalf("Failed to get path for state file: %s.", err)
+	}
+
+	p, err := state.NewProvider(stateFile)
+	if err != nil {
+		log.Fatalf("Failed to create state provider: %s.", err)
+	}
+
+	s, err := p.Get()
+	if err != nil {
+		log.Fatalf("Failed to get state: %s.", err)
+	}
+
+	level, err := zapcore.ParseLevel(cli.Log.Level)
+	if err != nil {
+		log.Fatal(err)
+	}
+
+	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()),
 	}
-	logger.Info("Starting FerretDB "+info.Version+"...", startFields...)
 
-	if !slices.Contains(clientconn.AllModes, clientconn.Mode(cli.Mode)) {
-		logger.Sugar().Fatalf("Unknown mode %q.", cli.Mode)
+	// 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() {
 		<-ctx.Done()
@@ -156,8 +191,8 @@ func run() {
 		Mode:            clientconn.Mode(cli.Mode),
 		Handler:         h,
 		Logger:          logger,
-		TestConnTimeout: cli.TestConnTimeout,
-		TestRecordPath:  cli.TestRecord,
+		TestConnTimeout: cli.Test.ConnTimeout,
+		TestRecordsDir:  cli.Test.RecordsDir,
 	})
 
 	prometheus.DefaultRegisterer.MustRegister(l)

diff --git a/cmd/ferretdb/main_test.go b/cmd/ferretdb/main_test.go
@@ -35,8 +35,8 @@ func TestCover(t *testing.T) {
 // TestMain ensures that command-line flags are initialized correctly when FerretDB is run with coverage enabled.
 func TestMain(m *testing.M) {
 	// Split flags for kong and for `go test` by "--". For example:
-	// bin/ferretdb-testcover -test.coverprofile=cover.txt -- --test-record=records --mode=diff-normal --listen-addr=:27017
-	// forKong: --test-record=records --mode=diff-normal --listen-addr=:27017
+	// bin/ferretdb-testcover -test.coverprofile=cover.txt -- --test-records-dir=records --mode=diff-normal --listen-addr=:27017
+	// forKong: --test-records-dir=records --mode=diff-normal --listen-addr=:27017
 	// forTest: -test.coverprofile=cover.txt
 	forKong := os.Args[1:]
 	forTest := []string{}

diff --git a/cmd/ferretdb/main_tigris.go b/cmd/ferretdb/main_tigris.go
@@ -23,10 +23,10 @@ import (
 // The tigrisFlags struct represents flags that
 // are used specifically for a "tigris" handler.
 var tigrisFlags struct {
-	TigrisClientID     string `default:"" help:"Tigris Client ID."`
-	TigrisClientSecret string `default:"" help:"Tigris Client secret."`
-	TigrisToken        string `default:"" help:"Tigris token."`
-	TigrisURL          string `default:"http://127.0.0.1:8081/" help:"Tigris URL."`
+	TigrisURL          string `default:"http://127.0.0.1:8081/" help:"Tigris URL for 'tigris' handler."`
+	TigrisClientID     string `default:""                       help:"Tigris Client ID."`
+	TigrisClientSecret string `default:""                       help:"Tigris Client secret."`
+	TigrisToken        string `default:""                       help:"Tigris token."`
 }
 
 // init adds "tigris" handler flags when "ferretdb_tigris" build tag is provided.

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()
 }
diff --git a/go.mod b/go.mod
@@ -5,6 +5,7 @@ go 1.19
 require (
 	github.com/AlekSi/pointer v1.2.0
 	github.com/alecthomas/kong v0.6.1
+	github.com/google/uuid v1.3.0
 	github.com/jackc/pgconn v1.13.0
 	github.com/jackc/pgerrcode v0.0.0-20220416144525-469b46aa5efa
 	github.com/jackc/pgx/v4 v4.17.2
@@ -33,7 +34,6 @@ require (
 	github.com/go-openapi/swag v0.21.1 // indirect
 	github.com/golang/protobuf v1.5.2 // indirect
 	github.com/google/gnostic v0.6.9 // indirect
-	github.com/google/uuid v1.3.0 // indirect
 	github.com/grpc-ecosystem/go-grpc-middleware v1.3.0 // indirect
 	github.com/grpc-ecosystem/grpc-gateway/v2 v2.10.2 // indirect
 	github.com/jackc/chunkreader/v2 v2.0.1 // indirect

diff --git a/integration/setup/common.go b/integration/setup/common.go
@@ -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/clientconn/conn.go b/internal/clientconn/conn.go
@@ -60,7 +60,12 @@ const (
 )
 
 // AllModes includes all operation modes, with the first one being the default.
-var AllModes = []Mode{NormalMode, ProxyMode, DiffNormalMode, DiffProxyMode}
+var AllModes = []string{
+	string(NormalMode),
+	string(ProxyMode),
+	string(DiffNormalMode),
+	string(DiffProxyMode),
+}
 
 // conn represents client connection.
 type conn struct {
@@ -71,7 +76,7 @@ type conn struct {
 	m              *ConnMetrics
 	proxy          *proxy.Router
 	lastRequestID  int32
-	testRecordPath string // if empty, no records are created
+	testRecordsDir string // if empty, no records are created
 }
 
 // newConnOpts represents newConn options.
@@ -82,11 +87,14 @@ type newConnOpts struct {
 	handler        handlers.Interface
 	connMetrics    *ConnMetrics
 	proxyAddr      string
-	testRecordPath string // if empty, no records are created
+	testRecordsDir string // if empty, no records are created
 }
 
 // newConn creates a new client connection for given net.Conn.
 func newConn(opts *newConnOpts) (*conn, error) {
+	if opts.mode == "" {
+		panic("mode required")
+	}
 	if opts.handler == nil {
 		panic("handler required")
 	}
@@ -106,7 +114,7 @@ func newConn(opts *newConnOpts) (*conn, error) {
 		h:              opts.handler,
 		m:              opts.connMetrics,
 		proxy:          p,
-		testRecordPath: opts.testRecordPath,
+		testRecordsDir: opts.testRecordsDir,
 	}, nil
 }
 
@@ -148,14 +156,14 @@ func (c *conn) run(ctx context.Context) (err error) {
 	bufr := bufio.NewReader(c.netConn)
 
 	// if test record path is set, split netConn reader to write to file and bufr
-	if c.testRecordPath != "" {
-		if err := os.MkdirAll(c.testRecordPath, 0o755); err != nil {
+	if c.testRecordsDir != "" {
+		if err := os.MkdirAll(c.testRecordsDir, 0o777); err != nil {
 			return err
 		}
 
 		filename := fmt.Sprintf("%s_%s.bin", time.Now().Format("2006-02-01_15:04:05"), c.netConn.RemoteAddr().String())
 
-		path := filepath.Join(c.testRecordPath, filename)
+		path := filepath.Join(c.testRecordsDir, filename)
 
 		f, err := os.Create(path)
 		if err != nil {

diff --git a/internal/clientconn/listener.go b/internal/clientconn/listener.go
@@ -50,7 +50,7 @@ type NewListenerOpts struct {
 	Logger             *zap.Logger
 	TestConnTimeout    time.Duration
 	TestRunCancelDelay time.Duration
-	TestRecordPath     string // if empty, no records are created
+	TestRecordsDir     string // if empty, no records are created
 }
 
 // NewListener returns a new listener, configured by the NewListenerOpts argument.
@@ -138,7 +138,7 @@ func (l *Listener) Run(ctx context.Context) error {
 				proxyAddr:      l.opts.ProxyAddr,
 				handler:        l.opts.Handler,
 				connMetrics:    l.metrics.connMetrics,
-				testRecordPath: l.opts.TestRecordPath,
+				testRecordsDir: l.opts.TestRecordsDir,
 			}
 			conn, e := newConn(opts)
 			if e != nil {

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)
 		}