From 6207c48c2d860602f102558dd8468d99b2752b3e Mon Sep 17 00:00:00 2001 From: lysu Date: Wed, 27 Jun 2018 17:25:36 +0800 Subject: [PATCH] executor, session: replace new line and add user in query log (#6748) (#6920) So we can grep a keyword to get the query, without the need to look up the query in the full log. user name is also needed for auditing purpose. --- executor/adapter.go | 29 ++++++++++++++++++++--------- session/session.go | 15 ++++++++------- 2 files changed, 28 insertions(+), 16 deletions(-) diff --git a/executor/adapter.go b/executor/adapter.go index 361f1f3b0b9f2..f1bf757f88fe5 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -325,6 +325,9 @@ func (a *ExecStmt) buildExecutor(ctx sessionctx.Context) (Executor, error) { return e, nil } +// QueryReplacer replaces new line and tab for grep result including query string. +var QueryReplacer = strings.NewReplacer("\r", " ", "\n", " ", "\t", " ") + func (a *ExecStmt) logSlowQuery(txnTS uint64, succ bool) { level := log.GetLevel() if level < log.WarnLevel { @@ -340,19 +343,27 @@ func (a *ExecStmt) logSlowQuery(txnTS uint64, succ bool) { if len(sql) > int(cfg.Log.QueryLogMaxLen) { sql = fmt.Sprintf("%.*q(len:%d)", cfg.Log.QueryLogMaxLen, sql, len(a.Text)) } - connID := a.Ctx.GetSessionVars().ConnectionID - currentDB := a.Ctx.GetSessionVars().CurrentDB - tableIDs := strings.Replace(fmt.Sprintf("%v", a.Ctx.GetSessionVars().StmtCtx.TableIDs), " ", ",", -1) - indexIDs := strings.Replace(fmt.Sprintf("%v", a.Ctx.GetSessionVars().StmtCtx.IndexIDs), " ", ",", -1) - + sql = QueryReplacer.Replace(sql) + + sessVars := a.Ctx.GetSessionVars() + connID := sessVars.ConnectionID + currentDB := sessVars.CurrentDB + var tableIDs, indexIDs string + if len(sessVars.StmtCtx.TableIDs) > 0 { + tableIDs = strings.Replace(fmt.Sprintf("table_ids:%v ", a.Ctx.GetSessionVars().StmtCtx.TableIDs), " ", ",", -1) + } + if len(sessVars.StmtCtx.IndexIDs) > 0 { + indexIDs = strings.Replace(fmt.Sprintf("index_ids:%v ", a.Ctx.GetSessionVars().StmtCtx.IndexIDs), " ", ",", -1) + } + user := a.Ctx.GetSessionVars().User if costTime < threshold { logutil.SlowQueryLogger.Debugf( - "[QUERY] cost_time:%v succ:%v connection_id:%v txn_start_ts:%v database:%v table_ids:%v index_ids:%v sql:%v", - costTime, succ, connID, txnTS, currentDB, tableIDs, indexIDs, sql) + "[QUERY] cost_time:%v succ:%v con:%v user:%s txn_start_ts:%v database:%v %v%vsql:%v", + costTime, succ, connID, user, txnTS, currentDB, tableIDs, indexIDs, sql) } else { logutil.SlowQueryLogger.Warnf( - "[SLOW_QUERY] cost_time:%v succ:%v connection_id:%v txn_start_ts:%v database:%v table_ids:%v index_ids:%v sql:%v", - costTime, succ, connID, txnTS, currentDB, tableIDs, indexIDs, sql) + "[SLOW_QUERY] cost_time:%v succ:%v con:%v user:%s txn_start_ts:%v database:%v %v%vsql:%v", + costTime, succ, connID, user, txnTS, currentDB, tableIDs, indexIDs, sql) } } diff --git a/session/session.go b/session/session.go index f95376a7e5201..bc253bb55b6b3 100644 --- a/session/session.go +++ b/session/session.go @@ -495,9 +495,9 @@ func (s *session) retry(ctx context.Context, maxCnt uint) error { if retryCnt == 0 { // We do not have to log the query every time. // We print the queries at the first try only. - log.Warnf("[con:%d] Retry:%d query:%d %s", connID, retryCnt, i, sqlForLog(st.OriginText())) + log.Warnf("con:%d retry_cnt:%d query_num:%d sql:%s", connID, retryCnt, i, sqlForLog(st.OriginText())) } else { - log.Warnf("[con:%d] Retry:%d query:%d", connID, retryCnt, i) + log.Warnf("con:%d retry_cnt:%d query_num:%d", connID, retryCnt, i) } s.sessionVars.StmtCtx = sr.stmtCtx s.sessionVars.StmtCtx.ResetForRetry() @@ -539,9 +539,9 @@ func (s *session) retry(ctx context.Context, maxCnt uint) error { func sqlForLog(sql string) string { if len(sql) > sqlLogMaxLen { - return sql[:sqlLogMaxLen] + fmt.Sprintf("(len:%d)", len(sql)) + sql = sql[:sqlLogMaxLen] + fmt.Sprintf("(len:%d)", len(sql)) } - return sql + return executor.QueryReplacer.Replace(sql) } func (s *session) sysSessionPool() *pools.ResourcePool { @@ -1405,9 +1405,9 @@ func logStmt(node ast.StmtNode, vars *variable.SessionVars) { *ast.DropDatabaseStmt, *ast.DropIndexStmt, *ast.DropTableStmt, *ast.RenameTableStmt, *ast.TruncateTableStmt: user := vars.User if ss, ok := node.(ast.SensitiveStmtNode); ok { - log.Infof("[CRUCIAL OPERATION] [con:%v] %s (by %s).", vars.ConnectionID, ss.SecureText(), user) + log.Infof("[CRUCIAL OPERATION] con:%d %s (by %s).", vars.ConnectionID, ss.SecureText(), user) } else { - log.Infof("[CRUCIAL OPERATION] [con:%v] %s (by %s).", vars.ConnectionID, stmt.Text(), user) + log.Infof("[CRUCIAL OPERATION] con:%d %s (by %s).", vars.ConnectionID, stmt.Text(), user) } default: logQuery(node.Text(), vars) @@ -1416,6 +1416,7 @@ func logStmt(node ast.StmtNode, vars *variable.SessionVars) { func logQuery(query string, vars *variable.SessionVars) { if atomic.LoadUint32(&variable.ProcessGeneralLog) != 0 && !vars.InRestrictedSQL { - log.Infof("[con:%d][txn:%d] %s", vars.ConnectionID, vars.TxnCtx.StartTS, query) + query = executor.QueryReplacer.Replace(query) + log.Infof("[GENERAL_LOG] con:%d user:%s schema_ver:%d start_ts:%d sql:%s", vars.ConnectionID, vars.User, vars.TxnCtx.SchemaVersion, vars.TxnCtx.StartTS, query) } }