From e2c95eeb6e8dddb38d66a2feb70378ddd7a61ef7 Mon Sep 17 00:00:00 2001 From: ti-srebot <66930949+ti-srebot@users.noreply.github.com> Date: Wed, 15 Jul 2020 17:13:57 +0800 Subject: [PATCH] log: add `tidb_log_desensitization` global variable to control whether do desensitization when log query (#18578) (#18581) Co-authored-by: crazycs Co-authored-by: Yiding Cui Co-authored-by: bb7133 --- executor/adapter.go | 26 ++++++++++++++++++-------- server/conn.go | 6 +++++- server/conn_stmt.go | 3 +++ session/session.go | 23 +++++++++++++---------- sessionctx/variable/session.go | 10 +++++----- sessionctx/variable/sysvar.go | 1 + sessionctx/variable/tidb_vars.go | 5 +++++ 7 files changed, 50 insertions(+), 24 deletions(-) diff --git a/executor/adapter.go b/executor/adapter.go index bac7780e5230b..2d03399e7b65f 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -120,7 +120,7 @@ func (a *recordSet) Next(ctx context.Context, req *chunk.Chunk) (err error) { return } err = errors.Errorf("%v", r) - logutil.Logger(ctx).Error("execute sql panic", zap.String("sql", a.stmt.Text), zap.Stack("stack")) + logutil.Logger(ctx).Error("execute sql panic", zap.String("sql", a.stmt.GetTextToLog()), zap.Stack("stack")) }() err = Next(ctx, a.executor, req) @@ -283,7 +283,7 @@ func (a *ExecStmt) Exec(ctx context.Context) (_ sqlexec.RecordSet, err error) { panic(r) } err = errors.Errorf("%v", r) - logutil.Logger(ctx).Error("execute sql panic", zap.String("sql", a.Text), zap.Stack("stack")) + logutil.Logger(ctx).Error("execute sql panic", zap.String("sql", a.GetTextToLog()), zap.Stack("stack")) }() sctx := a.Ctx @@ -806,7 +806,7 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) { } var sql stringutil.StringerFunc normalizedSQL, digest := sessVars.StmtCtx.SQLDigest() - if sessVars.EnableSlowLogMasking { + if sessVars.EnableLogDesensitization { sql = FormatSQL(normalizedSQL, nil) } else if sensitiveStmt, ok := a.StmtNode.(ast.SensitiveStmtNode); ok { sql = FormatSQL(sensitiveStmt.SecureText(), nil) @@ -956,12 +956,8 @@ func (a *ExecStmt) SummaryStmt(succ bool) { execDetail := stmtCtx.GetExecDetails() copTaskInfo := stmtCtx.CopTasksDetails() memMax := stmtCtx.MemTracker.MaxConsumed() - sql := a.Text - if sensitiveStmt, ok := a.StmtNode.(ast.SensitiveStmtNode); ok { - sql = sensitiveStmt.SecureText() - } diskMax := stmtCtx.DiskTracker.MaxConsumed() - + sql := a.GetTextToLog() stmtsummary.StmtSummaryByDigestMap.AddStatement(&stmtsummary.StmtExecInfo{ SchemaName: strings.ToLower(sessVars.CurrentDB), OriginalSQL: sql, @@ -987,3 +983,17 @@ func (a *ExecStmt) SummaryStmt(succ bool) { PlanInCache: sessVars.FoundInPlanCache, }) } + +// 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() + } else if sensitiveStmt, ok := a.StmtNode.(ast.SensitiveStmtNode); ok { + sql = sensitiveStmt.SecureText() + } else { + sql = a.Text + } + return sql +} diff --git a/server/conn.go b/server/conn.go index eb1d7754ff2ba..ba9e2ed3670fb 100644 --- a/server/conn.go +++ b/server/conn.go @@ -1617,7 +1617,11 @@ func (cc getLastStmtInConn) String() string { case mysql.ComFieldList: return "ListFields " + string(data) case mysql.ComQuery, mysql.ComStmtPrepare: - return queryStrForLog(string(hack.String(data))) + sql := string(hack.String(data)) + if cc.ctx.GetSessionVars().EnableLogDesensitization { + sql, _ = parser.NormalizeDigest(sql) + } + return queryStrForLog(sql) case mysql.ComStmtExecute, mysql.ComStmtFetch: stmtID := binary.LittleEndian.Uint32(data[0:4]) return queryStrForLog(cc.preparedStmt2String(stmtID)) diff --git a/server/conn_stmt.go b/server/conn_stmt.go index 0786b7c990fa0..92e392abe1fec 100644 --- a/server/conn_stmt.go +++ b/server/conn_stmt.go @@ -633,6 +633,9 @@ func (cc *clientConn) preparedStmt2String(stmtID uint32) string { if sv == nil { return "" } + if sv.EnableLogDesensitization { + return cc.preparedStmt2StringNoArgs(stmtID) + } return cc.preparedStmt2StringNoArgs(stmtID) + sv.PreparedParams.String() } diff --git a/session/session.go b/session/session.go index 1c40f0011cc3c..706e440a042b9 100644 --- a/session/session.go +++ b/session/session.go @@ -1033,8 +1033,8 @@ func (s *session) SetProcessInfo(sql string, t time.Time, command byte, maxExecu s.processInfo.Store(&pi) } -func (s *session) executeStatement(ctx context.Context, connID uint64, stmtNode ast.StmtNode, stmt sqlexec.Statement, recordSets []sqlexec.RecordSet, inMulitQuery bool) ([]sqlexec.RecordSet, error) { - logStmt(stmtNode, s.sessionVars) +func (s *session) executeStatement(ctx context.Context, stmt *executor.ExecStmt, recordSets []sqlexec.RecordSet, inMulitQuery bool) ([]sqlexec.RecordSet, error) { + logStmt(stmt, s.sessionVars) recordSet, err := runStmt(ctx, s, stmt) if err != nil { if !kv.ErrKeyExists.Equal(err) { @@ -1086,7 +1086,6 @@ func (s *session) Execute(ctx context.Context, sql string) (recordSets []sqlexec func (s *session) execute(ctx context.Context, sql string) (recordSets []sqlexec.RecordSet, err error) { s.PrepareTxnCtx(ctx) - connID := s.sessionVars.ConnectionID err = s.loadCommonGlobalVariablesIfNeeded() if err != nil { return nil, err @@ -1148,7 +1147,7 @@ func (s *session) execute(ctx context.Context, sql string) (recordSets []sqlexec s.currentPlan = stmt.Plan // Step3: Execute the physical plan. - if recordSets, err = s.executeStatement(ctx, connID, stmtNode, stmt, recordSets, multiQuery); err != nil { + if recordSets, err = s.executeStatement(ctx, stmt, recordSets, multiQuery); err != nil { return nil, err } } @@ -1244,7 +1243,7 @@ func (s *session) CachedPlanExec(ctx context.Context, stmtCtx.OriginalSQL = stmt.Text stmtCtx.InitSQLDigest(prepareStmt.NormalizedSQL, prepareStmt.SQLDigest) stmtCtx.SetPlanDigest(prepareStmt.NormalizedPlan, prepareStmt.PlanDigest) - logQuery(stmt.OriginText(), s.sessionVars) + logQuery(stmt.GetTextToLog(), s.sessionVars) // run ExecStmt var resultSet sqlexec.RecordSet @@ -1965,6 +1964,7 @@ var builtinGlobalVariable = []string{ variable.TiDBStoreLimit, variable.TiDBAllowAutoRandExplicitInsert, variable.TiDBSlowLogMasking, + variable.TiDBLogDesensitization, variable.TiDBEnableTelemetry, } @@ -2113,14 +2113,14 @@ func (s *session) ShowProcess() *util.ProcessInfo { // logStmt logs some crucial SQL including: CREATE USER/GRANT PRIVILEGE/CHANGE PASSWORD/DDL etc and normal SQL // if variable.ProcessGeneralLog is set. -func logStmt(node ast.StmtNode, vars *variable.SessionVars) { - switch stmt := node.(type) { +func logStmt(execStmt *executor.ExecStmt, vars *variable.SessionVars) { + switch stmt := execStmt.StmtNode.(type) { case *ast.CreateUserStmt, *ast.DropUserStmt, *ast.AlterUserStmt, *ast.SetPwdStmt, *ast.GrantStmt, *ast.RevokeStmt, *ast.AlterTableStmt, *ast.CreateDatabaseStmt, *ast.CreateIndexStmt, *ast.CreateTableStmt, *ast.DropDatabaseStmt, *ast.DropIndexStmt, *ast.DropTableStmt, *ast.RenameTableStmt, *ast.TruncateTableStmt: user := vars.User schemaVersion := vars.TxnCtx.SchemaVersion - if ss, ok := node.(ast.SensitiveStmtNode); ok { + if ss, ok := execStmt.StmtNode.(ast.SensitiveStmtNode); ok { logutil.BgLogger().Info("CRUCIAL OPERATION", zap.Uint64("conn", vars.ConnectionID), zap.Int64("schemaVersion", schemaVersion), @@ -2135,13 +2135,16 @@ func logStmt(node ast.StmtNode, vars *variable.SessionVars) { zap.Stringer("user", user)) } default: - logQuery(node.Text(), vars) + logQuery(execStmt.GetTextToLog(), vars) } } func logQuery(query string, vars *variable.SessionVars) { if atomic.LoadUint32(&variable.ProcessGeneralLog) != 0 && !vars.InRestrictedSQL { query = executor.QueryReplacer.Replace(query) + if !vars.EnableLogDesensitization { + query = query + vars.PreparedParams.String() + } logutil.BgLogger().Info("GENERAL_LOG", zap.Uint64("conn", vars.ConnectionID), zap.Stringer("user", vars.User), @@ -2151,7 +2154,7 @@ func logQuery(query string, vars *variable.SessionVars) { zap.Bool("isReadConsistency", vars.IsReadConsistencyTxn()), zap.String("current_db", vars.CurrentDB), zap.String("txn_mode", vars.GetReadableTxnMode()), - zap.String("sql", query+vars.PreparedParams.String())) + zap.String("sql", query)) } } diff --git a/sessionctx/variable/session.go b/sessionctx/variable/session.go index f6b6437bd9078..70e24677082e3 100644 --- a/sessionctx/variable/session.go +++ b/sessionctx/variable/session.go @@ -606,8 +606,8 @@ type SessionVars struct { // SelectLimit limits the max counts of select statement's output SelectLimit uint64 - // EnableSlowLogMasking indicates that whether masking the query data when log slow query. - EnableSlowLogMasking bool + // EnableLogDesensitization indicates that whether desensitization when log query. + EnableLogDesensitization bool } // PreparedParams contains the parameters of the current prepared statement when executing it. @@ -697,7 +697,7 @@ func NewSessionVars() *SessionVars { FoundInPlanCache: DefTiDBFoundInPlanCache, SelectLimit: math.MaxUint64, AllowAutoRandExplicitInsert: DefTiDBAllowAutoRandExplicitInsert, - EnableSlowLogMasking: DefTiDBSlowLogMasking, + EnableLogDesensitization: DefTiDBLogDesensitization, } vars.KVVars = kv.NewVariables(&vars.Killed) vars.Concurrency = Concurrency{ @@ -1282,8 +1282,8 @@ func (s *SessionVars) SetSystemVar(name string, val string) error { return errors.Trace(err) } s.SelectLimit = result - case TiDBSlowLogMasking: - s.EnableSlowLogMasking = TiDBOptOn(val) + case TiDBSlowLogMasking, TiDBLogDesensitization: + s.EnableLogDesensitization = TiDBOptOn(val) case TiDBEnableCollectExecutionInfo: config.GetGlobalConfig().EnableCollectExecutionInfo = TiDBOptOn(val) case TiDBAllowAutoRandExplicitInsert: diff --git a/sessionctx/variable/sysvar.go b/sessionctx/variable/sysvar.go index 32870bf93a0ce..11cb670fffc23 100644 --- a/sessionctx/variable/sysvar.go +++ b/sessionctx/variable/sysvar.go @@ -723,6 +723,7 @@ var defaultSysVars = []*SysVar{ {ScopeGlobal, TiDBSlowLogMasking, BoolToIntStr(DefTiDBSlowLogMasking)}, {ScopeSession, TiDBEnableCollectExecutionInfo, BoolToIntStr(DefTiDBEnableCollectExecutionInfo)}, {ScopeSession, TiDBAllowAutoRandExplicitInsert, boolToOnOff(DefTiDBAllowAutoRandExplicitInsert)}, + {ScopeGlobal, TiDBLogDesensitization, BoolToIntStr(DefTiDBLogDesensitization)}, {ScopeGlobal, TiDBEnableTelemetry, BoolToIntStr(DefTiDBEnableTelemetry)}, } diff --git a/sessionctx/variable/tidb_vars.go b/sessionctx/variable/tidb_vars.go index fc9259b9642d7..9649329d63877 100644 --- a/sessionctx/variable/tidb_vars.go +++ b/sessionctx/variable/tidb_vars.go @@ -395,11 +395,15 @@ const ( TiDBMetricSchemaRangeDuration = "tidb_metric_query_range_duration" // TiDBSlowLogMasking indicates that whether masking the query data when log slow query. + // Deprecated: use TiDBLogDesensitization 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" + // TiDBEnableTelemetry indicates that whether usage data report to PingCAP is enabled. TiDBEnableTelemetry = "tidb_enable_telemetry" ) @@ -498,6 +502,7 @@ const ( DefTiDBSlowLogMasking = false DefTiDBEnableCollectExecutionInfo = true DefTiDBAllowAutoRandExplicitInsert = false + DefTiDBLogDesensitization = false DefTiDBEnableTelemetry = true )