diff --git a/go/flags/endtoend/mysqlctl.txt b/go/flags/endtoend/mysqlctl.txt index cb757164d35..b680eb38aa8 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 a0e09e9898d..9eb395f962c 100644 --- a/go/flags/endtoend/mysqlctld.txt +++ b/go/flags/endtoend/mysqlctld.txt @@ -114,7 +114,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 9e968a1936b..dc333bd6699 100644 --- a/go/flags/endtoend/vtcombo.txt +++ b/go/flags/endtoend/vtcombo.txt @@ -335,7 +335,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 ad85915d34c..302dfef73cd 100644 --- a/go/flags/endtoend/vtctld.txt +++ b/go/flags/endtoend/vtctld.txt @@ -131,7 +131,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 dc5b10e0512..900bfb7f322 100644 --- a/go/flags/endtoend/vtgate.txt +++ b/go/flags/endtoend/vtgate.txt @@ -196,7 +196,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 9967be213a1..c629eed7166 100644 --- a/go/flags/endtoend/vtgateclienttest.txt +++ b/go/flags/endtoend/vtgateclienttest.txt @@ -61,7 +61,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 10019e979a8..2bc5916455c 100644 --- a/go/flags/endtoend/vtorc.txt +++ b/go/flags/endtoend/vtorc.txt @@ -78,7 +78,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 b887be36e63..fbdcabcb507 100644 --- a/go/flags/endtoend/vttablet.txt +++ b/go/flags/endtoend/vttablet.txt @@ -333,7 +333,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 c94918db1ed..97d7e722a85 100644 --- a/go/flags/endtoend/vttestserver.txt +++ b/go/flags/endtoend/vttestserver.txt @@ -115,7 +115,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 29b1ae02d74..24982a8ea3f 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" "strings" "sync" @@ -26,6 +29,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" @@ -388,27 +392,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 @@ -428,5 +480,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 9d8894a7eb6..05bbbae3faf 100644 --- a/go/vt/servenv/servenv.go +++ b/go/vt/servenv/servenv.go @@ -102,7 +102,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.") }) } @@ -291,8 +292,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) } } @@ -395,6 +395,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) + } + } +}