slack-19.0: fix structured logging

Signed-off-by: Tim Vaillancourt <tim@timvaillancourt.com>

go/vt/logutil/logger.go

@@ -26,6 +26,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,16 +389,21 @@ func fileAndLine(depth int) (string, int64) {
  return file, int64(line)
 }
 
-type StructuredLogger zap.SugaredLogger
+// newZapLoggerConfig creates a new config for a zap logger.
+func newZapLoggerConfig() zap.Config {
+ conf := zap.NewProductionConfig()
+ conf.EncoderConfig.EncodeTime = zapcore.TimeEncoderOfLayout(time.RFC3339)
+ return conf
+}
 
 // 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
+ defaultConf := newZapLoggerConfig()
+ conf = &defaultConf
  }
 
  // Build configuration and generate a sugared logger

go/vt/logutil/logger_test.go

@@ -193,24 +193,19 @@ func SetupLoggerWithMemSink() (sink *MemorySink, err error) {
 }
 
 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://"},
- }
+ conf := newZapLoggerConfig()
+ conf.Level = zap.NewAtomicLevelAt(zap.InfoLevel)
+ 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"`
+ Stacktrace string `json:"stacktrace"`
+ Timestamp string `json:"ts"`
  }
 
  type testCase struct {
@@ -232,6 +227,7 @@ 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:
@@ -240,6 +236,7 @@ func TestStructuredLogger_Replacing_glog(t *testing.T) {
  case zapcore.ErrorLevel:
  loggingFunc = vtlog.Errorf
  expectedLevel = "error"
+ expectStacktrace = true
  case zapcore.WarnLevel:
  loggingFunc = vtlog.Warningf
  expectedLevel = "warn"
@@ -256,7 +253,13 @@ 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
+ _, err = time.Parse(time.RFC3339, actualLog.Timestamp)
+ assert.NoError(t, err)
  })
  }
 }

go/vt/servenv/servenv.go

@@ -102,6 +102,7 @@ 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
+ fmt.Println("got here")
  fs.BoolVar(&useStructuredLogger, "structured-logging", useStructuredLogger, "enable structured logging")
  })
 }
@@ -395,6 +396,14 @@ func ParseFlagsWithArgs(cmd string) []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 {
  log.Exitf("%s expected at least one positional argument", cmd)

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,14 @@ func Init() {
  return int64(time.Since(serverStart).Nanoseconds())
  })
 
+ 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)
+ }
+ }
+
  // 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