From 7c8ca2773b1db965aa98146a523c7f399e0de5da Mon Sep 17 00:00:00 2001 From: Tim Vaillancourt Date: Wed, 10 Jul 2024 13:55:59 +0200 Subject: [PATCH 1/3] `slack-19.0`: add structured logging (#449) * Install zap log and noglog Signed-off-by: Emad Habib * Implement the Vitess Structure Logger VTSLoger Signed-off-by: Emad Habib * Move the structure logging code to logger.go file * make PR suggestions from vitessio/vitess#13061 Signed-off-by: Tim Vaillancourt * Fix bad merge conflict Signed-off-by: Tim Vaillancourt * Fix bad merge conflict again Signed-off-by: Tim Vaillancourt * fix test Signed-off-by: Tim Vaillancourt * add flags e2e test for vtgateclienttest Signed-off-by: Tim Vaillancourt * update error msg Signed-off-by: Tim Vaillancourt --------- Signed-off-by: Emad Habib Signed-off-by: Tim Vaillancourt Co-authored-by: Emad Habib Co-authored-by: Emad Mokhtar --- go.mod | 3 +- go.sum | 2 + go/flags/endtoend/mysqlctl.txt | 1 + go/flags/endtoend/mysqlctld.txt | 1 + go/flags/endtoend/vtcombo.txt | 1 + go/flags/endtoend/vtctld.txt | 1 + go/flags/endtoend/vtgate.txt | 1 + go/flags/endtoend/vtgateclienttest.txt | 1 + go/flags/endtoend/vtorc.txt | 1 + go/flags/endtoend/vttablet.txt | 1 + go/flags/endtoend/vttestserver.txt | 1 + go/vt/logutil/logger.go | 47 +++++++++++ go/vt/logutil/logger_test.go | 108 +++++++++++++++++++++++++ go/vt/servenv/servenv.go | 14 +++- 14 files changed, 181 insertions(+), 2 deletions(-) diff --git a/go.mod b/go.mod index 33eb78c7647..2af82aae517 100644 --- a/go.mod +++ b/go.mod @@ -107,10 +107,12 @@ require ( github.com/nsf/jsondiff v0.0.0-20210926074059-1e845ec5d249 github.com/shirou/gopsutil/v4 v4.25.4 github.com/slackhq/vitess-addons v0.22.1 + github.com/slok/noglog v0.2.0 github.com/spf13/afero v1.12.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-20250305212735-054e65f0b394 golang.org/x/sync v0.12.0 gonum.org/v1/gonum v0.15.1 @@ -230,7 +232,6 @@ require ( go.opentelemetry.io/otel/trace v1.35.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-20240903120638-7835f813f4da // indirect google.golang.org/genproto/googleapis/api v0.0.0-20250313205543-e70fdf4c4cb4 // indirect google.golang.org/genproto/googleapis/rpc v0.0.0-20250313205543-e70fdf4c4cb4 // indirect diff --git a/go.sum b/go.sum index f3ff3b31cd7..47614d997de 100644 --- a/go.sum +++ b/go.sum @@ -529,6 +529,8 @@ github.com/sjmudd/stopwatch v0.1.1 h1:x45OvxFB5OtCkjvYtzRF5fWB857Jzjjk84Oyd5C5eb github.com/sjmudd/stopwatch v0.1.1/go.mod h1:BLw0oIQJ1YLXBO/q9ufK/SgnKBVIkC2qrm6uy78Zw6U= github.com/slackhq/vitess-addons v0.22.1 h1:iyIZzhIanMtlzVA+75+qGoqGU7xXm6QWNClYsbTTcLA= github.com/slackhq/vitess-addons v0.22.1/go.mod h1:9yfuhO4dKYIACMOrtRBIeCKefa6Qlw9FHtRYV9mtqeo= +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 f803b393a76..4f88b194ec5 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 d4bc347e882..60e6d33f9b4 100644 --- a/go/flags/endtoend/mysqlctld.txt +++ b/go/flags/endtoend/mysqlctld.txt @@ -118,6 +118,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 935d946d804..d500510ad63 100644 --- a/go/flags/endtoend/vtcombo.txt +++ b/go/flags/endtoend/vtcombo.txt @@ -348,6 +348,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-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 index 402c12d9c0f..7258ddc0f40 100644 --- a/go/flags/endtoend/vtctld.txt +++ b/go/flags/endtoend/vtctld.txt @@ -137,6 +137,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 1b6b911ddae..6ce125a91c7 100644 --- a/go/flags/endtoend/vtgate.txt +++ b/go/flags/endtoend/vtgate.txt @@ -205,6 +205,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-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 index b62a54edea8..6191871829e 100644 --- a/go/flags/endtoend/vtgateclienttest.txt +++ b/go/flags/endtoend/vtgateclienttest.txt @@ -67,6 +67,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 7e2e6cfaf40..4d772b4aaba 100644 --- a/go/flags/endtoend/vtorc.txt +++ b/go/flags/endtoend/vtorc.txt @@ -83,6 +83,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 568c0a4a201..a1294db2002 100644 --- a/go/flags/endtoend/vttablet.txt +++ b/go/flags/endtoend/vttablet.txt @@ -348,6 +348,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 d7fd7d46ce8..c9a1359b4b2 100644 --- a/go/flags/endtoend/vttestserver.txt +++ b/go/flags/endtoend/vttestserver.txt @@ -128,6 +128,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 46d7c0052da..0c29e8bde57 100644 --- a/go/vt/logutil/logger.go +++ b/go/vt/logutil/logger.go @@ -25,7 +25,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" ) @@ -390,3 +394,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 42ce4a9cf12..1ba4cd81c4f 100644 --- a/go/vt/servenv/servenv.go +++ b/go/vt/servenv/servenv.go @@ -79,6 +79,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 ) type TimeoutFlags struct { @@ -107,7 +108,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") }) } @@ -310,6 +314,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() From 1a9f1cb9528ddeb4d88ea7c5a2ca618012e83ac2 Mon Sep 17 00:00:00 2001 From: Tim Vaillancourt Date: Thu, 17 Oct 2024 19:46:47 +0200 Subject: [PATCH 2/3] `slack-19.0`: fix structured logging (#532) * `slack-19.0`: fix structured logging Signed-off-by: Tim Vaillancourt * remove debug println Signed-off-by: Tim Vaillancourt * test cleanup Signed-off-by: Tim Vaillancourt * update flags and e2e tests Signed-off-by: Tim Vaillancourt * fix e2e flag test Signed-off-by: Tim Vaillancourt * code cleanup Signed-off-by: Tim Vaillancourt * simplify Signed-off-by: Tim Vaillancourt * fix goimports Signed-off-by: Tim Vaillancourt * log_dir WIP Signed-off-by: Tim Vaillancourt --------- Signed-off-by: Tim Vaillancourt --- go/flags/endtoend/mysqlctl.txt | 3 +- go/flags/endtoend/mysqlctld.txt | 3 +- go/flags/endtoend/vtcombo.txt | 3 +- go/flags/endtoend/vtctld.txt | 3 +- go/flags/endtoend/vtgate.txt | 3 +- go/flags/endtoend/vtgateclienttest.txt | 3 +- go/flags/endtoend/vtorc.txt | 3 +- go/flags/endtoend/vttablet.txt | 3 +- go/flags/endtoend/vttestserver.txt | 3 +- go/vt/logutil/logger.go | 82 +++++++++++++++++++++----- go/vt/logutil/logger_test.go | 56 ++++++++++-------- go/vt/servenv/servenv.go | 13 +++- go/vt/servenv/servenv_unix.go | 8 +++ go/vt/servenv/servenv_windows.go | 14 ++++- 14 files changed, 146 insertions(+), 54 deletions(-) diff --git a/go/flags/endtoend/mysqlctl.txt b/go/flags/endtoend/mysqlctl.txt index 4f88b194ec5..a49527d56dc 100644 --- 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 index 60e6d33f9b4..a07dbe60229 100644 --- a/go/flags/endtoend/mysqlctld.txt +++ b/go/flags/endtoend/mysqlctld.txt @@ -118,7 +118,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 index d500510ad63..49ffcdbc04f 100644 --- a/go/flags/endtoend/vtcombo.txt +++ b/go/flags/endtoend/vtcombo.txt @@ -348,7 +348,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 index 7258ddc0f40..a1f16466eb9 100644 --- a/go/flags/endtoend/vtctld.txt +++ b/go/flags/endtoend/vtctld.txt @@ -137,7 +137,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 index 6ce125a91c7..50b12905d8d 100644 --- a/go/flags/endtoend/vtgate.txt +++ b/go/flags/endtoend/vtgate.txt @@ -205,7 +205,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 index 6191871829e..bb1968cb053 100644 --- a/go/flags/endtoend/vtgateclienttest.txt +++ b/go/flags/endtoend/vtgateclienttest.txt @@ -67,7 +67,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 index 4d772b4aaba..2e950419ddc 100644 --- a/go/flags/endtoend/vtorc.txt +++ b/go/flags/endtoend/vtorc.txt @@ -83,7 +83,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 index a1294db2002..67a634c3ade 100644 --- a/go/flags/endtoend/vttablet.txt +++ b/go/flags/endtoend/vttablet.txt @@ -348,7 +348,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 index c9a1359b4b2..991d158d5bd 100644 --- a/go/flags/endtoend/vttestserver.txt +++ b/go/flags/endtoend/vttestserver.txt @@ -128,7 +128,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 index 0c29e8bde57..85cc263dbbd 100644 --- a/go/vt/logutil/logger.go +++ b/go/vt/logutil/logger.go @@ -17,8 +17,11 @@ limitations under the License. package logutil import ( + "flag" "fmt" "io" + "os" + "path/filepath" "runtime" "slices" "strings" @@ -27,6 +30,7 @@ import ( 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" @@ -395,27 +399,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 @@ -435,5 +487,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 index 5f34d2f7df3..a2f3f24d6a3 100644 --- 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 index 1ba4cd81c4f..5491d93c0b0 100644 --- a/go/vt/servenv/servenv.go +++ b/go/vt/servenv/servenv.go @@ -111,7 +111,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.") }) } @@ -316,8 +317,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) } } @@ -432,6 +432,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 index 17fa85c4167..745cdad8af7 100644 --- 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 index bd610b1f245..4c3ee0f6318 100644 --- 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) + } + } +} From 2cdada332e1ab49894d812735da18b9f495c3817 Mon Sep 17 00:00:00 2001 From: Tanjin Xu Date: Tue, 3 Feb 2026 11:59:02 -0800 Subject: [PATCH 3/3] Add structured logging flags to RegisterFlagsWithTimeouts The cherry-picked structured logging commits added the flags to RegisterFlags() but not to RegisterFlagsWithTimeouts(). This caused mysqlctld (which uses RegisterFlagsWithTimeouts) to not have the structured logging flags available. This commit adds the --structured-logging and --structured-log-level flags to RegisterFlagsWithTimeouts() to match RegisterFlags(). Signed-off-by: Tanjin Xu Co-Authored-By: Claude --- go/vt/servenv/servenv.go | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/go/vt/servenv/servenv.go b/go/vt/servenv/servenv.go index 5491d93c0b0..9ecf241979d 100644 --- a/go/vt/servenv/servenv.go +++ b/go/vt/servenv/servenv.go @@ -128,6 +128,10 @@ func RegisterFlagsWithTimeouts(tf *TimeoutFlags) { // 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.") + // 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.") + timeouts = tf }) }