From bb1e7326081b9431a311e5d512da2332b8e26c84 Mon Sep 17 00:00:00 2001 From: Neil Shen Date: Thu, 28 Jan 2021 20:57:00 +0800 Subject: [PATCH 1/2] cherry pick #723 to release-4.0 Signed-off-by: ti-srebot --- cmd/cmd.go | 4 +- cmd/debug.go | 4 +- pkg/backup/client.go | 43 +++++--- pkg/kv/kv.go | 62 ++++++------ pkg/kv/kv_test.go | 10 +- pkg/logutil/logging.go | 180 +++++++++++++++++++++------------- pkg/logutil/logging_test.go | 167 +++++++++++++++++++++++++++++++ pkg/logutil/redact.go | 57 ----------- pkg/redact/redact.go | 36 +++++++ pkg/redact/redact_test.go | 32 ++++++ pkg/restore/batcher.go | 5 +- pkg/restore/batcher_test.go | 2 +- pkg/restore/client.go | 27 +++-- pkg/restore/import.go | 16 +-- pkg/restore/log_client.go | 13 ++- pkg/restore/pipeline_items.go | 10 +- pkg/restore/range.go | 19 ++-- pkg/restore/split.go | 42 ++++---- pkg/restore/split_client.go | 2 +- pkg/restore/util.go | 70 +++++-------- pkg/rtree/logging.go | 61 ++++++++++++ pkg/rtree/logging_test.go | 47 +++++++++ pkg/rtree/rtree.go | 20 +++- tests/br_key_locked/locker.go | 2 +- 24 files changed, 640 insertions(+), 291 deletions(-) create mode 100644 pkg/logutil/logging_test.go delete mode 100644 pkg/logutil/redact.go create mode 100644 pkg/redact/redact.go create mode 100644 pkg/redact/redact_test.go create mode 100644 pkg/rtree/logging.go create mode 100644 pkg/rtree/logging_test.go diff --git a/cmd/cmd.go b/cmd/cmd.go index e4c59dbc6..428be4fad 100644 --- a/cmd/cmd.go +++ b/cmd/cmd.go @@ -18,7 +18,7 @@ import ( "github.com/spf13/cobra" "github.com/pingcap/br/pkg/gluetidb" - brlogutil "github.com/pingcap/br/pkg/logutil" + "github.com/pingcap/br/pkg/redact" "github.com/pingcap/br/pkg/summary" "github.com/pingcap/br/pkg/task" "github.com/pingcap/br/pkg/utils" @@ -127,7 +127,7 @@ func Init(cmd *cobra.Command) (err error) { err = e return } - brlogutil.InitRedact(redactLog || redactInfoLog) + redact.InitRedact(redactLog || redactInfoLog) slowLogFilename, e := cmd.Flags().GetString(FlagSlowLogFile) if e != nil { diff --git a/cmd/debug.go b/cmd/debug.go index 88e2c5703..c3e174b38 100644 --- a/cmd/debug.go +++ b/cmd/debug.go @@ -107,8 +107,8 @@ func newCheckSumCommand() *cobra.Command { zap.Uint64("totalBytes", file.GetTotalBytes()), zap.Uint64("startVersion", file.GetStartVersion()), zap.Uint64("endVersion", file.GetEndVersion()), - zap.Stringer("startKey", logutil.WrapKey(file.GetStartKey())), - zap.Stringer("endKey", logutil.WrapKey(file.GetEndKey())), + logutil.Key("startKey", file.GetStartKey()), + logutil.Key("endKey", file.GetEndKey()), ) var data []byte diff --git a/pkg/backup/client.go b/pkg/backup/client.go index e7fbef97b..06a5b5ba2 100644 --- a/pkg/backup/client.go +++ b/pkg/backup/client.go @@ -39,6 +39,7 @@ import ( berrors "github.com/pingcap/br/pkg/errors" "github.com/pingcap/br/pkg/glue" "github.com/pingcap/br/pkg/logutil" + "github.com/pingcap/br/pkg/redact" "github.com/pingcap/br/pkg/rtree" "github.com/pingcap/br/pkg/storage" "github.com/pingcap/br/pkg/summary" @@ -502,10 +503,10 @@ func (bc *Client) BackupRange( } }() log.Info("backup started", - zap.Stringer("StartKey", logutil.WrapKey(startKey)), - zap.Stringer("EndKey", logutil.WrapKey(endKey)), - zap.Uint64("RateLimit", req.RateLimit), - zap.Uint32("Concurrency", req.Concurrency)) + logutil.Key("startKey", startKey), + logutil.Key("endKey", endKey), + zap.Uint64("rateLimit", req.RateLimit), + zap.Uint32("concurrency", req.Concurrency)) var allStores []*metapb.Store allStores, err = conn.GetAllTiKVStores(ctx, bc.mgr.GetPDClient(), conn.SkipTiFlash) @@ -538,8 +539,8 @@ func (bc *Client) BackupRange( if req.IsRawKv { log.Info("backup raw ranges", - zap.Stringer("startKey", logutil.WrapKey(startKey)), - zap.Stringer("endKey", logutil.WrapKey(endKey)), + logutil.Key("startKey", startKey), + logutil.Key("endKey", endKey), zap.String("cf", req.Cf)) } else { log.Info("backup time range", @@ -574,14 +575,14 @@ func (bc *Client) findRegionLeader(ctx context.Context, key []byte) (*metapb.Pee } if region.Leader != nil { log.Info("find leader", - zap.Reflect("Leader", region.Leader), zap.Stringer("Key", logutil.WrapKey(key))) + zap.Reflect("Leader", region.Leader), logutil.Key("key", key)) return region.Leader, nil } - log.Warn("no region found", zap.Stringer("Key", logutil.WrapKey(key))) + log.Warn("no region found", logutil.Key("key", key)) time.Sleep(time.Millisecond * time.Duration(100*i)) continue } - log.Error("can not find leader", zap.Stringer("key", logutil.WrapKey(key))) + log.Error("can not find leader", logutil.Key("key", key)) return nil, errors.Annotatef(berrors.ErrBackupNoLeader, "can not find leader") } @@ -665,8 +666,8 @@ func (bc *Client) fineGrainedBackup( zap.Reflect("error", resp.Error)) } log.Info("put fine grained range", - zap.Stringer("StartKey", logutil.WrapKey(resp.StartKey)), - zap.Stringer("EndKey", logutil.WrapKey(resp.EndKey)), + logutil.Key("startKey", resp.StartKey), + logutil.Key("endKey", resp.EndKey), ) rangeTree.Put(resp.StartKey, resp.EndKey, resp.Files) @@ -826,12 +827,24 @@ func SendBackup( respFn func(*kvproto.BackupResponse) error, resetFn func() (kvproto.BackupClient, error), ) error { +<<<<<<< HEAD +======= + if span := opentracing.SpanFromContext(ctx); span != nil && span.Tracer() != nil { + span1 := span.Tracer().StartSpan( + fmt.Sprintf("Client.SendBackup, storeID = %d, StartKey = %s, EndKey = %s", + storeID, redact.Key(req.StartKey), redact.Key(req.EndKey)), + opentracing.ChildOf(span.Context())) + defer span1.Finish() + ctx = opentracing.ContextWithSpan(ctx, span1) + } + +>>>>>>> c206add... *: refine logs (#723) var errReset error backupLoop: for retry := 0; retry < backupRetryTimes; retry++ { log.Info("try backup", - zap.Stringer("StartKey", logutil.WrapKey(req.StartKey)), - zap.Stringer("EndKey", logutil.WrapKey(req.EndKey)), + logutil.Key("startKey", req.StartKey), + logutil.Key("endKey", req.EndKey), zap.Uint64("storeID", storeID), zap.Int("retry time", retry), ) @@ -880,8 +893,8 @@ backupLoop: } // TODO: handle errors in the resp. log.Info("range backuped", - zap.Stringer("StartKey", logutil.WrapKey(resp.GetStartKey())), - zap.Stringer("EndKey", logutil.WrapKey(resp.GetEndKey()))) + logutil.Key("startKey", resp.GetStartKey()), + logutil.Key("endKey", resp.GetEndKey())) err = respFn(resp) if err != nil { return errors.Trace(err) diff --git a/pkg/kv/kv.go b/pkg/kv/kv.go index b54b68362..39f2a8632 100644 --- a/pkg/kv/kv.go +++ b/pkg/kv/kv.go @@ -14,6 +14,8 @@ package kv import ( + "fmt" + "github.com/pingcap/errors" "github.com/pingcap/log" "github.com/pingcap/parser/model" @@ -23,9 +25,9 @@ import ( "github.com/pingcap/tidb/tablecodec" "github.com/pingcap/tidb/types" "go.uber.org/zap" - "go.uber.org/zap/zapcore" "github.com/pingcap/br/pkg/logutil" + "github.com/pingcap/br/pkg/redact" ) var extraHandleColumnInfo = model.NewExtraHandleColInfo() @@ -78,8 +80,6 @@ func NewTableKVEncoder(tbl table.Table, options *SessionOptions) Encoder { } } -type rowArrayMarshaler []types.Datum - var kindStr = [...]string{ types.KindNull: "null", types.KindInt64: "int64", @@ -103,31 +103,33 @@ var kindStr = [...]string{ } // MarshalLogArray implements the zapcore.ArrayMarshaler interface. -func (row rowArrayMarshaler) MarshalLogArray(encoder zapcore.ArrayEncoder) error { - for _, datum := range row { - kind := datum.Kind() - var str string - var err error - switch kind { - case types.KindNull: - str = "NULL" - case types.KindMinNotNull: - str = "-inf" - case types.KindMaxValue: - str = "+inf" - default: - str, err = datum.ToString() - if err != nil { - return errors.Trace(err) +func zapRow(key string, row []types.Datum) zap.Field { + return logutil.AbbreviatedArray(key, row, func(input interface{}) []string { + row := input.([]types.Datum) + vals := make([]string, 0, len(row)) + for _, datum := range row { + kind := datum.Kind() + var str string + var err error + switch kind { + case types.KindNull: + str = "NULL" + case types.KindMinNotNull: + str = "-inf" + case types.KindMaxValue: + str = "+inf" + default: + str, err = datum.ToString() + if err != nil { + vals = append(vals, err.Error()) + continue + } } + vals = append(vals, + fmt.Sprintf("kind: %s, val: %s", kindStr[kind], redact.String(str))) } - _ = encoder.AppendObject(zapcore.ObjectMarshalerFunc(func(enc zapcore.ObjectEncoder) error { - enc.AddString("kind", kindStr[kind]) - enc.AddString("val", logutil.RedactString(str)) - return nil - })) - } - return nil + return vals + }) } // Pairs represents the slice of Pair. @@ -214,8 +216,8 @@ func (kvcodec *tableKVEncoder) AddRecord( _, err = kvcodec.tbl.AddRecord(kvcodec.se, record) if err != nil { log.Error("kv add Record failed", - zap.Array("originalRow", rowArrayMarshaler(row)), - zap.Array("convertedRow", rowArrayMarshaler(record)), + zapRow("originalRow", row), + zapRow("convertedRow", record), zap.Error(err), ) return nil, 0, errors.Trace(err) @@ -265,8 +267,8 @@ func (kvcodec *tableKVEncoder) RemoveRecord( err = kvcodec.tbl.RemoveRecord(kvcodec.se, rowID, record) if err != nil { log.Error("kv remove record failed", - zap.Array("originalRow", rowArrayMarshaler(row)), - zap.Array("convertedRow", rowArrayMarshaler(record)), + zapRow("originalRow", row), + zapRow("convertedRow", record), zap.Error(err), ) return nil, 0, errors.Trace(err) diff --git a/pkg/kv/kv_test.go b/pkg/kv/kv_test.go index 9aa2c9554..b2109d2ad 100644 --- a/pkg/kv/kv_test.go +++ b/pkg/kv/kv_test.go @@ -14,12 +14,13 @@ package kv import ( + "strings" "testing" . "github.com/pingcap/check" - "github.com/pingcap/log" "github.com/pingcap/tidb/types" "go.uber.org/zap" + "go.uber.org/zap/zapcore" ) type rowSuite struct{} @@ -37,6 +38,9 @@ func (s *rowSuite) TestMarshal(c *C) { dats[2] = types.MaxValueDatum() dats[3] = types.MinNotNullDatum() - // save coverage for MarshalLogArray - log.Info("row marshal", zap.Array("row", rowArrayMarshaler(dats))) + encoder := zapcore.NewConsoleEncoder(zapcore.EncoderConfig{}) + out, err := encoder.EncodeEntry(zapcore.Entry{}, []zap.Field{zapRow("row", dats)}) + c.Assert(err, IsNil) + c.Assert(strings.TrimRight(out.String(), "\n"), Equals, + `{"row": ["kind: int64, val: 1", "kind: null, val: NULL", "kind: max, val: +inf", "kind: min, val: -inf"]}`) } diff --git a/pkg/logutil/logging.go b/pkg/logutil/logging.go index ee11f814b..b02bf4a99 100644 --- a/pkg/logutil/logging.go +++ b/pkg/logutil/logging.go @@ -8,23 +8,48 @@ import ( "strings" "github.com/google/uuid" - "github.com/pingcap/errors" "github.com/pingcap/kvproto/pkg/backup" "github.com/pingcap/kvproto/pkg/import_sstpb" "github.com/pingcap/kvproto/pkg/metapb" - "github.com/pingcap/tidb/kv" "go.uber.org/zap" "go.uber.org/zap/zapcore" + + "github.com/pingcap/br/pkg/redact" ) -type zapMarshalFileMixIn struct{ *backup.File } +// AbbreviatedArrayMarshaler abbreviates an array of elements. +type AbbreviatedArrayMarshaler []string + +// MarshalLogArray implements zapcore.ArrayMarshaler. +func (abb AbbreviatedArrayMarshaler) MarshalLogArray(encoder zapcore.ArrayEncoder) error { + if len(abb) <= 4 { + for _, e := range abb { + encoder.AppendString(e) + } + } else { + total := len(abb) + encoder.AppendString(abb[0]) + encoder.AppendString(fmt.Sprintf("(skip %d)", total-2)) + encoder.AppendString(abb[total-1]) + } + return nil +} + +// AbbreviatedArray constructs a field that abbreviates an array of elements. +func AbbreviatedArray( + key string, elements interface{}, marshalFunc func(interface{}) []string, +) zap.Field { + return zap.Array(key, AbbreviatedArrayMarshaler(marshalFunc(elements))) +} + +type zapFileMarshaler struct{ *backup.File } -func (file zapMarshalFileMixIn) MarshalLogObject(enc zapcore.ObjectEncoder) error { +func (file zapFileMarshaler) MarshalLogObject(enc zapcore.ObjectEncoder) error { enc.AddString("name", file.GetName()) enc.AddString("CF", file.GetCf()) enc.AddString("sha256", hex.EncodeToString(file.GetSha256())) - enc.AddString("startKey", WrapKey(file.GetStartKey()).String()) - enc.AddString("endKey", WrapKey(file.GetEndKey()).String()) + enc.AddString("startKey", redact.Key(file.GetStartKey())) + enc.AddString("endKey", redact.Key(file.GetEndKey())) enc.AddUint64("startVersion", file.GetStartVersion()) enc.AddUint64("endVersion", file.GetEndVersion()) enc.AddUint64("totalKvs", file.GetTotalKvs()) @@ -33,110 +58,131 @@ func (file zapMarshalFileMixIn) MarshalLogObject(enc zapcore.ObjectEncoder) erro return nil } -type zapMarshalRewriteRuleMixIn struct{ *import_sstpb.RewriteRule } +type zapFilesMarshaler []*backup.File -func (rewriteRule zapMarshalRewriteRuleMixIn) MarshalLogObject(enc zapcore.ObjectEncoder) error { +func (fs zapFilesMarshaler) MarshalLogObject(encoder zapcore.ObjectEncoder) error { + total := len(fs) + encoder.AddInt("total", total) + elements := make([]string, 0, total) + for _, f := range fs { + elements = append(elements, f.GetName()) + } + _ = encoder.AddArray("files", AbbreviatedArrayMarshaler(elements)) + + totalKVs := uint64(0) + totalBytes := uint64(0) + totalSize := uint64(0) + for _, file := range fs { + totalKVs += file.GetTotalKvs() + totalBytes += file.GetTotalBytes() + totalSize += file.GetSize_() + } + encoder.AddUint64("totalKVs", totalKVs) + encoder.AddUint64("totalBytes", totalBytes) + encoder.AddUint64("totalSize", totalSize) + return nil +} + +// File make the zap fields for a file. +func File(file *backup.File) zap.Field { + return zap.Object("file", zapFileMarshaler{file}) +} + +// Files make the zap field for a set of file. +func Files(fs []*backup.File) zap.Field { + return zap.Object("files", zapFilesMarshaler(fs)) +} + +type zapRewriteRuleMarshaler struct{ *import_sstpb.RewriteRule } + +func (rewriteRule zapRewriteRuleMarshaler) MarshalLogObject(enc zapcore.ObjectEncoder) error { enc.AddString("oldKeyPrefix", hex.EncodeToString(rewriteRule.GetOldKeyPrefix())) enc.AddString("newKeyPrefix", hex.EncodeToString(rewriteRule.GetNewKeyPrefix())) enc.AddUint64("newTimestamp", rewriteRule.GetNewTimestamp()) return nil } -type zapMarshalRegionMixIn struct{ *metapb.Region } +// RewriteRule make the zap fields for a rewrite rule. +func RewriteRule(rewriteRule *import_sstpb.RewriteRule) zap.Field { + return zap.Object("rewriteRule", zapRewriteRuleMarshaler{rewriteRule}) +} + +type zapMarshalRegionMarshaler struct{ *metapb.Region } -func (region zapMarshalRegionMixIn) MarshalLogObject(enc zapcore.ObjectEncoder) error { +func (region zapMarshalRegionMarshaler) MarshalLogObject(enc zapcore.ObjectEncoder) error { peers := make([]string, 0, len(region.GetPeers())) for _, peer := range region.GetPeers() { peers = append(peers, peer.String()) } enc.AddUint64("ID", region.Id) - enc.AddString("startKey", WrapKey(region.GetStartKey()).String()) - enc.AddString("endKey", WrapKey(region.GetEndKey()).String()) + enc.AddString("startKey", redact.Key(region.GetStartKey())) + enc.AddString("endKey", redact.Key(region.GetEndKey())) enc.AddString("epoch", region.GetRegionEpoch().String()) enc.AddString("peers", strings.Join(peers, ",")) return nil } -type zapMarshalSSTMetaMixIn struct{ *import_sstpb.SSTMeta } +// Region make the zap fields for a region. +func Region(region *metapb.Region) zap.Field { + return zap.Object("region", zapMarshalRegionMarshaler{region}) +} + +// Leader make the zap fields for a peer. +// nolint:interfacer +func Leader(peer *metapb.Peer) zap.Field { + return zap.String("leader", peer.String()) +} + +type zapSSTMetaMarshaler struct{ *import_sstpb.SSTMeta } -func (sstMeta zapMarshalSSTMetaMixIn) MarshalLogObject(enc zapcore.ObjectEncoder) error { +func (sstMeta zapSSTMetaMarshaler) MarshalLogObject(enc zapcore.ObjectEncoder) error { enc.AddString("CF", sstMeta.GetCfName()) enc.AddBool("endKeyExclusive", sstMeta.EndKeyExclusive) enc.AddUint32("CRC32", sstMeta.Crc32) enc.AddUint64("length", sstMeta.Length) enc.AddUint64("regionID", sstMeta.RegionId) enc.AddString("regionEpoch", sstMeta.RegionEpoch.String()) - enc.AddString("rangeStart", WrapKey(sstMeta.GetRange().GetStart()).String()) - enc.AddString("rangeEnd", WrapKey(sstMeta.GetRange().GetEnd()).String()) + enc.AddString("startKey", redact.Key(sstMeta.GetRange().GetStart())) + enc.AddString("endKey", redact.Key(sstMeta.GetRange().GetEnd())) sstUUID, err := uuid.FromBytes(sstMeta.GetUuid()) if err != nil { - return errors.Trace(err) + enc.AddString("UUID", fmt.Sprintf("invalid UUID %s", hex.EncodeToString(sstMeta.GetUuid()))) + } else { + enc.AddString("UUID", sstUUID.String()) } - enc.AddString("UUID", sstUUID.String()) return nil } -type zapArrayMarshalKeysMixIn [][]byte - -func (keys zapArrayMarshalKeysMixIn) MarshalLogArray(enc zapcore.ArrayEncoder) error { - for _, key := range keys { - enc.AppendString(WrapKey(key).String()) - } - return nil +// SSTMeta make the zap fields for a SST meta. +func SSTMeta(sstMeta *import_sstpb.SSTMeta) zap.Field { + return zap.Object("sstMeta", zapSSTMetaMarshaler{sstMeta}) } -type files []*backup.File +type zapKeysMarshaler [][]byte -func (fs files) MarshalLogObject(encoder zapcore.ObjectEncoder) error { - totalKVs := uint64(0) - totalSize := uint64(0) - for _, file := range fs { - totalKVs += file.GetTotalKvs() - totalSize += file.GetTotalBytes() +func (keys zapKeysMarshaler) MarshalLogObject(encoder zapcore.ObjectEncoder) error { + total := len(keys) + encoder.AddInt("total", total) + elements := make([]string, 0, total) + for _, k := range keys { + elements = append(elements, redact.Key(k)) } - encoder.AddUint64("totalKVs", totalKVs) - encoder.AddUint64("totalBytes", totalSize) - encoder.AddInt("totalFileCount", len(fs)) + _ = encoder.AddArray("keys", AbbreviatedArrayMarshaler(elements)) return nil } -// WrapKey wrap a key as a Stringer that can print proper upper hex format. -func WrapKey(key []byte) fmt.Stringer { - return RedactStringer(kv.Key(key)) -} - -// WrapKeys wrap keys as an ArrayMarshaler that can print proper upper hex format. -func WrapKeys(keys [][]byte) zapcore.ArrayMarshaler { - return zapArrayMarshalKeysMixIn(keys) -} - -// RewriteRule make the zap fields for a rewrite rule. -func RewriteRule(rewriteRule *import_sstpb.RewriteRule) zapcore.Field { - return zap.Object("rewriteRule", zapMarshalRewriteRuleMixIn{rewriteRule}) -} - -// Region make the zap fields for a region. -func Region(region *metapb.Region) zapcore.Field { - return zap.Object("region", zapMarshalRegionMixIn{region}) -} - -// File make the zap fields for a file. -func File(file *backup.File) zapcore.Field { - return zap.Object("file", zapMarshalFileMixIn{file}) +// Key constructs a field that carries upper hex format key. +func Key(fieldKey string, key []byte) zap.Field { + return zap.String(fieldKey, redact.Key(key)) } -// SSTMeta make the zap fields for a SST meta. -func SSTMeta(sstMeta *import_sstpb.SSTMeta) zapcore.Field { - return zap.Object("sstMeta", zapMarshalSSTMetaMixIn{sstMeta}) -} - -// Files make the zap field for a set of file. -func Files(fs []*backup.File) zapcore.Field { - return zap.Object("fs", files(fs)) +// Keys constructs a field that carries upper hex format keys. +func Keys(keys [][]byte) zap.Field { + return zap.Object("keys", zapKeysMarshaler(keys)) } // ShortError make the zap field to display error without verbose representation (e.g. the stack trace). -func ShortError(err error) zapcore.Field { +func ShortError(err error) zap.Field { return zap.String("error", err.Error()) } diff --git a/pkg/logutil/logging_test.go b/pkg/logutil/logging_test.go new file mode 100644 index 000000000..9042444a2 --- /dev/null +++ b/pkg/logutil/logging_test.go @@ -0,0 +1,167 @@ +// Copyright 2021 PingCAP, Inc. Licensed under Apache-2.0. + +package logutil_test + +import ( + "fmt" + "strings" + "testing" + + . "github.com/pingcap/check" + "github.com/pingcap/errors" + "github.com/pingcap/kvproto/pkg/backup" + "github.com/pingcap/kvproto/pkg/import_sstpb" + "github.com/pingcap/kvproto/pkg/metapb" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + + berrors "github.com/pingcap/br/pkg/errors" + "github.com/pingcap/br/pkg/logutil" +) + +func Test(t *testing.T) { + TestingT(t) +} + +var _ = Suite(&testLoggingSuite{}) + +type testLoggingSuite struct{} + +func assertTrimEqual(c *C, f zapcore.Field, expect string) { + encoder := zapcore.NewConsoleEncoder(zapcore.EncoderConfig{}) + out, err := encoder.EncodeEntry(zapcore.Entry{}, []zap.Field{f}) + c.Assert(err, IsNil) + c.Assert(strings.TrimRight(out.String(), "\n"), Equals, expect) +} + +func newFile(j int) *backup.File { + return &backup.File{ + Name: fmt.Sprint(j), + StartKey: []byte(fmt.Sprint(j)), + EndKey: []byte(fmt.Sprint(j + 1)), + TotalKvs: uint64(j), + TotalBytes: uint64(j), + StartVersion: uint64(j), + EndVersion: uint64(j + 1), + Crc64Xor: uint64(j), + Sha256: []byte(fmt.Sprint(j)), + Cf: "write", + Size_: uint64(j), + } +} + +func (s *testLoggingSuite) TestFile(c *C) { + assertTrimEqual(c, logutil.File(newFile(1)), + `{"file": {"name": "1", "CF": "write", "sha256": "31", "startKey": "31", "endKey": "32", "startVersion": 1, "endVersion": 2, "totalKvs": 1, "totalBytes": 1, "CRC64Xor": 1}}`) +} + +func (s *testLoggingSuite) TestFiles(c *C) { + cases := []struct { + count int + expect string + }{ + {0, `{"files": {"total": 0, "files": [], "totalKVs": 0, "totalBytes": 0, "totalSize": 0}}`}, + {1, `{"files": {"total": 1, "files": ["0"], "totalKVs": 0, "totalBytes": 0, "totalSize": 0}}`}, + {2, `{"files": {"total": 2, "files": ["0", "1"], "totalKVs": 1, "totalBytes": 1, "totalSize": 1}}`}, + {3, `{"files": {"total": 3, "files": ["0", "1", "2"], "totalKVs": 3, "totalBytes": 3, "totalSize": 3}}`}, + {4, `{"files": {"total": 4, "files": ["0", "1", "2", "3"], "totalKVs": 6, "totalBytes": 6, "totalSize": 6}}`}, + {5, `{"files": {"total": 5, "files": ["0", "(skip 3)", "4"], "totalKVs": 10, "totalBytes": 10, "totalSize": 10}}`}, + {6, `{"files": {"total": 6, "files": ["0", "(skip 4)", "5"], "totalKVs": 15, "totalBytes": 15, "totalSize": 15}}`}, + {1024, `{"files": {"total": 1024, "files": ["0", "(skip 1022)", "1023"], "totalKVs": 523776, "totalBytes": 523776, "totalSize": 523776}}`}, + } + + for _, cs := range cases { + ranges := make([]*backup.File, cs.count) + for j := 0; j < cs.count; j++ { + ranges[j] = newFile(j) + } + assertTrimEqual(c, logutil.Files(ranges), cs.expect) + } +} + +func (s *testLoggingSuite) TestKey(c *C) { + encoder := zapcore.NewConsoleEncoder(zapcore.EncoderConfig{}) + out, err := encoder.EncodeEntry(zapcore.Entry{}, []zap.Field{logutil.Key("test", []byte{0, 1, 2, 3})}) + c.Assert(err, IsNil) + c.Assert(strings.Trim(out.String(), "\n"), Equals, `{"test": "00010203"}`) +} + +func (s *testLoggingSuite) TestKeys(c *C) { + cases := []struct { + count int + expect string + }{ + {0, `{"keys": {"total": 0, "keys": []}}`}, + {1, `{"keys": {"total": 1, "keys": ["30303030"]}}`}, + {2, `{"keys": {"total": 2, "keys": ["30303030", "30303031"]}}`}, + {3, `{"keys": {"total": 3, "keys": ["30303030", "30303031", "30303032"]}}`}, + {4, `{"keys": {"total": 4, "keys": ["30303030", "30303031", "30303032", "30303033"]}}`}, + {5, `{"keys": {"total": 5, "keys": ["30303030", "(skip 3)", "30303034"]}}`}, + {6, `{"keys": {"total": 6, "keys": ["30303030", "(skip 4)", "30303035"]}}`}, + {1024, `{"keys": {"total": 1024, "keys": ["30303030", "(skip 1022)", "31303233"]}}`}, + } + + for _, cs := range cases { + keys := make([][]byte, cs.count) + for j := 0; j < cs.count; j++ { + keys[j] = []byte(fmt.Sprintf("%04d", j)) + } + assertTrimEqual(c, logutil.Keys(keys), cs.expect) + } +} + +func (s *testLoggingSuite) TestRewriteRule(c *C) { + rule := &import_sstpb.RewriteRule{ + OldKeyPrefix: []byte("old"), + NewKeyPrefix: []byte("new"), + NewTimestamp: 0x555555, + } + + encoder := zapcore.NewConsoleEncoder(zapcore.EncoderConfig{}) + out, err := encoder.EncodeEntry(zapcore.Entry{}, []zap.Field{logutil.RewriteRule(rule)}) + c.Assert(err, IsNil) + c.Assert(strings.Trim(out.String(), "\n"), Equals, `{"rewriteRule": {"oldKeyPrefix": "6f6c64", "newKeyPrefix": "6e6577", "newTimestamp": 5592405}}`) +} + +func (s *testLoggingSuite) TestRegion(c *C) { + region := &metapb.Region{ + Id: 1, + StartKey: []byte{0x00, 0x01}, + EndKey: []byte{0x00, 0x02}, + RegionEpoch: &metapb.RegionEpoch{ConfVer: 1, Version: 1}, + Peers: []*metapb.Peer{{Id: 2, StoreId: 3}, {Id: 4, StoreId: 5}}, + } + + assertTrimEqual(c, logutil.Region(region), + `{"region": {"ID": 1, "startKey": "0001", "endKey": "0002", "epoch": "conf_ver:1 version:1 ", "peers": "id:2 store_id:3 ,id:4 store_id:5 "}}`) +} + +func (s *testLoggingSuite) TestLeader(c *C) { + leader := &metapb.Peer{Id: 2, StoreId: 3} + + assertTrimEqual(c, logutil.Leader(leader), `{"leader": "id:2 store_id:3 "}`) +} + +func (s *testLoggingSuite) TestSSTMeta(c *C) { + meta := &import_sstpb.SSTMeta{ + Uuid: []byte("mock uuid"), + Range: &import_sstpb.Range{ + Start: []byte{0x00, 0x01}, + End: []byte{0x00, 0x02}, + }, + Crc32: uint32(0x555555), + Length: 1, + CfName: "default", + RegionId: 1, + RegionEpoch: &metapb.RegionEpoch{ConfVer: 1, Version: 1}, + } + + assertTrimEqual(c, logutil.SSTMeta(meta), + `{"sstMeta": {"CF": "default", "endKeyExclusive": false, "CRC32": 5592405, "length": 1, "regionID": 1, "regionEpoch": "conf_ver:1 version:1 ", "startKey": "0001", "endKey": "0002", "UUID": "invalid UUID 6d6f636b2075756964"}}`) +} + +func (s *testLoggingSuite) TestShortError(c *C) { + err := errors.Annotate(berrors.ErrInvalidArgument, "test") + + assertTrimEqual(c, logutil.ShortError(err), `{"error": "test: [BR:Common:ErrInvalidArgument]invalid argument"}`) +} diff --git a/pkg/logutil/redact.go b/pkg/logutil/redact.go deleted file mode 100644 index a188d077a..000000000 --- a/pkg/logutil/redact.go +++ /dev/null @@ -1,57 +0,0 @@ -// Copyright 2020 PingCAP, Inc. Licensed under Apache-2.0. - -package logutil - -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() -} - -// 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 "?" -} diff --git a/pkg/redact/redact.go b/pkg/redact/redact.go new file mode 100644 index 000000000..495bceb08 --- /dev/null +++ b/pkg/redact/redact.go @@ -0,0 +1,36 @@ +// Copyright 2020 PingCAP, Inc. Licensed under Apache-2.0. + +package redact + +import ( + "encoding/hex" + "strings" + + "github.com/pingcap/errors" +) + +// 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() +} + +// String receives string argument and return omitted information if redact log enabled +func String(arg string) string { + if NeedRedact() { + return "?" + } + return arg +} + +// Key receives a key return omitted information if redact log enabled +func Key(key []byte) string { + if NeedRedact() { + return "?" + } + return strings.ToUpper(hex.EncodeToString(key)) +} diff --git a/pkg/redact/redact_test.go b/pkg/redact/redact_test.go new file mode 100644 index 000000000..d9891a510 --- /dev/null +++ b/pkg/redact/redact_test.go @@ -0,0 +1,32 @@ +// Copyright 2021 PingCAP, Inc. Licensed under Apache-2.0. + +package redact_test + +import ( + "testing" + + . "github.com/pingcap/check" + + "github.com/pingcap/br/pkg/redact" +) + +type testRedactSuite struct{} + +func (s *testRedactSuite) SetUpSuite(c *C) {} +func (s *testRedactSuite) TearDownSuite(c *C) {} + +var _ = Suite(&testRedactSuite{}) + +func TestT(t *testing.T) {} + +func (s *testRedactSuite) TestRedact(c *C) { + redacted, secret := "?", "secret" + + redact.InitRedact(false) + c.Assert(redact.String(secret), Equals, secret) + c.Assert(redact.Key([]byte(secret)), Equals, secret) + + redact.InitRedact(true) + c.Assert(redact.String(secret), Equals, redacted) + c.Assert(redact.Key([]byte(secret)), Equals, redacted) +} diff --git a/pkg/restore/batcher.go b/pkg/restore/batcher.go index 18f0ff6cb..ad5687ccb 100644 --- a/pkg/restore/batcher.go +++ b/pkg/restore/batcher.go @@ -317,10 +317,7 @@ func (b *Batcher) Send(ctx context.Context) { drainResult := b.drainRanges() tbs := drainResult.TablesToSend ranges := drainResult.Ranges - log.Info("restore batch start", - ZapRanges(ranges), - ZapTables(tbs), - ) + log.Info("restore batch start", rtree.ZapRanges(ranges), ZapTables(tbs)) // Leave is called at b.contextCleaner if err := b.manager.Enter(ctx, drainResult.TablesToSend); err != nil { b.sendErr <- err diff --git a/pkg/restore/batcher_test.go b/pkg/restore/batcher_test.go index 453f09701..c79e15596 100644 --- a/pkg/restore/batcher_test.go +++ b/pkg/restore/batcher_test.go @@ -41,7 +41,7 @@ func (sender *drySender) PutSink(sink restore.TableSink) { func (sender *drySender) RestoreBatch(ranges restore.DrainResult) { sender.mu.Lock() defer sender.mu.Unlock() - log.Info("fake restore range", restore.ZapRanges(ranges.Ranges)) + log.Info("fake restore range", rtree.ZapRanges(ranges.Ranges)) sender.nBatch++ sender.rewriteRules.Append(*ranges.RewriteRules) sender.ranges = append(sender.ranges, ranges.Ranges...) diff --git a/pkg/restore/client.go b/pkg/restore/client.go index 2a59d3414..ff1ff1a65 100644 --- a/pkg/restore/client.go +++ b/pkg/restore/client.go @@ -536,16 +536,25 @@ func (rc *Client) RestoreFiles( defer func() { elapsed := time.Since(start) if err == nil { - log.Info("Restore files", - zap.Duration("take", elapsed), - logutil.Files(files)) + log.Info("Restore files", zap.Duration("take", elapsed), logutil.Files(files)) summary.CollectSuccessUnit("files", len(files), elapsed) } }() +<<<<<<< HEAD log.Debug("start to restore files", zap.Int("files", len(files)), ) +======= + log.Debug("start to restore files", zap.Int("files", len(files))) + + if span := opentracing.SpanFromContext(ctx); span != nil && span.Tracer() != nil { + span1 := span.Tracer().StartSpan("Client.RestoreFiles", opentracing.ChildOf(span.Context())) + defer span1.Finish() + ctx = opentracing.ContextWithSpan(ctx, span1) + } + +>>>>>>> c206add... *: refine logs (#723) eg, ectx := errgroup.WithContext(ctx) err = rc.setSpeedLimit(ctx) if err != nil { @@ -584,8 +593,8 @@ func (rc *Client) RestoreRaw( defer func() { elapsed := time.Since(start) log.Info("Restore Raw", - zap.Stringer("startKey", logutil.WrapKey(startKey)), - zap.Stringer("endKey", logutil.WrapKey(endKey)), + logutil.Key("startKey", startKey), + logutil.Key("endKey", endKey), zap.Duration("take", elapsed)) }() errCh := make(chan error, len(files)) @@ -608,16 +617,16 @@ func (rc *Client) RestoreRaw( if err := eg.Wait(); err != nil { log.Error( "restore raw range failed", - zap.Stringer("startKey", logutil.WrapKey(startKey)), - zap.Stringer("endKey", logutil.WrapKey(endKey)), + logutil.Key("startKey", startKey), + logutil.Key("endKey", endKey), zap.Error(err), ) return errors.Trace(err) } log.Info( "finish to restore raw range", - zap.Stringer("startKey", logutil.WrapKey(startKey)), - zap.Stringer("endKey", logutil.WrapKey(endKey)), + logutil.Key("startKey", startKey), + logutil.Key("endKey", endKey), ) return nil } diff --git a/pkg/restore/import.go b/pkg/restore/import.go index d50ad9f0a..fd6fd5d48 100644 --- a/pkg/restore/import.go +++ b/pkg/restore/import.go @@ -216,8 +216,8 @@ func (importer *FileImporter) Import( } log.Debug("rewrite file keys", logutil.File(file), - zap.Stringer("startKey", logutil.WrapKey(startKey)), - zap.Stringer("endKey", logutil.WrapKey(endKey))) + logutil.Key("startKey", startKey), + logutil.Key("endKey", endKey)) err = utils.WithRetry(ctx, func() error { tctx, cancel := context.WithTimeout(ctx, importScanRegionTime) @@ -253,8 +253,8 @@ func (importer *FileImporter) Import( log.Warn("download file skipped", logutil.File(file), logutil.Region(info.Region), - zap.Stringer("startKey", logutil.WrapKey(startKey)), - zap.Stringer("endKey", logutil.WrapKey(endKey)), + logutil.Key("startKey", startKey), + logutil.Key("endKey", endKey), logutil.ShortError(e)) continue regionLoop } @@ -262,8 +262,8 @@ func (importer *FileImporter) Import( log.Error("download file failed", logutil.File(file), logutil.Region(info.Region), - zap.Stringer("startKey", logutil.WrapKey(startKey)), - zap.Stringer("endKey", logutil.WrapKey(endKey)), + logutil.Key("startKey", startKey), + logutil.Key("endKey", endKey), logutil.ShortError(errDownload)) return errors.Trace(errDownload) } @@ -327,7 +327,7 @@ func (importer *FileImporter) Import( if errIngest != nil { log.Error("ingest file failed", logutil.File(file), - logutil.ZapRedactStringer("range", downloadMeta.GetRange()), + logutil.SSTMeta(downloadMeta), logutil.Region(info.Region), zap.Error(errIngest)) return errors.Trace(errIngest) @@ -467,7 +467,7 @@ func (importer *FileImporter) ingestSST( Context: reqCtx, Sst: sstMeta, } - log.Debug("ingest SST", logutil.SSTMeta(sstMeta), zap.Reflect("leader", leader)) + log.Debug("ingest SST", logutil.SSTMeta(sstMeta), logutil.Leader(leader)) resp, err := importer.importClient.IngestSST(ctx, leader.GetStoreId(), req) if err != nil { return nil, errors.Trace(err) diff --git a/pkg/restore/log_client.go b/pkg/restore/log_client.go index f01c67067..39fb1c007 100644 --- a/pkg/restore/log_client.go +++ b/pkg/restore/log_client.go @@ -555,8 +555,8 @@ func (l *LogClient) doWriteAndIngest(ctx context.Context, kvs kv.Pairs, region * log.Debug("ingest meta", zap.Reflect("meta", meta)) resp, err := l.Ingest(ctx, meta, region) if err != nil { - log.Warn("ingest failed", zap.Error(err), logutil.SSTMeta(meta), - logutil.Region(region.Region), zap.Any("leader", region.Leader)) + log.Warn("ingest failed, retry", zap.Error(err), logutil.SSTMeta(meta), + logutil.Region(region.Region), logutil.Leader(region.Leader)) continue } needRetry, newRegion, errIngest := isIngestRetryable(resp, region, meta) @@ -565,8 +565,13 @@ func (l *LogClient) doWriteAndIngest(ctx context.Context, kvs kv.Pairs, region * break } if !needRetry { +<<<<<<< HEAD log.Warn("ingest failed noretry", zap.Error(errIngest), logutil.SSTMeta(meta), logutil.Region(region.Region), zap.Any("leader", region.Leader)) +======= + log.Warn("ingest failed", zap.Error(errIngest), logutil.SSTMeta(meta), + logutil.Region(region.Region), logutil.Leader(region.Leader)) +>>>>>>> c206add... *: refine logs (#723) // met non-retryable error retry whole Write procedure return errIngest } @@ -574,8 +579,8 @@ func (l *LogClient) doWriteAndIngest(ctx context.Context, kvs kv.Pairs, region * if newRegion != nil && i < maxRetryTimes-1 { region = newRegion } else { - log.Warn("retry ingest due to", logutil.SSTMeta(meta), logutil.Region(region.Region), - zap.Any("leader", region.Leader), logutil.ZapRedactReflect("new region", newRegion), + log.Warn("ingest failed", logutil.SSTMeta(meta), logutil.Region(region.Region), + logutil.Leader(region.Leader), logutil.Region(newRegion.Region), zap.Error(errIngest)) return errIngest } diff --git a/pkg/restore/pipeline_items.go b/pkg/restore/pipeline_items.go index d639f4be4..55490be0d 100644 --- a/pkg/restore/pipeline_items.go +++ b/pkg/restore/pipeline_items.go @@ -232,10 +232,7 @@ func (b *tikvSender) splitWorker(ctx context.Context, ranges <-chan DrainResult, return } if err := SplitRanges(ctx, b.client, result.Ranges, result.RewriteRules, b.updateCh); err != nil { - log.Error("failed on split range", - ZapRanges(result.Ranges), - zap.Error(err), - ) + log.Error("failed on split range", rtree.ZapRanges(result.Ranges), zap.Error(err)) b.sink.EmitError(err) return } @@ -264,10 +261,7 @@ func (b *tikvSender) restoreWorker(ctx context.Context, ranges <-chan DrainResul return } - log.Info("restore batch done", - ZapRanges(result.Ranges), - zap.Int("file count", len(files)), - ) + log.Info("restore batch done", rtree.ZapRanges(result.Ranges)) b.sink.EmitTables(result.BlankTablesAfterSend...) } } diff --git a/pkg/restore/range.go b/pkg/restore/range.go index 16058f7e2..54e5fa687 100644 --- a/pkg/restore/range.go +++ b/pkg/restore/range.go @@ -28,26 +28,25 @@ func SortRanges(ranges []rtree.Range, rewriteRules *RewriteRules) ([]rtree.Range if startID == endID { rg.StartKey, rule = replacePrefix(rg.StartKey, rewriteRules) if rule == nil { - log.Warn("cannot find rewrite rule", zap.Stringer("key", logutil.WrapKey(rg.StartKey))) + log.Warn("cannot find rewrite rule", logutil.Key("key", rg.StartKey)) } else { log.Debug( "rewrite start key", - zap.Stringer("key", logutil.WrapKey(rg.StartKey)), - logutil.RewriteRule(rule)) + logutil.Key("key", rg.StartKey), logutil.RewriteRule(rule)) } rg.EndKey, rule = replacePrefix(rg.EndKey, rewriteRules) if rule == nil { - log.Warn("cannot find rewrite rule", zap.Stringer("key", logutil.WrapKey(rg.EndKey))) + log.Warn("cannot find rewrite rule", logutil.Key("key", rg.EndKey)) } else { log.Debug( "rewrite end key", - zap.Stringer("key", logutil.WrapKey(rg.EndKey)), + logutil.Key("key", rg.EndKey), logutil.RewriteRule(rule)) } } else { log.Warn("table id does not match", - zap.Stringer("startKey", logutil.WrapKey(rg.StartKey)), - zap.Stringer("endKey", logutil.WrapKey(rg.EndKey)), + logutil.Key("startKey", rg.StartKey), + logutil.Key("endKey", rg.EndKey), zap.Int64("startID", startID), zap.Int64("endID", endID)) return nil, errors.Annotate(berrors.ErrRestoreTableIDMismatch, "table id mismatch") @@ -55,8 +54,10 @@ func SortRanges(ranges []rtree.Range, rewriteRules *RewriteRules) ([]rtree.Range } if out := rangeTree.InsertRange(rg); out != nil { log.Error("insert ranges overlapped", - logutil.ZapRedactReflect("out", out), - logutil.ZapRedactReflect("range", rg)) + logutil.Key("startKeyOut", out.StartKey), + logutil.Key("endKeyOut", out.EndKey), + logutil.Key("startKeyIn", rg.StartKey), + logutil.Key("endKeyIn", rg.EndKey)) return nil, errors.Annotatef(berrors.ErrRestoreInvalidRange, "ranges overlapped") } } diff --git a/pkg/restore/split.go b/pkg/restore/split.go index 6ff850732..74a95310d 100644 --- a/pkg/restore/split.go +++ b/pkg/restore/split.go @@ -69,6 +69,7 @@ func (rs *RegionSplitter) Split( onSplit OnSplitFunc, ) error { if len(ranges) == 0 { + log.Info("skip split regions, no range") return nil } startTime := time.Now() @@ -104,7 +105,7 @@ SplitRegions: return errors.Trace(errScan) } if len(regions) == 0 { - log.Warn("cannot scan any region") + log.Warn("split regions cannot scan any region") return nil } splitKeyMap := GetSplitKeys(rewriteRules, sortedRanges, regions) @@ -115,14 +116,19 @@ SplitRegions: for regionID, keys := range splitKeyMap { var newRegions []*RegionInfo region := regionMap[regionID] + log.Info("split regions", + logutil.Region(region.Region), logutil.Keys(keys), rtree.ZapRanges(ranges)) newRegions, errSplit = rs.splitAndScatterRegions(ctx, region, keys) if errSplit != nil { if strings.Contains(errSplit.Error(), "no valid key") { for _, key := range keys { - log.Error("no valid key", - zap.Stringer("startKey", logutil.WrapKey(region.Region.StartKey)), - zap.Stringer("endKey", logutil.WrapKey(region.Region.EndKey)), - zap.Stringer("key", logutil.WrapKey(codec.EncodeBytes([]byte{}, key)))) + // Region start/end keys are encoded. split_region RPC + // requires raw keys (without encoding). + log.Error("split regions no valid key", + logutil.Key("startKey", region.Region.StartKey), + logutil.Key("endKey", region.Region.EndKey), + logutil.Key("key", codec.EncodeBytes([]byte{}, key)), + rtree.ZapRanges(ranges)) } return errors.Trace(errSplit) } @@ -131,16 +137,18 @@ SplitRegions: interval = SplitMaxRetryInterval } time.Sleep(interval) - if i > 3 { - log.Warn("splitting regions failed, retry it", - zap.Error(errSplit), - logutil.Region(region.Region), - zap.Any("leader", region.Leader), - zap.Array("keys", logutil.WrapKeys(keys))) - } + log.Warn("split regions failed, retry", + zap.Error(errSplit), + logutil.Region(region.Region), + logutil.Leader(region.Leader), + logutil.Keys(keys), rtree.ZapRanges(ranges)) continue SplitRegions } - log.Debug("split regions", logutil.Region(region.Region), zap.Array("keys", logutil.WrapKeys(keys))) + if len(newRegions) != len(keys) { + log.Warn("split key count and new region count mismatch", + zap.Int("new region count", len(newRegions)), + zap.Int("split key count", len(keys))) + } scatterRegions = append(scatterRegions, newRegions...) onSplit(keys) } @@ -194,7 +202,7 @@ func (rs *RegionSplitter) isScatterRegionFinished(ctx context.Context, regionID } retryTimes := ctx.Value(retryTimes).(int) if retryTimes > 3 { - log.Warn("get operator", zap.Uint64("regionID", regionID), zap.Stringer("resp", resp)) + log.Info("get operator", zap.Uint64("regionID", regionID), zap.Stringer("resp", resp)) } // If the current operator of the region is not 'scatter-region', we could assume // that 'scatter-operator' has finished or timeout @@ -286,9 +294,9 @@ func GetSplitKeys(rewriteRules *RewriteRules, ranges []rtree.Range, regions []*R } splitKeyMap[region.Region.GetId()] = append(splitKeys, key) log.Debug("get key for split region", - zap.Stringer("key", logutil.WrapKey(key)), - zap.Stringer("startKey", logutil.WrapKey(region.Region.StartKey)), - zap.Stringer("endKey", logutil.WrapKey(region.Region.EndKey))) + logutil.Key("key", key), + logutil.Key("startKey", region.Region.StartKey), + logutil.Key("endKey", region.Region.EndKey)) } } return splitKeyMap diff --git a/pkg/restore/split_client.go b/pkg/restore/split_client.go index 70f2763e1..1c5a56fcf 100755 --- a/pkg/restore/split_client.go +++ b/pkg/restore/split_client.go @@ -168,7 +168,7 @@ func (c *pdClient) SplitRegion(ctx context.Context, regionInfo *RegionInfo, key if resp.RegionError != nil { log.Error("fail to split region", logutil.Region(regionInfo.Region), - zap.Stringer("key", logutil.WrapKey(key)), + logutil.Key("key", key), zap.Stringer("regionErr", resp.RegionError)) return nil, errors.Annotatef(berrors.ErrRestoreSplitFailed, "err=%v", resp.RegionError) } diff --git a/pkg/restore/util.go b/pkg/restore/util.go index 19be1e4ab..5e0f4633c 100644 --- a/pkg/restore/util.go +++ b/pkg/restore/util.go @@ -126,14 +126,14 @@ func GetSSTMetaFromFile( if bytes.Compare(rangeStart, rangeEnd) > 0 { log.Panic("range start exceed range end", logutil.File(file), - zap.Stringer("rangeStart", logutil.WrapKey(rangeStart)), - zap.Stringer("rangeEnd", logutil.WrapKey(rangeEnd))) + logutil.Key("startKey", rangeStart), + logutil.Key("endKey", rangeEnd)) } log.Debug("get sstMeta", logutil.File(file), - zap.Stringer("rangeStart", logutil.WrapKey(rangeStart)), - zap.Stringer("rangeEnd", logutil.WrapKey(rangeEnd))) + logutil.Key("startKey", rangeStart), + logutil.Key("endKey", rangeEnd)) return import_sstpb.SSTMeta{ Uuid: id, @@ -204,14 +204,14 @@ func MapTableToFiles(files []*backup.File) map[int64][]*backup.File { if tableID != tableEndID { log.Panic("key range spread between many files.", zap.String("file name", file.Name), - zap.Stringer("start key", logutil.WrapKey(file.GetStartKey())), - zap.Stringer("end key", logutil.WrapKey(file.GetEndKey()))) + logutil.Key("startKey", file.StartKey), + logutil.Key("endKey", file.EndKey)) } if tableID == 0 { log.Panic("invalid table key of file", zap.String("file name", file.Name), - zap.Stringer("start key", logutil.WrapKey(file.GetStartKey())), - zap.Stringer("end key", logutil.WrapKey(file.GetEndKey()))) + logutil.Key("startKey", file.StartKey), + logutil.Key("endKey", file.EndKey)) } result[tableID] = append(result[tableID], file) } @@ -444,7 +444,7 @@ func rewriteFileKeys(file *backup.File, rewriteRules *RewriteRules) (startKey, e startKey, rule = rewriteRawKey(file.GetStartKey(), rewriteRules) if rewriteRules != nil && rule == nil { log.Error("cannot find rewrite rule", - zap.Stringer("startKey", logutil.WrapKey(file.GetStartKey())), + logutil.Key("startKey", file.GetStartKey()), zap.Reflect("rewrite table", rewriteRules.Table), zap.Reflect("rewrite data", rewriteRules.Data)) err = errors.Annotate(berrors.ErrRestoreInvalidRewrite, "cannot find rewrite rule for start key") @@ -459,8 +459,8 @@ func rewriteFileKeys(file *backup.File, rewriteRules *RewriteRules) (startKey, e log.Error("table ids dont matched", zap.Int64("startID", startID), zap.Int64("endID", endID), - zap.Stringer("startKey", logutil.WrapKey(startKey)), - zap.Stringer("endKey", logutil.WrapKey(endKey))) + logutil.Key("startKey", startKey), + logutil.Key("endKey", endKey)) err = errors.Annotate(berrors.ErrRestoreInvalidRewrite, "invalid table id") } return @@ -481,8 +481,8 @@ func PaginateScanRegion( ) ([]*RegionInfo, error) { if len(endKey) != 0 && bytes.Compare(startKey, endKey) >= 0 { log.Error("restore range startKey >= endKey", - zap.Stringer("startKey", logutil.WrapKey(startKey)), - zap.Stringer("endKey", logutil.WrapKey(endKey))) + logutil.Key("startKey", startKey), + logutil.Key("endKey", endKey)) return nil, errors.Annotatef(berrors.ErrRestoreInvalidRange, "startKey >= endKey") } @@ -509,42 +509,16 @@ func PaginateScanRegion( // ZapTables make zap field of table for debuging, including table names. func ZapTables(tables []CreatedTable) zapcore.Field { - return zap.Array("tables", tableSliceArrayMixIn(tables)) -} - -// ZapRanges make zap fields for debuging, which contains kv, size and count of ranges. -// TODO make it a lazy zap object. -func ZapRanges(ranges []rtree.Range) zapcore.Field { - return zap.Object("rangeInfo", rangesSliceObjectMixin(ranges)) -} - -type tableSliceArrayMixIn []CreatedTable - -func (ss tableSliceArrayMixIn) MarshalLogArray(encoder zapcore.ArrayEncoder) error { - for _, s := range ss { - encoder.AppendString(fmt.Sprintf("%s.%s", - utils.EncloseName(s.OldTable.DB.Name.String()), - utils.EncloseName(s.OldTable.Info.Name.String()))) - } - return nil -} - -type rangesSliceObjectMixin []rtree.Range - -func (rs rangesSliceObjectMixin) MarshalLogObject(encoder zapcore.ObjectEncoder) error { - totalKV := uint64(0) - totalSize := uint64(0) - for _, r := range rs { - for _, f := range r.Files { - totalKV += f.GetTotalKvs() - totalSize += f.GetTotalBytes() + return logutil.AbbreviatedArray("tables", tables, func(input interface{}) []string { + tables := input.([]CreatedTable) + names := make([]string, 0, len(tables)) + for _, t := range tables { + names = append(names, fmt.Sprintf("%s.%s", + utils.EncloseName(t.OldTable.DB.Name.String()), + utils.EncloseName(t.OldTable.Info.Name.String()))) } - } - - encoder.AddInt("ranges", len(rs)) - encoder.AddUint64("total kv", totalKV) - encoder.AddUint64("total size", totalSize) - return nil + return names + }) } // ParseQuoteName parse the quote `db`.`table` name, and split it. diff --git a/pkg/rtree/logging.go b/pkg/rtree/logging.go new file mode 100644 index 000000000..7c9e85d27 --- /dev/null +++ b/pkg/rtree/logging.go @@ -0,0 +1,61 @@ +// Copyright 2021 PingCAP, Inc. Licensed under Apache-2.0. + +package rtree + +import ( + "fmt" + + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + + "github.com/pingcap/br/pkg/logutil" + "github.com/pingcap/br/pkg/redact" +) + +// String formats a range to a string. +func (rg Range) String() string { + return fmt.Sprintf("[%s, %s)", redact.Key(rg.StartKey), redact.Key(rg.EndKey)) +} + +// ZapRanges make zap fields for logging Range slice. +func ZapRanges(ranges []Range) zapcore.Field { + return zap.Object("ranges", rangesMarshaler(ranges)) +} + +type rangesMarshaler []Range + +func (rs rangesMarshaler) MarshalLogArray(encoder zapcore.ArrayEncoder) error { + for _, r := range rs { + encoder.AppendString(r.String()) + } + return nil +} + +func (rs rangesMarshaler) MarshalLogObject(encoder zapcore.ObjectEncoder) error { + total := len(rs) + encoder.AddInt("total", total) + elements := make([]string, 0, total) + for _, r := range rs { + elements = append(elements, r.String()) + } + _ = encoder.AddArray("ranges", logutil.AbbreviatedArrayMarshaler(elements)) + + totalKV := uint64(0) + totalBytes := uint64(0) + totalSize := uint64(0) + totalFile := 0 + for _, r := range rs { + for _, f := range r.Files { + totalKV += f.GetTotalKvs() + totalBytes += f.GetTotalBytes() + totalSize += f.GetSize_() + } + totalFile += len(r.Files) + } + + encoder.AddInt("totalFiles", totalFile) + encoder.AddUint64("totalKVs", totalKV) + encoder.AddUint64("totalBytes", totalBytes) + encoder.AddUint64("totalSize", totalBytes) + return nil +} diff --git a/pkg/rtree/logging_test.go b/pkg/rtree/logging_test.go new file mode 100644 index 000000000..326fd8c26 --- /dev/null +++ b/pkg/rtree/logging_test.go @@ -0,0 +1,47 @@ +// Copyright 2021 PingCAP, Inc. Licensed under Apache-2.0. + +package rtree_test + +import ( + "fmt" + "strings" + + . "github.com/pingcap/check" + "github.com/pingcap/kvproto/pkg/backup" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + + "github.com/pingcap/br/pkg/rtree" +) + +var _ = Suite(&testLoggingSuite{}) + +type testLoggingSuite struct{} + +func (s *testLoggingSuite) TestLogRanges(c *C) { + cases := []struct { + count int + expect string + }{ + {0, `{"ranges": {"total": 0, "ranges": [], "totalFiles": 0, "totalKVs": 0, "totalBytes": 0, "totalSize": 0}}`}, + {1, `{"ranges": {"total": 1, "ranges": ["[30, 31)"], "totalFiles": 1, "totalKVs": 0, "totalBytes": 0, "totalSize": 0}}`}, + {2, `{"ranges": {"total": 2, "ranges": ["[30, 31)", "[31, 32)"], "totalFiles": 2, "totalKVs": 1, "totalBytes": 1, "totalSize": 1}}`}, + {3, `{"ranges": {"total": 3, "ranges": ["[30, 31)", "[31, 32)", "[32, 33)"], "totalFiles": 3, "totalKVs": 3, "totalBytes": 3, "totalSize": 3}}`}, + {4, `{"ranges": {"total": 4, "ranges": ["[30, 31)", "[31, 32)", "[32, 33)", "[33, 34)"], "totalFiles": 4, "totalKVs": 6, "totalBytes": 6, "totalSize": 6}}`}, + {5, `{"ranges": {"total": 5, "ranges": ["[30, 31)", "(skip 3)", "[34, 35)"], "totalFiles": 5, "totalKVs": 10, "totalBytes": 10, "totalSize": 10}}`}, + {6, `{"ranges": {"total": 6, "ranges": ["[30, 31)", "(skip 4)", "[35, 36)"], "totalFiles": 6, "totalKVs": 15, "totalBytes": 15, "totalSize": 15}}`}, + {1024, `{"ranges": {"total": 1024, "ranges": ["[30, 31)", "(skip 1022)", "[31303233, 31303234)"], "totalFiles": 1024, "totalKVs": 523776, "totalBytes": 523776, "totalSize": 523776}}`}, + } + + encoder := zapcore.NewConsoleEncoder(zapcore.EncoderConfig{}) + for _, cs := range cases { + ranges := make([]rtree.Range, cs.count) + for j := 0; j < cs.count; j++ { + ranges[j] = *newRange([]byte(fmt.Sprintf("%d", j)), []byte(fmt.Sprintf("%d", j+1))) + ranges[j].Files = append(ranges[j].Files, &backup.File{TotalKvs: uint64(j), TotalBytes: uint64(j)}) + } + out, err := encoder.EncodeEntry(zapcore.Entry{}, []zap.Field{rtree.ZapRanges(ranges)}) + c.Assert(err, IsNil) + c.Assert(strings.TrimRight(out.String(), "\n"), Equals, cs.expect) + } +} diff --git a/pkg/rtree/rtree.go b/pkg/rtree/rtree.go index cc33e6700..04a2f1c0e 100644 --- a/pkg/rtree/rtree.go +++ b/pkg/rtree/rtree.go @@ -4,12 +4,10 @@ package rtree import ( "bytes" - "fmt" "github.com/google/btree" "github.com/pingcap/kvproto/pkg/backup" "github.com/pingcap/log" - "go.uber.org/zap" "github.com/pingcap/br/pkg/logutil" ) @@ -21,12 +19,25 @@ type Range struct { Files []*backup.File } +<<<<<<< HEAD // String formats a range to a string. func (rg *Range) String() string { return fmt.Sprintf("[%x %x]", rg.StartKey, rg.EndKey) } // Intersect returns? +======= +// BytesAndKeys returns total bytes and keys in a range. +func (rg *Range) BytesAndKeys() (bytes, keys uint64) { + for _, f := range rg.Files { + bytes += f.TotalBytes + keys += f.TotalKvs + } + return +} + +// Intersect returns intersect range in the tree. +>>>>>>> c206add... *: refine logs (#723) func (rg *Range) Intersect( start, end []byte, ) (subStart, subEnd []byte, isIntersect bool) { @@ -134,9 +145,8 @@ func (rangeTree *RangeTree) Update(rg Range) { // Range has backuped, overwrite overlapping range. for _, item := range overlaps { log.Info("delete overlapping range", - zap.Stringer("StartKey", logutil.WrapKey(item.StartKey)), - zap.Stringer("EndKey", logutil.WrapKey(item.EndKey)), - ) + logutil.Key("startKey", item.StartKey), + logutil.Key("endKey", item.EndKey)) rangeTree.Delete(item) } rangeTree.ReplaceOrInsert(&rg) diff --git a/tests/br_key_locked/locker.go b/tests/br_key_locked/locker.go index 6b2276a15..80bc653a8 100644 --- a/tests/br_key_locked/locker.go +++ b/tests/br_key_locked/locker.go @@ -306,7 +306,7 @@ func randStr() string { length := rand.Intn(128) res := "" for i := 0; i < length; i++ { - res += string('a' + rand.Intn(26)) + res += fmt.Sprint(rand.Intn(10)) } return res } From d2866f4e6435d37a1621215057cf9d6af400bcee Mon Sep 17 00:00:00 2001 From: Neil Shen Date: Thu, 28 Jan 2021 21:04:44 +0800 Subject: [PATCH 2/2] resolve conflicts Signed-off-by: Neil Shen --- pkg/backup/client.go | 13 ------------- pkg/restore/client.go | 12 ------------ pkg/restore/log_client.go | 5 ----- pkg/restore/util.go | 4 ++-- pkg/rtree/rtree.go | 18 ------------------ 5 files changed, 2 insertions(+), 50 deletions(-) diff --git a/pkg/backup/client.go b/pkg/backup/client.go index 06a5b5ba2..408e1b2c1 100644 --- a/pkg/backup/client.go +++ b/pkg/backup/client.go @@ -39,7 +39,6 @@ import ( berrors "github.com/pingcap/br/pkg/errors" "github.com/pingcap/br/pkg/glue" "github.com/pingcap/br/pkg/logutil" - "github.com/pingcap/br/pkg/redact" "github.com/pingcap/br/pkg/rtree" "github.com/pingcap/br/pkg/storage" "github.com/pingcap/br/pkg/summary" @@ -827,18 +826,6 @@ func SendBackup( respFn func(*kvproto.BackupResponse) error, resetFn func() (kvproto.BackupClient, error), ) error { -<<<<<<< HEAD -======= - if span := opentracing.SpanFromContext(ctx); span != nil && span.Tracer() != nil { - span1 := span.Tracer().StartSpan( - fmt.Sprintf("Client.SendBackup, storeID = %d, StartKey = %s, EndKey = %s", - storeID, redact.Key(req.StartKey), redact.Key(req.EndKey)), - opentracing.ChildOf(span.Context())) - defer span1.Finish() - ctx = opentracing.ContextWithSpan(ctx, span1) - } - ->>>>>>> c206add... *: refine logs (#723) var errReset error backupLoop: for retry := 0; retry < backupRetryTimes; retry++ { diff --git a/pkg/restore/client.go b/pkg/restore/client.go index ff1ff1a65..0dc8292ba 100644 --- a/pkg/restore/client.go +++ b/pkg/restore/client.go @@ -541,20 +541,8 @@ func (rc *Client) RestoreFiles( } }() -<<<<<<< HEAD - log.Debug("start to restore files", - zap.Int("files", len(files)), - ) -======= log.Debug("start to restore files", zap.Int("files", len(files))) - if span := opentracing.SpanFromContext(ctx); span != nil && span.Tracer() != nil { - span1 := span.Tracer().StartSpan("Client.RestoreFiles", opentracing.ChildOf(span.Context())) - defer span1.Finish() - ctx = opentracing.ContextWithSpan(ctx, span1) - } - ->>>>>>> c206add... *: refine logs (#723) eg, ectx := errgroup.WithContext(ctx) err = rc.setSpeedLimit(ctx) if err != nil { diff --git a/pkg/restore/log_client.go b/pkg/restore/log_client.go index 39fb1c007..79945456a 100644 --- a/pkg/restore/log_client.go +++ b/pkg/restore/log_client.go @@ -565,13 +565,8 @@ func (l *LogClient) doWriteAndIngest(ctx context.Context, kvs kv.Pairs, region * break } if !needRetry { -<<<<<<< HEAD log.Warn("ingest failed noretry", zap.Error(errIngest), logutil.SSTMeta(meta), logutil.Region(region.Region), zap.Any("leader", region.Leader)) -======= - log.Warn("ingest failed", zap.Error(errIngest), logutil.SSTMeta(meta), - logutil.Region(region.Region), logutil.Leader(region.Leader)) ->>>>>>> c206add... *: refine logs (#723) // met non-retryable error retry whole Write procedure return errIngest } diff --git a/pkg/restore/util.go b/pkg/restore/util.go index 5e0f4633c..a3313e17a 100644 --- a/pkg/restore/util.go +++ b/pkg/restore/util.go @@ -308,8 +308,8 @@ func AttachFilesToRanges( }) if rg == nil { log.Panic("range not found", - zap.Stringer("startKey", logutil.WrapKey(f.GetStartKey())), - zap.Stringer("endKey", logutil.WrapKey(f.GetEndKey()))) + logutil.Key("startKey", f.GetStartKey()), + logutil.Key("endKey", f.GetEndKey())) } file := *f rg.Files = append(rg.Files, &file) diff --git a/pkg/rtree/rtree.go b/pkg/rtree/rtree.go index 04a2f1c0e..80c220fe0 100644 --- a/pkg/rtree/rtree.go +++ b/pkg/rtree/rtree.go @@ -19,25 +19,7 @@ type Range struct { Files []*backup.File } -<<<<<<< HEAD -// String formats a range to a string. -func (rg *Range) String() string { - return fmt.Sprintf("[%x %x]", rg.StartKey, rg.EndKey) -} - // Intersect returns? -======= -// BytesAndKeys returns total bytes and keys in a range. -func (rg *Range) BytesAndKeys() (bytes, keys uint64) { - for _, f := range rg.Files { - bytes += f.TotalBytes - keys += f.TotalKvs - } - return -} - -// Intersect returns intersect range in the tree. ->>>>>>> c206add... *: refine logs (#723) func (rg *Range) Intersect( start, end []byte, ) (subStart, subEnd []byte, isIntersect bool) {