From afa544e896d3c895394dd5e8e9a26fd4345011ac Mon Sep 17 00:00:00 2001 From: Chunzhu Li Date: Mon, 21 Dec 2020 19:47:30 +0800 Subject: [PATCH 1/5] label redact log --- lightning/backend/local.go | 11 +++++++++++ lightning/backend/localhelper.go | 5 +++++ lightning/backend/tidb.go | 1 + 3 files changed, 17 insertions(+) diff --git a/lightning/backend/local.go b/lightning/backend/local.go index 132d69058..fe121b613 100644 --- a/lightning/backend/local.go +++ b/lightning/backend/local.go @@ -517,6 +517,7 @@ func (local *local) WriteToTiKV( } if !iter.Valid() { + // TODO: REDACT log.L().Info("keys within region is empty, skip ingest", zap.Binary("start", start), zap.Binary("regionStart", region.Region.StartKey), zap.Binary("end", end), zap.Binary("regionEnd", region.Region.EndKey)) @@ -641,6 +642,7 @@ func (local *local) WriteToTiKV( // if there is not leader currently, we should directly return an error if leaderPeerMetas == nil { + // TODO: REDACT log.L().Warn("write to tikv no leader", zap.Reflect("region", region), zap.Uint64("leader_id", leaderID), zap.Reflect("meta", meta), zap.Int("kv_pairs", totalCount), zap.Int64("total_bytes", size)) @@ -658,6 +660,7 @@ func (local *local) WriteToTiKV( if iter.Valid() && iter.Next() { firstKey := append([]byte{}, iter.Key()...) remainRange = &Range{start: firstKey, end: regionRange.end} + // TODO: REDACT log.L().Info("write to tikv partial finish", zap.Int("count", totalCount), zap.Int64("size", size), zap.Binary("startKey", regionRange.start), zap.Binary("endKey", regionRange.end), zap.Binary("remainStart", remainRange.start), zap.Binary("remainEnd", remainRange.end), @@ -758,6 +761,7 @@ func (local *local) readAndSplitIntoRange(engineFile *LocalFile) ([]Range, error ranges := splitRangeBySizeProps(Range{start: firstKey, end: endKey}, sizeProps, local.regionSplitSize, regionMaxKeyCount*2/3) + // TODO: REDACT log.L().Info("split engine key ranges", zap.Stringer("engine", engineFile.Uuid), zap.Int64("totalSize", engineFile.TotalSize), zap.Int64("totalCount", engineFile.Length), zap.Binary("firstKey", firstKey), zap.Binary("lastKey", lastKey), @@ -881,6 +885,7 @@ func (local *local) writeAndIngestByRange( return errors.Annotate(iter.Error(), "failed to read the first key") } if !hasKey { + // TODO: REDACT log.L().Info("There is no pairs in iterator", zap.Binary("start", start), zap.Binary("end", end), @@ -912,6 +917,7 @@ WriteAndIngest: endKey := codec.EncodeBytes([]byte{}, nextKey(pairEnd)) regions, err = paginateScanRegion(ctx, local.splitCli, startKey, endKey, 128) if err != nil || len(regions) == 0 { + // TODO: REDACT log.L().Warn("scan region failed", log.ShortError(err), zap.Int("region_len", len(regions)), zap.Binary("startKey", startKey), zap.Binary("endKey", endKey), zap.Int("retry", retry)) retry++ @@ -936,6 +942,7 @@ WriteAndIngest: } else { retry++ } + // TODO: REDACT log.L().Info("retry write and ingest kv pairs", zap.Binary("startKey", pairStart), zap.Binary("endKey", end), log.ShortError(err), zap.Int("retry", retry)) continue WriteAndIngest @@ -986,6 +993,7 @@ loopWrite: if errors.Cause(err) == context.Canceled { return nil, err } + // TODO: REDACT log.L().Warn("ingest failed", log.ShortError(err), zap.Reflect("meta", meta), zap.Reflect("region", region)) errCnt++ @@ -1010,6 +1018,7 @@ loopWrite: } switch retryTy { case retryNone: + // TODO: REDACT log.L().Warn("ingest failed noretry", log.ShortError(err), zap.Reflect("meta", meta), zap.Reflect("region", region)) // met non-retryable error retry whole Write procedure @@ -1025,6 +1034,7 @@ loopWrite: } if err != nil { + // TODO: REDACT log.L().Warn("write and ingest region, will retry import full range", log.ShortError(err), zap.Stringer("region", region.Region), zap.Binary("start", start), zap.Binary("end", end)) } @@ -1261,6 +1271,7 @@ func (local *local) isIngestRetryable( if newRegion != nil { return newRegion, nil } + // TODO: REDACT log.L().Warn("get region by key return nil, will retry", zap.Reflect("region", region), zap.Int("retry", i)) select { diff --git a/lightning/backend/localhelper.go b/lightning/backend/localhelper.go index 6f54b915c..9e295f3cf 100644 --- a/lightning/backend/localhelper.go +++ b/lightning/backend/localhelper.go @@ -56,6 +56,7 @@ func (local *local) SplitAndScatterRegionByRanges(ctx context.Context, ranges [] minKey := codec.EncodeBytes([]byte{}, ranges[0].start) maxKey := codec.EncodeBytes([]byte{}, ranges[len(ranges)-1].end) + // TODO: REDACT log.L().Info("split and scatter region", zap.Binary("minKey", minKey), zap.Binary("maxKey", maxKey), @@ -80,6 +81,7 @@ func (local *local) SplitAndScatterRegionByRanges(ctx context.Context, ranges [] var regions []*split.RegionInfo regions, err = paginateScanRegion(ctx, local.splitCli, minKey, maxKey, 128) if err != nil { + // TODO: REDACT log.L().Warn("paginate scan region failed", zap.Binary("minKey", minKey), zap.Binary("maxKey", maxKey), log.ShortError(err), zap.Int("retry", i)) continue @@ -110,6 +112,7 @@ func (local *local) SplitAndScatterRegionByRanges(ctx context.Context, ranges [] splitRegionStart := codec.EncodeBytes([]byte{}, keys[start]) splitRegionEnd := codec.EncodeBytes([]byte{}, keys[end-1]) if bytes.Compare(splitRegionStart, splitRegion.Region.StartKey) <= 0 || !beforeEnd(splitRegionEnd, splitRegion.Region.EndKey) { + // TODO: REDACT log.L().Fatal("no valid key in region", zap.Binary("startKey", splitRegionStart), zap.Binary("endKey", splitRegionEnd), zap.Binary("regionStart", splitRegion.Region.StartKey), zap.Binary("regionEnd", splitRegion.Region.EndKey), @@ -119,6 +122,7 @@ func (local *local) SplitAndScatterRegionByRanges(ctx context.Context, ranges [] if err != nil { if strings.Contains(err.Error(), "no valid key") { for _, key := range keys { + // TODO: REDACT log.L().Warn("no valid key", zap.Binary("startKey", region.Region.StartKey), zap.Binary("endKey", region.Region.EndKey), @@ -275,6 +279,7 @@ func (local *local) waitForScatterRegion(ctx context.Context, regionInfo *split. for i := 0; i < split.ScatterWaitMaxRetryTimes; i++ { ok, err := local.isScatterRegionFinished(ctx, regionID) if err != nil { + // TODO: REDACT log.L().Warn("scatter region failed: do not have the region", zap.Stringer("region", regionInfo.Region)) return diff --git a/lightning/backend/tidb.go b/lightning/backend/tidb.go index 32c2d9ac7..2bfc111c0 100644 --- a/lightning/backend/tidb.go +++ b/lightning/backend/tidb.go @@ -358,6 +358,7 @@ func (be *tidbBackend) WriteRows(ctx context.Context, _ uuid.UUID, tableName str // Retry will be done externally, so we're not going to retry here. _, err := be.db.ExecContext(ctx, insertStmt.String()) if err != nil { + // TODO: REDACT log.L().Error("execute statement failed", zap.String("stmt", insertStmt.String()), zap.Array("rows", rows), zap.Error(err)) } From e8cdad048276a8fd158c017723521a7328a618c3 Mon Sep 17 00:00:00 2001 From: Chunzhu Li Date: Fri, 25 Dec 2020 17:40:32 +0800 Subject: [PATCH 2/5] add --redact-log parameter and redact sensitive log --- lightning/backend/local.go | 54 +++++++++----------- lightning/backend/localhelper.go | 35 ++++++------- lightning/backend/tidb.go | 3 +- lightning/config/global.go | 4 ++ lightning/log/log.go | 4 ++ lightning/log/redact.go | 84 ++++++++++++++++++++++++++++++++ 6 files changed, 130 insertions(+), 54 deletions(-) create mode 100644 lightning/log/redact.go diff --git a/lightning/backend/local.go b/lightning/backend/local.go index fe121b613..c6aa48919 100644 --- a/lightning/backend/local.go +++ b/lightning/backend/local.go @@ -517,10 +517,9 @@ func (local *local) WriteToTiKV( } if !iter.Valid() { - // TODO: REDACT - log.L().Info("keys within region is empty, skip ingest", zap.Binary("start", start), - zap.Binary("regionStart", region.Region.StartKey), zap.Binary("end", end), - zap.Binary("regionEnd", region.Region.EndKey)) + log.L().Info("keys within region is empty, skip ingest", log.ZapRedactBinary("start", start), + log.ZapRedactBinary("regionStart", region.Region.StartKey), log.ZapRedactBinary("end", end), + log.ZapRedactBinary("regionEnd", region.Region.EndKey)) return nil, nil, nil } @@ -642,9 +641,8 @@ func (local *local) WriteToTiKV( // if there is not leader currently, we should directly return an error if leaderPeerMetas == nil { - // TODO: REDACT - log.L().Warn("write to tikv no leader", zap.Reflect("region", region), - zap.Uint64("leader_id", leaderID), zap.Reflect("meta", meta), + log.L().Warn("write to tikv no leader", log.ZapRedactReflect("region", region), + zap.Uint64("leader_id", leaderID), log.ZapRedactReflect("meta", meta), zap.Int("kv_pairs", totalCount), zap.Int64("total_bytes", size)) return nil, nil, errors.Errorf("write to tikv with no leader returned, region '%d', leader: %d", region.Region.Id, leaderID) @@ -660,11 +658,10 @@ func (local *local) WriteToTiKV( if iter.Valid() && iter.Next() { firstKey := append([]byte{}, iter.Key()...) remainRange = &Range{start: firstKey, end: regionRange.end} - // TODO: REDACT log.L().Info("write to tikv partial finish", zap.Int("count", totalCount), - zap.Int64("size", size), zap.Binary("startKey", regionRange.start), zap.Binary("endKey", regionRange.end), - zap.Binary("remainStart", remainRange.start), zap.Binary("remainEnd", remainRange.end), - zap.Reflect("region", region)) + zap.Int64("size", size), log.ZapRedactBinary("startKey", regionRange.start), log.ZapRedactBinary("endKey", regionRange.end), + log.ZapRedactBinary("remainStart", remainRange.start), log.ZapRedactBinary("remainEnd", remainRange.end), + log.ZapRedactReflect("region", region)) } return leaderPeerMetas, remainRange, nil @@ -761,10 +758,9 @@ func (local *local) readAndSplitIntoRange(engineFile *LocalFile) ([]Range, error ranges := splitRangeBySizeProps(Range{start: firstKey, end: endKey}, sizeProps, local.regionSplitSize, regionMaxKeyCount*2/3) - // TODO: REDACT log.L().Info("split engine key ranges", zap.Stringer("engine", engineFile.Uuid), zap.Int64("totalSize", engineFile.TotalSize), zap.Int64("totalCount", engineFile.Length), - zap.Binary("firstKey", firstKey), zap.Binary("lastKey", lastKey), + log.ZapRedactBinary("firstKey", firstKey), log.ZapRedactBinary("lastKey", lastKey), zap.Int("ranges", len(ranges))) return ranges, nil @@ -885,11 +881,10 @@ func (local *local) writeAndIngestByRange( return errors.Annotate(iter.Error(), "failed to read the first key") } if !hasKey { - // TODO: REDACT log.L().Info("There is no pairs in iterator", - zap.Binary("start", start), - zap.Binary("end", end), - zap.Binary("next end", nextKey(end))) + log.ZapRedactBinary("start", start), + log.ZapRedactBinary("end", end), + log.ZapRedactBinary("next end", nextKey(end))) return nil } pairStart := append([]byte{}, iter.Key()...) @@ -917,9 +912,8 @@ WriteAndIngest: endKey := codec.EncodeBytes([]byte{}, nextKey(pairEnd)) regions, err = paginateScanRegion(ctx, local.splitCli, startKey, endKey, 128) if err != nil || len(regions) == 0 { - // TODO: REDACT log.L().Warn("scan region failed", log.ShortError(err), zap.Int("region_len", len(regions)), - zap.Binary("startKey", startKey), zap.Binary("endKey", endKey), zap.Int("retry", retry)) + log.ZapRedactBinary("startKey", startKey), log.ZapRedactBinary("endKey", endKey), zap.Int("retry", retry)) retry++ continue WriteAndIngest } @@ -942,9 +936,8 @@ WriteAndIngest: } else { retry++ } - // TODO: REDACT - log.L().Info("retry write and ingest kv pairs", zap.Binary("startKey", pairStart), - zap.Binary("endKey", end), log.ShortError(err), zap.Int("retry", retry)) + log.L().Info("retry write and ingest kv pairs", log.ZapRedactBinary("startKey", pairStart), + log.ZapRedactBinary("endKey", end), log.ShortError(err), zap.Int("retry", retry)) continue WriteAndIngest } if rg != nil { @@ -993,9 +986,8 @@ loopWrite: if errors.Cause(err) == context.Canceled { return nil, err } - // TODO: REDACT - log.L().Warn("ingest failed", log.ShortError(err), zap.Reflect("meta", meta), - zap.Reflect("region", region)) + log.L().Warn("ingest failed", log.ShortError(err), log.ZapRedactReflect("meta", meta), + log.ZapRedactReflect("region", region)) errCnt++ continue } @@ -1018,9 +1010,8 @@ loopWrite: } switch retryTy { case retryNone: - // TODO: REDACT - log.L().Warn("ingest failed noretry", log.ShortError(err), zap.Reflect("meta", meta), - zap.Reflect("region", region)) + log.L().Warn("ingest failed noretry", log.ShortError(err), log.ZapRedactReflect("meta", meta), + log.ZapRedactReflect("region", region)) // met non-retryable error retry whole Write procedure return remainRange, err case retryWrite: @@ -1034,9 +1025,9 @@ loopWrite: } if err != nil { - // TODO: REDACT log.L().Warn("write and ingest region, will retry import full range", log.ShortError(err), - zap.Stringer("region", region.Region), zap.Binary("start", start), zap.Binary("end", end)) + log.ZapRedactStringer("region", region.Region), log.ZapRedactBinary("start", start), + log.ZapRedactBinary("end", end)) } return remainRange, errors.Trace(err) } @@ -1271,8 +1262,7 @@ func (local *local) isIngestRetryable( if newRegion != nil { return newRegion, nil } - // TODO: REDACT - log.L().Warn("get region by key return nil, will retry", zap.Reflect("region", region), + log.L().Warn("get region by key return nil, will retry", log.ZapRedactReflect("region", region), zap.Int("retry", i)) select { case <-ctx.Done(): diff --git a/lightning/backend/localhelper.go b/lightning/backend/localhelper.go index 7790f868f..f2dd142d4 100644 --- a/lightning/backend/localhelper.go +++ b/lightning/backend/localhelper.go @@ -64,10 +64,9 @@ func (local *local) SplitAndScatterRegionByRanges(ctx context.Context, ranges [] var retryKeys [][]byte waitTime := splitRegionBaseBackOffTime for i := 0; i < SplitRetryTimes; i++ { - // TODO: REDACT log.L().Info("split and scatter region", - zap.Binary("minKey", minKey), - zap.Binary("maxKey", maxKey), + log.ZapRedactBinary("minKey", minKey), + log.ZapRedactBinary("maxKey", maxKey), zap.Int("retry", i), ) if i > 0 { @@ -84,19 +83,18 @@ func (local *local) SplitAndScatterRegionByRanges(ctx context.Context, ranges [] var regions []*split.RegionInfo regions, err = paginateScanRegion(ctx, local.splitCli, minKey, maxKey, 128) if err != nil { - // TODO: REDACT - log.L().Warn("paginate scan region failed", zap.Binary("minKey", minKey), zap.Binary("maxKey", maxKey), + log.L().Warn("paginate scan region failed", log.ZapRedactBinary("minKey", minKey), log.ZapRedactBinary("maxKey", maxKey), log.ShortError(err), zap.Int("retry", i)) continue } if len(regions) == 0 { - log.L().Warn("paginate scan region returns empty result", zap.Binary("minKey", minKey), zap.Binary("maxKey", maxKey), + log.L().Warn("paginate scan region returns empty result", log.ZapRedactBinary("minKey", minKey), log.ZapRedactBinary("maxKey", maxKey), zap.Int("retry", i)) return errors.New("paginate scan region returns empty result") } - log.L().Info("paginate scan region finished", zap.Binary("minKey", minKey), zap.Binary("maxKey", maxKey), + log.L().Info("paginate scan region finished", log.ZapRedactBinary("minKey", minKey), log.ZapRedactBinary("maxKey", maxKey), zap.Int("regions", len(regions))) regionMap := make(map[uint64]*split.RegionInfo) @@ -110,9 +108,9 @@ func (local *local) SplitAndScatterRegionByRanges(ctx context.Context, ranges [] lastKeyEnc := codec.EncodeBytes([]byte{}, retryKeys[len(retryKeys)-1]) if bytes.Compare(firstKeyEnc, regions[0].Region.StartKey) < 0 || !beforeEnd(lastKeyEnc, regions[len(regions)-1].Region.EndKey) { log.L().Warn("no valid key for split region", - zap.Binary("firstKey", firstKeyEnc), zap.Binary("lastKey", lastKeyEnc), - zap.Binary("firstRegionStart", regions[0].Region.StartKey), - zap.Binary("lastRegionEnd", regions[len(regions)-1].Region.EndKey)) + log.ZapRedactBinary("firstKey", firstKeyEnc), log.ZapRedactBinary("lastKey", lastKeyEnc), + log.ZapRedactBinary("firstRegionStart", regions[0].Region.StartKey), + log.ZapRedactBinary("lastRegionEnd", regions[len(regions)-1].Region.EndKey)) return errors.New("check split keys failed") } splitKeyMap = getSplitKeys(retryKeys, regions) @@ -133,21 +131,19 @@ func (local *local) SplitAndScatterRegionByRanges(ctx context.Context, ranges [] splitRegionStart := codec.EncodeBytes([]byte{}, keys[start]) splitRegionEnd := codec.EncodeBytes([]byte{}, keys[end-1]) if bytes.Compare(splitRegionStart, splitRegion.Region.StartKey) < 0 || !beforeEnd(splitRegionEnd, splitRegion.Region.EndKey) { - // TODO: REDACT log.L().Fatal("no valid key in region", - zap.Binary("startKey", splitRegionStart), zap.Binary("endKey", splitRegionEnd), - zap.Binary("regionStart", splitRegion.Region.StartKey), zap.Binary("regionEnd", splitRegion.Region.EndKey), - zap.Reflect("region", splitRegion)) + log.ZapRedactBinary("startKey", splitRegionStart), log.ZapRedactBinary("endKey", splitRegionEnd), + log.ZapRedactBinary("regionStart", splitRegion.Region.StartKey), log.ZapRedactBinary("regionEnd", splitRegion.Region.EndKey), + log.ZapRedactReflect("region", splitRegion)) } splitRegion, newRegions, err = local.BatchSplitRegions(ctx, splitRegion, keys[start:end]) if err != nil { if strings.Contains(err.Error(), "no valid key") { for _, key := range keys { - // TODO: REDACT log.L().Warn("no valid key", - zap.Binary("startKey", region.Region.StartKey), - zap.Binary("endKey", region.Region.EndKey), - zap.Binary("key", codec.EncodeBytes([]byte{}, key))) + log.ZapRedactBinary("startKey", region.Region.StartKey), + log.ZapRedactBinary("endKey", region.Region.EndKey), + log.ZapRedactBinary("key", codec.EncodeBytes([]byte{}, key))) } return errors.Trace(err) } @@ -303,9 +299,8 @@ func (local *local) waitForScatterRegion(ctx context.Context, regionInfo *split. for i := 0; i < split.ScatterWaitMaxRetryTimes; i++ { ok, err := local.isScatterRegionFinished(ctx, regionID) if err != nil { - // TODO: REDACT log.L().Warn("scatter region failed: do not have the region", - zap.Stringer("region", regionInfo.Region)) + log.ZapRedactStringer("region", regionInfo.Region)) return } if ok { diff --git a/lightning/backend/tidb.go b/lightning/backend/tidb.go index 2bfc111c0..b95a4833c 100644 --- a/lightning/backend/tidb.go +++ b/lightning/backend/tidb.go @@ -358,9 +358,8 @@ func (be *tidbBackend) WriteRows(ctx context.Context, _ uuid.UUID, tableName str // Retry will be done externally, so we're not going to retry here. _, err := be.db.ExecContext(ctx, insertStmt.String()) if err != nil { - // TODO: REDACT log.L().Error("execute statement failed", zap.String("stmt", insertStmt.String()), - zap.Array("rows", rows), zap.Error(err)) + log.ZapRedactArray("rows", rows), zap.Error(err)) } failpoint.Inject("FailIfImportedSomeRows", func() { panic("forcing failure due to FailIfImportedSomeRows, before saving checkpoint") diff --git a/lightning/config/global.go b/lightning/config/global.go index eb1075fda..6ec954cd1 100644 --- a/lightning/config/global.go +++ b/lightning/config/global.go @@ -144,6 +144,7 @@ func LoadGlobalConfig(args []string, extraFlags func(*flag.FlagSet)) (*GlobalCon logLevel := flagext.ChoiceVar(fs, "L", "", `log level: info, debug, warn, error, fatal (default info)`, "", "info", "debug", "warn", "warning", "error", "fatal") logFilePath := fs.String("log-file", "", "log file path") + redactLog := fs.Bool("redact-log", false, "whether to redact sensitive info in log") tidbHost := fs.String("tidb-host", "", "TiDB server host") tidbPort := fs.Int("tidb-port", 0, "TiDB server port (default 4000)") tidbUser := fs.String("tidb-user", "", "TiDB user name to connect") @@ -198,6 +199,9 @@ func LoadGlobalConfig(args []string, extraFlags func(*flag.FlagSet)) (*GlobalCon if *logFilePath != "" { cfg.App.Config.File = *logFilePath } + if *redactLog { + cfg.App.Config.RedactLog = *redactLog + } // "-" is a special config for log to stdout if cfg.App.Config.File == "-" { cfg.App.Config.File = "" diff --git a/lightning/log/log.go b/lightning/log/log.go index e3b8f3328..c597af477 100644 --- a/lightning/log/log.go +++ b/lightning/log/log.go @@ -44,6 +44,8 @@ type Config struct { FileMaxDays int `toml:"max-days" json:"max-days"` // Maximum number of old log files to retain. FileMaxBackups int `toml:"max-backups" json:"max-backups"` + // Redact sensitive logs during the whole process + RedactLog bool `toml:"redact-log" json:"redact-log"` } func (cfg *Config) Adjust() { @@ -98,6 +100,8 @@ func InitLogger(cfg *Config, tidbLoglevel string) error { appLogger = Logger{logger.WithOptions(zap.AddStacktrace(zap.DPanicLevel))} appLevel = props.Level + InitRedact(cfg.RedactLog) + return nil } diff --git a/lightning/log/redact.go b/lightning/log/redact.go new file mode 100644 index 000000000..b8d6e91fd --- /dev/null +++ b/lightning/log/redact.go @@ -0,0 +1,84 @@ +// Copyright 2020 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// See the License for the specific language governing permissions and +// limitations under the License. + +package log + +import ( + "fmt" + + "github.com/pingcap/errors" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +// InitRedact inits the enableRedactLog +func InitRedact(redactLog bool) { + errors.RedactLogEnabled.Store(redactLog) +} + +// NeedRedact returns whether to redact log +func NeedRedact() bool { + return errors.RedactLogEnabled.Load() +} + +// ZapRedactBinary receives zap.Binary and return omitted information if redact log enabled +func ZapRedactBinary(key string, val []byte) zapcore.Field { + if NeedRedact() { + return zap.String(key, "?") + } + return zap.Binary(key, val) +} + +// ZapRedactArray receives zap.Array and return omitted information if redact log enabled +func ZapRedactArray(key string, val zapcore.ArrayMarshaler) zapcore.Field { + if NeedRedact() { + return zap.String(key, "?") + } + return zap.Array(key, val) +} + +// ZapRedactReflect receives zap.Reflect and return omitted information if redact log enabled +func ZapRedactReflect(key string, val interface{}) zapcore.Field { + if NeedRedact() { + return zap.String(key, "?") + } + return zap.Reflect(key, val) +} + +// 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)) +} + +// RedactString receives string argument and return omitted information if redact log enabled +func RedactString(arg string) string { + if NeedRedact() { + return "?" + } + return arg +} + +// RedactStringer receives stringer argument and return omitted information if redact log enabled +func RedactStringer(arg fmt.Stringer) fmt.Stringer { + if NeedRedact() { + return stringer{} + } + return arg +} + +type stringer struct{} + +// String implement fmt.Stringer +func (s stringer) String() string { + return "?" +} From 0513f09a3425e3049495df99855780ddb7a15cc8 Mon Sep 17 00:00:00 2001 From: Chunzhu Li Date: Fri, 25 Dec 2020 18:25:19 +0800 Subject: [PATCH 3/5] remove sensitive info in error --- lightning/backend/localhelper.go | 6 ++++-- lightning/backend/sql2kv.go | 6 ++++-- lightning/log/redact.go | 5 +++++ 3 files changed, 13 insertions(+), 4 deletions(-) diff --git a/lightning/backend/localhelper.go b/lightning/backend/localhelper.go index f2dd142d4..07cefadbc 100644 --- a/lightning/backend/localhelper.go +++ b/lightning/backend/localhelper.go @@ -205,8 +205,10 @@ func paginateScanRegion( ctx context.Context, client split.SplitClient, startKey, endKey []byte, limit int, ) ([]*split.RegionInfo, error) { if len(endKey) != 0 && bytes.Compare(startKey, endKey) >= 0 { - return nil, errors.Errorf("startKey > endKey, startKey %s, endkey %s", - hex.EncodeToString(startKey), hex.EncodeToString(endKey)) + log.L().Error("startKey > endKey when paginating scan region", + log.ZapRedactString("startKey", hex.EncodeToString(startKey)), + log.ZapRedactString("endKey", hex.EncodeToString(endKey))) + return nil, errors.Errorf("startKey > endKey when paginating scan region") } var regions []*split.RegionInfo diff --git a/lightning/backend/sql2kv.go b/lightning/backend/sql2kv.go index 19ef074b3..a22e17dea 100644 --- a/lightning/backend/sql2kv.go +++ b/lightning/backend/sql2kv.go @@ -236,10 +236,12 @@ func logKVConvertFailed(logger log.Logger, row []types.Datum, j int, colInfo *mo log.ShortError(err), ) + log.L().Error("failed to covert kv value", log.ZapRedactReflect("origVal", original.GetValue()), + zap.Stringer("fieldType", &colInfo.FieldType), zap.String("column", colInfo.Name.O), + zap.Int("columnID", j+1)) return errors.Annotatef( err, - "failed to cast `%v` as %s for column `%s` (#%d)", - original.GetValue(), &colInfo.FieldType, colInfo.Name.O, j+1, + "failed to cast value as %s for column `%s` (#%d)", &colInfo.FieldType, colInfo.Name.O, j+1, ) } diff --git a/lightning/log/redact.go b/lightning/log/redact.go index b8d6e91fd..e75f5cadc 100644 --- a/lightning/log/redact.go +++ b/lightning/log/redact.go @@ -60,6 +60,11 @@ func ZapRedactStringer(key string, arg fmt.Stringer) zap.Field { return zap.Stringer(key, RedactStringer(arg)) } +// ZapRedactString receives stringer argument and return omitted information in zap.Field if redact log enabled +func ZapRedactString(key string, arg string) zap.Field { + return zap.String(key, RedactString(arg)) +} + // RedactString receives string argument and return omitted information if redact log enabled func RedactString(arg string) string { if NeedRedact() { From 4263e5f3976e38895349524e1a2fa85635e776ae Mon Sep 17 00:00:00 2001 From: Chunzhu Li Date: Mon, 28 Dec 2020 16:08:26 +0800 Subject: [PATCH 4/5] address comments --- lightning/backend/tidb.go | 2 +- tidb-lightning.toml | 2 ++ 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/lightning/backend/tidb.go b/lightning/backend/tidb.go index b95a4833c..f62d3ff05 100644 --- a/lightning/backend/tidb.go +++ b/lightning/backend/tidb.go @@ -358,7 +358,7 @@ func (be *tidbBackend) WriteRows(ctx context.Context, _ uuid.UUID, tableName str // Retry will be done externally, so we're not going to retry here. _, err := be.db.ExecContext(ctx, insertStmt.String()) if err != nil { - log.L().Error("execute statement failed", zap.String("stmt", insertStmt.String()), + log.L().Error("execute statement failed", log.ZapRedactString("stmt", insertStmt.String()), log.ZapRedactArray("rows", rows), zap.Error(err)) } failpoint.Inject("FailIfImportedSomeRows", func() { diff --git a/tidb-lightning.toml b/tidb-lightning.toml index e31fdb2e5..eea44bbba 100644 --- a/tidb-lightning.toml +++ b/tidb-lightning.toml @@ -41,6 +41,8 @@ file = "tidb-lightning.log" max-size = 128 # MB max-days = 28 max-backups = 14 +# If set to true, lightning will redact sensitive infomation in log. +redact-log = false [security] # specifies certificates and keys for TLS connections within the cluster. From 83d42fb7d3ccfcaa8694cf14ff6236cc945ef9cc Mon Sep 17 00:00:00 2001 From: Chunzhu Li Date: Mon, 28 Dec 2020 16:52:52 +0800 Subject: [PATCH 5/5] fix ut --- lightning/backend/sql2kv.go | 2 +- lightning/backend/sql2kv_test.go | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/lightning/backend/sql2kv.go b/lightning/backend/sql2kv.go index a22e17dea..3878e30a0 100644 --- a/lightning/backend/sql2kv.go +++ b/lightning/backend/sql2kv.go @@ -214,7 +214,7 @@ func (row rowArrayMarshaler) MarshalLogArray(encoder zapcore.ArrayEncoder) error } encoder.AppendObject(zapcore.ObjectMarshalerFunc(func(enc zapcore.ObjectEncoder) error { enc.AddString("kind", kindStr[kind]) - enc.AddString("val", str) + enc.AddString("val", log.RedactString(str)) return nil })) } diff --git a/lightning/backend/sql2kv_test.go b/lightning/backend/sql2kv_test.go index 75955ff0f..d3a7441cc 100644 --- a/lightning/backend/sql2kv_test.go +++ b/lightning/backend/sql2kv_test.go @@ -88,7 +88,7 @@ func (s *kvSuite) TestEncode(c *C) { }) c.Assert(err, IsNil) pairs, err := strictMode.Encode(logger, rows, 1, []int{0, 1}) - c.Assert(err, ErrorMatches, "failed to cast `10000000` as tinyint\\(4\\) for column `c1` \\(#1\\):.*overflows tinyint") + c.Assert(err, ErrorMatches, "failed to cast value as tinyint\\(4\\) for column `c1` \\(#1\\):.*overflows tinyint") c.Assert(pairs, IsNil) rowsWithPk := []types.Datum{ @@ -96,7 +96,7 @@ func (s *kvSuite) TestEncode(c *C) { types.NewStringDatum("invalid-pk"), } pairs, err = strictMode.Encode(logger, rowsWithPk, 2, []int{0, 1}) - c.Assert(err, ErrorMatches, "failed to cast `invalid-pk` as bigint\\(20\\) for column `_tidb_rowid`.*Truncated.*") + c.Assert(err, ErrorMatches, "failed to cast value as bigint\\(20\\) for column `_tidb_rowid`.*Truncated.*") rowsWithPk2 := []types.Datum{ types.NewIntDatum(1),