Skip to content

Commit

Permalink
executor, session: replace new line and add user in query log (#6748)
Browse files Browse the repository at this point in the history 
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.
  • Loading branch information
@coocood
coocood authored Jun 11, 2018
1 parent 1ac0c36 commit d85334d
Show file tree
Hide file tree
Showing 2 changed files with 28 additions and 16 deletions.
29 changes: 20 additions & 9 deletions executor/adapter.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand All @@ -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 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)
}
}

Expand Down
15 changes: 8 additions & 7 deletions session/session.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand Down Expand Up @@ -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 {
Expand Down Expand Up @@ -1429,9 +1429,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)
Expand All @@ -1440,6 +1440,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("[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)
}
}

0 comments on commit d85334d

Please sign in to comment.