diff --git a/go.mod b/go.mod index dafc96fe585..943530dfc34 100644 --- a/go.mod +++ b/go.mod @@ -102,10 +102,12 @@ 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.11.0 github.com/spf13/jwalterweatherman v1.1.0 github.com/xlab/treeprint v1.2.0 go.uber.org/goleak v1.3.0 + go.uber.org/zap v1.27.0 golang.org/x/exp v0.0.0-20240222234643-814bf88cf225 golang.org/x/sync v0.6.0 gonum.org/v1/gonum v0.14.0 @@ -183,7 +185,6 @@ require ( go.opentelemetry.io/otel/trace v1.24.0 // indirect go.uber.org/atomic v1.11.0 // indirect go.uber.org/multierr v1.11.0 // indirect - go.uber.org/zap v1.27.0 // indirect golang.org/x/xerrors v0.0.0-20231012003039-104605ab7028 // indirect google.golang.org/appengine v1.6.8 // indirect google.golang.org/genproto/googleapis/api v0.0.0-20240304212257-790db918fca8 // indirect diff --git a/go.sum b/go.sum index 05ca79a0c00..59ad72493b1 100644 --- a/go.sum +++ b/go.sum @@ -450,6 +450,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 d729a44826d..cb757164d35 100644 --- a/go/flags/endtoend/mysqlctl.txt +++ b/go/flags/endtoend/mysqlctl.txt @@ -88,6 +88,7 @@ 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 --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 index a5bec13f09a..a0e09e9898d 100644 --- a/go/flags/endtoend/mysqlctld.txt +++ b/go/flags/endtoend/mysqlctld.txt @@ -114,6 +114,7 @@ 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 --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 index 99142bd0b74..93db5d6e8f5 100644 --- a/go/flags/endtoend/vtcombo.txt +++ b/go/flags/endtoend/vtcombo.txt @@ -334,6 +334,7 @@ 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 --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_dir string The directory within the vtdataroot to store vttablet/mysql files. Defaults to being generated by the tablet uid. diff --git a/go/flags/endtoend/vtctld.txt b/go/flags/endtoend/vtctld.txt index 4cb5c1e5082..ad85915d34c 100644 --- a/go/flags/endtoend/vtctld.txt +++ b/go/flags/endtoend/vtctld.txt @@ -131,6 +131,7 @@ 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 --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 f42f6a2f331..f2519ddaedb 100644 --- a/go/flags/endtoend/vtgate.txt +++ b/go/flags/endtoend/vtgate.txt @@ -192,6 +192,7 @@ 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 --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/vtgateclienttest.txt b/go/flags/endtoend/vtgateclienttest.txt index 32e892805e4..9967be213a1 100644 --- a/go/flags/endtoend/vtgateclienttest.txt +++ b/go/flags/endtoend/vtgateclienttest.txt @@ -61,6 +61,7 @@ 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 --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 index f65eb12d142..aa0b03c63ff 100644 --- a/go/flags/endtoend/vtorc.txt +++ b/go/flags/endtoend/vtorc.txt @@ -78,6 +78,7 @@ 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 --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 index dbc14039ec3..08d4266aeab 100644 --- a/go/flags/endtoend/vttablet.txt +++ b/go/flags/endtoend/vttablet.txt @@ -332,6 +332,7 @@ 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 --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 ece7ff2bcec..c94918db1ed 100644 --- a/go/flags/endtoend/vttestserver.txt +++ b/go/flags/endtoend/vttestserver.txt @@ -115,6 +115,7 @@ 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 --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 47c3f124238..29b1ae02d74 100644 --- a/go/vt/logutil/logger.go +++ b/go/vt/logutil/logger.go @@ -24,7 +24,11 @@ import ( "sync" "time" + noglog "github.com/slok/noglog" + "go.uber.org/zap" + "vitess.io/vitess/go/protoutil" + "vitess.io/vitess/go/vt/log" logutilpb "vitess.io/vitess/go/vt/proto/logutil" ) @@ -383,3 +387,46 @@ func fileAndLine(depth int) (string, int64) { } return file, int64(line) } + +type StructuredLogger zap.SugaredLogger + +// SetStructuredLogger in-place noglog replacement with Zap's logger. +func SetStructuredLogger(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 ce25543da5f..5f34d2f7df3 100644 --- a/go/vt/logutil/logger_test.go +++ b/go/vt/logutil/logger_test.go @@ -17,9 +17,18 @@ limitations under the License. package logutil import ( + "bytes" + "encoding/json" + "net/url" "testing" "time" + "github.com/stretchr/testify/assert" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + + vtlog "vitess.io/vitess/go/vt/log" + "vitess.io/vitess/go/protoutil" "vitess.io/vitess/go/race" logutilpb "vitess.io/vitess/go/vt/proto/logutil" @@ -152,3 +161,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 = SetStructuredLogger(&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 TestStructuredLogger_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 6a7898501f8..9d8894a7eb6 100644 --- a/go/vt/servenv/servenv.go +++ b/go/vt/servenv/servenv.go @@ -82,6 +82,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 + useStructuredLogger bool ) // RegisterFlags installs the flags used by Init, Run, and RunDefault. @@ -98,7 +99,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(&useStructuredLogger, "structured-logging", useStructuredLogger, "enable structured logging") }) } @@ -285,6 +289,14 @@ func ParseFlags(cmd string) { os.Exit(0) } + if useStructuredLogger { + // Replace glog logger with zap logger + _, err := logutil.SetStructuredLogger(nil) + if err != nil { + log.Exitf("error while setting the structured logger: %s", err) + } + } + args := fs.Args() if len(args) > 0 { _flag.Usage()