slack-19.0: fix structured logging (#532)

* `slack-19.0`: fix structured logging Signed-off-by: Tim Vaillancourt <tim@timvaillancourt.com> * remove debug println Signed-off-by: Tim Vaillancourt <tim@timvaillancourt.com> * test cleanup Signed-off-by: Tim Vaillancourt <tim@timvaillancourt.com> * update flags and e2e tests Signed-off-by: Tim Vaillancourt <tim@timvaillancourt.com> * fix e2e flag test Signed-off-by: Tim Vaillancourt <tim@timvaillancourt.com> * code cleanup Signed-off-by: Tim Vaillancourt <tim@timvaillancourt.com> * simplify Signed-off-by: Tim Vaillancourt <tim@timvaillancourt.com> * fix goimports Signed-off-by: Tim Vaillancourt <tim@timvaillancourt.com> * log_dir WIP Signed-off-by: Tim Vaillancourt <tim@timvaillancourt.com> --------- Signed-off-by: Tim Vaillancourt <tim@timvaillancourt.com>
slackhq · Oct 17, 2024 · 3ead23e · 3ead23e
1 parent d9206dd
commit 3ead23e
Show file tree

Hide file tree

Showing 14 changed files with 146 additions and 54 deletions.
diff --git a/go/flags/endtoend/mysqlctl.txt b/go/flags/endtoend/mysqlctl.txt
@@ -88,7 +88,8 @@ Flags:
       --service_map strings                                         comma separated list of services to enable (or disable if prefixed with '-') Example: grpc-queryservice
       --socket_file string                                          Local unix socket file to listen on
       --stderrthreshold severityFlag                                logs at or above this threshold go to stderr (default 1)
-      --structured-logging                                          enable structured logging
+      --structured-log-level logLevel                               The minimum log level, options: debug, info, warn, error. (default info)
+      --structured-logging                                          Enable json-based structured logging
       --table-refresh-interval int                                  interval in milliseconds to refresh tables in status page with refreshRequired class
       --tablet_dir string                                           The directory within the vtdataroot to store vttablet/mysql files. Defaults to being generated by the tablet uid.
       --tablet_uid uint32                                           Tablet UID. (default 41983)

diff --git a/go/flags/endtoend/mysqlctld.txt b/go/flags/endtoend/mysqlctld.txt
@@ -114,7 +114,8 @@ Flags:
       --shutdown-wait-time duration                                      How long to wait for mysqld shutdown (default 5m0s)
       --socket_file string                                               Local unix socket file to listen on
       --stderrthreshold severityFlag                                     logs at or above this threshold go to stderr (default 1)
-      --structured-logging                                               enable structured logging
+      --structured-log-level logLevel                                    The minimum log level, options: debug, info, warn, error. (default info)
+      --structured-logging                                               Enable json-based structured logging
       --table-refresh-interval int                                       interval in milliseconds to refresh tables in status page with refreshRequired class
       --tablet_dir string                                                The directory within the vtdataroot to store vttablet/mysql files. Defaults to being generated by the tablet uid.
       --tablet_uid uint32                                                Tablet UID (default 41983)

diff --git a/go/flags/endtoend/vtcombo.txt b/go/flags/endtoend/vtcombo.txt
@@ -335,7 +335,8 @@ Flags:
       --stderrthreshold severityFlag                                     logs at or above this threshold go to stderr (default 1)
       --stream_buffer_size int                                           the number of bytes sent from vtgate for each stream call. It's recommended to keep this value in sync with vttablet's query-server-config-stream-buffer-size. (default 32768)
       --stream_health_buffer_size uint                                   max streaming health entries to buffer per streaming health client (default 20)
-      --structured-logging                                               enable structured logging
+      --structured-log-level logLevel                                    The minimum log level, options: debug, info, warn, error. (default info)
+      --structured-logging                                               Enable json-based structured logging
       --table-refresh-interval int                                       interval in milliseconds to refresh tables in status page with refreshRequired class
       --table_gc_lifecycle string                                        States for a DROP TABLE garbage collection cycle. Default is 'hold,purge,evac,drop', use any subset ('drop' implicitly always included) (default "hold,purge,evac,drop")
       --tablet-filter-tags StringMap                                     Specifies a comma-separated list of tablet tags (as key:value pairs) to filter the tablets to watch.

diff --git a/go/flags/endtoend/vtctld.txt b/go/flags/endtoend/vtctld.txt
@@ -131,7 +131,8 @@ Flags:
       --stats_drop_variables string                                      Variables to be dropped from the list of exported variables.
       --stats_emit_period duration                                       Interval between emitting stats to all registered backends (default 1m0s)
       --stderrthreshold severityFlag                                     logs at or above this threshold go to stderr (default 1)
-      --structured-logging                                               enable structured logging
+      --structured-log-level logLevel                                    The minimum log level, options: debug, info, warn, error. (default info)
+      --structured-logging                                               Enable json-based structured logging
       --table-refresh-interval int                                       interval in milliseconds to refresh tables in status page with refreshRequired class
       --tablet_dir string                                                The directory within the vtdataroot to store vttablet/mysql files. Defaults to being generated by the tablet uid.
       --tablet_grpc_ca string                                            the server ca to use to validate servers when connecting

diff --git a/go/flags/endtoend/vtgate.txt b/go/flags/endtoend/vtgate.txt
@@ -196,7 +196,8 @@ Flags:
       --statsd_sample_rate float                                         Sample rate for statsd metrics (default 1)
       --stderrthreshold severityFlag                                     logs at or above this threshold go to stderr (default 1)
       --stream_buffer_size int                                           the number of bytes sent from vtgate for each stream call. It's recommended to keep this value in sync with vttablet's query-server-config-stream-buffer-size. (default 32768)
-      --structured-logging                                               enable structured logging
+      --structured-log-level logLevel                                    The minimum log level, options: debug, info, warn, error. (default info)
+      --structured-logging                                               Enable json-based structured logging
       --table-refresh-interval int                                       interval in milliseconds to refresh tables in status page with refreshRequired class
       --tablet-filter-tags StringMap                                     Specifies a comma-separated list of tablet tags (as key:value pairs) to filter the tablets to watch.
       --tablet_filters strings                                           Specifies a comma-separated list of 'keyspace|shard_name or keyrange' values to filter the tablets to watch.

diff --git a/go/flags/endtoend/vtgateclienttest.txt b/go/flags/endtoend/vtgateclienttest.txt
@@ -61,7 +61,8 @@ Flags:
       --security_policy string                                           the name of a registered security policy to use for controlling access to URLs - empty means allow all for anyone (built-in policies: deny-all, read-only)
       --service_map strings                                              comma separated list of services to enable (or disable if prefixed with '-') Example: grpc-queryservice
       --stderrthreshold severityFlag                                     logs at or above this threshold go to stderr (default 1)
-      --structured-logging                                               enable structured logging
+      --structured-log-level logLevel                                    The minimum log level, options: debug, info, warn, error. (default info)
+      --structured-logging                                               Enable json-based structured logging
       --table-refresh-interval int                                       interval in milliseconds to refresh tables in status page with refreshRequired class
       --v Level                                                          log level for V logs
   -v, --version                                                          print binary version

diff --git a/go/flags/endtoend/vtorc.txt b/go/flags/endtoend/vtorc.txt
@@ -78,7 +78,8 @@ Flags:
       --stats_drop_variables string                                 Variables to be dropped from the list of exported variables.
       --stats_emit_period duration                                  Interval between emitting stats to all registered backends (default 1m0s)
       --stderrthreshold severityFlag                                logs at or above this threshold go to stderr (default 1)
-      --structured-logging                                          enable structured logging
+      --structured-log-level logLevel                               The minimum log level, options: debug, info, warn, error. (default info)
+      --structured-logging                                          Enable json-based structured logging
       --table-refresh-interval int                                  interval in milliseconds to refresh tables in status page with refreshRequired class
       --tablet_manager_grpc_ca string                               the server ca to use to validate servers when connecting
       --tablet_manager_grpc_cert string                             the cert to use to connect

diff --git a/go/flags/endtoend/vttablet.txt b/go/flags/endtoend/vttablet.txt
@@ -333,7 +333,8 @@ Flags:
       --statsd_sample_rate float                                         Sample rate for statsd metrics (default 1)
       --stderrthreshold severityFlag                                     logs at or above this threshold go to stderr (default 1)
       --stream_health_buffer_size uint                                   max streaming health entries to buffer per streaming health client (default 20)
-      --structured-logging                                               enable structured logging
+      --structured-log-level logLevel                                    The minimum log level, options: debug, info, warn, error. (default info)
+      --structured-logging                                               Enable json-based structured logging
       --table-acl-config string                                          path to table access checker config file; send SIGHUP to reload this file
       --table-acl-config-reload-interval duration                        Ticker to reload ACLs. Duration flag, format e.g.: 30s. Default: do not reload
       --table-refresh-interval int                                       interval in milliseconds to refresh tables in status page with refreshRequired class

diff --git a/go/flags/endtoend/vttestserver.txt b/go/flags/endtoend/vttestserver.txt
@@ -115,7 +115,8 @@ Flags:
       --sql-max-length-errors int                                        truncate queries in error logs to the given length (default unlimited)
       --sql-max-length-ui int                                            truncate queries in debug UIs to the given length (default 512) (default 512)
       --stderrthreshold severityFlag                                     logs at or above this threshold go to stderr (default 1)
-      --structured-logging                                               enable structured logging
+      --structured-log-level logLevel                                    The minimum log level, options: debug, info, warn, error. (default info)
+      --structured-logging                                               Enable json-based structured logging
       --table-refresh-interval int                                       interval in milliseconds to refresh tables in status page with refreshRequired class
       --tablet_dir string                                                The directory within the vtdataroot to store vttablet/mysql files. Defaults to being generated by the tablet uid.
       --tablet_hostname string                                           The hostname to use for the tablet otherwise it will be derived from OS' hostname (default "localhost")

diff --git a/go/vt/logutil/logger.go b/go/vt/logutil/logger.go
@@ -17,15 +17,19 @@ limitations under the License.
 package logutil
 
 import (
+	"flag"
 	"fmt"
 	"io"
+	"os"
+	"path/filepath"
 	"runtime"
 	"strings"
 	"sync"
 	"time"
 
 	noglog "github.com/slok/noglog"
 	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
 
 	"vitess.io/vitess/go/protoutil"
 	"vitess.io/vitess/go/vt/log"
@@ -388,27 +392,75 @@ func fileAndLine(depth int) (string, int64) {
 	return file, int64(line)
 }
 
-type StructuredLogger zap.SugaredLogger
+// StructuredLoggingLevel defines the log level of structured logging.
+var StructuredLoggingLevel = zapcore.InfoLevel
 
-// SetStructuredLogger in-place noglog replacement with Zap's logger.
-func SetStructuredLogger(conf *zap.Config) (vtSLogger *zap.SugaredLogger, err error) {
-	var l *zap.Logger
+// newZapLoggerConfig creates a new config for a zap logger that uses RFC3339 timestamps.
+func newZapLoggerConfig() zap.Config {
+	conf := zap.NewProductionConfig()
+	conf.EncoderConfig.EncodeTime = zapcore.TimeEncoderOfLayout(time.RFC3339)
+	conf.Level = zap.NewAtomicLevelAt(StructuredLoggingLevel)
+
+	// use --log_dir if provided
+	ld := flag.Lookup("log_dir")
+	if ld.Value != nil && ld.Value.String() != "" {
+		program := filepath.Base(os.Args[0])
+		conf.OutputPaths = append(
+			conf.OutputPaths,
+			filepath.Join(ld.Value.String(), program+".log"),
+		)
+	}
+
+	return conf
+}
+
+// ZapLogLevelFlag implements the pflag.Value interface, for parsing a zap log level string.
+type ZapLogLevelFlag zapcore.Level
+
+// String represents a zapcore.Level as a lowercase string.
+func (z *ZapLogLevelFlag) String() string {
+	level := zapcore.Level(*z)
+	return level.String()
+}
 
-	// Use the passed configuration instead of the default configuration
+// Set is part of the pflag.Value interface.
+func (z *ZapLogLevelFlag) Set(v string) error {
+	level, err := zapcore.ParseLevel(v)
+	if err == nil {
+		*z = ZapLogLevelFlag(level)
+	}
+	return err
+}
+
+// Type is part of the pflag.Value interface.
+func (z *ZapLogLevelFlag) Type() string {
+	return "logLevel"
+}
+
+// SetStructuredLogger in-place noglog replacement with Zap's logger.
+func SetStructuredLogger(conf *zap.Config) error {
+	// Use the passed configuration instead of
+	// the default configuration.
 	if conf == nil {
-		defaultProdConf := zap.NewProductionConfig()
-		conf = &defaultProdConf
+		defaultConf := newZapLoggerConfig()
+		conf = &defaultConf
+	}
+
+	// Build configuration and generate a sugared logger.
+	// Skip 3 callers so we log the real caller vs the
+	// noglog wrapper.
+	l, err := conf.Build(zap.AddCallerSkip(3))
+	if err != nil {
+		return err
 	}
 
-	// Build configuration and generate a sugared logger
-	l, err = conf.Build()
-	vtSLogger = l.Sugar()
+	logger := l.Sugar()
 
 	noglog.SetLogger(&noglog.LoggerFunc{
-		DebugfFunc: func(f string, a ...interface{}) { vtSLogger.Debugf(f, a...) },
-		InfofFunc:  func(f string, a ...interface{}) { vtSLogger.Infof(f, a...) },
-		WarnfFunc:  func(f string, a ...interface{}) { vtSLogger.Warnf(f, a...) },
-		ErrorfFunc: func(f string, a ...interface{}) { vtSLogger.Errorf(f, a...) },
+		DebugfFunc: func(f string, a ...interface{}) { logger.Debugf(f, a...) },
+		InfofFunc:  func(f string, a ...interface{}) { logger.Infof(f, a...) },
+		WarnfFunc:  func(f string, a ...interface{}) { logger.Warnf(f, a...) },
+		ErrorfFunc: func(f string, a ...interface{}) { logger.Errorf(f, a...) },
 	})
 
 	log.Flush = noglog.Flush
@@ -428,5 +480,5 @@ func SetStructuredLogger(conf *zap.Config) (vtSLogger *zap.SugaredLogger, err er
 	log.Fatalf = noglog.Fatalf
 	log.FatalDepth = noglog.FatalDepth
 
-	return
+	return nil
 }
diff --git a/go/vt/logutil/logger_test.go b/go/vt/logutil/logger_test.go
@@ -183,34 +183,25 @@ func SetupLoggerWithMemSink() (sink *MemorySink, err error) {
 		return nil, err
 	}
 
-	testLoggerConf := NewMemorySinkConfig()
-	_, err = SetStructuredLogger(&testLoggerConf)
-	if err != nil {
-		return nil, err
-	}
-
-	return
+	testLoggerConf := NewTestMemorySinkConfig()
+	err = SetStructuredLogger(&testLoggerConf)
+	return sink, err
 }
 
-func NewMemorySinkConfig() zap.Config {
-	return zap.Config{
-		Level:       zap.NewAtomicLevelAt(zap.InfoLevel),
-		Development: false,
-		Sampling: &zap.SamplingConfig{
-			Initial:    100,
-			Thereafter: 100,
-		},
-		Encoding:         "json",
-		EncoderConfig:    zap.NewProductionEncoderConfig(),
-		OutputPaths:      []string{"memory://"},
-		ErrorOutputPaths: []string{"memory://"},
-	}
+func NewTestMemorySinkConfig() zap.Config {
+	conf := newZapLoggerConfig()
+	conf.OutputPaths = []string{"memory://"}
+	conf.ErrorOutputPaths = []string{"memory://"}
+	return conf
 }
 
 func TestStructuredLogger_Replacing_glog(t *testing.T) {
 	type logMsg struct {
-		Level string `json:"level"`
-		Msg   string `json:"msg"`
+		Level      string `json:"level"`
+		Msg        string `json:"msg"`
+		Caller     string `json:"caller"`
+		Stacktrace string `json:"stacktrace"`
+		Timestamp  string `json:"ts"`
 	}
 
 	type testCase struct {
@@ -220,6 +211,7 @@ func TestStructuredLogger_Replacing_glog(t *testing.T) {
 
 	dummyLogMessage := "testing log"
 	testCases := []testCase{
+		{"log debug", zap.DebugLevel},
 		{"log info", zap.InfoLevel},
 		{"log warn", zap.WarnLevel},
 		{"log error", zap.ErrorLevel},
@@ -232,17 +224,19 @@ func TestStructuredLogger_Replacing_glog(t *testing.T) {
 		t.Run(tc.name, func(t *testing.T) {
 			var loggingFunc func(format string, args ...interface{})
 			var expectedLevel string
+			var expectStacktrace bool
 
 			switch tc.logLevel {
-			case zapcore.InfoLevel:
+			case zapcore.InfoLevel, zapcore.DebugLevel:
 				loggingFunc = vtlog.Infof
 				expectedLevel = "info"
-			case zapcore.ErrorLevel:
-				loggingFunc = vtlog.Errorf
-				expectedLevel = "error"
 			case zapcore.WarnLevel:
 				loggingFunc = vtlog.Warningf
 				expectedLevel = "warn"
+			case zapcore.ErrorLevel:
+				loggingFunc = vtlog.Errorf
+				expectedLevel = "error"
+				expectStacktrace = true
 			}
 
 			loggingFunc(dummyLogMessage)
@@ -256,7 +250,17 @@ func TestStructuredLogger_Replacing_glog(t *testing.T) {
 
 			assert.Equal(t, expectedLevel, actualLog.Level)
 			assert.Equal(t, dummyLogMessage, actualLog.Msg)
+			if expectStacktrace {
+				assert.NotEmpty(t, actualLog.Stacktrace)
+			}
+
+			// confirm RFC3339 timestamp
+			assert.NotEmpty(t, actualLog.Timestamp)
+			_, err = time.Parse(time.RFC3339, actualLog.Timestamp)
+			assert.NoError(t, err)
 
+			// confirm caller
+			assert.Contains(t, actualLog.Caller, "logutil/logger_test.go")
 		})
 	}
 }
diff --git a/go/vt/servenv/servenv.go b/go/vt/servenv/servenv.go
@@ -102,7 +102,8 @@ func RegisterFlags() {
 		fs.StringVar(&pidFile, "pid_file", pidFile, "If set, the process will write its pid to the named file, and delete it on graceful shutdown.") // Logging
 
 		// Logging
-		fs.BoolVar(&useStructuredLogger, "structured-logging", useStructuredLogger, "enable structured logging")
+		fs.BoolVar(&useStructuredLogger, "structured-logging", useStructuredLogger, "Enable json-based structured logging")
+		fs.Var((*logutil.ZapLogLevelFlag)(&logutil.StructuredLoggingLevel), "structured-log-level", "The minimum log level, options: debug, info, warn, error.")
 	})
 }
 
@@ -291,8 +292,7 @@ func ParseFlags(cmd string) {
 
 	if useStructuredLogger {
 		// Replace glog logger with zap logger
-		_, err := logutil.SetStructuredLogger(nil)
-		if err != nil {
+		if err := logutil.SetStructuredLogger(nil); err != nil {
 			log.Exitf("error while setting the structured logger: %s", err)
 		}
 	}
@@ -395,6 +395,13 @@ func ParseFlagsWithArgs(cmd string) []string {
 		os.Exit(0)
 	}
 
+	if useStructuredLogger {
+		// Replace glog logger with zap logger
+		if err := logutil.SetStructuredLogger(nil); err != nil {
+			log.Exitf("error while setting the structured logger: %s", err)
+		}
+	}
+
 	args := fs.Args()
 	if len(args) == 0 {
 		log.Exitf("%s expected at least one positional argument", cmd)

diff --git a/go/vt/servenv/servenv_unix.go b/go/vt/servenv/servenv_unix.go
@@ -27,6 +27,7 @@ import (
 
 	"vitess.io/vitess/go/stats"
 	"vitess.io/vitess/go/vt/log"
+	"vitess.io/vitess/go/vt/logutil"
 )
 
 // Init is the first phase of the server startup.
@@ -40,6 +41,13 @@ func Init() {
 		return int64(time.Since(serverStart).Nanoseconds())
 	})
 
+	if useStructuredLogger {
+		// Replace glog logger with zap logger
+		if err := logutil.SetStructuredLogger(nil); err != nil {
+			log.Exitf("error while setting the structured logger: %s", err)
+		}
+	}
+
 	// Ignore SIGPIPE if specified
 	// The Go runtime catches SIGPIPE for us on all fds except stdout/stderr
 	// See https://golang.org/pkg/os/signal/#hdr-SIGPIPE

diff --git a/go/vt/servenv/servenv_windows.go b/go/vt/servenv/servenv_windows.go
@@ -18,4 +18,16 @@ limitations under the License.
 
 package servenv
 
-func Init() {}
+import (
+	"vitess.io/vitess/go/vt/log"
+	"vitess.io/vitess/go/vt/logutil"
+)
+
+func Init() {
+	if useStructuredLogger {
+		// Replace glog logger with zap logger
+		if err := logutil.SetStructuredLogger(nil); err != nil {
+			log.Exitf("error while setting the structured logger: %s", err)
+		}
+	}
+}