From be234d3e2a29c81d27457494e43809cad7be45da Mon Sep 17 00:00:00 2001 From: Ewan Chou Date: Mon, 4 Jun 2018 16:56:33 +0800 Subject: [PATCH 1/5] executor, session: replace new line and add user in query log 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 | 3 ++- 2 files changed, 22 insertions(+), 10 deletions(-) diff --git a/executor/adapter.go b/executor/adapter.go index acdafbd386291..5a880f0442c0b 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -324,6 +324,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 { @@ -339,19 +342,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 connection_id:%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 connection_id:%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 6365b098657cb..c27cca0593612 100644 --- a/session/session.go +++ b/session/session.go @@ -1468,6 +1468,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][schema ver:%d][txn:%d] %s", vars.ConnectionID, vars.TxnCtx.SchemaVersion, vars.TxnCtx.StartTS, query) + query = executor.QueryReplacer.Replace(query) + log.Infof("[con:%d][user:%s][schema_ver:%d][txn:%d] %s", vars.ConnectionID, vars.User, vars.TxnCtx.SchemaVersion, vars.TxnCtx.StartTS, query) } } From 955cdae973d19150f4b2cc63310fc183f177ebc7 Mon Sep 17 00:00:00 2001 From: Ewan Chou Date: Mon, 4 Jun 2018 18:29:23 +0800 Subject: [PATCH 2/5] refine general log and slow log format --- executor/adapter.go | 4 ++-- session/session.go | 6 +++--- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/executor/adapter.go b/executor/adapter.go index 5a880f0442c0b..6fb33838eb1a4 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -357,11 +357,11 @@ func (a *ExecStmt) logSlowQuery(txnTS uint64, succ bool) { user := a.Ctx.GetSessionVars().User if costTime < threshold { logutil.SlowQueryLogger.Debugf( - "[QUERY] cost_time:%v succ:%v connection_id:%v user:%s txn_start_ts:%v database:%v %v%vsql:%v", + "[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 user:%s txn_start_ts:%v database:%v %v%vsql:%v", + "[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 c27cca0593612..cab198155f79f 100644 --- a/session/session.go +++ b/session/session.go @@ -1457,9 +1457,9 @@ func logStmt(node ast.StmtNode, vars *variable.SessionVars) { user := vars.User schemaVersion := vars.TxnCtx.SchemaVersion if ss, ok := node.(ast.SensitiveStmtNode); ok { - log.Infof("[CRUCIAL OPERATION] [con:%d][schema ver:%d] %s (by %s).", vars.ConnectionID, schemaVersion, ss.SecureText(), user) + log.Infof("[CRUCIAL OPERATION] con:%d schema_ver:%d %s (by %s).", vars.ConnectionID, schemaVersion, ss.SecureText(), user) } else { - log.Infof("[CRUCIAL OPERATION] [con:%d][schema ver:%d] %s (by %s).", vars.ConnectionID, schemaVersion, stmt.Text(), user) + log.Infof("[CRUCIAL OPERATION] con:%d schema_ver:%d %s (by %s).", vars.ConnectionID, schemaVersion, stmt.Text(), user) } default: logQuery(node.Text(), vars) @@ -1469,6 +1469,6 @@ func logStmt(node ast.StmtNode, vars *variable.SessionVars) { func logQuery(query string, vars *variable.SessionVars) { if atomic.LoadUint32(&variable.ProcessGeneralLog) != 0 && !vars.InRestrictedSQL { query = executor.QueryReplacer.Replace(query) - log.Infof("[con:%d][user:%s][schema_ver:%d][txn:%d] %s", vars.ConnectionID, vars.User, vars.TxnCtx.SchemaVersion, vars.TxnCtx.StartTS, 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) } } From b3fbac00563ba5ac99855ba1bd6ce7be696e5c74 Mon Sep 17 00:00:00 2001 From: Ewan Chou Date: Tue, 5 Jun 2018 12:32:21 +0800 Subject: [PATCH 3/5] address comment --- session/session.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/session/session.go b/session/session.go index cab198155f79f..2d8a23e16402b 100644 --- a/session/session.go +++ b/session/session.go @@ -500,9 +500,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][schema ver:%d] Retry:%d query:%d %s", connID, schemaVersion, retryCnt, i, sqlForLog(st.OriginText())) + log.Warnf("con:%d schema_ver:%d retry_cnt:%d query_num:%d sql:%s", connID, schemaVersion, retryCnt, i, sqlForLog(st.OriginText())) } else { - log.Warnf("[con:%d][schema ver:%d] Retry:%d query:%d", connID, schemaVersion, retryCnt, i) + log.Warnf("con:%d schema_ver:%d retry_cnt:%d query_num:%d", connID, schemaVersion, retryCnt, i) } s.sessionVars.StmtCtx = sr.stmtCtx s.sessionVars.StmtCtx.ResetForRetry() @@ -544,9 +544,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 { From f59855af66c301b982918e11dd1c5f997c8f4c0f Mon Sep 17 00:00:00 2001 From: Ewan Chou Date: Wed, 6 Jun 2018 18:33:56 +0800 Subject: [PATCH 4/5] address comment --- executor/adapter.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/executor/adapter.go b/executor/adapter.go index 6fb33838eb1a4..15f2d835c3df2 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -325,7 +325,7 @@ func (a *ExecStmt) buildExecutor(ctx sessionctx.Context) (Executor, error) { } // QueryReplacer replaces new line and tab for grep result including query string. -var QueryReplacer = strings.NewReplacer("\r", "", "\n", "", "\t", " ") +var QueryReplacer = strings.NewReplacer("\r", "", "\n", " ", "\t", " ") func (a *ExecStmt) logSlowQuery(txnTS uint64, succ bool) { level := log.GetLevel() From 95b2ddeb0d702dda04cc3efce84d64bad018e77e Mon Sep 17 00:00:00 2001 From: Ewan Chou Date: Mon, 11 Jun 2018 11:18:46 +0800 Subject: [PATCH 5/5] address comment --- executor/adapter.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/executor/adapter.go b/executor/adapter.go index 15f2d835c3df2..aee4bdf23c045 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -325,7 +325,7 @@ func (a *ExecStmt) buildExecutor(ctx sessionctx.Context) (Executor, error) { } // QueryReplacer replaces new line and tab for grep result including query string. -var QueryReplacer = strings.NewReplacer("\r", "", "\n", " ", "\t", " ") +var QueryReplacer = strings.NewReplacer("\r", " ", "\n", " ", "\t", " ") func (a *ExecStmt) logSlowQuery(txnTS uint64, succ bool) { level := log.GetLevel()