From 7b36ffc5b1c003e9a51749ca024bbdba57bd749d Mon Sep 17 00:00:00 2001 From: ti-srebot <66930949+ti-srebot@users.noreply.github.com> Date: Thu, 31 Dec 2020 14:02:46 +0800 Subject: [PATCH] logutil, *: implement log desensitization (#3011) (#3266) * cherry pick #3011 to release-4.0 Signed-off-by: ti-srebot * fix conflict Signed-off-by: Song Gao * fix conflict Signed-off-by: Song Gao Co-authored-by: Song Gao Co-authored-by: Ti Prow Robot <71242396+ti-community-prow-bot@users.noreply.github.com> --- pkg/logutil/log.go | 66 ++++++++++++++++++++++++ pkg/logutil/log_test.go | 53 +++++++++++++++++++ server/cluster/cluster.go | 9 ++-- server/cluster/cluster_worker.go | 16 ++++-- server/config/config.go | 9 ++++ server/config/config_test.go | 1 + server/core/region_tree.go | 10 ++-- server/replication/replication_mode.go | 9 +++- server/schedule/checker/merge_checker.go | 6 ++- 9 files changed, 162 insertions(+), 17 deletions(-) diff --git a/pkg/logutil/log.go b/pkg/logutil/log.go index 64d26a1de44..6de4ddf4ae8 100644 --- a/pkg/logutil/log.go +++ b/pkg/logutil/log.go @@ -21,6 +21,7 @@ import ( "runtime" "strings" "sync" + "sync/atomic" "github.com/coreos/pkg/capnslog" zaplog "github.com/pingcap/log" @@ -292,3 +293,68 @@ func LogPanic() { zaplog.Fatal("panic", zap.Reflect("recover", e)) } } + +var ( + enabledRedactLog atomic.Value +) + +func init() { + SetRedactLog(false) +} + +// IsRedactLogEnabled indicates whether the log desensitization is enabled +func IsRedactLogEnabled() bool { + return enabledRedactLog.Load().(bool) +} + +// SetRedactLog sets enabledRedactLog +func SetRedactLog(enabled bool) { + enabledRedactLog.Store(enabled) +} + +// ZapRedactByteString receives []byte argument and return omitted information zap.Field if redact log enabled +func ZapRedactByteString(key string, arg []byte) zap.Field { + return zap.ByteString(key, RedactBytes(arg)) +} + +// ZapRedactString receives string argument and return omitted information in zap.Field if redact log enabled +func ZapRedactString(key, arg string) zap.Field { + return zap.String(key, RedactString(arg)) +} + +// ZapRedactStringer receives stringer argument and return omitted information in zap.Field if redact log enabled +func ZapRedactStringer(key string, arg fmt.Stringer) zap.Field { + return zap.Stringer(key, RedactStringer(arg)) +} + +// RedactBytes receives []byte argument and return omitted information if redact log enabled +func RedactBytes(arg []byte) []byte { + if IsRedactLogEnabled() { + return []byte("?") + } + return arg +} + +// RedactString receives string argument and return omitted information if redact log enabled +func RedactString(arg string) string { + if IsRedactLogEnabled() { + return "?" + } + return arg +} + +// RedactStringer receives stringer argument and return omitted information if redact log enabled +func RedactStringer(arg fmt.Stringer) fmt.Stringer { + if IsRedactLogEnabled() { + return stringer{} + } + return arg +} + +type stringer struct { +} + +// String implement fmt.Stringer +func (s stringer) String() string { + return "?" +} diff --git a/pkg/logutil/log_test.go b/pkg/logutil/log_test.go index 205333c5b66..ff8c29c4aa4 100644 --- a/pkg/logutil/log_test.go +++ b/pkg/logutil/log_test.go @@ -15,6 +15,7 @@ package logutil import ( "bytes" + "fmt" "strings" "testing" @@ -109,3 +110,55 @@ func (s *testLogSuite) TestFileLog(c *C) { c.Assert(InitFileLog(&zaplog.FileLogConfig{Filename: "/tmp"}), NotNil) c.Assert(InitFileLog(&zaplog.FileLogConfig{Filename: "/tmp/test_file_log", MaxSize: 0}), IsNil) } + +func (s *testLogSuite) TestRedactLog(c *C) { + testcases := []struct { + name string + arg interface{} + enableRedactLog bool + expect interface{} + }{ + { + name: "string arg, enable redact", + arg: "foo", + enableRedactLog: true, + expect: "?", + }, + { + name: "string arg", + arg: "foo", + enableRedactLog: false, + expect: "foo", + }, + { + name: "[]byte arg, enable redact", + arg: []byte("foo"), + enableRedactLog: true, + expect: []byte("?"), + }, + { + name: "[]byte arg", + arg: []byte("foo"), + enableRedactLog: false, + expect: []byte("foo"), + }, + } + + for _, testcase := range testcases { + c.Log(testcase.name) + SetRedactLog(testcase.enableRedactLog) + switch testcase.arg.(type) { + case []byte: + r := RedactBytes(testcase.arg.([]byte)) + c.Assert(r, DeepEquals, testcase.expect) + case string: + r := RedactString(testcase.arg.(string)) + c.Assert(r, DeepEquals, testcase.expect) + case fmt.Stringer: + r := RedactStringer(testcase.arg.(fmt.Stringer)) + c.Assert(r, DeepEquals, testcase.expect) + default: + panic("unmatched case") + } + } +} diff --git a/server/cluster/cluster.go b/server/cluster/cluster.go index ec9ff2f4f67..36c749cef1e 100644 --- a/server/cluster/cluster.go +++ b/server/cluster/cluster.go @@ -532,8 +532,7 @@ func (c *RaftCluster) processRegionHeartbeat(region *core.RegionInfo) error { if origin == nil { log.Debug("insert new region", zap.Uint64("region-id", region.GetID()), - zap.Stringer("meta-region", core.RegionToHexMeta(region.GetMeta())), - ) + logutil.ZapRedactStringer("meta-region", core.RegionToHexMeta(region.GetMeta()))) saveKV, saveCache, isNew = true, true, true } else { r := region.GetRegionEpoch() @@ -541,7 +540,7 @@ func (c *RaftCluster) processRegionHeartbeat(region *core.RegionInfo) error { if r.GetVersion() > o.GetVersion() { log.Info("region Version changed", zap.Uint64("region-id", region.GetID()), - zap.String("detail", core.DiffRegionKeyInfo(origin, region)), + logutil.ZapRedactString("detail", core.DiffRegionKeyInfo(origin, region)), zap.Uint64("old-version", o.GetVersion()), zap.Uint64("new-version", r.GetVersion()), ) @@ -621,7 +620,7 @@ func (c *RaftCluster) processRegionHeartbeat(region *core.RegionInfo) error { if err := c.storage.DeleteRegion(item.GetMeta()); err != nil { log.Error("failed to delete region from storage", zap.Uint64("region-id", item.GetID()), - zap.Stringer("region-meta", core.RegionToHexMeta(item.GetMeta())), + logutil.ZapRedactStringer("region-meta", core.RegionToHexMeta(item.GetMeta())), errs.ZapError(err)) } } @@ -673,7 +672,7 @@ func (c *RaftCluster) processRegionHeartbeat(region *core.RegionInfo) error { // after restart. Here we only log the error then go on updating cache. log.Error("failed to save region to storage", zap.Uint64("region-id", region.GetID()), - zap.Stringer("region-meta", core.RegionToHexMeta(region.GetMeta())), + logutil.ZapRedactStringer("region-meta", core.RegionToHexMeta(region.GetMeta())), errs.ZapError(err)) } regionEventCounter.WithLabelValues("update_kv").Inc() diff --git a/server/cluster/cluster_worker.go b/server/cluster/cluster_worker.go index 82e4dd0a3a9..c3ae70c748b 100644 --- a/server/cluster/cluster_worker.go +++ b/server/cluster/cluster_worker.go @@ -22,6 +22,7 @@ import ( "github.com/pingcap/kvproto/pkg/pdpb" "github.com/pingcap/log" "github.com/tikv/pd/pkg/errs" + "github.com/tikv/pd/pkg/logutil" "github.com/tikv/pd/server/core" "github.com/tikv/pd/server/schedule" "go.uber.org/zap" @@ -33,6 +34,13 @@ func (c *RaftCluster) HandleRegionHeartbeat(region *core.RegionInfo) error { return err } + // If the region peer count is 0, then we should not handle this. + if len(region.GetPeers()) == 0 { + log.Warn("invalid region, zero region peer count", + logutil.ZapRedactStringer("region-meta", core.RegionToHexMeta(region.GetMeta()))) + return errors.Errorf("invalid region, zero region peer count: %v", logutil.RedactStringer(core.RegionToHexMeta(region.GetMeta()))) + } + c.RLock() co := c.coordinator c.RUnlock() @@ -80,7 +88,7 @@ func (c *RaftCluster) ValidRequestRegion(reqRegion *metapb.Region) error { startKey := reqRegion.GetStartKey() region := c.GetRegionByKey(startKey) if region == nil { - return errors.Errorf("region not found, request region: %v", core.RegionToHexMeta(reqRegion)) + return errors.Errorf("region not found, request region: %v", logutil.RedactStringer(core.RegionToHexMeta(reqRegion))) } // If the request epoch is less than current region epoch, then returns an error. reqRegionEpoch := reqRegion.GetRegionEpoch() @@ -183,8 +191,8 @@ func (c *RaftCluster) HandleReportSplit(request *pdpb.ReportSplitRequest) (*pdpb err := c.checkSplitRegion(left, right) if err != nil { log.Warn("report split region is invalid", - zap.Stringer("left-region", core.RegionToHexMeta(left)), - zap.Stringer("right-region", core.RegionToHexMeta(right)), + logutil.ZapRedactStringer("left-region", core.RegionToHexMeta(left)), + logutil.ZapRedactStringer("right-region", core.RegionToHexMeta(right)), errs.ZapError(err)) return nil, err } @@ -195,7 +203,7 @@ func (c *RaftCluster) HandleReportSplit(request *pdpb.ReportSplitRequest) (*pdpb originRegion.StartKey = left.GetStartKey() log.Info("region split, generate new region", zap.Uint64("region-id", originRegion.GetId()), - zap.Stringer("region-meta", core.RegionToHexMeta(left))) + logutil.ZapRedactStringer("region-meta", core.RegionToHexMeta(left))) return &pdpb.ReportSplitResponse{}, nil } diff --git a/server/config/config.go b/server/config/config.go index 908648570e2..06ff6377840 100644 --- a/server/config/config.go +++ b/server/config/config.go @@ -28,6 +28,7 @@ import ( "github.com/tikv/pd/pkg/errs" "github.com/tikv/pd/pkg/grpcutil" + "github.com/tikv/pd/pkg/logutil" "github.com/tikv/pd/pkg/metricutil" "github.com/tikv/pd/pkg/typeutil" "github.com/tikv/pd/server/schedule" @@ -142,6 +143,8 @@ type Config struct { Dashboard DashboardConfig `toml:"dashboard" json:"dashboard"` ReplicationMode ReplicationModeConfig `toml:"replication-mode" json:"replication-mode"` + // EnableRedactLog indicates that whether redact log, 0 is disable. 1 is enable. + EnableRedactLog bool `toml:"enable-redact-log" json:"enable-redact-log"` } // NewConfig creates a new config. @@ -218,6 +221,7 @@ const ( defaultDRWaitStoreTimeout = time.Minute defaultDRWaitSyncTimeout = time.Minute + defaultEnableRedactLog = false ) var ( @@ -536,6 +540,10 @@ func (c *Config) Adjust(meta *toml.MetaData) error { c.ReplicationMode.adjust(configMetaData.Child("replication-mode")) + if !configMetaData.IsDefined("enable-redact-log") { + c.EnableRedactLog = defaultEnableRedactLog + } + return nil } @@ -1073,6 +1081,7 @@ func (c *Config) SetupLogger() error { } c.logger = lg c.logProps = p + logutil.SetRedactLog(c.EnableRedactLog) return nil } diff --git a/server/config/config_test.go b/server/config/config_test.go index 07d1b814cb5..2984693e91b 100644 --- a/server/config/config_test.go +++ b/server/config/config_test.go @@ -160,6 +160,7 @@ leader-schedule-limit = 0 c.Assert(cfg.PreVote, IsTrue) c.Assert(cfg.Schedule.MaxMergeRegionKeys, Equals, uint64(defaultMaxMergeRegionKeys)) c.Assert(cfg.PDServerCfg.MetricStorage, Equals, "http://127.0.0.1:9090") + c.Assert(cfg.EnableRedactLog, Equals, defaultEnableRedactLog) // Check undefined config fields cfgData = ` diff --git a/server/core/region_tree.go b/server/core/region_tree.go index f8d179ee7d5..f3abef95c14 100644 --- a/server/core/region_tree.go +++ b/server/core/region_tree.go @@ -21,6 +21,7 @@ import ( "github.com/pingcap/log" "github.com/tikv/pd/pkg/btree" "github.com/tikv/pd/pkg/errs" + "github.com/tikv/pd/pkg/logutil" "go.uber.org/zap" ) @@ -95,8 +96,8 @@ func (t *regionTree) update(region *RegionInfo) []*RegionInfo { for _, item := range overlaps { log.Debug("overlapping region", zap.Uint64("region-id", item.GetID()), - zap.Stringer("delete-region", RegionToHexMeta(item.GetMeta())), - zap.Stringer("update-region", RegionToHexMeta(region.GetMeta()))) + logutil.ZapRedactStringer("delete-region", RegionToHexMeta(item.GetMeta())), + logutil.ZapRedactStringer("update-region", RegionToHexMeta(region.GetMeta()))) t.tree.Delete(®ionItem{item}) } @@ -229,8 +230,9 @@ func (t *regionTree) RandomRegion(ranges []KeyRange) *RegionInfo { if endIndex <= startIndex { if len(endKey) > 0 && bytes.Compare(startKey, endKey) > 0 { log.Error("wrong range keys", - zap.String("start-key", string(HexRegionKey(startKey))), - zap.String("end-key", string(HexRegionKey(endKey))), errs.ZapError(errs.ErrWrongRangeKeys)) + logutil.ZapRedactString("start-key", string(HexRegionKey(startKey))), + logutil.ZapRedactString("end-key", string(HexRegionKey(endKey))), + errs.ZapError(errs.ErrWrongRangeKeys)) } continue } diff --git a/server/replication/replication_mode.go b/server/replication/replication_mode.go index 22b5a0f6ccf..22691f7e62e 100644 --- a/server/replication/replication_mode.go +++ b/server/replication/replication_mode.go @@ -24,6 +24,7 @@ import ( pb "github.com/pingcap/kvproto/pkg/replication_modepb" "github.com/pingcap/log" "github.com/tikv/pd/pkg/errs" + "github.com/tikv/pd/pkg/logutil" "github.com/tikv/pd/server/config" "github.com/tikv/pd/server/core" "github.com/tikv/pd/server/schedule/opt" @@ -389,7 +390,8 @@ func (m *ModeManager) updateProgress() { for len(m.drRecoverKey) > 0 || m.drRecoverCount == 0 { regions := m.cluster.ScanRegions(m.drRecoverKey, nil, regionScanBatchSize) if len(regions) == 0 { - log.Warn("scan empty regions", zap.ByteString("recover-key", m.drRecoverKey)) + log.Warn("scan empty regions", + logutil.ZapRedactByteString("recover-key", m.drRecoverKey)) return } for i, r := range regions { @@ -440,7 +442,10 @@ func (m *ModeManager) estimateProgress() float32 { func (m *ModeManager) checkRegionRecover(region *core.RegionInfo, startKey []byte) bool { if !bytes.Equal(startKey, region.GetStartKey()) { - log.Warn("found region gap", zap.ByteString("key", startKey), zap.ByteString("region-start-key", region.GetStartKey()), zap.Uint64("region-id", region.GetID())) + log.Warn("found region gap", + logutil.ZapRedactByteString("key", startKey), + logutil.ZapRedactByteString("region-start-key", region.GetStartKey()), + zap.Uint64("region-id", region.GetID())) return false } return region.GetReplicationStatus().GetStateId() == m.drAutoSync.StateID && diff --git a/server/schedule/checker/merge_checker.go b/server/schedule/checker/merge_checker.go index 9869464f93d..c2a33394348 100644 --- a/server/schedule/checker/merge_checker.go +++ b/server/schedule/checker/merge_checker.go @@ -22,11 +22,11 @@ import ( "github.com/tikv/pd/pkg/cache" "github.com/tikv/pd/pkg/codec" "github.com/tikv/pd/pkg/errs" + "github.com/tikv/pd/pkg/logutil" "github.com/tikv/pd/server/core" "github.com/tikv/pd/server/schedule/operator" "github.com/tikv/pd/server/schedule/opt" "github.com/tikv/pd/server/schedule/placement" - "go.uber.org/zap" ) // MergeChecker ensures region to merge with adjacent region when size is small @@ -119,7 +119,9 @@ func (m *MergeChecker) Check(region *core.RegionInfo) []*operator.Operator { return nil } - log.Debug("try to merge region", zap.Stringer("from", core.RegionToHexMeta(region.GetMeta())), zap.Stringer("to", core.RegionToHexMeta(target.GetMeta()))) + log.Debug("try to merge region", + logutil.ZapRedactStringer("from", core.RegionToHexMeta(region.GetMeta())), + logutil.ZapRedactStringer("to", core.RegionToHexMeta(target.GetMeta()))) ops, err := operator.CreateMergeRegionOperator("merge-region", m.cluster, region, target, operator.OpMerge) if err != nil { log.Warn("create merge region operator failed", errs.ZapError(err))