*: refine logs (#723)

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 {

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

pkg/backup/client.go

@@ -502,10 +502,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 +538,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 +574,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 +665,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)
 
@@ -830,8 +830,8 @@ func SendBackup(
 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 +880,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)

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)

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"]}`)
 }