diff --git a/config/config.go b/config/config.go index 14467afaa0b4f..8390ba050b98f 100644 --- a/config/config.go +++ b/config/config.go @@ -297,7 +297,7 @@ func (b *nullableBool) UnmarshalJSON(data []byte) error { type Log struct { // Log level. Level string `toml:"level" json:"level"` - // Log format. one of json, text, or console. + // Log format, one of json or text. Format string `toml:"format" json:"format"` // Disable automatic timestamps in output. Deprecated: use EnableTimestamp instead. DisableTimestamp nullableBool `toml:"disable-timestamp" json:"disable-timestamp"` diff --git a/config/config.toml.example b/config/config.toml.example index 6db0b5c517277..1cc2674d01727 100644 --- a/config/config.toml.example +++ b/config/config.toml.example @@ -136,7 +136,7 @@ enable-enum-length-limit = true # Log level: debug, info, warn, error, fatal. level = "info" -# Log format, one of json, text, console. +# Log format, one of json or text. format = "text" # Enable automatic timestamps in log output, if not set, it will be defaulted to true. diff --git a/go.mod b/go.mod index d29f89bfade55..ac4ef88fd215d 100644 --- a/go.mod +++ b/go.mod @@ -54,7 +54,7 @@ require ( github.com/prometheus/common v0.9.1 github.com/rivo/uniseg v0.2.0 // indirect github.com/shirou/gopsutil v3.21.2+incompatible - github.com/sirupsen/logrus v1.6.0 + github.com/sirupsen/logrus v1.6.0 // indirect github.com/soheilhy/cmux v0.1.4 github.com/tiancaiamao/appdash v0.0.0-20181126055449-889f96f722a2 github.com/tikv/pd v1.1.0-beta.0.20210323121136-78679e5e209d @@ -77,9 +77,8 @@ require ( golang.org/x/tools v0.1.0 google.golang.org/grpc v1.27.1 gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c // indirect - gopkg.in/natefinch/lumberjack.v2 v2.0.0 gopkg.in/yaml.v2 v2.4.0 // indirect - honnef.co/go/tools v0.1.4 // indirect + honnef.co/go/tools v0.2.0 // indirect modernc.org/mathutil v1.2.2 // indirect sourcegraph.com/sourcegraph/appdash v0.0.0-20190731080439-ebfcffb1b5c0 sourcegraph.com/sourcegraph/appdash-data v0.0.0-20151005221446-73f23eafcf67 diff --git a/go.sum b/go.sum index 991423501bec3..6336c1749649d 100644 --- a/go.sum +++ b/go.sum @@ -928,8 +928,8 @@ honnef.co/go/tools v0.0.0-20190418001031-e561f6794a2a/go.mod h1:rf3lG4BRIbNafJWh honnef.co/go/tools v0.0.0-20190523083050-ea95bdfd59fc/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4= honnef.co/go/tools v0.0.1-2019.2.3/go.mod h1:a3bituU0lyd329TUQxRnasdCoJDkEUEAqEt0JzvZhAg= honnef.co/go/tools v0.0.1-2020.1.3/go.mod h1:X/FiERA/W4tHapMX5mGpAtMSVEeEUOyHaw9vFzvIQ3k= -honnef.co/go/tools v0.1.4 h1:SadWOkti5uVN1FAMgxn165+Mw00fuQKyk4Gyn/inxNQ= -honnef.co/go/tools v0.1.4/go.mod h1:NgwopIslSNH47DimFoV78dnkksY2EFtX0ajyb3K/las= +honnef.co/go/tools v0.2.0 h1:ws8AfbgTX3oIczLPNPCu5166oBg9ST2vNs0rcht+mDE= +honnef.co/go/tools v0.2.0/go.mod h1:lPVVZ2BS5TfnjLyizF7o7hv7j9/L+8cZY2hLyjP9cGY= k8s.io/klog v1.0.0/go.mod h1:4Bi6QPql/J/LkTDqv7R/cd3hPo4k2DG6Ptcz060Ez5I= modernc.org/mathutil v1.2.2 h1:+yFk8hBprV+4c0U9GjFtL+dV3N8hOJ8JCituQcMShFY= modernc.org/mathutil v1.2.2/go.mod h1:mZW8CKdRPY1v87qxC/wUdX5O1qDzXMP5TH3wjfpga6E= diff --git a/server/http_handler.go b/server/http_handler.go index 4aaab275430c4..0642924359210 100644 --- a/server/http_handler.go +++ b/server/http_handler.go @@ -34,6 +34,7 @@ import ( "github.com/pingcap/failpoint" "github.com/pingcap/kvproto/pkg/kvrpcpb" "github.com/pingcap/kvproto/pkg/metapb" + "github.com/pingcap/log" "github.com/pingcap/parser/model" "github.com/pingcap/parser/terror" "github.com/pingcap/tidb/config" @@ -61,7 +62,6 @@ import ( "github.com/pingcap/tidb/util/gcutil" "github.com/pingcap/tidb/util/logutil" "github.com/pingcap/tidb/util/pdapi" - log "github.com/sirupsen/logrus" "go.uber.org/zap" ) @@ -625,13 +625,6 @@ func (h settingsHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) { return } - l, err1 := log.ParseLevel(levelStr) - if err1 != nil { - writeError(w, err1) - return - } - log.SetLevel(l) - config.GetGlobalConfig().Log.Level = levelStr } if generalLog := req.Form.Get("tidb_general_log"); generalLog != "" { @@ -1090,7 +1083,7 @@ func (h ddlResignOwnerHandler) ServeHTTP(w http.ResponseWriter, req *http.Reques err := h.resignDDLOwner() if err != nil { - log.Error(err) + log.Error("failed to resign DDL owner", zap.Error(err)) writeError(w, err) return } @@ -1134,7 +1127,7 @@ func (h tableHandler) addScatterSchedule(startKey, endKey []byte, name string) e return err } if err := resp.Body.Close(); err != nil { - log.Error(err) + log.Error("failed to close response body", zap.Error(err)) } return nil } @@ -1154,7 +1147,7 @@ func (h tableHandler) deleteScatterSchedule(name string) error { return err } if err := resp.Body.Close(); err != nil { - log.Error(err) + log.Error("failed to close response body", zap.Error(err)) } return nil } @@ -1664,14 +1657,14 @@ func (h serverInfoHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) { do, err := session.GetDomain(h.Store) if err != nil { writeError(w, errors.New("create session error")) - log.Error(err) + log.Error("failed to get session domain", zap.Error(err)) return } info := serverInfo{} info.ServerInfo, err = infosync.GetServerInfo() if err != nil { writeError(w, err) - log.Error(err) + log.Error("failed to get server info", zap.Error(err)) return } info.IsOwner = do.DDL().OwnerManager().IsOwner() @@ -1694,14 +1687,14 @@ func (h allServerInfoHandler) ServeHTTP(w http.ResponseWriter, req *http.Request do, err := session.GetDomain(h.Store) if err != nil { writeError(w, errors.New("create session error")) - log.Error(err) + log.Error("failed to get session domain", zap.Error(err)) return } ctx := context.Background() allServersInfo, err := infosync.GetAllServerInfo(ctx) if err != nil { writeError(w, errors.New("ddl server information not found")) - log.Error(err) + log.Error("failed to get all server info", zap.Error(err)) return } ctx, cancel := context.WithTimeout(ctx, 3*time.Second) @@ -1709,7 +1702,7 @@ func (h allServerInfoHandler) ServeHTTP(w http.ResponseWriter, req *http.Request cancel() if err != nil { writeError(w, errors.New("ddl server information not found")) - log.Error(err) + log.Error("failed to get owner id", zap.Error(err)) return } allVersionsMap := map[infosync.ServerVersionInfo]struct{}{} @@ -1905,13 +1898,13 @@ func (h ddlHookHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) { dom, err := session.GetDomain(h.store) if err != nil { - log.Error(err) + log.Error("failed to get session domain", zap.Error(err)) writeError(w, err) } newCallbackFunc, err := ddl.GetCustomizedHook(req.FormValue("ddl_hook")) if err != nil { - log.Error(err) + log.Error("failed to get customized hook", zap.Error(err)) writeError(w, err) } callback := newCallbackFunc(dom) diff --git a/server/http_handler_test.go b/server/http_handler_test.go index 208714ac082e1..5d2b654262a54 100644 --- a/server/http_handler_test.go +++ b/server/http_handler_test.go @@ -36,7 +36,7 @@ import ( . "github.com/pingcap/check" "github.com/pingcap/failpoint" "github.com/pingcap/kvproto/pkg/kvrpcpb" - zaplog "github.com/pingcap/log" + "github.com/pingcap/log" "github.com/pingcap/parser/model" "github.com/pingcap/parser/mysql" "github.com/pingcap/tidb/config" @@ -57,7 +57,6 @@ import ( "github.com/pingcap/tidb/util/codec" "github.com/pingcap/tidb/util/rowcodec" "github.com/pingcap/tidb/util/versioninfo" - log "github.com/sirupsen/logrus" "go.uber.org/zap" ) @@ -1155,8 +1154,7 @@ func (ts *HTTPHandlerTestSuite) TestPostSettings(c *C) { resp, err := ts.formStatus("/settings", form) c.Assert(err, IsNil) c.Assert(resp.StatusCode, Equals, http.StatusOK) - c.Assert(log.GetLevel(), Equals, log.ErrorLevel) - c.Assert(zaplog.GetLevel(), Equals, zap.ErrorLevel) + c.Assert(log.GetLevel(), Equals, zap.ErrorLevel) c.Assert(config.GetGlobalConfig().Log.Level, Equals, "error") c.Assert(variable.ProcessGeneralLog.Load(), IsTrue) val, err := variable.GetGlobalSystemVar(se.GetSessionVars(), variable.TiDBEnableAsyncCommit) @@ -1175,8 +1173,7 @@ func (ts *HTTPHandlerTestSuite) TestPostSettings(c *C) { c.Assert(err, IsNil) c.Assert(resp.StatusCode, Equals, http.StatusOK) c.Assert(variable.ProcessGeneralLog.Load(), IsFalse) - c.Assert(log.GetLevel(), Equals, log.FatalLevel) - c.Assert(zaplog.GetLevel(), Equals, zap.FatalLevel) + c.Assert(log.GetLevel(), Equals, zap.FatalLevel) c.Assert(config.GetGlobalConfig().Log.Level, Equals, "fatal") val, err = variable.GetGlobalSystemVar(se.GetSessionVars(), variable.TiDBEnableAsyncCommit) c.Assert(err, IsNil) @@ -1244,7 +1241,7 @@ func (ts *HTTPHandlerTestSuite) TestPprof(c *C) { } time.Sleep(time.Millisecond * 10) } - zaplog.Fatal("failed to get profile for %d retries in every 10 ms", zap.Int("retryTime", retryTime)) + log.Fatal("failed to get profile for %d retries in every 10 ms", zap.Int("retryTime", retryTime)) } func (ts *HTTPHandlerTestSuite) TestServerInfo(c *C) { diff --git a/tidb-server/main.go b/tidb-server/main.go index ed1da6abfb7fb..a4e81f51862af 100644 --- a/tidb-server/main.go +++ b/tidb-server/main.go @@ -17,7 +17,6 @@ import ( "context" "flag" "fmt" - "io" "os" "runtime" "strconv" @@ -69,7 +68,6 @@ import ( pd "github.com/tikv/pd/client" "go.uber.org/automaxprocs/maxprocs" "go.uber.org/zap" - "google.golang.org/grpc/grpclog" ) // Flag Names @@ -588,14 +586,6 @@ func setupLog() { err := logutil.InitZapLogger(cfg.Log.ToLogConfig()) terror.MustNil(err) - err = logutil.InitLogger(cfg.Log.ToLogConfig()) - terror.MustNil(err) - - if len(os.Getenv("GRPC_DEBUG")) > 0 { - grpclog.SetLoggerV2(grpclog.NewLoggerV2WithVerbosity(os.Stderr, os.Stderr, os.Stderr, 999)) - } else { - grpclog.SetLoggerV2(grpclog.NewLoggerV2(io.Discard, io.Discard, os.Stderr)) - } // trigger internal http(s) client init. util.InternalHTTPClient() } diff --git a/util/logutil/log.go b/util/logutil/log.go index 48088318b2d6b..b62484658495f 100644 --- a/util/logutil/log.go +++ b/util/logutil/log.go @@ -14,35 +14,26 @@ package logutil import ( - "bytes" "context" "fmt" "os" - "path/filepath" - "runtime" "runtime/trace" - "sort" - "strings" "time" + gzap "github.com/grpc-ecosystem/go-grpc-middleware/logging/zap" "github.com/opentracing/opentracing-go" tlog "github.com/opentracing/opentracing-go/log" "github.com/pingcap/errors" - zaplog "github.com/pingcap/log" - tikvlog "github.com/pingcap/tidb/store/tikv/logutil" - log "github.com/sirupsen/logrus" + "github.com/pingcap/log" "go.uber.org/zap" "go.uber.org/zap/zapcore" - "gopkg.in/natefinch/lumberjack.v2" ) const ( - defaultLogTimeFormat = "2006/01/02 15:04:05.000" // DefaultLogMaxSize is the default size of log files. DefaultLogMaxSize = 300 // MB // DefaultLogFormat is the default format of the log. DefaultLogFormat = "text" - defaultLogLevel = log.InfoLevel // DefaultSlowThreshold is the default slow log threshold in millisecond. DefaultSlowThreshold = 300 // DefaultQueryLogMaxLen is the default max length of the query in the log. @@ -51,6 +42,8 @@ const ( DefaultRecordPlanInSlowLog = 1 // DefaultTiDBEnableSlowLog enables TiDB to log slow queries. DefaultTiDBEnableSlowLog = true + // GRPCLogDebugVerbosity enables max verbosity when debugging grpc code. + GRPCLogDebugVerbosity = 99 ) // EmptyFileLogConfig is an empty FileLogConfig. @@ -58,12 +51,12 @@ var EmptyFileLogConfig = FileLogConfig{} // FileLogConfig serializes file log related config in toml/json. type FileLogConfig struct { - zaplog.FileLogConfig + log.FileLogConfig } // NewFileLogConfig creates a FileLogConfig. func NewFileLogConfig(maxSize uint) FileLogConfig { - return FileLogConfig{FileLogConfig: zaplog.FileLogConfig{ + return FileLogConfig{FileLogConfig: log.FileLogConfig{ MaxSize: int(maxSize), }, } @@ -71,16 +64,16 @@ func NewFileLogConfig(maxSize uint) FileLogConfig { // LogConfig serializes log related config in toml/json. type LogConfig struct { - zaplog.Config + log.Config // SlowQueryFile filename, default to File log config on empty. SlowQueryFile string } // NewLogConfig creates a LogConfig. -func NewLogConfig(level, format, slowQueryFile string, fileCfg FileLogConfig, disableTimestamp bool, opts ...func(*zaplog.Config)) *LogConfig { +func NewLogConfig(level, format, slowQueryFile string, fileCfg FileLogConfig, disableTimestamp bool, opts ...func(*log.Config)) *LogConfig { c := &LogConfig{ - Config: zaplog.Config{ + Config: log.Config{ Level: level, Format: format, DisableTimestamp: disableTimestamp, @@ -94,102 +87,6 @@ func NewLogConfig(level, format, slowQueryFile string, fileCfg FileLogConfig, di return c } -// isSKippedPackageName tests wether path name is on log library calling stack. -func isSkippedPackageName(name string) bool { - return strings.Contains(name, "github.com/sirupsen/logrus") || - strings.Contains(name, "github.com/coreos/pkg/capnslog") -} - -// modifyHook injects file name and line pos into log entry. -type contextHook struct{} - -// Fire implements logrus.Hook interface -// https://github.com/sirupsen/logrus/issues/63 -func (hook *contextHook) Fire(entry *log.Entry) error { - pc := make([]uintptr, 4) - cnt := runtime.Callers(8, pc) - - for i := 0; i < cnt; i++ { - fu := runtime.FuncForPC(pc[i] - 1) - name := fu.Name() - if !isSkippedPackageName(name) { - file, line := fu.FileLine(pc[i] - 1) - entry.Data["file"] = filepath.Base(file) - entry.Data["line"] = line - break - } - } - return nil -} - -// Levels implements logrus.Hook interface. -func (hook *contextHook) Levels() []log.Level { - return log.AllLevels -} - -func stringToLogLevel(level string) log.Level { - switch strings.ToLower(level) { - case "fatal": - return log.FatalLevel - case "error": - return log.ErrorLevel - case "warn", "warning": - return log.WarnLevel - case "debug": - return log.DebugLevel - case "info": - return log.InfoLevel - } - return defaultLogLevel -} - -// textFormatter is for compatibility with ngaut/log -type textFormatter struct { - DisableTimestamp bool - EnableEntryOrder bool -} - -// Format implements logrus.Formatter -func (f *textFormatter) Format(entry *log.Entry) ([]byte, error) { - var b *bytes.Buffer - if entry.Buffer != nil { - b = entry.Buffer - } else { - b = &bytes.Buffer{} - } - - if !f.DisableTimestamp { - fmt.Fprintf(b, "%s ", entry.Time.Format(defaultLogTimeFormat)) - } - if file, ok := entry.Data["file"]; ok { - fmt.Fprintf(b, "%s:%v:", file, entry.Data["line"]) - } - fmt.Fprintf(b, " [%s] %s", entry.Level.String(), entry.Message) - - if f.EnableEntryOrder { - keys := make([]string, 0, len(entry.Data)) - for k := range entry.Data { - if k != "file" && k != "line" { - keys = append(keys, k) - } - } - sort.Strings(keys) - for _, k := range keys { - fmt.Fprintf(b, " %v=%v", k, entry.Data[k]) - } - } else { - for k, v := range entry.Data { - if k != "file" && k != "line" { - fmt.Fprintf(b, " %v=%v", k, v) - } - } - } - - b.WriteByte('\n') - - return b.Bytes(), nil -} - const ( // SlowLogTimeFormat is the time format for slow log. SlowLogTimeFormat = time.RFC3339Nano @@ -197,125 +94,34 @@ const ( OldSlowLogTimeFormat = "2006-01-02-15:04:05.999999999 -0700" ) -type slowLogFormatter struct{} - -func (f *slowLogFormatter) Format(entry *log.Entry) ([]byte, error) { - var b *bytes.Buffer - if entry.Buffer != nil { - b = entry.Buffer - } else { - b = &bytes.Buffer{} - } +// SlowQueryLogger is used to log slow query, InitZapLogger will modify it according to config file. +var SlowQueryLogger = log.L() - fmt.Fprintf(b, "# Time: %s\n", entry.Time.Format(SlowLogTimeFormat)) - fmt.Fprintf(b, "%s\n", entry.Message) - return b.Bytes(), nil -} - -func stringToLogFormatter(format string, disableTimestamp bool) log.Formatter { - switch strings.ToLower(format) { - case "text": - return &textFormatter{ - DisableTimestamp: disableTimestamp, - } - default: - return &textFormatter{} - } -} - -// initFileLog initializes file based logging options. -func initFileLog(cfg *zaplog.FileLogConfig, logger *log.Logger) error { - if st, err := os.Stat(cfg.Filename); err == nil { - if st.IsDir() { - return errors.New("can't use directory as log file name") - } - } - if cfg.MaxSize == 0 { - cfg.MaxSize = DefaultLogMaxSize - } - - // use lumberjack to logrotate - output := &lumberjack.Logger{ - Filename: cfg.Filename, - MaxSize: cfg.MaxSize, - MaxBackups: cfg.MaxBackups, - MaxAge: cfg.MaxDays, - LocalTime: true, - } - - if logger == nil { - log.SetOutput(output) - } else { - logger.Out = output - } - return nil -} - -// SlowQueryLogger is used to log slow query, InitLogger will modify it according to config file. -var SlowQueryLogger = log.StandardLogger() - -// SlowQueryZapLogger is used to log slow query, InitZapLogger will modify it according to config file. -var SlowQueryZapLogger = zaplog.L() - -// InitLogger initializes PD's logger. +// InitLogger delegates to InitZapLogger. Keeping it here for historical reason. func InitLogger(cfg *LogConfig) error { - log.SetLevel(stringToLogLevel(cfg.Level)) - log.AddHook(&contextHook{}) - - if cfg.Format == "" { - cfg.Format = DefaultLogFormat - } - formatter := stringToLogFormatter(cfg.Format, cfg.DisableTimestamp) - log.SetFormatter(formatter) - - if len(cfg.File.Filename) != 0 { - if err := initFileLog(&cfg.File, nil); err != nil { - return errors.Trace(err) - } - } - - if len(cfg.SlowQueryFile) != 0 { - SlowQueryLogger = log.New() - tmp := cfg.File - tmp.Filename = cfg.SlowQueryFile - if err := initFileLog(&tmp, SlowQueryLogger); err != nil { - return errors.Trace(err) - } - SlowQueryLogger.Formatter = &slowLogFormatter{} - } - - // Setup log key for tikv client. - tikvlog.CtxLogKey = ctxLogKey - - return nil + return InitZapLogger(cfg) } // InitZapLogger initializes a zap logger with cfg. func InitZapLogger(cfg *LogConfig) error { - gl, props, err := zaplog.InitLogger(&cfg.Config, zap.AddStacktrace(zapcore.FatalLevel)) + gl, props, err := log.InitLogger(&cfg.Config, zap.AddStacktrace(zapcore.FatalLevel)) if err != nil { return errors.Trace(err) } - zaplog.ReplaceGlobals(gl, props) - - if len(cfg.SlowQueryFile) != 0 { - sqfCfg := zaplog.FileLogConfig{ - MaxSize: cfg.File.MaxSize, - Filename: cfg.SlowQueryFile, - } - sqCfg := &zaplog.Config{ - Level: cfg.Level, - Format: cfg.Format, - DisableTimestamp: cfg.DisableTimestamp, - File: sqfCfg, - } - sqLogger, _, err := zaplog.InitLogger(sqCfg) - if err != nil { - return errors.Trace(err) - } - SlowQueryZapLogger = sqLogger + log.ReplaceGlobals(gl, props) + + // init dedicated logger for slow query log + SlowQueryLogger, err = newSlowQueryLogger(cfg) + if err != nil { + return errors.Trace(err) + } + + // init logger for grpc debugging + if len(os.Getenv("GRPC_DEBUG")) > 0 { + // more information for verbosity: https://github.com/google/glog#verbose-logging + gzap.ReplaceGrpcLoggerV2WithVerbosity(gl, GRPCLogDebugVerbosity) } else { - SlowQueryZapLogger = gl + gzap.ReplaceGrpcLoggerV2(gl) } return nil @@ -327,7 +133,7 @@ func SetLevel(level string) error { if err := l.UnmarshalText([]byte(level)); err != nil { return errors.Trace(err) } - zaplog.SetLevel(l.Level()) + log.SetLevel(l.Level()) return nil } @@ -341,12 +147,12 @@ func Logger(ctx context.Context) *zap.Logger { if ctxlogger, ok := ctx.Value(ctxLogKey).(*zap.Logger); ok { return ctxlogger } - return zaplog.L() + return log.L() } // BgLogger is alias of `logutil.BgLogger()` func BgLogger() *zap.Logger { - return zaplog.L() + return log.L() } // WithConnID attaches connId to context. @@ -355,7 +161,7 @@ func WithConnID(ctx context.Context, connID uint64) context.Context { if ctxLogger, ok := ctx.Value(ctxLogKey).(*zap.Logger); ok { logger = ctxLogger } else { - logger = zaplog.L() + logger = log.L() } return context.WithValue(ctx, ctxLogKey, logger.With(zap.Uint64("conn", connID))) } @@ -366,7 +172,7 @@ func WithTraceLogger(ctx context.Context, connID uint64) context.Context { if ctxLogger, ok := ctx.Value(ctxLogKey).(*zap.Logger); ok { logger = ctxLogger } else { - logger = zaplog.L() + logger = log.L() } return context.WithValue(ctx, ctxLogKey, wrapTraceLogger(ctx, connID, logger)) } @@ -374,7 +180,7 @@ func WithTraceLogger(ctx context.Context, connID uint64) context.Context { func wrapTraceLogger(ctx context.Context, connID uint64, logger *zap.Logger) *zap.Logger { return logger.WithOptions(zap.WrapCore(func(core zapcore.Core) zapcore.Core { tl := &traceLog{ctx: ctx} - traceCore := zaplog.NewTextCore(zaplog.NewTextEncoder(&zaplog.Config{}), tl, tl). + traceCore := log.NewTextCore(log.NewTextEncoder(&log.Config{}), tl, tl). With([]zapcore.Field{zap.Uint64("conn", connID)}) return zapcore.NewTee(traceCore, core) })) @@ -403,7 +209,7 @@ func WithKeyValue(ctx context.Context, key, value string) context.Context { if ctxLogger, ok := ctx.Value(ctxLogKey).(*zap.Logger); ok { logger = ctxLogger } else { - logger = zaplog.L() + logger = log.L() } return context.WithValue(ctx, ctxLogKey, logger.With(zap.String(key, value))) } diff --git a/util/logutil/log_test.go b/util/logutil/log_test.go index 4961aa28e98f1..ecc9fb9d03679 100644 --- a/util/logutil/log_test.go +++ b/util/logutil/log_test.go @@ -17,7 +17,6 @@ import ( "bufio" "bytes" "context" - "fmt" "io" "os" "runtime" @@ -25,19 +24,15 @@ import ( "testing" . "github.com/pingcap/check" - zaplog "github.com/pingcap/log" - log "github.com/sirupsen/logrus" + "github.com/pingcap/log" "go.uber.org/zap" ) const ( - logPattern = `\d\d\d\d/\d\d/\d\d \d\d:\d\d:\d\d\.\d\d\d ([\w_%!$@.,+~-]+|\\.)+:\d+: \[(fatal|error|warning|info|debug)\] .*?\n` // zapLogPatern is used to match the zap log format, such as the following log: - // [2019/02/13 15:56:05.385 +08:00] [INFO] [log_test.go:167] ["info message"] ["str key"=val] ["int key"=123] - zapLogPattern = `\[\d\d\d\d/\d\d/\d\d \d\d:\d\d:\d\d.\d\d\d\ (\+|-)\d\d:\d\d\] \[(FATAL|ERROR|WARN|INFO|DEBUG)\] \[([\w_%!$@.,+~-]+|\\.)+:\d+\] \[.*\] (\[.*=.*\]).*\n` - // [2019/02/13 15:56:05.385 +08:00] [INFO] [log_test.go:167] ["info message"] ["str key"=val] ["int key"=123] + // [2019/02/13 15:56:05.385 +08:00] [INFO] [log_test.go:167] ["info message"] [conn=conn1] ["str key"=val] ["int key"=123] zapLogWithConnIDPattern = `\[\d\d\d\d/\d\d/\d\d \d\d:\d\d:\d\d.\d\d\d\ (\+|-)\d\d:\d\d\] \[(FATAL|ERROR|WARN|INFO|DEBUG)\] \[([\w_%!$@.,+~-]+|\\.)+:\d+\] \[.*\] \[conn=.*\] (\[.*=.*\]).*\n` - // [2019/02/13 15:56:05.385 +08:00] [INFO] [log_test.go:167] ["info message"] ["str key"=val] ["int key"=123] + // [2019/02/13 15:56:05.385 +08:00] [INFO] [log_test.go:167] ["info message"] [ctxKey=ctxKey1] ["str key"=val] ["int key"=123] zapLogWithKeyValPattern = `\[\d\d\d\d/\d\d/\d\d \d\d:\d\d:\d\d.\d\d\d\ (\+|-)\d\d:\d\d\] \[(FATAL|ERROR|WARN|INFO|DEBUG)\] \[([\w_%!$@.,+~-]+|\\.)+:\d+\] \[.*\] \[ctxKey=.*\] (\[.*=.*\]).*\n` ) @@ -53,156 +48,14 @@ type testLogSuite struct { buf *bytes.Buffer } -func (s *testLogSuite) SetUpSuite(c *C) { +func (s *testLogSuite) SetUpSuite(_ *C) { s.buf = &bytes.Buffer{} } -func (s *testLogSuite) SetUpTest(c *C) { +func (s *testLogSuite) SetUpTest(_ *C) { s.buf = &bytes.Buffer{} } -func (s *testLogSuite) TestStringToLogLevel(c *C) { - c.Assert(stringToLogLevel("fatal"), Equals, log.FatalLevel) - c.Assert(stringToLogLevel("ERROR"), Equals, log.ErrorLevel) - c.Assert(stringToLogLevel("warn"), Equals, log.WarnLevel) - c.Assert(stringToLogLevel("warning"), Equals, log.WarnLevel) - c.Assert(stringToLogLevel("debug"), Equals, log.DebugLevel) - c.Assert(stringToLogLevel("info"), Equals, log.InfoLevel) - c.Assert(stringToLogLevel("whatever"), Equals, log.InfoLevel) -} - -// TestLogging assure log format and log redirection works. -func (s *testLogSuite) TestLogging(c *C) { - conf := NewLogConfig("warn", DefaultLogFormat, "", NewFileLogConfig(0), false) - conf.File.Filename = "log_file" - c.Assert(InitLogger(conf), IsNil) - - log.SetOutput(s.buf) - - log.Infof("[this message should not be sent to buf]") - c.Assert(s.buf.Len(), Equals, 0) - - log.Warningf("[this message should be sent to buf]") - entry, err := s.buf.ReadString('\n') - c.Assert(err, IsNil) - c.Assert(entry, Matches, logPattern) - - log.Warnf("this message comes from logrus") - entry, err = s.buf.ReadString('\n') - c.Assert(err, IsNil) - c.Assert(entry, Matches, logPattern) - c.Assert(strings.Contains(entry, "log_test.go"), IsTrue) -} - -func (s *testLogSuite) TestSlowQueryLogger(c *C) { - fileName := "slow_query" - os.Remove(fileName) - conf := NewLogConfig("info", DefaultLogFormat, fileName, NewFileLogConfig(DefaultLogMaxSize), false) - c.Assert(conf.File.MaxSize, Equals, DefaultLogMaxSize) - err := InitLogger(conf) - c.Assert(err, IsNil) - defer os.Remove(fileName) - - SlowQueryLogger.Debug("debug message") - SlowQueryLogger.Info("info message") - SlowQueryLogger.Warn("warn message") - SlowQueryLogger.Error("error message") - c.Assert(s.buf.Len(), Equals, 0) - - f, err := os.Open(fileName) - c.Assert(err, IsNil) - defer f.Close() - - r := bufio.NewReader(f) - for { - var str string - str, err = r.ReadString('\n') - if err != nil { - break - } - if strings.HasPrefix(str, "# ") { - c.Assert(str, Matches, `# Time: .*?\n`) - } else { - c.Assert(str, Matches, `.*? message\n`) - } - } - c.Assert(err, Equals, io.EOF) -} - -func (s *testLogSuite) TestLoggerKeepOrder(c *C) { - conf := NewLogConfig("warn", DefaultLogFormat, "", EmptyFileLogConfig, true) - c.Assert(InitLogger(conf), IsNil) - logger := log.StandardLogger() - ft, ok := logger.Formatter.(*textFormatter) - c.Assert(ok, IsTrue) - ft.EnableEntryOrder = true - logger.Out = s.buf - logEntry := log.NewEntry(logger) - logEntry.Data = log.Fields{ - "connectionId": 1, - "costTime": "1", - "database": "test", - "sql": "select 1", - "txnStartTS": 1, - } - - _, _, line, _ := runtime.Caller(0) - logEntry.WithField("type", "slow-query").WithField("succ", true).Warnf("slow-query") - expectMsg := fmt.Sprintf("log_test.go:%v: [warning] slow-query connectionId=1 costTime=1 database=test sql=select 1 succ=true txnStartTS=1 type=slow-query\n", line+1) - c.Assert(s.buf.String(), Equals, expectMsg) - - s.buf.Reset() - logEntry.Data = log.Fields{ - "a": "a", - "d": "d", - "e": "e", - "b": "b", - "f": "f", - "c": "c", - } - - _, _, line, _ = runtime.Caller(0) - logEntry.Warnf("slow-query") - expectMsg = fmt.Sprintf("log_test.go:%v: [warning] slow-query a=a b=b c=c d=d e=e f=f\n", line+1) - c.Assert(s.buf.String(), Equals, expectMsg) -} - -func (s *testLogSuite) TestSlowQueryZapLogger(c *C) { - if runtime.GOOS == "windows" { - // Skip this test on windows for two reasons: - // 1. The pattern match fails somehow. It seems windows treat \n as slash and character n. - // 2. Remove file doesn't work as long as the log instance hold the file. - c.Skip("skip on windows") - } - - fileName := "slow_query" - conf := NewLogConfig("info", DefaultLogFormat, fileName, EmptyFileLogConfig, false) - err := InitZapLogger(conf) - c.Assert(err, IsNil) - defer os.Remove(fileName) - - SlowQueryZapLogger.Debug("debug message", zap.String("str key", "val")) - 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)) - - f, err := os.Open(fileName) - c.Assert(err, IsNil) - defer f.Close() - - r := bufio.NewReader(f) - for { - var str string - str, err = r.ReadString('\n') - if err != nil { - break - } - c.Assert(str, Matches, zapLogPattern) - } - c.Assert(err, Equals, io.EOF) - -} - func (s *testLogSuite) TestZapLoggerWithKeys(c *C) { if runtime.GOOS == "windows" { // Skip this test on windows for two reason: @@ -211,7 +64,7 @@ func (s *testLogSuite) TestZapLoggerWithKeys(c *C) { c.Skip("skip on windows") } - fileCfg := FileLogConfig{zaplog.FileLogConfig{Filename: "zap_log", MaxSize: 4096}} + fileCfg := FileLogConfig{log.FileLogConfig{Filename: "zap_log", MaxSize: 4096}} conf := NewLogConfig("info", DefaultLogFormat, "", fileCfg, false) err := InitZapLogger(conf) c.Assert(err, IsNil) @@ -258,14 +111,14 @@ func (s *testLogSuite) TestSetLevel(c *C) { err := InitZapLogger(conf) c.Assert(err, IsNil) - c.Assert(zaplog.GetLevel(), Equals, zap.InfoLevel) + c.Assert(log.GetLevel(), Equals, zap.InfoLevel) err = SetLevel("warn") c.Assert(err, IsNil) - c.Assert(zaplog.GetLevel(), Equals, zap.WarnLevel) + c.Assert(log.GetLevel(), Equals, zap.WarnLevel) err = SetLevel("Error") c.Assert(err, IsNil) - c.Assert(zaplog.GetLevel(), Equals, zap.ErrorLevel) + c.Assert(log.GetLevel(), Equals, zap.ErrorLevel) err = SetLevel("DEBUG") c.Assert(err, IsNil) - c.Assert(zaplog.GetLevel(), Equals, zap.DebugLevel) + c.Assert(log.GetLevel(), Equals, zap.DebugLevel) } diff --git a/util/logutil/slow_query_logger.go b/util/logutil/slow_query_logger.go new file mode 100644 index 0000000000000..3910b6ecd1192 --- /dev/null +++ b/util/logutil/slow_query_logger.go @@ -0,0 +1,76 @@ +package logutil + +import ( + "fmt" + "time" + + "github.com/pingcap/errors" + "github.com/pingcap/log" + "go.uber.org/zap" + "go.uber.org/zap/buffer" + "go.uber.org/zap/zapcore" +) + +var _pool = buffer.NewPool() + +func newSlowQueryLogger(cfg *LogConfig) (*zap.Logger, error) { + + // reuse global config and override slow query log file + // if slow query log filename is empty, slow query log will behave the same as global log + sqConfig := &cfg.Config + if len(cfg.SlowQueryFile) != 0 { + sqConfig.File = log.FileLogConfig{ + MaxSize: cfg.File.MaxSize, + Filename: cfg.SlowQueryFile, + } + } + + // create the slow query logger + sqLogger, prop, err := log.InitLogger(sqConfig) + if err != nil { + return nil, errors.Trace(err) + } + + // replace 2018-12-19-unified-log-format text encoder with slow log encoder + sqLogger = sqLogger.WithOptions(zap.WrapCore(func(core zapcore.Core) zapcore.Core { + return log.NewTextCore(&slowLogEncoder{}, prop.Syncer, prop.Level) + })) + + return sqLogger, nil +} + +type slowLogEncoder struct{} + +func (e *slowLogEncoder) EncodeEntry(entry zapcore.Entry, _ []zapcore.Field) (*buffer.Buffer, error) { + b := _pool.Get() + fmt.Fprintf(b, "# Time: %s\n", entry.Time.Format(SlowLogTimeFormat)) + fmt.Fprintf(b, "%s\n", entry.Message) + return b, nil +} + +func (e *slowLogEncoder) Clone() zapcore.Encoder { return e } +func (e *slowLogEncoder) AddArray(string, zapcore.ArrayMarshaler) error { return nil } +func (e *slowLogEncoder) AddObject(string, zapcore.ObjectMarshaler) error { return nil } +func (e *slowLogEncoder) AddBinary(string, []byte) {} +func (e *slowLogEncoder) AddByteString(string, []byte) {} +func (e *slowLogEncoder) AddBool(string, bool) {} +func (e *slowLogEncoder) AddComplex128(string, complex128) {} +func (e *slowLogEncoder) AddComplex64(string, complex64) {} +func (e *slowLogEncoder) AddDuration(string, time.Duration) {} +func (e *slowLogEncoder) AddFloat64(string, float64) {} +func (e *slowLogEncoder) AddFloat32(string, float32) {} +func (e *slowLogEncoder) AddInt(string, int) {} +func (e *slowLogEncoder) AddInt64(string, int64) {} +func (e *slowLogEncoder) AddInt32(string, int32) {} +func (e *slowLogEncoder) AddInt16(string, int16) {} +func (e *slowLogEncoder) AddInt8(string, int8) {} +func (e *slowLogEncoder) AddString(string, string) {} +func (e *slowLogEncoder) AddTime(string, time.Time) {} +func (e *slowLogEncoder) AddUint(string, uint) {} +func (e *slowLogEncoder) AddUint64(string, uint64) {} +func (e *slowLogEncoder) AddUint32(string, uint32) {} +func (e *slowLogEncoder) AddUint16(string, uint16) {} +func (e *slowLogEncoder) AddUint8(string, uint8) {} +func (e *slowLogEncoder) AddUintptr(string, uintptr) {} +func (e *slowLogEncoder) AddReflected(string, interface{}) error { return nil } +func (e *slowLogEncoder) OpenNamespace(string) {}