Repository: pingcap/dumpling
Pull request #335 (2021-08-23 06:57:11)

*: update dumpling log and pd usage
<!--
Thank you for contributing to Dumpling! Please read the [CONTRIBUTING](https://github.com/pingcap/dumpling/blob/master/CONTRIBUTING.md) document **BEFORE** filing this PR.

If you want to open the **Challenge Program** pull request, please use the following template:
https://raw.githubusercontent.com/pingcap/.github/master/.github/PULL_REQUEST_TEMPLATE/challenge-program.md

You can use it with query parameters: https://github.com/pingcap/dumpling/compare/master...${you branch}?template=challenge-program.md
-->

### What problem does this PR solve? <!--add issue link with summary if exists-->
1. Dumpling's warning log with error stack may terrify users. Users may think the dump task is failed but actually, it's not.
2. Dumpling may fail when dumpling account lacks privileges for `MYSQL.TiDB`.

### What is changed and how it works?
1. Change error stack to short error.
2. Ignore all errors when trying auto adjust gc to PD.

### Check List <!--REMOVE the items that are not applicable-->

Tests <!-- At least one of them must be included. -->

 - Unit test
 - Manual test (add detailed scripts or steps below)

Related changes

 - Need to cherry-pick to the release branch
 
### Release note

<!-- bugfixes or new feature need a release note, must in the form of a list, such as

- support -T/--tables-list argument

or if no need to be included in the release note, just add the following line

- No release note
-->
- No release note


ti-chi-bot: [REVIEW NOTIFICATION]

This pull request has not been approved.


To complete the [pull request process](https://book.prow.tidb.io/#/en/workflows/pr), please ask the reviewers in the [list](https://prow.tidb.io/tichi/repos/pingcap/dumpling/pulls/335/owners) to review by filling `/cc @reviewer` in the comment.
After your PR has acquired the required number of LGTMs, you can assign this pull request to the committer in the [list](https://prow.tidb.io/tichi/repos/pingcap/dumpling/pulls/335/owners) by filling  `/assign @committer` in the comment to help you merge this pull request.

The full list of commands accepted by this bot can be found [here](https://prow.tidb.io/command-help?repo=pingcap%2Fdumpling).

<details>

Reviewer can indicate their review by submitting an approval review.
Reviewer can cancel approval by submitting a request changes review.
</details>

<!--Review Notification Identifier-->

Patch:
diff --git a/v4/export/block_allow_list.go b/v4/export/block_allow_list.go
index 381bea6..194be0e 100644
--- a/v4/export/block_allow_list.go
+++ b/v4/export/block_allow_list.go
@@ -8,6 +8,23 @@ import (
 	tcontext "github.com/pingcap/dumpling/v4/context"
 )
 
+func filterDatabases(tctx *tcontext.Context, conf *Config, databases []string) []string {
+	tctx.L().Debug("start to filter databases")
+	newDatabases := make([]string, 0, len(databases))
+	ignoreDatabases := make([]string, 0, len(databases))
+	for _, database := range databases {
+		if conf.TableFilter.MatchSchema(database) {
+			newDatabases = append(newDatabases, database)
+		} else {
+			ignoreDatabases = append(ignoreDatabases, database)
+		}
+	}
+	if len(ignoreDatabases) > 0 {
+		tctx.L().Debug("ignore database", zap.Strings("databases", ignoreDatabases))
+	}
+	return newDatabases
+}
+
 func filterTables(tctx *tcontext.Context, conf *Config) {
 	filterTablesFunc(tctx, conf, conf.TableFilter.MatchTable)
 }
diff --git a/v4/export/dump.go b/v4/export/dump.go
index 51a96fb..2d36c17 100755
--- a/v4/export/dump.go
+++ b/v4/export/dump.go
@@ -470,7 +470,7 @@ func (d *Dumper) concurrentDumpTable(tctx *tcontext.Context, conn *sql.Conn, met
 			return err
 		}
 		tctx.L().Warn("fallback to concurrent dump tables using rows due to tidb error",
-			zap.String("database", db), zap.String("table", tbl), zap.Error(err))
+			zap.String("database", db), zap.String("table", tbl), log.ShortError(err))
 	}
 
 	orderByClause, err := buildOrderByClause(conf, conn, db, tbl, meta.HasImplicitRowID())
@@ -482,7 +482,7 @@ func (d *Dumper) concurrentDumpTable(tctx *tcontext.Context, conn *sql.Conn, met
 	if err != nil || field == "" {
 		// skip split chunk logic if not found proper field
 		tctx.L().Warn("fallback to sequential dump due to no proper field",
-			zap.String("database", db), zap.String("table", tbl), zap.Error(err))
+			zap.String("database", db), zap.String("table", tbl), log.ShortError(err))
 		return d.dumpWholeTableDirectly(tctx, meta, taskChan, "", orderByClause, 0, 1)
 	}
 
@@ -865,7 +865,7 @@ func getListTableTypeByConf(conf *Config) listTableType {
 }
 
 func prepareTableListToDump(tctx *tcontext.Context, conf *Config, db *sql.Conn) error {
-	databases, err := prepareDumpingDatabases(conf, db)
+	databases, err := prepareDumpingDatabases(tctx, conf, db)
 	if err != nil {
 		return err
 	}
@@ -1023,7 +1023,7 @@ func startHTTPService(d *Dumper) error {
 		go func() {
 			err := startDumplingService(d.tctx, conf.StatusAddr)
 			if err != nil {
-				d.L().Warn("meet error when stopping dumpling http service", zap.Error(err))
+				d.L().Warn("meet error when stopping dumpling http service", log.ShortError(err))
 			}
 		}()
 	}
@@ -1080,16 +1080,17 @@ func tidbSetPDClientForGC(d *Dumper) error {
 	}
 	pdAddrs, err := GetPdAddrs(tctx, pool)
 	if err != nil {
-		return err
+		tctx.L().Warn("meet error while fetching pd addrs", log.ShortError(err))
+		return nil
 	}
 	if len(pdAddrs) > 0 {
 		doPdGC, err := checkSameCluster(tctx, pool, pdAddrs)
 		if err != nil {
-			tctx.L().Warn("meet error while check whether fetched pd addr and TiDB belong to one cluster", zap.Error(err), zap.Strings("pdAddrs", pdAddrs))
+			tctx.L().Warn("meet error while check whether fetched pd addr and TiDB belong to one cluster", log.ShortError(err), zap.Strings("pdAddrs", pdAddrs))
 		} else if doPdGC {
 			pdClient, err := pd.NewClientWithContext(tctx, pdAddrs, pd.SecurityOption{})
 			if err != nil {
-				tctx.L().Warn("create pd client to control GC failed", zap.Error(err), zap.Strings("pdAddrs", pdAddrs))
+				tctx.L().Warn("create pd client to control GC failed", log.ShortError(err), zap.Strings("pdAddrs", pdAddrs))
 			}
 			d.tidbPDClientForGC = pdClient
 		}
@@ -1105,13 +1106,13 @@ func tidbGetSnapshot(d *Dumper) error {
 	if conf.Snapshot == "" && (doPdGC || consistency == "snapshot") {
 		conn, err := pool.Conn(tctx)
 		if err != nil {
-			tctx.L().Warn("cannot get snapshot from TiDB", zap.Error(err))
+			tctx.L().Warn("cannot get snapshot from TiDB", log.ShortError(err))
 			return nil
 		}
 		snapshot, err := getSnapshot(conn)
 		_ = conn.Close()
 		if err != nil {
-			tctx.L().Warn("cannot get snapshot from TiDB", zap.Error(err))
+			tctx.L().Warn("cannot get snapshot from TiDB", log.ShortError(err))
 			return nil
 		}
 		conf.Snapshot = snapshot
@@ -1186,7 +1187,7 @@ func setSessionParam(d *Dumper) error {
 		if consistency == consistencyTypeSnapshot {
 			conf.ServerInfo.HasTiKV, err = CheckTiDBWithTiKV(pool)
 			if err != nil {
-				return err
+				d.L().Warn("fail to check whether TiDB has TiKV", log.ShortError(err))
 			}
 			if conf.ServerInfo.HasTiKV {
 				sessionParam["tidb_snapshot"] = snapshot
diff --git a/v4/export/http_handler.go b/v4/export/http_handler.go
index 656e68e..cfe1494 100644
--- a/v4/export/http_handler.go
+++ b/v4/export/http_handler.go
@@ -9,12 +9,13 @@ import (
 	"strings"
 	"time"
 
+	"github.com/pingcap/dumpling/v4/log"
+
 	tcontext "github.com/pingcap/dumpling/v4/context"
 
 	"github.com/pingcap/errors"
 	"github.com/prometheus/client_golang/prometheus/promhttp"
 	"github.com/soheilhy/cmux"
-	"go.uber.org/zap"
 )
 
 var cmuxReadTimeout = 10 * time.Second
@@ -35,7 +36,7 @@ func startHTTPServer(tctx *tcontext.Context, lis net.Listener) {
 	err := httpServer.Serve(lis)
 	err = errors.Cause(err)
 	if err != nil && !isErrNetClosing(err) && err != http.ErrServerClosed {
-		tctx.L().Warn("http server return with error", zap.Error(err))
+		tctx.L().Warn("dumpling http handler return with error", log.ShortError(err))
 	}
 }
 
diff --git a/v4/export/prepare.go b/v4/export/prepare.go
index e995f8a..2a6d7a1 100644
--- a/v4/export/prepare.go
+++ b/v4/export/prepare.go
@@ -10,6 +10,8 @@ import (
 	"text/template"
 
 	"github.com/pingcap/errors"
+
+	tcontext "github.com/pingcap/dumpling/v4/context"
 )
 
 const (
@@ -75,10 +77,14 @@ func ParseOutputFileTemplate(text string) (*template.Template, error) {
 	return template.Must(DefaultOutputFileTemplate.Clone()).Parse(text)
 }
 
-func prepareDumpingDatabases(conf *Config, db *sql.Conn) ([]string, error) {
+func prepareDumpingDatabases(tctx *tcontext.Context, conf *Config, db *sql.Conn) ([]string, error) {
 	databases, err := ShowDatabases(db)
+	if err != nil {
+		return nil, err
+	}
+	databases = filterDatabases(tctx, conf, databases)
 	if len(conf.Databases) == 0 {
-		return databases, err
+		return databases, nil
 	}
 	dbMap := make(map[string]interface{}, len(databases))
 	for _, database := range databases {
diff --git a/v4/export/sql.go b/v4/export/sql.go
index 76c8edb..80fd432 100644
--- a/v4/export/sql.go
+++ b/v4/export/sql.go
@@ -12,6 +12,8 @@ import (
 	"strconv"
 	"strings"
 
+	"github.com/pingcap/dumpling/v4/log"
+
 	"github.com/go-sql-driver/mysql"
 
 	tcontext "github.com/pingcap/dumpling/v4/context"
@@ -586,11 +588,10 @@ func GetPdAddrs(tctx *tcontext.Context, db *sql.DB) ([]string, error) {
 	query := "SELECT * FROM information_schema.cluster_info where type = 'pd';"
 	rows, err := db.QueryContext(tctx, query)
 	if err != nil {
-		tctx.L().Warn("can't execute query from db",
-			zap.String("query", query), zap.Error(err))
 		return []string{}, errors.Annotatef(err, "sql: %s", query)
 	}
-	return GetSpecifiedColumnValueAndClose(rows, "STATUS_ADDRESS")
+	pdAddrs, err := GetSpecifiedColumnValueAndClose(rows, "STATUS_ADDRESS")
+	return pdAddrs, errors.Annotatef(err, "sql: %s", query)
 }
 
 // GetTiDBDDLIDs gets DDL IDs from TiDB
@@ -598,11 +599,10 @@ func GetTiDBDDLIDs(tctx *tcontext.Context, db *sql.DB) ([]string, error) {
 	query := "SELECT * FROM information_schema.tidb_servers_info;"
 	rows, err := db.QueryContext(tctx, query)
 	if err != nil {
-		tctx.L().Warn("can't execute query from db",
-			zap.String("query", query), zap.Error(err))
 		return []string{}, errors.Annotatef(err, "sql: %s", query)
 	}
-	return GetSpecifiedColumnValueAndClose(rows, "DDL_ID")
+	ddlIDs, err := GetSpecifiedColumnValueAndClose(rows, "DDL_ID")
+	return ddlIDs, errors.Annotatef(err, "sql: %s", query)
 }
 
 // CheckTiDBWithTiKV use sql to check whether current TiDB has TiKV
@@ -612,7 +612,9 @@ func CheckTiDBWithTiKV(db *sql.DB) (bool, error) {
 	row := db.QueryRow(query)
 	err := row.Scan(&count)
 	if err != nil {
-		return false, errors.Annotatef(err, "sql: %s", query)
+		// still return true here. Because sometimes users may not have privileges for MySQL.TiDB database
+		// In most production cases TiDB has TiKV
+		return true, errors.Annotatef(err, "sql: %s", query)
 	}
 	return count > 0, nil
 }
@@ -995,8 +997,8 @@ func estimateCount(tctx *tcontext.Context, dbName, tableName string, db *sql.Con
 func detectEstimateRows(tctx *tcontext.Context, db *sql.Conn, query string, fieldNames []string) uint64 {
 	rows, err := db.QueryContext(tctx, query)
 	if err != nil {
-		tctx.L().Warn("can't execute query from db",
-			zap.String("query", query), zap.Error(err))
+		tctx.L().Warn("can't detect estimate rows from db",
+			zap.String("query", query), log.ShortError(err))
 		return 0
 	}
 	defer rows.Close()
@@ -1004,13 +1006,13 @@ func detectEstimateRows(tctx *tcontext.Context, db *sql.Conn, query string, fiel
 	columns, err := rows.Columns()
 	if err != nil {
 		tctx.L().Warn("can't get columns from db",
-			zap.String("query", query), zap.Error(err))
+			zap.String("query", query), log.ShortError(err))
 		return 0
 	}
 	err = rows.Err()
 	if err != nil {
 		tctx.L().Warn("rows meet some error during the query",
-			zap.String("query", query), zap.Error(err))
+			zap.String("query", query), log.ShortError(err))
 		return 0
 	}
 	addr := make([]interface{}, len(columns))
@@ -1031,14 +1033,14 @@ found:
 	err = rows.Scan(addr...)
 	if err != nil || fieldIndex < 0 {
 		tctx.L().Warn("can't get estimate count from db",
-			zap.String("query", query), zap.Error(err))
+			zap.String("query", query), log.ShortError(err))
 		return 0
 	}
 
 	estRows, err := strconv.ParseFloat(oneRow[fieldIndex].String, 64)
 	if err != nil {
 		tctx.L().Warn("can't get parse rows from db",
-			zap.String("query", query), zap.Error(err))
+			zap.String("query", query), log.ShortError(err))
 		return 0
 	}
 	return uint64(estRows)
diff --git a/v4/export/writer_util.go b/v4/export/writer_util.go
index 18bcc6e..434fbf0 100755
--- a/v4/export/writer_util.go
+++ b/v4/export/writer_util.go
@@ -13,6 +13,7 @@ import (
 	"time"
 
 	tcontext "github.com/pingcap/dumpling/v4/context"
+	"github.com/pingcap/dumpling/v4/log"
 
 	"github.com/pingcap/br/pkg/storage"
 	"github.com/pingcap/br/pkg/summary"
@@ -177,12 +178,12 @@ func WriteInsert(pCtx *tcontext.Context, cfg *Config, meta TableMeta, tblIR Tabl
 
 	defer func() {
 		if err != nil {
-			pCtx.L().Warn("fail to dumping table(chunk), will revert some metrics now",
-				zap.Error(err),
+			pCtx.L().Warn("fail to dumping table(chunk), will revert some metrics and start a retry if possible",
 				zap.String("database", meta.DatabaseName()),
 				zap.String("table", meta.TableName()),
 				zap.Uint64("finished rows", lastCounter),
-				zap.Uint64("finished size", wp.finishedFileSize))
+				zap.Uint64("finished size", wp.finishedFileSize),
+				log.ShortError(err))
 			SubGauge(finishedRowsGauge, cfg.Labels, float64(lastCounter))
 			SubGauge(finishedSizeGauge, cfg.Labels, float64(wp.finishedFileSize))
 		} else {
@@ -315,12 +316,12 @@ func WriteInsertInCsv(pCtx *tcontext.Context, cfg *Config, meta TableMeta, tblIR
 
 	defer func() {
 		if err != nil {
-			pCtx.L().Warn("fail to dumping table(chunk), will revert some metrics now",
-				zap.Error(err),
+			pCtx.L().Warn("fail to dumping table(chunk), will revert some metrics and start a retry if possible",
 				zap.String("database", meta.DatabaseName()),
 				zap.String("table", meta.TableName()),
 				zap.Uint64("finished rows", lastCounter),
-				zap.Uint64("finished size", wp.finishedFileSize))
+				zap.Uint64("finished size", wp.finishedFileSize),
+				log.ShortError(err))
 			SubGauge(finishedRowsGauge, cfg.Labels, float64(lastCounter))
 			SubGauge(finishedSizeGauge, cfg.Labels, float64(wp.finishedFileSize))
 		} else {
diff --git a/v4/log/log.go b/v4/log/log.go
index 79f840d..78df0a2 100644
--- a/v4/log/log.go
+++ b/v4/log/log.go
@@ -59,3 +59,12 @@ func InitAppLogger(cfg *Config) (Logger, *pclog.ZapProperties, error) {
 func NewAppLogger(logger *zap.Logger) Logger {
 	return Logger{logger}
 }
+
+// ShortError contructs a field which only records the error message without the
+// verbose text (i.e. excludes the stack trace).
+func ShortError(err error) zap.Field {
+	if err == nil {
+		return zap.Skip()
+	}
+	return zap.String("error", err.Error())
+}


Test patch:
diff --git a/v4/export/block_allow_list_test.go b/v4/export/block_allow_list_test.go
index fddc771..845bcfb 100644
--- a/v4/export/block_allow_list_test.go
+++ b/v4/export/block_allow_list_test.go
@@ -17,6 +17,7 @@ var _ = Suite(&testBWListSuite{})
 type testBWListSuite struct{}
 
 func (s *testBWListSuite) TestFilterTables(c *C) {
+	tctx := tcontext.Background().WithLogger(appLogger)
 	dbTables := DatabaseTables{}
 	expectedDBTables := DatabaseTables{}
 
@@ -36,7 +37,11 @@ func (s *testBWListSuite) TestFilterTables(c *C) {
 		TableFilter: tableFilter,
 	}
 
+	databases := []string{filter.InformationSchemaName, filter.PerformanceSchemaName, "xxx", "yyy"}
+	c.Assert(filterDatabases(tctx, conf, databases), DeepEquals, databases)
+
 	conf.TableFilter = tf.NewSchemasFilter("xxx")
+	c.Assert(filterDatabases(tctx, conf, databases), DeepEquals, []string{"xxx"})
 	filterTables(tcontext.Background(), conf)
 	c.Assert(conf.Tables, HasLen, 1)
 	c.Assert(conf.Tables, DeepEquals, expectedDBTables)
diff --git a/v4/export/prepare_test.go b/v4/export/prepare_test.go
index 04b806d..aeb218b 100644
--- a/v4/export/prepare_test.go
+++ b/v4/export/prepare_test.go
@@ -21,7 +21,8 @@ func (s *testPrepareSuite) TestPrepareDumpingDatabases(c *C) {
 	db, mock, err := sqlmock.New()
 	c.Assert(err, IsNil)
 	defer db.Close()
-	conn, err := db.Conn(context.Background())
+	tctx := tcontext.Background().WithLogger(appLogger)
+	conn, err := db.Conn(tctx)
 	c.Assert(err, IsNil)
 
 	rows := sqlmock.NewRows([]string{"Database"}).
@@ -32,7 +33,7 @@ func (s *testPrepareSuite) TestPrepareDumpingDatabases(c *C) {
 	mock.ExpectQuery("SHOW DATABASES").WillReturnRows(rows)
 	conf := defaultConfigForTest(c)
 	conf.Databases = []string{"db1", "db2", "db3"}
-	result, err := prepareDumpingDatabases(conf, conn)
+	result, err := prepareDumpingDatabases(tctx, conf, conn)
 	c.Assert(err, IsNil)
 	c.Assert(result, DeepEquals, []string{"db1", "db2", "db3"})
 
@@ -41,12 +42,12 @@ func (s *testPrepareSuite) TestPrepareDumpingDatabases(c *C) {
 		AddRow("db1").
 		AddRow("db2")
 	mock.ExpectQuery("SHOW DATABASES").WillReturnRows(rows)
-	result, err = prepareDumpingDatabases(conf, conn)
+	result, err = prepareDumpingDatabases(tctx, conf, conn)
 	c.Assert(err, IsNil)
 	c.Assert(result, DeepEquals, []string{"db1", "db2"})
 
 	mock.ExpectQuery("SHOW DATABASES").WillReturnError(fmt.Errorf("err"))
-	_, err = prepareDumpingDatabases(conf, conn)
+	_, err = prepareDumpingDatabases(tctx, conf, conn)
 	c.Assert(err, NotNil)
 
 	rows = sqlmock.NewRows([]string{"Database"}).
@@ -56,7 +57,7 @@ func (s *testPrepareSuite) TestPrepareDumpingDatabases(c *C) {
 		AddRow("db5")
 	mock.ExpectQuery("SHOW DATABASES").WillReturnRows(rows)
 	conf.Databases = []string{"db1", "db2", "db4", "db6"}
-	_, err = prepareDumpingDatabases(conf, conn)
+	_, err = prepareDumpingDatabases(tctx, conf, conn)
 	c.Assert(err, ErrorMatches, `Unknown databases \[db4,db6\]`)
 	c.Assert(mock.ExpectationsWereMet(), IsNil)
 }