From c1cc79a9e0b131c1b4b996a1d0edb95c03beb1a2 Mon Sep 17 00:00:00 2001 From: yifan Date: Tue, 15 Jun 2021 21:39:20 +0800 Subject: [PATCH 1/9] remove useless grpc log --- util/logutil/log.go | 31 +++++++++++++++++++++++++------ 1 file changed, 25 insertions(+), 6 deletions(-) diff --git a/util/logutil/log.go b/util/logutil/log.go index 6ccb146ff26ab..58e8e2c475548 100644 --- a/util/logutil/log.go +++ b/util/logutil/log.go @@ -42,8 +42,6 @@ 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. @@ -111,12 +109,33 @@ func InitLogger(cfg *LogConfig) error { return errors.Trace(err) } - // init logger for grpc debugging + err = initGRPCLogger(cfg) + if err != nil { + return errors.Trace(err) + } + + return nil +} + +func initGRPCLogger(cfg *LogConfig) error { + + config := &cfg.Config + // hack: force stdout + config.File.Filename = "" if len(os.Getenv("GRPC_DEBUG")) > 0 { - // more information for verbosity: https://github.com/google/glog#verbose-logging - gzap.ReplaceGrpcLoggerV2WithVerbosity(gl, GRPCLogDebugVerbosity) + config.Level = "debug" + l, _, err := log.InitLogger(&cfg.Config, zap.AddStacktrace(zapcore.DebugLevel)) + if err != nil { + return errors.Trace(err) + } + gzap.ReplaceGrpcLoggerV2WithVerbosity(l, 999) } else { - gzap.ReplaceGrpcLoggerV2(gl) + config.Level = "error" + l, _, err := log.InitLogger(&cfg.Config, zap.AddStacktrace(zapcore.FatalLevel)) + if err != nil { + return errors.Trace(err) + } + gzap.ReplaceGrpcLoggerV2(l) } return nil From 6c76acca26043525d58ca5370e5f7a066e949a1b Mon Sep 17 00:00:00 2001 From: yifan Date: Tue, 15 Jun 2021 22:15:34 +0800 Subject: [PATCH 2/9] use deepcopy to make init more safer --- util/logutil/log.go | 25 ++++++++++++++++++++++++- util/logutil/slow_query_logger.go | 2 +- 2 files changed, 25 insertions(+), 2 deletions(-) diff --git a/util/logutil/log.go b/util/logutil/log.go index 58e8e2c475548..1a7b41ade9208 100644 --- a/util/logutil/log.go +++ b/util/logutil/log.go @@ -119,7 +119,7 @@ func InitLogger(cfg *LogConfig) error { func initGRPCLogger(cfg *LogConfig) error { - config := &cfg.Config + config := deepcopyLogConfig(&cfg.Config) // hack: force stdout config.File.Filename = "" if len(os.Getenv("GRPC_DEBUG")) > 0 { @@ -141,6 +141,29 @@ func initGRPCLogger(cfg *LogConfig) error { return nil } +func deepcopyLogConfig(o *log.Config) *log.Config { + return &log.Config{ + Level: o.Level, + Format: o.Format, + DisableTimestamp: o.DisableTimestamp, + File: log.FileLogConfig{ + Filename: o.File.Filename, + MaxSize: o.File.MaxSize, + MaxDays: o.File.MaxDays, + MaxBackups: o.File.MaxBackups, + }, + Development: o.Development, + DisableCaller: o.DisableCaller, + DisableStacktrace: o.DisableStacktrace, + DisableErrorVerbose: o.DisableErrorVerbose, + Sampling: &zap.SamplingConfig{ + Initial: o.Sampling.Initial, + Thereafter: o.Sampling.Thereafter, + Hook: o.Sampling.Hook, + }, + } +} + // InitZapLogger is delegated to InitLogger. // Deprecated: prefer InitLogger func InitZapLogger(cfg *LogConfig) error { diff --git a/util/logutil/slow_query_logger.go b/util/logutil/slow_query_logger.go index 3910b6ecd1192..0a2814a472c50 100644 --- a/util/logutil/slow_query_logger.go +++ b/util/logutil/slow_query_logger.go @@ -17,7 +17,7 @@ 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 + sqConfig := deepcopyLogConfig(&cfg.Config) if len(cfg.SlowQueryFile) != 0 { sqConfig.File = log.FileLogConfig{ MaxSize: cfg.File.MaxSize, From 6062f296034aba72bdcf29ba55812d025d6faeeb Mon Sep 17 00:00:00 2001 From: yifan Date: Tue, 15 Jun 2021 22:31:58 +0800 Subject: [PATCH 3/9] fix null pointer --- util/logutil/log.go | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/util/logutil/log.go b/util/logutil/log.go index 1a7b41ade9208..d99227e364e77 100644 --- a/util/logutil/log.go +++ b/util/logutil/log.go @@ -142,7 +142,7 @@ func initGRPCLogger(cfg *LogConfig) error { } func deepcopyLogConfig(o *log.Config) *log.Config { - return &log.Config{ + c := &log.Config{ Level: o.Level, Format: o.Format, DisableTimestamp: o.DisableTimestamp, @@ -156,12 +156,15 @@ func deepcopyLogConfig(o *log.Config) *log.Config { DisableCaller: o.DisableCaller, DisableStacktrace: o.DisableStacktrace, DisableErrorVerbose: o.DisableErrorVerbose, - Sampling: &zap.SamplingConfig{ + } + if o.Sampling != nil { + c.Sampling = &zap.SamplingConfig{ Initial: o.Sampling.Initial, Thereafter: o.Sampling.Thereafter, Hook: o.Sampling.Hook, - }, + } } + return c } // InitZapLogger is delegated to InitLogger. From af74b3db5569e3c52bdea7a8ee8d87d741b5b9a8 Mon Sep 17 00:00:00 2001 From: yifan Date: Wed, 16 Jun 2021 17:34:51 +0800 Subject: [PATCH 4/9] fix config copy --- util/logutil/log.go | 30 ++---------------------------- util/logutil/slow_query_logger.go | 6 +++--- 2 files changed, 5 insertions(+), 31 deletions(-) diff --git a/util/logutil/log.go b/util/logutil/log.go index d99227e364e77..7ac0233c0abca 100644 --- a/util/logutil/log.go +++ b/util/logutil/log.go @@ -118,8 +118,8 @@ func InitLogger(cfg *LogConfig) error { } func initGRPCLogger(cfg *LogConfig) error { - - config := deepcopyLogConfig(&cfg.Config) + // copy Config struct by assignment + config := cfg.Config // hack: force stdout config.File.Filename = "" if len(os.Getenv("GRPC_DEBUG")) > 0 { @@ -141,32 +141,6 @@ func initGRPCLogger(cfg *LogConfig) error { return nil } -func deepcopyLogConfig(o *log.Config) *log.Config { - c := &log.Config{ - Level: o.Level, - Format: o.Format, - DisableTimestamp: o.DisableTimestamp, - File: log.FileLogConfig{ - Filename: o.File.Filename, - MaxSize: o.File.MaxSize, - MaxDays: o.File.MaxDays, - MaxBackups: o.File.MaxBackups, - }, - Development: o.Development, - DisableCaller: o.DisableCaller, - DisableStacktrace: o.DisableStacktrace, - DisableErrorVerbose: o.DisableErrorVerbose, - } - if o.Sampling != nil { - c.Sampling = &zap.SamplingConfig{ - Initial: o.Sampling.Initial, - Thereafter: o.Sampling.Thereafter, - Hook: o.Sampling.Hook, - } - } - return c -} - // InitZapLogger is delegated to InitLogger. // Deprecated: prefer InitLogger func InitZapLogger(cfg *LogConfig) error { diff --git a/util/logutil/slow_query_logger.go b/util/logutil/slow_query_logger.go index 0a2814a472c50..6faa394024c7f 100644 --- a/util/logutil/slow_query_logger.go +++ b/util/logutil/slow_query_logger.go @@ -15,9 +15,9 @@ var _pool = buffer.NewPool() func newSlowQueryLogger(cfg *LogConfig) (*zap.Logger, error) { - // reuse global config and override slow query log file + // copy 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 := deepcopyLogConfig(&cfg.Config) + sqConfig := cfg.Config if len(cfg.SlowQueryFile) != 0 { sqConfig.File = log.FileLogConfig{ MaxSize: cfg.File.MaxSize, @@ -26,7 +26,7 @@ func newSlowQueryLogger(cfg *LogConfig) (*zap.Logger, error) { } // create the slow query logger - sqLogger, prop, err := log.InitLogger(sqConfig) + sqLogger, prop, err := log.InitLogger(&sqConfig) if err != nil { return nil, errors.Trace(err) } From 66e4c6c499a37adab6c7fd03e2a4a0caec9606ac Mon Sep 17 00:00:00 2001 From: yifan Date: Wed, 16 Jun 2021 21:00:48 +0800 Subject: [PATCH 5/9] add unit test --- util/logutil/log.go | 19 +++++++++++-------- util/logutil/log_test.go | 25 +++++++++++++++++++++++++ util/logutil/slow_query_logger.go | 10 ++++++---- 3 files changed, 42 insertions(+), 12 deletions(-) diff --git a/util/logutil/log.go b/util/logutil/log.go index 7ac0233c0abca..31502fd40ae78 100644 --- a/util/logutil/log.go +++ b/util/logutil/log.go @@ -104,12 +104,12 @@ func InitLogger(cfg *LogConfig) error { log.ReplaceGlobals(gl, props) // init dedicated logger for slow query log - SlowQueryLogger, err = newSlowQueryLogger(cfg) + SlowQueryLogger, _, err = newSlowQueryLogger(cfg) if err != nil { return errors.Trace(err) } - err = initGRPCLogger(cfg) + _, _, err = initGRPCLogger(cfg) if err != nil { return errors.Trace(err) } @@ -117,28 +117,31 @@ func InitLogger(cfg *LogConfig) error { return nil } -func initGRPCLogger(cfg *LogConfig) error { +func initGRPCLogger(cfg *LogConfig) (*zap.Logger, *log.ZapProperties, error) { // copy Config struct by assignment config := cfg.Config // hack: force stdout config.File.Filename = "" + var l *zap.Logger + var err error + var prop *log.ZapProperties if len(os.Getenv("GRPC_DEBUG")) > 0 { config.Level = "debug" - l, _, err := log.InitLogger(&cfg.Config, zap.AddStacktrace(zapcore.DebugLevel)) + l, prop, err = log.InitLogger(&config, zap.AddStacktrace(zapcore.FatalLevel)) if err != nil { - return errors.Trace(err) + return nil, nil, errors.Trace(err) } gzap.ReplaceGrpcLoggerV2WithVerbosity(l, 999) } else { config.Level = "error" - l, _, err := log.InitLogger(&cfg.Config, zap.AddStacktrace(zapcore.FatalLevel)) + l, prop, err = log.InitLogger(&config, zap.AddStacktrace(zapcore.FatalLevel)) if err != nil { - return errors.Trace(err) + return nil, nil, errors.Trace(err) } gzap.ReplaceGrpcLoggerV2(l) } - return nil + return l, prop, nil } // InitZapLogger is delegated to InitLogger. diff --git a/util/logutil/log_test.go b/util/logutil/log_test.go index 5733fb7259be5..a63d5353a4408 100644 --- a/util/logutil/log_test.go +++ b/util/logutil/log_test.go @@ -122,3 +122,28 @@ func (s *testLogSuite) TestSetLevel(c *C) { c.Assert(err, IsNil) c.Assert(log.GetLevel(), Equals, zap.DebugLevel) } + +func (s *testLogSuite) TestGrpcLoggerCreation(c *C) { + conf := NewLogConfig("info", DefaultLogFormat, "", EmptyFileLogConfig, false) + copiedConfig := *conf + // assert that the new conf's address not same as the old one + c.Assert(&copiedConfig != conf, Equals, true) + _, p, err := initGRPCLogger(conf) + c.Assert(err, IsNil) + c.Assert(p.Level.Level(), Equals, zap.ErrorLevel) + os.Setenv("GRPC_DEBUG", "1") + defer os.Unsetenv("GRPC_DEBUG") + _, newP, err := initGRPCLogger(conf) + c.Assert(err, IsNil) + c.Assert(newP.Level.Level(), Equals, zap.DebugLevel) +} + +func (s *testLogSuite) TestSlowQueryLoggerCreation(c *C) { + conf := NewLogConfig("warn", DefaultLogFormat, "", EmptyFileLogConfig, false) + copiedConfig := *conf + // assert that the new conf's address not same as the old one + c.Assert(&copiedConfig != conf, Equals, true) + _, prop, err := newSlowQueryLogger(conf) + c.Assert(err, IsNil) + c.Assert(prop.Level.String(), Equals, conf.Level) +} diff --git a/util/logutil/slow_query_logger.go b/util/logutil/slow_query_logger.go index 6faa394024c7f..433fd5746eca7 100644 --- a/util/logutil/slow_query_logger.go +++ b/util/logutil/slow_query_logger.go @@ -13,7 +13,7 @@ import ( var _pool = buffer.NewPool() -func newSlowQueryLogger(cfg *LogConfig) (*zap.Logger, error) { +func newSlowQueryLogger(cfg *LogConfig) (*zap.Logger, *log.ZapProperties, error) { // copy 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 @@ -28,15 +28,17 @@ func newSlowQueryLogger(cfg *LogConfig) (*zap.Logger, error) { // create the slow query logger sqLogger, prop, err := log.InitLogger(&sqConfig) if err != nil { - return nil, errors.Trace(err) + return nil, nil, errors.Trace(err) } // replace 2018-12-19-unified-log-format text encoder with slow log encoder + newCore := log.NewTextCore(&slowLogEncoder{}, prop.Syncer, prop.Level) sqLogger = sqLogger.WithOptions(zap.WrapCore(func(core zapcore.Core) zapcore.Core { - return log.NewTextCore(&slowLogEncoder{}, prop.Syncer, prop.Level) + return newCore })) + prop.Core = newCore - return sqLogger, nil + return sqLogger, prop, nil } type slowLogEncoder struct{} From ac14a4e18a19a58357665d42a08bfcb3b9350d8f Mon Sep 17 00:00:00 2001 From: yifan Date: Thu, 17 Jun 2021 12:52:49 +0800 Subject: [PATCH 6/9] grpc log follows global log output --- util/logutil/log.go | 2 -- 1 file changed, 2 deletions(-) diff --git a/util/logutil/log.go b/util/logutil/log.go index 31502fd40ae78..f5c35a4da876c 100644 --- a/util/logutil/log.go +++ b/util/logutil/log.go @@ -120,8 +120,6 @@ func InitLogger(cfg *LogConfig) error { func initGRPCLogger(cfg *LogConfig) (*zap.Logger, *log.ZapProperties, error) { // copy Config struct by assignment config := cfg.Config - // hack: force stdout - config.File.Filename = "" var l *zap.Logger var err error var prop *log.ZapProperties From fcf78d1456a2c19ec1dde350b6de2d96039b6278 Mon Sep 17 00:00:00 2001 From: yifan Date: Thu, 17 Jun 2021 13:45:37 +0800 Subject: [PATCH 7/9] assert after init a logger, the original conf is not changed --- util/logutil/log_test.go | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/util/logutil/log_test.go b/util/logutil/log_test.go index a63d5353a4408..4c87c70c7fa54 100644 --- a/util/logutil/log_test.go +++ b/util/logutil/log_test.go @@ -124,11 +124,14 @@ func (s *testLogSuite) TestSetLevel(c *C) { } func (s *testLogSuite) TestGrpcLoggerCreation(c *C) { - conf := NewLogConfig("info", DefaultLogFormat, "", EmptyFileLogConfig, false) + level := "info" + conf := NewLogConfig(level, DefaultLogFormat, "", EmptyFileLogConfig, false) copiedConfig := *conf // assert that the new conf's address not same as the old one c.Assert(&copiedConfig != conf, Equals, true) _, p, err := initGRPCLogger(conf) + // assert after init grpc logger, the original conf is not changed + c.Assert(conf.Level, Equals, level) c.Assert(err, IsNil) c.Assert(p.Level.Level(), Equals, zap.ErrorLevel) os.Setenv("GRPC_DEBUG", "1") @@ -139,11 +142,14 @@ func (s *testLogSuite) TestGrpcLoggerCreation(c *C) { } func (s *testLogSuite) TestSlowQueryLoggerCreation(c *C) { - conf := NewLogConfig("warn", DefaultLogFormat, "", EmptyFileLogConfig, false) + level := "warn" + conf := NewLogConfig(level, DefaultLogFormat, "", EmptyFileLogConfig, false) copiedConfig := *conf // assert that the new conf's address not same as the old one c.Assert(&copiedConfig != conf, Equals, true) _, prop, err := newSlowQueryLogger(conf) + // assert after init slow query logger, the original conf is not changed + c.Assert(conf.Level, Equals, level) c.Assert(err, IsNil) c.Assert(prop.Level.String(), Equals, conf.Level) } From ea31a5165d3a04762eff44d7be6896c9571aedb7 Mon Sep 17 00:00:00 2001 From: yifan Date: Fri, 13 Aug 2021 13:28:36 +0800 Subject: [PATCH 8/9] migrate test framework to testify --- util/logutil/log_test.go | 26 ++++++++++---------------- 1 file changed, 10 insertions(+), 16 deletions(-) diff --git a/util/logutil/log_test.go b/util/logutil/log_test.go index cbfa6e1c15fae..4c5232c50cd1f 100644 --- a/util/logutil/log_test.go +++ b/util/logutil/log_test.go @@ -98,33 +98,27 @@ func TestSetLevel(t *testing.T) { require.Equal(t, zap.DebugLevel, log.GetLevel()) } -func (s *testLogSuite) TestGrpcLoggerCreation(c *C) { +func TestGrpcLoggerCreation(t *testing.T) { level := "info" conf := NewLogConfig(level, DefaultLogFormat, "", EmptyFileLogConfig, false) - copiedConfig := *conf - // assert that the new conf's address not same as the old one - c.Assert(&copiedConfig != conf, Equals, true) _, p, err := initGRPCLogger(conf) // assert after init grpc logger, the original conf is not changed - c.Assert(conf.Level, Equals, level) - c.Assert(err, IsNil) - c.Assert(p.Level.Level(), Equals, zap.ErrorLevel) + require.Equal(t, conf.Level, level) + require.Nil(t, err) + require.Equal(t, p.Level.Level(), zap.ErrorLevel) os.Setenv("GRPC_DEBUG", "1") defer os.Unsetenv("GRPC_DEBUG") _, newP, err := initGRPCLogger(conf) - c.Assert(err, IsNil) - c.Assert(newP.Level.Level(), Equals, zap.DebugLevel) + require.Nil(t, err) + require.Equal(t, newP.Level.Level(), zap.DebugLevel) } -func (s *testLogSuite) TestSlowQueryLoggerCreation(c *C) { +func TestSlowQueryLoggerCreation(t *testing.T) { level := "warn" conf := NewLogConfig(level, DefaultLogFormat, "", EmptyFileLogConfig, false) - copiedConfig := *conf - // assert that the new conf's address not same as the old one - c.Assert(&copiedConfig != conf, Equals, true) _, prop, err := newSlowQueryLogger(conf) // assert after init slow query logger, the original conf is not changed - c.Assert(conf.Level, Equals, level) - c.Assert(err, IsNil) - c.Assert(prop.Level.String(), Equals, conf.Level) + require.Equal(t, conf.Level, level) + require.Nil(t, err) + require.Equal(t, prop.Level.String(), conf.Level) } From 19660f4e3749ad062ad155e7c70b962d4495e6fd Mon Sep 17 00:00:00 2001 From: yifan Date: Fri, 13 Aug 2021 13:33:03 +0800 Subject: [PATCH 9/9] fix comments --- util/logutil/log.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/util/logutil/log.go b/util/logutil/log.go index 121b2e5cfef9c..66bee73e69fb3 100644 --- a/util/logutil/log.go +++ b/util/logutil/log.go @@ -118,7 +118,7 @@ func InitLogger(cfg *LogConfig) error { } func initGRPCLogger(cfg *LogConfig) (*zap.Logger, *log.ZapProperties, error) { - // copy Config struct by assignment + // Copy Config struct by assignment. config := cfg.Config var l *zap.Logger var err error