*: improve the format of the error log (pingcap#12155) (pingcap#16181)

config/config.go

@@ -28,6 +28,7 @@ import (
 
 	"github.com/BurntSushi/toml"
 	"github.com/pingcap/errors"
+	zaplog "github.com/pingcap/log"
 	"github.com/pingcap/parser/mysql"
 	"github.com/pingcap/tidb/util/logutil"
 	tracing "github.com/uber/jaeger-client-go/config"
@@ -112,6 +113,9 @@ type Log struct {
 	Format string `toml:"format" json:"format"`
 	// Disable automatic timestamps in output.
 	DisableTimestamp bool `toml:"disable-timestamp" json:"disable-timestamp"`
+	// DisableErrorStack stops annotating logs with the full stack error
+	// message.
+	DisableErrorStack bool `toml:"disable-error-stack" json:"disable-error-stack"`
 	// File log config.
 	File logutil.FileLogConfig `toml:"file" json:"file"`
 
@@ -387,6 +391,7 @@ var defaultConf = Config{
 		ExpensiveThreshold:  10000,
 		QueryLogMaxLen:      logutil.DefaultQueryLogMaxLen,
 		RecordPlanInSlowLog: logutil.DefaultRecordPlanInSlowLog,
+		DisableErrorStack:   true,
 	},
 	Status: Status{
 		ReportStatus:    true,
@@ -649,7 +654,7 @@ func hasRootPrivilege() bool {
 
 // ToLogConfig converts *Log to *logutil.LogConfig.
 func (l *Log) ToLogConfig() *logutil.LogConfig {
-	return logutil.NewLogConfig(l.Level, l.Format, l.SlowQueryFile, l.File, l.DisableTimestamp)
+	return logutil.NewLogConfig(l.Level, l.Format, l.SlowQueryFile, l.File, l.DisableTimestamp, func(config *zaplog.Config) { config.DisableErrorVerbose = l.DisableErrorStack })
 }
 
 // ToTracingConfig converts *OpenTracing to *tracing.Configuration.

config/config.toml.example

@@ -81,9 +81,12 @@ level = "info"
 # Log format, one of json, text, console.
 format = "text"
 
-# Disable automatic timestamp in output
+# Disable automatic timestamp in output.
 disable-timestamp = false
 
+# Disable stack information in error message.
+disable-error-stack = true
+
 # Stores slow query log into separated files.
 slow-query-file = "tidb-slow.log"
 

config/config_test.go

@@ -20,6 +20,7 @@ import (
 	"testing"
 
 	. "github.com/pingcap/check"
+	zaplog "github.com/pingcap/log"
 	"github.com/pingcap/parser/mysql"
 	"github.com/pingcap/tidb/util/logutil"
 	tracing "github.com/uber/jaeger-client-go/config"
@@ -124,8 +125,7 @@ history-size=100
 	c.Assert(conf, DeepEquals, GetGlobalConfig())
 
 	// Test for log config.
-	c.Assert(conf.Log.ToLogConfig(), DeepEquals, logutil.NewLogConfig("info", "text", "tidb-slow.log", conf.Log.File, false))
-
+	c.Assert(conf.Log.ToLogConfig(), DeepEquals, logutil.NewLogConfig("info", "text", "tidb-slow.log", conf.Log.File, false, func(config *zaplog.Config) { config.DisableErrorVerbose = conf.Log.DisableErrorStack }))
 	// Test for tracing config.
 	tracingConf := &tracing.Configuration{
 		Disabled: true,

util/logutil/log.go

@@ -28,6 +28,7 @@ import (
 	zaplog "github.com/pingcap/log"
 	log "github.com/sirupsen/logrus"
 	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
 	"gopkg.in/natefinch/lumberjack.v2"
 )
 
@@ -72,8 +73,8 @@ type LogConfig struct {
 }
 
 // NewLogConfig creates a LogConfig.
-func NewLogConfig(level, format, slowQueryFile string, fileCfg FileLogConfig, disableTimestamp bool) *LogConfig {
-	return &LogConfig{
+func NewLogConfig(level, format, slowQueryFile string, fileCfg FileLogConfig, disableTimestamp bool, opts ...func(*zaplog.Config)) *LogConfig {
+	c := &LogConfig{
 		Config: zaplog.Config{
 			Level:            level,
 			Format:           format,
@@ -82,6 +83,10 @@ func NewLogConfig(level, format, slowQueryFile string, fileCfg FileLogConfig, di
 		},
 		SlowQueryFile: slowQueryFile,
 	}
+	for _, opt := range opts {
+		opt(&c.Config)
+	}
+	return c
 }
 
 // isSKippedPackageName tests wether path name is on log library calling stack.
@@ -324,7 +329,7 @@ func InitLogger(cfg *LogConfig) error {
 
 // InitZapLogger initializes a zap logger with cfg.
 func InitZapLogger(cfg *LogConfig) error {
-	gl, props, err := zaplog.InitLogger(&cfg.Config)
+	gl, props, err := zaplog.InitLogger(&cfg.Config, zap.AddStacktrace(zapcore.FatalLevel))
 	if err != nil {
 		return errors.Trace(err)
 	}
@@ -337,12 +342,13 @@ func InitZapLogger(cfg *LogConfig) error {
 			Filename:  cfg.SlowQueryFile,
 		}
 		sqCfg := &zaplog.Config{
-			Level:            cfg.Level,
-			Format:           cfg.Format,
-			DisableTimestamp: cfg.DisableTimestamp,
-			File:             sqfCfg,
+			Level:               cfg.Level,
+			Format:              cfg.Format,
+			DisableTimestamp:    cfg.DisableTimestamp,
+			File:                sqfCfg,
+			DisableErrorVerbose: cfg.DisableErrorVerbose,
 		}
-		sqLogger, _, err := zaplog.InitLogger(sqCfg)
+		sqLogger, _, err := zaplog.InitLogger(sqCfg, zap.AddStacktrace(zapcore.FatalLevel))
 		if err != nil {
 			return errors.Trace(err)
 		}

util/logutil/log_test.go

@@ -24,6 +24,7 @@ import (
 	"testing"
 
 	. "github.com/pingcap/check"
+	"github.com/pingcap/errors"
 	zaplog "github.com/pingcap/log"
 	log "github.com/sirupsen/logrus"
 	"go.uber.org/zap"
@@ -160,7 +161,7 @@ func (s *testLogSuite) TestLoggerKeepOrder(c *C) {
 
 func (s *testLogSuite) TestSlowQueryZapLogger(c *C) {
 	fileName := "slow_query"
-	conf := NewLogConfig("info", DefaultLogFormat, fileName, EmptyFileLogConfig, false)
+	conf := NewLogConfig("info", DefaultLogFormat, fileName, EmptyFileLogConfig, false, func(config *zaplog.Config) { config.DisableErrorVerbose = true })
 	err := InitZapLogger(conf)
 	c.Assert(err, IsNil)
 	defer os.Remove(fileName)
@@ -169,6 +170,7 @@ func (s *testLogSuite) TestSlowQueryZapLogger(c *C) {
 	SlowQueryZapLogger.Info("info message", zap.String("str key", "val"))
 	SlowQueryZapLogger.Warn("warn", zap.Int("int key", 123))
 	SlowQueryZapLogger.Error("error message", zap.Bool("bool key", true))
+	SlowQueryZapLogger.Error("error message", zap.Error(errors.New("unexpect")))
 
 	f, err := os.Open(fileName)
 	c.Assert(err, IsNil)
@@ -182,6 +184,8 @@ func (s *testLogSuite) TestSlowQueryZapLogger(c *C) {
 			break
 		}
 		c.Assert(str, Matches, zapLogPattern)
+		c.Assert(strings.Contains(str, "stack"), IsFalse)
+		c.Assert(strings.Contains(str, "errorVerbose"), IsFalse)
 	}
 	c.Assert(err, Equals, io.EOF)
 }