Repository: tikv/pd (go)

Issue:
log: requesting log desensitization
## Development Task

To reinforce the security in the PD, one thing we need to do is to do the log desensitization.  
Here are some examples we need to hide from the logs in my view:

1. region key in logs like following:
```golang
log.Error("wrong range keys",zap.String("start-key", string(HexRegionKey(startKey))),zap.String("end-key", string(HexRegionKey(endKey))))
```

2.  etcd key and value in logs like following:
```golang
log.Warn("kv gets too slow", zap.String("request-key", key), zap.Duration("cost", cost), zap.Error(err))
```

3. store label key and value in logs like following:
```golang
log.Warn("not found the key match with the store label",zap.Stringer("store", s.GetMeta()),zap.String("label-key", key))
```

4. placement rule key and value in logs like following:
```golang
log.Error("rule is in bad format", zap.String("rule-key", k), zap.String("rule-value", v), zap.Error(errs.ErrLoadRule.FastGenByArgs()), zap.NamedError("cause", err))
```

We will add a new configuration like "enable-log-desensitization"(default false). If this configuration is enabled, the sensitive information won't appear on the previous log.

Pull request:
logutil, *: implement log desensitization  (#3011)
cherry-pick #3011 to release-4.0

---

<!--
Thank you for working on PD! Please read PD's [CONTRIBUTING](https://github.com/tikv/pd/blob/master/CONTRIBUTING.md) document **BEFORE** filing this PR.
PR Title Format:
1. pkg [, pkg2, pkg3]: what's changed
2. *: what's changed
-->

### What problem does this PR solve?
close #2852 

Implement log desensitization to omit the region key information from the log.

<!-- Add the issue link with a summary if it exists. -->

### What is changed and how it works?

### Check List

<!-- Remove the items that are not applicable. -->

Tests

<!-- At least one of them must be included. -->

- Unit test

Code changes

- Has configuration change


Related changes

- PR to update [`pingcap/docs`](https://github.com/pingcap/docs)/[`pingcap/docs-cn`](https://github.com/pingcap/docs-cn):


### Release note

<!-- A bugfix or a new feature needs a release note. If there is no need release note, just uncomment the below line. -->

<!-- - No release note -->

- Support configuration `enable-redact-log` to enable log desensitization or not.

Patch:
diff --git a/pkg/logutil/log.go b/pkg/logutil/log.go
index 64d26a1de..6de4ddf4a 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/server/cluster/cluster.go b/server/cluster/cluster.go
index ec9ff2f4f..36c749cef 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 82e4dd0a3..c3ae70c74 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 908648570..06ff63778 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/core/region_tree.go b/server/core/region_tree.go
index f8d179ee7..f3abef95c 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(&regionItem{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 22b5a0f6c..22691f7e6 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 9869464f9..c2a333943 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))


Test patch:
diff --git a/pkg/logutil/log_test.go b/pkg/logutil/log_test.go
index 205333c5b..ff8c29c4a 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/config/config_test.go b/server/config/config_test.go
index 07d1b814c..2984693e9 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 = `