Add structure logging (Zap) to Vitess

go.mod

@@ -108,7 +108,9 @@ require (
 	github.com/kr/pretty v0.3.1
 	github.com/kr/text v0.2.0
 	github.com/nsf/jsondiff v0.0.0-20210926074059-1e845ec5d249
+	github.com/slok/noglog v0.2.0
 	github.com/xlab/treeprint v1.2.0
+	go.uber.org/zap v1.24.0
 	golang.org/x/exp v0.0.0-20230131160201-f062dba9d201
 	golang.org/x/sync v0.1.0
 	modernc.org/sqlite v1.20.3
@@ -183,9 +185,8 @@ require (
 	github.com/tidwall/match v1.1.1 // indirect
 	github.com/tidwall/pretty v1.2.0 // indirect
 	go.opencensus.io v0.24.0 // indirect
-	go.uber.org/atomic v1.10.0 // indirect
-	go.uber.org/multierr v1.9.0 // indirect
-	go.uber.org/zap v1.23.0 // indirect
+	go.uber.org/atomic v1.11.0 // indirect
+	go.uber.org/multierr v1.11.0 // indirect
 	go4.org/intern v0.0.0-20220617035311-6925f38cc365 // indirect
 	go4.org/unsafe/assume-no-moving-gc v0.0.0-20220617031537-928513b29760 // indirect
 	golang.org/x/xerrors v0.0.0-20220907171357-04be3eba64a2 // indirect

go.sum

@@ -701,6 +701,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.4/go.mod h1:IM3LyeVVIOuxMH7sFAkER9+bJ4dT7Ms6E4xg4kGIyLM=
@@ -809,15 +811,16 @@ go.opencensus.io v0.24.0/go.mod h1:vNK8G9p7aAivkbmorf4v+7Hgx+Zs0yY+0fOtgBfjQKo=
 go.opentelemetry.io/proto/otlp v0.7.0/go.mod h1:PqfVotwruBrMGOCsRd/89rSnXhoiJIqeYNgFYFoEGnI=
 go.uber.org/atomic v1.3.2/go.mod h1:gD2HeocX3+yG+ygLZcrzQJaqmWj9AIm7n08wl/qW/PE=
 go.uber.org/atomic v1.4.0/go.mod h1:gD2HeocX3+yG+ygLZcrzQJaqmWj9AIm7n08wl/qW/PE=
-go.uber.org/atomic v1.10.0 h1:9qC72Qh0+3MqyJbAn8YU5xVq1frD8bn3JtD2oXtafVQ=
 go.uber.org/atomic v1.10.0/go.mod h1:LUxbIzbOniOlMKjJjyPfpl4v+PKK2cNJn91OQbhoJI0=
+go.uber.org/atomic v1.11.0 h1:ZvwS0R+56ePWxUNi+Atn9dWONBPp/AUETXlHW0DxSjE=
+go.uber.org/atomic v1.11.0/go.mod h1:LUxbIzbOniOlMKjJjyPfpl4v+PKK2cNJn91OQbhoJI0=
 go.uber.org/goleak v1.1.11 h1:wy28qYRKZgnJTxGxvye5/wgWr1EKjmUDGYox5mGlRlI=
 go.uber.org/multierr v1.1.0/go.mod h1:wR5kodmAFQ0UK8QlbwjlSNy0Z68gJhDJUG5sjR94q/0=
-go.uber.org/multierr v1.9.0 h1:7fIwc/ZtS0q++VgcfqFDxSBZVv/Xo49/SYnDFupUwlI=
-go.uber.org/multierr v1.9.0/go.mod h1:X2jQV1h+kxSjClGpnseKVIxpmcjrj7MNnI0bnlfKTVQ=
+go.uber.org/multierr v1.11.0 h1:blXXJkSxSSfBVBlC76pxqeO+LN3aDfLQo+309xJstO0=
+go.uber.org/multierr v1.11.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y=
 go.uber.org/zap v1.10.0/go.mod h1:vwi/ZaCAaUcBkycHslxD9B2zi4UTXhF60s6SWpuDF0Q=
-go.uber.org/zap v1.23.0 h1:OjGQ5KQDEUawVHxNwQgPpiypGHOxo2mNZsOqTak4fFY=
-go.uber.org/zap v1.23.0/go.mod h1:D+nX8jyLsMHMYrln8A0rJjFt/T/9/bGgIhAqxv5URuY=
+go.uber.org/zap v1.24.0 h1:FiJd5l1UOLj0wCgbSE0rwwXHzEdAZS6hiiSnxJN/D60=
+go.uber.org/zap v1.24.0/go.mod h1:2kMP+WWQ8aoFoedH3T2sq6iJ2yDWpHbP0f6MQbS9Gkg=
 go4.org/intern v0.0.0-20211027215823-ae77deb06f29/go.mod h1:cS2ma+47FKrLPdXFpr7CuxiTW3eyJbWew4qx0qtQWDA=
 go4.org/intern v0.0.0-20220617035311-6925f38cc365 h1:t9hFvR102YlOqU0fQn1wgwhNvSbHGBbbJxX9JKfU3l0=
 go4.org/intern v0.0.0-20220617035311-6925f38cc365/go.mod h1:WXRv3p7T6gzt0CcJm43AAKdKVZmcQbwwC7EwquU5BZU=

go/flags/endtoend/mysqlctl.txt

@@ -73,6 +73,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)
+      --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)

go/flags/endtoend/mysqlctld.txt

@@ -84,6 +84,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)

go/flags/endtoend/vtctld.txt

@@ -101,6 +101,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

go/flags/endtoend/vtgate.txt

@@ -157,6 +157,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

go/flags/endtoend/vtorc.txt

@@ -51,6 +51,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)
+      --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

go/flags/endtoend/vttablet.txt

@@ -280,6 +280,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

go/flags/endtoend/vttestserver.txt

@@ -100,6 +100,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")

go/vt/logutil/vts_logger.go

@@ -0,0 +1,67 @@
+/*
+Copyright 2023 The Vitess Authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package logutil
+
+import (
+	noglog "github.com/slok/noglog"
+	"go.uber.org/zap"
+
+	"vitess.io/vitess/go/vt/log"
+)
+
+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
+}

go/vt/logutil/vts_logger_test.go

@@ -0,0 +1,130 @@
+/*
+Copyright 2023 The Vitess Authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package logutil
+
+import (
+	"bytes"
+	"encoding/json"
+	"net/url"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+
+	vtlog "vitess.io/vitess/go/vt/log"
+)
+
+// 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)
+
+		})
+	}
+}

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
+	useVTSLogger         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(&useVTSLogger, "structured-logging", useVTSLogger, "whether to use structured logging (Zap) or the original (glog) logger")
 	})
 }
 
@@ -335,6 +339,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()