session: refine error message desensitization (#19409)

config/config.go

@@ -58,6 +58,8 @@ const (
 	DefStatusHost = "0.0.0.0"
 	// DefStoreLivenessTimeout is the default value for store liveness timeout.
 	DefStoreLivenessTimeout = "5s"
+	// DefTiDBRedactLog is the default value for redact log.
+	DefTiDBRedactLog = 0
 )
 
 // Valid config maps
@@ -143,6 +145,8 @@ type Config struct {
 	SkipRegisterToDashboard bool `toml:"skip-register-to-dashboard" json:"skip-register-to-dashboard"`
 	// EnableTelemetry enables the usage data report to PingCAP.
 	EnableTelemetry bool `toml:"enable-telemetry" json:"enable-telemetry"`
+	// EnableRedactLog indicates that whether redact log, 0 is disable. 1 is enable.
+	EnableRedactLog int32 `toml:"enable-redact-log" json:"enable-redact-log"`
 }
 
 // UpdateTempStoragePath is to update the `TempStoragePath` if port/statusPort was changed
@@ -685,6 +689,7 @@ var defaultConf = Config{
 	},
 	EnableCollectExecutionInfo: true,
 	EnableTelemetry:            true,
+	EnableRedactLog:            DefTiDBRedactLog,
 }
 
 var (
@@ -917,6 +922,23 @@ var TableLockDelayClean = func() uint64 {
 	return GetGlobalConfig().DelayCleanTableLock
 }
 
+// RedactLogEnabled uses to check whether enabled the log redact.
+func RedactLogEnabled() bool {
+	return atomic.LoadInt32(&GetGlobalConfig().EnableRedactLog) == 1
+}
+
+// SetRedactLog uses to set log redact status.
+func SetRedactLog(enable bool) {
+	value := int32(0)
+	if enable {
+		value = 1
+	}
+	g := GetGlobalConfig()
+	newConf := *g
+	newConf.EnableRedactLog = value
+	StoreGlobalConfig(&newConf)
+}
+
 // ToLogConfig converts *Log to *logutil.LogConfig.
 func (l *Log) ToLogConfig() *logutil.LogConfig {
 	return logutil.NewLogConfig(l.Level, l.Format, l.SlowQueryFile, l.File, l.getDisableTimestamp(), func(config *zaplog.Config) { config.DisableErrorVerbose = l.getDisableErrorStack() })

executor/adapter.go

@@ -798,7 +798,7 @@ func (a *ExecStmt) FinishExecuteStmt(txnTS uint64, succ bool, hasMoreResults boo
 	a.SummaryStmt(succ)
 	sessVars := a.Ctx.GetSessionVars()
 	prevStmt := a.GetTextToLog()
-	if sessVars.EnableLogDesensitization {
+	if config.RedactLogEnabled() {
 		sessVars.PrevStmt = FormatSQL(prevStmt, nil)
 	} else {
 		pps := types.CloneRow(sessVars.PreparedParams)
@@ -827,7 +827,7 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) {
 	}
 	var sql stringutil.StringerFunc
 	normalizedSQL, digest := sessVars.StmtCtx.SQLDigest()
-	if sessVars.EnableLogDesensitization {
+	if config.RedactLogEnabled() {
 		sql = FormatSQL(normalizedSQL, nil)
 	} else if sensitiveStmt, ok := a.StmtNode.(ast.SensitiveStmtNode); ok {
 		sql = FormatSQL(sensitiveStmt.SecureText(), nil)
@@ -1018,9 +1018,8 @@ func (a *ExecStmt) SummaryStmt(succ bool) {
 // GetTextToLog return the query text to log.
 func (a *ExecStmt) GetTextToLog() string {
 	var sql string
-	sessVars := a.Ctx.GetSessionVars()
-	if sessVars.EnableLogDesensitization {
-		sql, _ = sessVars.StmtCtx.SQLDigest()
+	if config.RedactLogEnabled() {
+		sql, _ = a.Ctx.GetSessionVars().StmtCtx.SQLDigest()
 	} else if sensitiveStmt, ok := a.StmtNode.(ast.SensitiveStmtNode); ok {
 		sql = sensitiveStmt.SecureText()
 	} else {

executor/executor_test.go

@@ -5963,6 +5963,21 @@ func (s *testSplitTable) TestKillTableReader(c *C) {
 	wg.Wait()
 }
 
+func (s *testSerialSuite1) TestPrevStmtDesensitization(c *C) {
+	tk := testkit.NewTestKit(c, s.store)
+	tk.MustExec("use test;")
+	oriCfg := config.GetGlobalConfig()
+	defer config.StoreGlobalConfig(oriCfg)
+	newCfg := *oriCfg
+	newCfg.EnableRedactLog = 1
+	config.StoreGlobalConfig(&newCfg)
+	tk.MustExec("drop table if exists t")
+	tk.MustExec("create table t (a int)")
+	tk.MustExec("begin")
+	tk.MustExec("insert into t values (1),(2)")
+	c.Assert(tk.Se.GetSessionVars().PrevStmt.String(), Equals, "insert into t values ( ? ) , ( ? )")
+}
+
 func (s *testSuite) TestIssue19372(c *C) {
 	tk := testkit.NewTestKit(c, s.store)
 	tk.MustExec("use test;")
@@ -5974,17 +5989,6 @@ func (s *testSuite) TestIssue19372(c *C) {
 	tk.MustQuery("select (select t2.c_str from t2 where t2.c_str <= t1.c_str and t2.c_int in (1, 2) order by t2.c_str limit 1) x from t1 order by c_int;").Check(testkit.Rows("a", "a", "a"))
 }
 
-func (s *testSuite) TestPrevStmtDesensitization(c *C) {
-	tk := testkit.NewTestKit(c, s.store)
-	tk.MustExec("use test;")
-	tk.Se.GetSessionVars().EnableLogDesensitization = true
-	tk.MustExec("drop table if exists t")
-	tk.MustExec("create table t (a int)")
-	tk.MustExec("begin")
-	tk.MustExec("insert into t values (1),(2)")
-	c.Assert(tk.Se.GetSessionVars().PrevStmt.String(), Equals, "insert into t values ( ? ) , ( ? )")
-}
-
 func (s *testSuite) TestIssue13758(c *C) {
 	tk := testkit.NewTestKit(c, s.store)
 	tk.MustExec("use test")

kv/error.go

@@ -16,6 +16,7 @@ package kv
 import (
 	"github.com/pingcap/parser/terror"
 	mysql "github.com/pingcap/tidb/errno"
+	"github.com/pingcap/tidb/util/redact"
 )
 
 // TxnRetryableMark is used to uniform the commit error messages which could retry the transaction.
@@ -39,7 +40,7 @@ var (
 	// ErrEntryTooLarge is the error when a key value entry is too large.
 	ErrEntryTooLarge = terror.ClassKV.New(mysql.ErrEntryTooLarge, mysql.MySQLErrName[mysql.ErrEntryTooLarge])
 	// ErrKeyExists returns when key is already exist.
-	ErrKeyExists = terror.ClassKV.New(mysql.ErrDupEntry, mysql.MySQLErrName[mysql.ErrDupEntry])
+	ErrKeyExists = redact.NewRedactError(terror.ClassKV.New(mysql.ErrDupEntry, mysql.MySQLErrName[mysql.ErrDupEntry]), 0, 1)
 	// ErrNotImplemented returns when a function is not implemented yet.
 	ErrNotImplemented = terror.ClassKV.New(mysql.ErrNotImplemented, mysql.MySQLErrName[mysql.ErrNotImplemented])
 	// ErrWriteConflict is the error when the commit meets an write conflict error.

kv/error_test.go

@@ -31,7 +31,6 @@ func (s testErrorSuite) TestError(c *C) {
 		ErrInvalidTxn,
 		ErrTxnTooLarge,
 		ErrEntryTooLarge,
-		ErrKeyExists,
 		ErrNotImplemented,
 		ErrWriteConflict,
 		ErrWriteConflictInTiDB,

server/conn.go

@@ -1701,7 +1701,7 @@ func (cc getLastStmtInConn) String() string {
 		return "ListFields " + string(data)
 	case mysql.ComQuery, mysql.ComStmtPrepare:
 		sql := string(hack.String(data))
-		if cc.ctx.GetSessionVars().EnableLogDesensitization {
+		if config.RedactLogEnabled() {
 			sql, _ = parser.NormalizeDigest(sql)
 		}
 		return queryStrForLog(sql)

server/conn_stmt.go

@@ -45,6 +45,7 @@ import (
 
 	"github.com/pingcap/errors"
 	"github.com/pingcap/parser/mysql"
+	"github.com/pingcap/tidb/config"
 	plannercore "github.com/pingcap/tidb/planner/core"
 	"github.com/pingcap/tidb/sessionctx/stmtctx"
 	"github.com/pingcap/tidb/types"
@@ -637,7 +638,7 @@ func (cc *clientConn) preparedStmt2String(stmtID uint32) string {
 	if sv == nil {
 		return ""
 	}
-	if sv.EnableLogDesensitization {
+	if config.RedactLogEnabled() {
 		return cc.preparedStmt2StringNoArgs(stmtID)
 	}
 	return cc.preparedStmt2StringNoArgs(stmtID) + sv.PreparedParams.String()

session/session.go

@@ -475,7 +475,6 @@ func (s *session) doCommitWithRetry(ctx context.Context) error {
 				zap.Int64("tidb_retry_limit", s.sessionVars.RetryLimit),
 				zap.Bool("tidb_disable_txn_auto_retry", s.sessionVars.DisableTxnAutoRetry))
 		}
-
 	}
 	counter := s.sessionVars.TxnCtx.StatementCount
 	duration := time.Since(s.GetSessionVars().TxnCtx.CreateTime).Seconds()
@@ -654,7 +653,7 @@ func (s *session) retry(ctx context.Context, maxCnt uint) (err error) {
 				// We do not have to log the query every time.
 				// We print the queries at the first try only.
 				sql := sqlForLog(st.GetTextToLog())
-				if !sessVars.EnableLogDesensitization {
+				if !config.RedactLogEnabled() {
 					sql += sessVars.PreparedParams.String()
 				}
 				logutil.Logger(ctx).Warn("retrying",
@@ -1988,7 +1987,7 @@ var builtinGlobalVariable = []string{
 	variable.TiDBStoreLimit,
 	variable.TiDBAllowAutoRandExplicitInsert,
 	variable.TiDBSlowLogMasking,
-	variable.TiDBLogDesensitization,
+	variable.TiDBRedactLog,
 	variable.TiDBEnableTelemetry,
 }
 
@@ -2168,7 +2167,7 @@ func logStmt(execStmt *executor.ExecStmt, vars *variable.SessionVars) {
 func logQuery(query string, vars *variable.SessionVars) {
 	if atomic.LoadUint32(&variable.ProcessGeneralLog) != 0 && !vars.InRestrictedSQL {
 		query = executor.QueryReplacer.Replace(query)
-		if !vars.EnableLogDesensitization {
+		if !config.RedactLogEnabled() {
 			query = query + vars.PreparedParams.String()
 		}
 		logutil.BgLogger().Info("GENERAL_LOG",

sessionctx/variable/session.go

@@ -636,9 +636,6 @@ type SessionVars struct {
 
 	// SelectLimit limits the max counts of select statement's output
 	SelectLimit uint64
-
-	// EnableLogDesensitization indicates that whether desensitization when log query.
-	EnableLogDesensitization bool
 }
 
 // PreparedParams contains the parameters of the current prepared statement when executing it.
@@ -730,7 +727,6 @@ func NewSessionVars() *SessionVars {
 		FoundInPlanCache:            DefTiDBFoundInPlanCache,
 		SelectLimit:                 math.MaxUint64,
 		AllowAutoRandExplicitInsert: DefTiDBAllowAutoRandExplicitInsert,
-		EnableLogDesensitization:    DefTiDBLogDesensitization,
 	}
 	vars.KVVars = kv.NewVariables(&vars.Killed)
 	vars.Concurrency = Concurrency{
@@ -1340,12 +1336,12 @@ func (s *SessionVars) SetSystemVar(name string, val string) error {
 			return errors.Trace(err)
 		}
 		s.SelectLimit = result
-	case TiDBSlowLogMasking, TiDBLogDesensitization:
-		s.EnableLogDesensitization = TiDBOptOn(val)
 	case TiDBEnableCollectExecutionInfo:
 		config.GetGlobalConfig().EnableCollectExecutionInfo = TiDBOptOn(val)
 	case TiDBAllowAutoRandExplicitInsert:
 		s.AllowAutoRandExplicitInsert = TiDBOptOn(val)
+	case TiDBSlowLogMasking, TiDBRedactLog:
+		config.SetRedactLog(TiDBOptOn(val))
 	}
 	s.systems[name] = val
 	return nil

sessionctx/variable/sysvar.go

@@ -726,7 +726,7 @@ var defaultSysVars = []*SysVar{
 	{ScopeGlobal, TiDBSlowLogMasking, BoolToIntStr(DefTiDBSlowLogMasking)},
 	{ScopeSession, TiDBEnableCollectExecutionInfo, BoolToIntStr(DefTiDBEnableCollectExecutionInfo)},
 	{ScopeGlobal | ScopeSession, TiDBAllowAutoRandExplicitInsert, boolToOnOff(DefTiDBAllowAutoRandExplicitInsert)},
-	{ScopeGlobal, TiDBLogDesensitization, BoolToIntStr(DefTiDBLogDesensitization)},
+	{ScopeGlobal, TiDBRedactLog, strconv.Itoa(config.DefTiDBRedactLog)},
 	{ScopeGlobal, TiDBEnableTelemetry, BoolToIntStr(DefTiDBEnableTelemetry)},
 }
 

sessionctx/variable/tidb_vars.go

@@ -401,14 +401,14 @@ const (
 	TiDBMetricSchemaRangeDuration = "tidb_metric_query_range_duration"
 
 	// TiDBSlowLogMasking indicates that whether masking the query data when log slow query.
-	// Deprecated: use TiDBLogDesensitization instead.
+	// Deprecated: use TiDBRedactLog instead.
 	TiDBSlowLogMasking = "tidb_slow_log_masking"
 
 	// TiDBEnableCollectExecutionInfo indicates that whether execution info is collected.
 	TiDBEnableCollectExecutionInfo = "tidb_enable_collect_execution_info"
 
-	// TiDBLogDesensitization indicates that whether desensitization when log query.
-	TiDBLogDesensitization = "tidb_log_desensitization"
+	// TiDBRedactLog indicates that whether redact log.
+	TiDBRedactLog = "tidb_redact_log"
 
 	// TiDBEnableTelemetry indicates that whether usage data report to PingCAP is enabled.
 	TiDBEnableTelemetry = "tidb_enable_telemetry"
@@ -511,7 +511,6 @@ const (
 	DefTiDBSlowLogMasking              = false
 	DefTiDBEnableCollectExecutionInfo  = true
 	DefTiDBAllowAutoRandExplicitInsert = false
-	DefTiDBLogDesensitization          = false
 	DefTiDBEnableTelemetry             = true
 )
 

util/redact/redact.go

@@ -0,0 +1,67 @@
+// 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 redact
+
+import (
+	"github.com/pingcap/parser/terror"
+	"github.com/pingcap/tidb/config"
+)
+
+// TError is a alias, use to avoid `Error` method name in conflict with field name.
+type TError = terror.Error
+
+type redactError struct {
+	*TError
+	redactPositions []int
+}
+
+// GenWithStackByArgs generates a new *Error with the same class and code, and new arguments.
+func (e *redactError) GenWithStackByArgs(args ...interface{}) error {
+	redactErrorArg(args, e.redactPositions)
+	return e.TError.GenWithStackByArgs(args...)
+}
+
+// FastGen generates a new *Error with the same class and code, and a new arguments.
+func (e *redactError) FastGenByArgs(args ...interface{}) error {
+	redactErrorArg(args, e.redactPositions)
+	return e.TError.GenWithStackByArgs(args...)
+}
+
+// Equal checks if err is equal to e.
+func (e *redactError) Equal(err error) bool {
+	if redactErr, ok := err.(*redactError); ok {
+		return e.TError.Equal(redactErr.TError)
+	}
+	return e.TError.Equal(err)
+}
+
+// Cause implement the Cause interface.
+func (e *redactError) Cause() error {
+	return e.TError
+}
+
+func redactErrorArg(args []interface{}, position []int) {
+	if config.RedactLogEnabled() {
+		for _, pos := range position {
+			if len(args) > pos {
+				args[pos] = "?"
+			}
+		}
+	}
+}
+
+// NewRedactError returns a new redact error.
+func NewRedactError(err *terror.Error, redactPositions ...int) *redactError {
+	return &redactError{err, redactPositions}
+}