diff --git a/go.mod b/go.mod index af6767ba7bc..1010dd4d662 100644 --- a/go.mod +++ b/go.mod @@ -103,9 +103,11 @@ require ( github.com/kr/text v0.2.0 github.com/mitchellh/mapstructure v1.5.0 github.com/nsf/jsondiff v0.0.0-20210926074059-1e845ec5d249 + github.com/slok/noglog v0.2.0 github.com/spf13/afero v1.9.3 github.com/spf13/jwalterweatherman v1.1.0 github.com/xlab/treeprint v1.2.0 + go.uber.org/zap v1.24.0 golang.org/x/exp v0.0.0-20230725093048-515e97ebf090 golang.org/x/sync v0.1.0 modernc.org/sqlite v1.20.3 @@ -171,7 +173,6 @@ require ( go.opencensus.io v0.24.0 // indirect go.uber.org/atomic v1.11.0 // indirect go.uber.org/multierr v1.11.0 // indirect - go.uber.org/zap v1.24.0 // indirect go4.org/intern v0.0.0-20230205224052-192e9f60865c // indirect go4.org/unsafe/assume-no-moving-gc v0.0.0-20230426161633-7e06285ff160 // indirect golang.org/x/xerrors v0.0.0-20220907171357-04be3eba64a2 // indirect diff --git a/go.sum b/go.sum index 39777e9b54a..56927a7cac8 100644 --- a/go.sum +++ b/go.sum @@ -537,6 +537,8 @@ github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6Mwd github.com/sirupsen/logrus v1.7.0/go.mod h1:yWOB1SBYBC5VeMP7gHvWumXLIWorT60ONWic61uBYv0= github.com/sjmudd/stopwatch v0.1.1 h1:x45OvxFB5OtCkjvYtzRF5fWB857Jzjjk84Oyd5C5ebw= github.com/sjmudd/stopwatch v0.1.1/go.mod h1:BLw0oIQJ1YLXBO/q9ufK/SgnKBVIkC2qrm6uy78Zw6U= +github.com/slok/noglog v0.2.0 h1:1czu4l2EoJ8L92UwdSXXa1Y+c5TIjFAFm2P+mjej95E= +github.com/slok/noglog v0.2.0/go.mod h1:TfKxwpEZPT+UA83bQ6RME146k0MM4e8mwHLf6bhcGDI= github.com/smartystreets/assertions v0.0.0-20190116191733-b6c0e53d7304/go.mod h1:OnSkiWE9lh6wB0YB77sQom3nweQdgAjqCqsofrRNTgc= github.com/smartystreets/goconvey v0.0.0-20181108003508-044398e4856c/go.mod h1:XDJAKZRPZ1CvBcN2aX5YOUTYGHki24fSF0Iv48Ibg0s= github.com/soheilhy/cmux v0.1.5 h1:jjzc5WVemNEDTLwv9tlmemhC73tI08BNOIGwBOo10Js= diff --git a/go/flags/endtoend/mysqlctl.txt b/go/flags/endtoend/mysqlctl.txt index 4af44804749..ba972423682 100644 --- a/go/flags/endtoend/mysqlctl.txt +++ b/go/flags/endtoend/mysqlctl.txt @@ -79,7 +79,7 @@ Global 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 severity logs at or above this threshold go to stderr (default 1) - --table-refresh-interval int interval in milliseconds to refresh tables in status page with refreshRequired class + --structured-logging whether to use structured logging (Zap) or the original (glog) logger --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) --v Level log level for V logs diff --git a/go/flags/endtoend/mysqlctld.txt b/go/flags/endtoend/mysqlctld.txt index 6fbbd059492..8ffe47bab6c 100644 --- a/go/flags/endtoend/mysqlctld.txt +++ b/go/flags/endtoend/mysqlctld.txt @@ -90,6 +90,7 @@ Usage of mysqlctld: --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 severity logs at or above this threshold go to stderr (default 1) + --structured-logging whether to use structured logging (Zap) or the original (glog) logger --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/vtctld.txt b/go/flags/endtoend/vtctld.txt index e653f32d8fb..1705fdbc4da 100644 --- a/go/flags/endtoend/vtctld.txt +++ b/go/flags/endtoend/vtctld.txt @@ -104,6 +104,7 @@ Usage of vtctld: --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 severity logs at or above this threshold go to stderr (default 1) + --structured-logging whether to use structured logging (Zap) or the original (glog) logger --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 index 3f2752be084..7145ea9042e 100644 --- a/go/flags/endtoend/vtgate.txt +++ b/go/flags/endtoend/vtgate.txt @@ -163,6 +163,7 @@ Usage of vtgate: --statsd_sample_rate float Sample rate for statsd metrics (default 1) --stderrthreshold severity 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 whether to use structured logging (Zap) or the original (glog) logger --table-refresh-interval int interval in milliseconds to refresh tables in status page with refreshRequired class --tablet_filters strings Specifies a comma-separated list of 'keyspace|shard_name or keyrange' values to filter the tablets to watch. --tablet_grpc_ca string the server ca to use to validate servers when connecting diff --git a/go/flags/endtoend/vtorc.txt b/go/flags/endtoend/vtorc.txt index 5a49255fd95..a8f70e98cdb 100644 --- a/go/flags/endtoend/vtorc.txt +++ b/go/flags/endtoend/vtorc.txt @@ -1,5 +1,4 @@ Usage of vtorc: - --allow-emergency-reparent Whether VTOrc should be allowed to run emergency reparent operation when it detects a dead primary (default true) --alsologtostderr log to standard error as well as files --audit-file-location string File location where the audit logs are to be stored --audit-purge-duration duration Duration for which audit logs are held before being purged. Should be in multiples of days (default 168h0m0s) @@ -58,7 +57,7 @@ Usage of vtorc: --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 severity logs at or above this threshold go to stderr (default 1) - --table-refresh-interval int interval in milliseconds to refresh tables in status page with refreshRequired class + --structured-logging whether to use structured logging (Zap) or the original (glog) logger --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 --tablet_manager_grpc_concurrency int concurrency to use to talk to a vttablet server for performance-sensitive RPCs (like ExecuteFetchAs{Dba,AllPrivs,App}) (default 8) diff --git a/go/flags/endtoend/vttablet.txt b/go/flags/endtoend/vttablet.txt index fc9a28bc541..6c2371c086a 100644 --- a/go/flags/endtoend/vttablet.txt +++ b/go/flags/endtoend/vttablet.txt @@ -289,6 +289,7 @@ Usage of vttablet: --statsd_sample_rate float Sample rate for statsd metrics (default 1) --stderrthreshold severity 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 whether to use structured logging (Zap) or the original (glog) logger --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 index 5849f0c1e81..6a89e0ad46f 100644 --- a/go/flags/endtoend/vttestserver.txt +++ b/go/flags/endtoend/vttestserver.txt @@ -107,6 +107,7 @@ Usage of vttestserver: --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 severity logs at or above this threshold go to stderr (default 1) + --structured-logging whether to use structured logging (Zap) or the original (glog) logger --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 index 8ebf88e085d..ffd3d384c58 100644 --- a/go/vt/logutil/logger.go +++ b/go/vt/logutil/logger.go @@ -25,6 +25,10 @@ import ( "sync" "time" + noglog "github.com/slok/noglog" + "go.uber.org/zap" + + "vitess.io/vitess/go/vt/log" logutilpb "vitess.io/vitess/go/vt/proto/logutil" ) @@ -404,3 +408,46 @@ func fileAndLine(depth int) (string, int64) { } return file, int64(line) } + +type VTSLogger zap.SugaredLogger + +// SetVTStructureLogger in-place noglog replacement with Zap's logger. +func SetVTStructureLogger(conf *zap.Config) (vtSLogger *zap.SugaredLogger, err error) { + var l *zap.Logger + + // Use the passed configuration instead of the default configuration + if conf == nil { + defaultProdConf := zap.NewProductionConfig() + conf = &defaultProdConf + } + + // Build configuration and generate a sugared logger + l, err = conf.Build() + vtSLogger = 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...) }, + }) + + log.Flush = noglog.Flush + log.Info = noglog.Info + log.Infof = noglog.Infof + log.InfoDepth = noglog.InfoDepth + log.Warning = noglog.Warning + log.Warningf = noglog.Warningf + log.WarningDepth = noglog.WarningDepth + log.Error = noglog.Error + log.Errorf = noglog.Errorf + log.ErrorDepth = noglog.ErrorDepth + log.Exit = noglog.Exit + log.Exitf = noglog.Exitf + log.ExitDepth = noglog.ExitDepth + log.Fatal = noglog.Fatal + log.Fatalf = noglog.Fatalf + log.FatalDepth = noglog.FatalDepth + + return +} diff --git a/go/vt/logutil/logger_test.go b/go/vt/logutil/logger_test.go index c34f8cf8ec3..f57331d2826 100644 --- a/go/vt/logutil/logger_test.go +++ b/go/vt/logutil/logger_test.go @@ -17,8 +17,15 @@ limitations under the License. package logutil import ( + "bytes" + "encoding/json" + "github.com/stretchr/testify/assert" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "net/url" "testing" "time" + vtlog "vitess.io/vitess/go/vt/log" "vitess.io/vitess/go/race" logutilpb "vitess.io/vitess/go/vt/proto/logutil" @@ -180,3 +187,102 @@ func TestTeeLogger(t *testing.T) { } } } + +// MemorySink implements zap.Sink by writing all messages to a buffer. +// It's used to capture the logs. +type MemorySink struct { + *bytes.Buffer +} + +// Implement Close and Sync as no-ops to satisfy the interface. The Write +// method is provided by the embedded buffer. +func (s *MemorySink) Close() error { return nil } +func (s *MemorySink) Sync() error { return nil } + +func SetupLoggerWithMemSink() (sink *MemorySink, err error) { + // Create a sink instance, and register it with zap for the "memory" protocol. + sink = &MemorySink{new(bytes.Buffer)} + err = zap.RegisterSink("memory", func(*url.URL) (zap.Sink, error) { + return sink, nil + }) + if err != nil { + return nil, err + } + + testLoggerConf := NewMemorySinkConfig() + _, err = SetVTStructureLogger(&testLoggerConf) + if err != nil { + return nil, err + } + + return +} + +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 TestVTSLogger_Replacing_glog(t *testing.T) { + type logMsg struct { + Level string `json:"level"` + Msg string `json:"msg"` + } + + type testCase struct { + name string + logLevel zapcore.Level + } + + dummyLogMessage := "testing log" + testCases := []testCase{ + {"log info", zap.InfoLevel}, + {"log warn", zap.WarnLevel}, + {"log error", zap.ErrorLevel}, + } + + sink, err := SetupLoggerWithMemSink() + assert.NoError(t, err) + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + var loggingFunc func(format string, args ...interface{}) + var expectedLevel string + + switch tc.logLevel { + case zapcore.InfoLevel: + loggingFunc = vtlog.Infof + expectedLevel = "info" + case zapcore.ErrorLevel: + loggingFunc = vtlog.Errorf + expectedLevel = "error" + case zapcore.WarnLevel: + loggingFunc = vtlog.Warningf + expectedLevel = "warn" + } + + loggingFunc(dummyLogMessage) + + // Unmarshal the captured log. This means we're getting a struct log. + actualLog := logMsg{} + err = json.Unmarshal(sink.Bytes(), &actualLog) + assert.NoError(t, err) + // Reset the sink so that it'll contain one log per test case. + sink.Reset() + + assert.Equal(t, expectedLevel, actualLog.Level) + assert.Equal(t, dummyLogMessage, actualLog.Msg) + + }) + } +} diff --git a/go/vt/servenv/servenv.go b/go/vt/servenv/servenv.go index 1944a39453d..965f295f4b6 100644 --- a/go/vt/servenv/servenv.go +++ b/go/vt/servenv/servenv.go @@ -81,6 +81,7 @@ var ( maxStackSize = 64 * 1024 * 1024 initStartTime time.Time // time when tablet init started: for debug purposes to time how long a tablet init takes tableRefreshInterval int + useVTSLogger bool ) // RegisterFlags installs the flags used by Init, Run, and RunDefault. @@ -97,7 +98,10 @@ func RegisterFlags() { fs.IntVar(&tableRefreshInterval, "table-refresh-interval", tableRefreshInterval, "interval in milliseconds to refresh tables in status page with refreshRequired class") // pid_file.go - fs.StringVar(&pidFile, "pid_file", pidFile, "If set, the process will write its pid to the named file, and delete it on graceful shutdown.") + 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(&useVTSLogger, "structured-logging", useVTSLogger, "whether to use structured logging (Zap) or the original (glog) logger") }) } @@ -340,6 +344,14 @@ func ParseFlags(cmd string) { os.Exit(0) } + if useVTSLogger { + // Replace glog logger with zap logger + _, err := logutil.SetVTStructureLogger(nil) + if err != nil { + log.Exitf("error while setting the Zap logger: %s", err) + } + } + args := fs.Args() if len(args) > 0 { _flag.Usage()