slack-vitess-r14.0.5:Implement the Vitess Structure Logger VTSLogger

go.mod

@@ -76,7 +76,7 @@ require (
 	github.com/spf13/pflag v1.0.5
 	github.com/spf13/viper v1.8.1
 	github.com/spyzhov/ajson v0.4.2
-	github.com/stretchr/testify v1.7.1
+	github.com/stretchr/testify v1.8.0
 	github.com/tchap/go-patricia v2.2.6+incompatible
 	github.com/tebeka/selenium v0.9.9
 	github.com/tidwall/gjson v1.12.1
@@ -121,6 +121,16 @@ require (
 
 require github.com/bndr/gotabulate v1.1.2
 
+require (
+	github.com/slok/noglog v0.2.0
+	go.uber.org/zap v1.23.0
+)
+
+require (
+	go.uber.org/atomic v1.7.0 // indirect
+	go.uber.org/multierr v1.6.0 // indirect
+)
+
 require (
 	cloud.google.com/go v0.81.0 // indirect
 	github.com/BurntSushi/toml v0.3.1 // indirect
@@ -178,9 +188,6 @@ require (
 	github.com/valyala/bytebufferpool v1.0.0 // indirect
 	github.com/valyala/fasttemplate v1.0.1 // indirect
 	go.opencensus.io v0.23.0 // indirect
-	go.uber.org/atomic v1.7.0 // indirect
-	go.uber.org/multierr v1.6.0 // indirect
-	go.uber.org/zap v1.17.0 // indirect
 	golang.org/x/crypto v0.0.0-20210921155107-089bfa567519 // indirect
 	golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1 // indirect
 	google.golang.org/appengine v1.6.7 // indirect

go.sum

@@ -123,6 +123,7 @@ github.com/asaskevich/govalidator v0.0.0-20180720115003-f9ffefc3facf/go.mod h1:l
 github.com/asaskevich/govalidator v0.0.0-20190424111038-f61b66f89f4a/go.mod h1:lB+ZfQJz7igIIfQNfa7Ml4HSf2uFQQRzpGGRXenZAgY=
 github.com/aws/aws-sdk-go v1.34.2 h1:9vCknCdTAmmV4ht7lPuda7aJXzllXwEQyCMZKJHjBrM=
 github.com/aws/aws-sdk-go v1.34.2/go.mod h1:5zCpMtNQVjRREroY7sYe8lOMRSxkhG6MZveU8YkpAk0=
+github.com/benbjohnson/clock v1.1.0 h1:Q92kusRqC1XV2MjkWETPvjJVqKetz1OzxZB7mHJLju8=
 github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973/go.mod h1:Dwedo/Wpr24TaqPxmxbtue+5NUziq4I4S80YR8gNf3Q=
 github.com/beorn7/perks v1.0.0/go.mod h1:KWe93zE9D1o94FZ5RNwFwVgaQK1VOXiVxmqh+CedLV8=
 github.com/beorn7/perks v1.0.1 h1:VlbKKnNfV8bJzeqoa4cOKqO6bYr3WgKZxO8Z16+hsOM=
@@ -666,6 +667,8 @@ github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6Mwd
 github.com/sirupsen/logrus v1.6.0/go.mod h1:7uNnSEd1DgxDLC74fIahvMZmmYsHGZGEOFrfsX/uA88=
 github.com/sjmudd/stopwatch v0.0.0-20170613150411-f380bf8a9be1 h1:acClJNSOjUrAUKW+ZneCZymCFDWtSaJG5YQl8FoOlyI=
 github.com/sjmudd/stopwatch v0.0.0-20170613150411-f380bf8a9be1/go.mod h1:Pgf1sZ2KrHK8vdRTV5UHGp80LT7HMUKuNAiKC402abY=
+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-20180927180507-b2de0cb4f26d/go.mod h1:OnSkiWE9lh6wB0YB77sQom3nweQdgAjqCqsofrRNTgc=
 github.com/smartystreets/assertions v0.0.0-20190116191733-b6c0e53d7304 h1:Jpy1PXuP99tXNrhbq2BaPz9B+jNAvH1JPQQpG/9GCXY=
 github.com/smartystreets/assertions v0.0.0-20190116191733-b6c0e53d7304/go.mod h1:OnSkiWE9lh6wB0YB77sQom3nweQdgAjqCqsofrRNTgc=
@@ -701,16 +704,18 @@ github.com/spyzhov/ajson v0.4.2 h1:JMByd/jZApPKDvNsmO90X2WWGbmT2ahDFp73QhZbg3s=
 github.com/spyzhov/ajson v0.4.2/go.mod h1:63V+CGM6f1Bu/p4nLIN8885ojBdt88TbLoSFzyqMuVA=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/objx v0.1.1/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
-github.com/stretchr/objx v0.2.0 h1:Hbg2NidpLE8veEBkEZTL3CvlkUIVzuU9jDplZO54c48=
 github.com/stretchr/objx v0.2.0/go.mod h1:qt09Ya8vawLte6SNmTgCsAVtYtaKzEcn8ATUoHMkEqE=
+github.com/stretchr/objx v0.4.0 h1:M2gUjqZET1qApGOWNSnZ49BAIMX4F/1plDv3+l31EJ4=
+github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw=
 github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
 github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
 github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4=
 github.com/stretchr/testify v1.5.1/go.mod h1:5W2xD1RspED5o8YsWQXVCued0rvSQ+mT+I5cxcmMvtA=
 github.com/stretchr/testify v1.6.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
 github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
-github.com/stretchr/testify v1.7.1 h1:5TQK59W5E3v0r2duFAb7P95B6hEeOyEnHRa8MjYSMTY=
 github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
+github.com/stretchr/testify v1.8.0 h1:pSgiaMZlXftHpm5L7V1+rVB+AZJydKsMxsQBIJw4PKk=
+github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU=
 github.com/subosito/gotenv v1.2.0 h1:Slr1R9HxAlEKefgq5jn9U+DnETlIUa6HfgEzj0g5d7s=
 github.com/subosito/gotenv v1.2.0/go.mod h1:N0PQaV/YGNqwC0u51sEeR/aUtSLEXKX9iv69rRypqCw=
 github.com/tchap/go-patricia v2.2.6+incompatible h1:JvoDL7JSoIP2HDE8AbDH3zC8QBPxmzYe32HHy5yQ+Ck=
@@ -777,12 +782,14 @@ 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.7.0 h1:ADUqmZGgLDDfbSL9ZmPxKTybcoEYHgpYfELNoN+7hsw=
 go.uber.org/atomic v1.7.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc=
+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.6.0 h1:y6IPFStTAIT5Ytl7/XYmHvzXQ7S3g/IeZW9hyZ5thw4=
 go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU=
 go.uber.org/zap v1.10.0/go.mod h1:vwi/ZaCAaUcBkycHslxD9B2zi4UTXhF60s6SWpuDF0Q=
-go.uber.org/zap v1.17.0 h1:MTjgFu6ZLKvY6Pvaqk97GlxNBuMpV4Hy/3P6tRGlI2U=
 go.uber.org/zap v1.17.0/go.mod h1:MXVU+bhUf/A7Xi2HNOnopQOrmycQ5Ih87HtOu4q5SSo=
+go.uber.org/zap v1.23.0 h1:OjGQ5KQDEUawVHxNwQgPpiypGHOxo2mNZsOqTak4fFY=
+go.uber.org/zap v1.23.0/go.mod h1:D+nX8jyLsMHMYrln8A0rJjFt/T/9/bGgIhAqxv5URuY=
 golang.org/x/crypto v0.0.0-20180904163835-0709b304e793/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
 golang.org/x/crypto v0.0.0-20181029021203-45a5f77698d3/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
 golang.org/x/crypto v0.0.0-20181203042331-505ab145d0a9/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=

go/flags/endtoend/vtgate.txt

@@ -309,6 +309,8 @@ Usage of vtgate:
 	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
   --tablet_filters value
 	Specifies a comma-separated list of 'keyspace|shard_name or keyrange' values to filter the tablets to watch
   --tablet_grpc_ca string

go/flags/endtoend/vttablet.txt

@@ -783,6 +783,8 @@ Usage of vttablet:
 	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

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/grpc_auth.go

@@ -54,15 +54,15 @@ func GetAuthenticator(name string) func() (Authenticator, error) {
 }
 
 // FakeAuthStreamInterceptor fake interceptor to test plugin
-func FakeAuthStreamInterceptor(srv any, stream grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error {
+func FakeAuthStreamInterceptor(srv any, stream grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error { // nolint:revive
 	if fakeDummyAuthenticate(stream.Context()) {
 		return handler(srv, stream)
 	}
 	return status.Errorf(codes.Unauthenticated, "username and password must be provided")
 }
 
 // FakeAuthUnaryInterceptor fake interceptor to test plugin
-func FakeAuthUnaryInterceptor(ctx context.Context, req any, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (any, error) {
+func FakeAuthUnaryInterceptor(ctx context.Context, req any, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (any, error) { // nolint:revive
 	if fakeDummyAuthenticate(ctx) {
 		return handler(ctx, req)
 	}

go/vt/servenv/grpc_server_auth_mtls.go

@@ -46,7 +46,7 @@ type MtlsAuthPlugin struct {
 
 // Authenticate implements Authenticator interface. This method will be used inside a middleware in grpc_server to authenticate
 // incoming requests.
-func (ma *MtlsAuthPlugin) Authenticate(ctx context.Context, fullMethod string) (context.Context, error) {
+func (ma *MtlsAuthPlugin) Authenticate(ctx context.Context, fullMethod string) (context.Context, error) { // nolint:revive
 	p, ok := peer.FromContext(ctx)
 	if !ok {
 		return nil, status.Errorf(codes.Unauthenticated, "no peer connection info")

go/vt/servenv/grpc_server_auth_static.go

@@ -54,7 +54,7 @@ type StaticAuthPlugin struct {
 
 // Authenticate implements AuthPlugin interface. This method will be used inside a middleware in grpc_server to authenticate
 // incoming requests.
-func (sa *StaticAuthPlugin) Authenticate(ctx context.Context, fullMethod string) (context.Context, error) {
+func (sa *StaticAuthPlugin) Authenticate(ctx context.Context, fullMethod string) (context.Context, error) { // nolint:revive
 	if md, ok := metadata.FromIncomingContext(ctx); ok {
 		if len(md["username"]) == 0 || len(md["password"]) == 0 {
 			return nil, status.Errorf(codes.Unauthenticated, "username and password must be provided")

go/vt/servenv/servenv.go

@@ -38,6 +38,8 @@ import (
 	"syscall"
 	"time"
 
+	"vitess.io/vitess/go/vt/logutil"
+
 	// register the HTTP handlers for profiling
 	_ "net/http/pprof"
 
@@ -64,6 +66,7 @@ var (
 	_              = flag.Int("mem-profile-rate", 512*1024, "deprecated: use '-pprof=mem' instead")
 	_              = flag.Int("mutex-profile-fraction", 0, "deprecated: use '-pprof=mutex' instead")
 	catchSigpipe   = flag.Bool("catch-sigpipe", false, "catch and ignore SIGPIPE on stdout and stderr if specified")
+	useVTSLogger   = flag.Bool("structured-logging", false, "whether to use structured logging (Zap) or the original (glog) logger")
 
 	// mutex used to protect the Init function
 	mu sync.Mutex
@@ -244,6 +247,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 := _flag.Args()
 	if len(args) > 0 {
 		flag.Usage()