executor, session: replace new line and add user in query log #6748

coocood · 2018-06-04T09:12:43Z

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.

Fixes #6673

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.

shenli · 2018-06-04T10:24:51Z

executor/adapter.go

-			"[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)


Does the user contain host-ip?

shenli · 2018-06-04T10:25:42Z

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", " ")


How about there is a newline or tab in the string literal?

It will be escaped as three characters `\' '\' 'n' instead of a single character '\n'.

This query is used for logging, it's ok even if we replace new line in the string.

shenli · 2018-06-04T10:26:04Z

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)


Could you post an example of the new log?

coocood · 2018-06-05T02:21:23Z

general log example:

2018/06/05 10:19:29.944 session.go:1472: [info] [GENERAL_LOG] con:2 user:root@127.0.0.1 schema_ver:15 start_ts:0 sql:select 1

zimulala · 2018-06-05T03:40:39Z

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)


Do we need to make the same changes to unify the log format in line 503?

coocood · 2018-06-05T04:33:07Z

@zimulala PTAL

zimulala · 2018-06-06T02:18:51Z

executor/adapter.go

+	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)


Why do you want to replace spaces with commas? I think it has a certain loss of performance. If it is not necessary, it may not be done.

It is useful when we need to use ' ' as fields separator.

or should we Itoa to []string and strings.Join if performance is critial?

The performance is not critical here, we better use a simpler solution.

jackysp · 2018-06-06T07:55:25Z

mysql> select 
    -> sleep(1);

will look like

[SLOW_QUERY] cost_time:1.001480917s succ:true con:2 user:root@127.0.0.1 txn_start_ts:400627245054951425 database:test sql:selectsleep(1)

coocood · 2018-06-06T10:34:20Z

@jackysp PTAL

lysu · 2018-06-06T11:24:25Z

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", " ")


maybe use var QueryReplacer = strings.NewReplacer("\r", " ", "\n", " ", "\t", " ") although give more 1 space ?
if len(new) == len(old) == 1 replace will be more quicker~

func BenchmarkPureBinary(b *testing.B) { var r = strings.NewReplacer(",", " ", "-", " ") for i := 0; i < b.N; i++ { a := r.Replace("sadfsadfa,sdfsd,dsfsa,sdfsad,dsfsa-sdfa-sdf-dsfad-fsadf-sa,sadfas") a = a } } func BenchmarkBinaryString(b *testing.B) { var r = strings.NewReplacer(",", "", "-", "") for i := 0; i < b.N; i++ { a := r.Replace("sadfsadfa,sdfsd,dsfsa,sdfsad,dsfsa-sdfa-sdf-dsfad-fsadf-sa,sadfas") a = a } } BenchmarkPureBinary-8 10000000 144 ns/op 160 B/op 2 allocs/op BenchmarkBinaryString-8 5000000 267 ns/op 128 B/op 2 allocs/op

lysu · 2018-06-06T11:35:44Z

executor/adapter.go

+	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)


or should we Itoa to []string and strings.Join if performance is critial?

lysu · 2018-06-06T11:51:28Z

executor/adapter.go

 	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",


maybe not use %v if it know real type~

I think it doesn't matter much.

coocood · 2018-06-11T03:22:45Z

@lysu PTAL

coocood · 2018-06-11T03:24:17Z

@zimulala PTAL

jackysp

LGTM

lysu · 2018-06-11T08:49:33Z

LGTM

coocood · 2018-06-11T09:04:25Z

/run-all-tests

coocood · 2018-06-11T11:59:42Z

/run-unit-test

…#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, session: replace new line and add user in query log

be234d3

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.

shenli reviewed Jun 4, 2018

View reviewed changes

refine general log and slow log format

955cdae

zimulala reviewed Jun 5, 2018

View reviewed changes

address comment

b3fbac0

zimulala reviewed Jun 6, 2018

View reviewed changes

address comment

f59855a

lysu reviewed Jun 6, 2018

View reviewed changes

coocood added 2 commits June 11, 2018 11:18

address comment

95b2dde

Merge branch 'master' into refine-query-log

62314b6

jackysp reviewed Jun 11, 2018

View reviewed changes

Merge branch 'master' into refine-query-log

784d3dc

zimulala added the status/LGT2 Indicates that a PR has LGTM 2. label Jun 11, 2018

zimulala approved these changes Jun 11, 2018

View reviewed changes

coocood merged commit d85334d into pingcap:master Jun 11, 2018

coocood deleted the refine-query-log branch June 11, 2018 12:38

This was referenced Jun 27, 2018

can we record more information about slow_sql log #6898

Closed

executor, session: replace new line and add user in query log (#6748) #6920

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

executor, session: replace new line and add user in query log #6748

executor, session: replace new line and add user in query log #6748

coocood commented Jun 4, 2018 •

edited

Loading

shenli Jun 4, 2018

shenli Jun 4, 2018

coocood Jun 5, 2018 •

edited

Loading

coocood Jun 5, 2018 •

edited

Loading

shenli Jun 4, 2018

coocood commented Jun 5, 2018

zimulala Jun 5, 2018

coocood commented Jun 5, 2018

zimulala Jun 6, 2018

coocood Jun 6, 2018

lysu Jun 6, 2018 •

edited

Loading

coocood Jun 11, 2018

jackysp commented Jun 6, 2018

coocood commented Jun 6, 2018

lysu Jun 6, 2018

lysu Jun 6, 2018 •

edited

Loading

lysu Jun 6, 2018

coocood Jun 11, 2018

coocood commented Jun 11, 2018

coocood commented Jun 11, 2018

jackysp left a comment

lysu commented Jun 11, 2018

coocood commented Jun 11, 2018

coocood commented Jun 11, 2018

executor, session: replace new line and add user in query log #6748

executor, session: replace new line and add user in query log #6748

Conversation

coocood commented Jun 4, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

coocood Jun 5, 2018 • edited Loading

Choose a reason for hiding this comment

coocood Jun 5, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

coocood commented Jun 5, 2018

Choose a reason for hiding this comment

coocood commented Jun 5, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lysu Jun 6, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jackysp commented Jun 6, 2018

coocood commented Jun 6, 2018

Choose a reason for hiding this comment

lysu Jun 6, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

coocood commented Jun 11, 2018

coocood commented Jun 11, 2018

jackysp left a comment

Choose a reason for hiding this comment

lysu commented Jun 11, 2018

coocood commented Jun 11, 2018

coocood commented Jun 11, 2018

coocood commented Jun 4, 2018 •

edited

Loading

coocood Jun 5, 2018 •

edited

Loading

coocood Jun 5, 2018 •

edited

Loading

lysu Jun 6, 2018 •

edited

Loading

lysu Jun 6, 2018 •

edited

Loading