Skip to content
This repository has been archived by the owner on Dec 8, 2021. It is now read-only.

*: redact log and error messages, add log-redact parameter #538

Merged
merged 7 commits into from
Dec 28, 2020
Merged
Show file tree
Hide file tree
Changes from 4 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
43 changes: 22 additions & 21 deletions lightning/backend/local.go
Original file line number Diff line number Diff line change
Expand Up @@ -517,9 +517,9 @@ func (local *local) WriteToTiKV(
}

if !iter.Valid() {
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
}

Expand Down Expand Up @@ -641,8 +641,8 @@ func (local *local) WriteToTiKV(

// if there is not leader currently, we should directly return an error
if leaderPeerMetas == nil {
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)
Expand All @@ -659,9 +659,9 @@ func (local *local) WriteToTiKV(
firstKey := append([]byte{}, iter.Key()...)
remainRange = &Range{start: firstKey, end: regionRange.end}
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
Expand Down Expand Up @@ -760,7 +760,7 @@ func (local *local) readAndSplitIntoRange(engineFile *LocalFile) ([]Range, error

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
Expand Down Expand Up @@ -882,9 +882,9 @@ func (local *local) writeAndIngestByRange(
}
if !hasKey {
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()...)
Expand Down Expand Up @@ -913,7 +913,7 @@ WriteAndIngest:
regions, err = paginateScanRegion(ctx, local.splitCli, startKey, endKey, 128)
if err != nil || len(regions) == 0 {
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
}
Expand All @@ -936,8 +936,8 @@ WriteAndIngest:
} else {
retry++
}
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 {
Expand Down Expand Up @@ -986,8 +986,8 @@ loopWrite:
if errors.Cause(err) == context.Canceled {
return nil, err
}
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
}
Expand All @@ -1010,8 +1010,8 @@ loopWrite:
}
switch retryTy {
case retryNone:
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:
Expand All @@ -1026,7 +1026,8 @@ loopWrite:

if err != nil {
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)
}
Expand Down Expand Up @@ -1261,7 +1262,7 @@ func (local *local) isIngestRetryable(
if newRegion != nil {
return newRegion, nil
}
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():
Expand Down
37 changes: 20 additions & 17 deletions lightning/backend/localhelper.go
Original file line number Diff line number Diff line change
Expand Up @@ -58,14 +58,15 @@ func (local *local) SplitAndScatterRegionByRanges(ctx context.Context, ranges []

minKey := codec.EncodeBytes([]byte{}, ranges[0].start)
maxKey := codec.EncodeBytes([]byte{}, ranges[len(ranges)-1].end)

var err error
scatterRegions := make([]*split.RegionInfo, 0)
var retryKeys [][]byte
waitTime := splitRegionBaseBackOffTime
for i := 0; i < SplitRetryTimes; i++ {
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 {
Expand All @@ -82,18 +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 {
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)
Expand All @@ -107,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)
Expand All @@ -131,18 +132,18 @@ func (local *local) SplitAndScatterRegionByRanges(ctx context.Context, ranges []
splitRegionEnd := codec.EncodeBytes([]byte{}, keys[end-1])
if bytes.Compare(splitRegionStart, splitRegion.Region.StartKey) < 0 || !beforeEnd(splitRegionEnd, splitRegion.Region.EndKey) {
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 {
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)
}
Expand Down Expand Up @@ -204,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
Expand Down Expand Up @@ -299,7 +302,7 @@ func (local *local) waitForScatterRegion(ctx context.Context, regionInfo *split.
ok, err := local.isScatterRegionFinished(ctx, regionID)
if err != nil {
log.L().Warn("scatter region failed: do not have the region",
zap.Stringer("region", regionInfo.Region))
log.ZapRedactStringer("region", regionInfo.Region))
return
}
if ok {
Expand Down
6 changes: 4 additions & 2 deletions lightning/backend/sql2kv.go
Original file line number Diff line number Diff line change
Expand Up @@ -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,
)
}

Expand Down
2 changes: 1 addition & 1 deletion lightning/backend/tidb.go
Original file line number Diff line number Diff line change
Expand Up @@ -359,7 +359,7 @@ func (be *tidbBackend) WriteRows(ctx context.Context, _ uuid.UUID, tableName str
_, err := be.db.ExecContext(ctx, insertStmt.String())
if err != nil {
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))
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The stmt should be redacted too since it contains the rawData

}
failpoint.Inject("FailIfImportedSomeRows", func() {
panic("forcing failure due to FailIfImportedSomeRows, before saving checkpoint")
Expand Down
4 changes: 4 additions & 0 deletions lightning/config/global.go
Original file line number Diff line number Diff line change
Expand Up @@ -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")
Expand Down Expand Up @@ -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 = ""
Expand Down
4 changes: 4 additions & 0 deletions lightning/log/log.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"`
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We should allow config this field from toml too

}

func (cfg *Config) Adjust() {
Expand Down Expand Up @@ -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
}

Expand Down
89 changes: 89 additions & 0 deletions lightning/log/redact.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,89 @@
// 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
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

shall we directly shall the package in br? Since they should be almost the same

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Some functions are not implemented in br's package. Since these two repositories are going to be merged together, I think we can do the refactor at that time to avoid update the dependencies now.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@overvenus FYI about this task.


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))
}

// 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() {
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 "?"
}