executor: make the format of user and host fields in slow logs be com…

…patible with MySQL (#18162)
pingcap · Jul 6, 2020 · ef8ad55 · ef8ad55
1 parent 5a52c5d
commit ef8ad55
Show file tree

Hide file tree

Showing 5 changed files with 44 additions and 10 deletions.
diff --git a/executor/slow_query.go b/executor/slow_query.go
@@ -231,6 +231,17 @@ func (e *slowQueryRetriever) parseSlowLog(ctx sessionctx.Context, reader *bufio.
 				line = line[len(variable.SlowLogRowPrefixStr):]
 				if strings.HasPrefix(line, variable.SlowLogPrevStmtPrefix) {
 					st.prevStmt = line[len(variable.SlowLogPrevStmtPrefix):]
+				} else if strings.HasPrefix(line, variable.SlowLogUserAndHostStr+variable.SlowLogSpaceMarkStr) {
+					// the user and hostname field has a special format, for example, # User@Host: root[root] @ localhost [127.0.0.1]
+					value := line[len(variable.SlowLogUserAndHostStr+variable.SlowLogSpaceMarkStr):]
+					valid, err := st.setFieldValue(tz, variable.SlowLogUserAndHostStr, value, e.fileLine, e.checker)
+					if err != nil {
+						ctx.GetSessionVars().StmtCtx.AppendWarning(err)
+						continue
+					}
+					if !valid {
+						startFlag = false
+					}
 				} else {
 					fieldValues := strings.Split(line, " ")
 					for i := 0; i < len(fieldValues)-1; i += 2 {
@@ -374,6 +385,7 @@ func (st *slowQueryTuple) setFieldValue(tz *time.Location, field, value string,
 	case variable.SlowLogTxnStartTSStr:
 		st.txnStartTs, err = strconv.ParseUint(value, 10, 64)
 	case variable.SlowLogUserStr:
+		// the old User format is kept for compatibility
 		fields := strings.SplitN(value, "@", 2)
 		if len(field) > 0 {
 			st.user = fields[0]
@@ -384,6 +396,20 @@ func (st *slowQueryTuple) setFieldValue(tz *time.Location, field, value string,
 		if checker != nil {
 			valid = checker.hasPrivilege(st.user)
 		}
+	case variable.SlowLogUserAndHostStr:
+		// the new User&Host format: root[root] @ localhost [127.0.0.1]
+		fields := strings.SplitN(value, "@", 2)
+		if len(fields) > 0 {
+			tmp := strings.Split(fields[0], "[")
+			st.user = strings.TrimSpace(tmp[0])
+		}
+		if len(fields) > 1 {
+			tmp := strings.Split(fields[1], "[")
+			st.host = strings.TrimSpace(tmp[0])
+		}
+		if checker != nil {
+			valid = checker.hasPrivilege(st.user)
+		}
 	case variable.SlowLogConnIDStr:
 		st.connID, err = strconv.ParseUint(value, 10, 64)
 	case variable.SlowLogQueryTimeStr:

diff --git a/executor/slow_query_test.go b/executor/slow_query_test.go
@@ -46,6 +46,7 @@ func (s *testExecSuite) TestParseSlowLogFile(c *C) {
 	slowLogStr :=
 		`# Time: 2019-04-28T15:24:04.309074+08:00
 # Txn_start_ts: 405888132465033227
+# User@Host: root[root] @ localhost [127.0.0.1]
 # Query_time: 0.216905
 # Cop_time: 0.38 Process_time: 0.021 Request_count: 1 Total_keys: 637 Processed_keys: 436
 # Is_internal: true
@@ -77,7 +78,7 @@ select * from t;`
 		}
 		recordString += str
 	}
-	expectRecordString := "2019-04-28 15:24:04.309074,405888132465033227,,,0,0.216905,0,0,0,0,0,0,0,0,0,0,0,0,,0,0,0,0,0,0,0.38,0.021,0,0,0,1,637,0,,,1,42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772,t1:1,t2:2,0.1,0.2,0.03,127.0.0.1:20160,0.05,0.6,0.8,0.0.0.0:20160,70724,65536,0,1,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,update t set i = 1;,select * from t;"
+	expectRecordString := "2019-04-28 15:24:04.309074,405888132465033227,root,localhost,0,0.216905,0,0,0,0,0,0,0,0,0,0,0,0,,0,0,0,0,0,0,0.38,0.021,0,0,0,1,637,0,,,1,42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772,t1:1,t2:2,0.1,0.2,0.03,127.0.0.1:20160,0.05,0.6,0.8,0.0.0.0:20160,70724,65536,0,1,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,update t set i = 1;,select * from t;"
 	c.Assert(expectRecordString, Equals, recordString)
 
 	// fix sql contain '# ' bug

diff --git a/infoschema/tables_test.go b/infoschema/tables_test.go
@@ -531,7 +531,7 @@ func prepareSlowLogfile(c *C, slowLogFileName string) {
 	c.Assert(err, IsNil)
 	_, err = f.Write([]byte(`# Time: 2019-02-12T19:33:56.571953+08:00
 # Txn_start_ts: 406315658548871171
-# User: root@127.0.0.1
+# User@Host: root[root] @ localhost [127.0.0.1]
 # Conn_ID: 6
 # Query_time: 4.895492
 # Parse_time: 0.4
@@ -623,10 +623,10 @@ func (s *testTableSuite) TestSlowQuery(c *C) {
 	tk.MustExec("set time_zone = '+08:00';")
 	re := tk.MustQuery("select * from information_schema.slow_query")
 	re.Check(testutil.RowsWithSep("|",
-		"2019-02-12 19:33:56.571953|406315658548871171|root|127.0.0.1|6|4.895492|0.4|0.2|0.000000003|2|0.000000002|0.00000001|0.000000003|0.19|0.21|0.01|0|0.18|[txnLock]|0.03|0|15|480|1|8|0.3824278|0.161|0.101|0.092|1.71|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|0.1|0.2|0.03|127.0.0.1:20160|0.05|0.6|0.8|0.0.0.0:20160|70724|65536|1|1|abcd|60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4|update t set i = 2;|select * from t_slim;"))
+		"2019-02-12 19:33:56.571953|406315658548871171|root|localhost|6|4.895492|0.4|0.2|0.000000003|2|0.000000002|0.00000001|0.000000003|0.19|0.21|0.01|0|0.18|[txnLock]|0.03|0|15|480|1|8|0.3824278|0.161|0.101|0.092|1.71|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|0.1|0.2|0.03|127.0.0.1:20160|0.05|0.6|0.8|0.0.0.0:20160|70724|65536|1|1|abcd|60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4|update t set i = 2;|select * from t_slim;"))
 	tk.MustExec("set time_zone = '+00:00';")
 	re = tk.MustQuery("select * from information_schema.slow_query")
-	re.Check(testutil.RowsWithSep("|", "2019-02-12 11:33:56.571953|406315658548871171|root|127.0.0.1|6|4.895492|0.4|0.2|0.000000003|2|0.000000002|0.00000001|0.000000003|0.19|0.21|0.01|0|0.18|[txnLock]|0.03|0|15|480|1|8|0.3824278|0.161|0.101|0.092|1.71|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|0.1|0.2|0.03|127.0.0.1:20160|0.05|0.6|0.8|0.0.0.0:20160|70724|65536|1|1|abcd|60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4|update t set i = 2;|select * from t_slim;"))
+	re.Check(testutil.RowsWithSep("|", "2019-02-12 11:33:56.571953|406315658548871171|root|localhost|6|4.895492|0.4|0.2|0.000000003|2|0.000000002|0.00000001|0.000000003|0.19|0.21|0.01|0|0.18|[txnLock]|0.03|0|15|480|1|8|0.3824278|0.161|0.101|0.092|1.71|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|0.1|0.2|0.03|127.0.0.1:20160|0.05|0.6|0.8|0.0.0.0:20160|70724|65536|1|1|abcd|60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4|update t set i = 2;|select * from t_slim;"))
 
 	// Test for long query.
 	f, err := os.OpenFile(slowLogFileName, os.O_CREATE|os.O_WRONLY, 0644)
@@ -814,13 +814,13 @@ func (s *testClusterTableSuite) TestSelectClusterTablePrivelege(c *C) {
 	c.Assert(err, IsNil)
 	_, err = f.Write([]byte(
 		`# Time: 2019-02-12T19:33:57.571953+08:00
-# User: user2@127.0.0.1
+# User@Host: user2 [user2] @ 127.0.0.1 [127.0.0.1]
 select * from t2;
 # Time: 2019-02-12T19:33:56.571953+08:00
-# User: user1@127.0.0.1
+# User@Host: user1 [user1] @ 127.0.0.1 [127.0.0.1]
 select * from t1;
 # Time: 2019-02-12T19:33:58.571953+08:00
-# User: user2@127.0.0.1
+# User@Host: user2 [user2] @ 127.0.0.1 [127.0.0.1]
 select * from t3;
 # Time: 2019-02-12T19:33:59.571953+08:00
 select * from t3;

diff --git a/sessionctx/variable/session.go b/sessionctx/variable/session.go
@@ -1710,6 +1710,8 @@ const (
 	SlowLogStartPrefixStr = SlowLogRowPrefixStr + SlowLogTimeStr + SlowLogSpaceMarkStr
 	// SlowLogTxnStartTSStr is slow log field name.
 	SlowLogTxnStartTSStr = "Txn_start_ts"
+	// SlowLogUserAndHostStr is the user and host field name, which is compatible with MySQL.
+	SlowLogUserAndHostStr = "User@Host"
 	// SlowLogUserStr is slow log field name.
 	SlowLogUserStr = "User"
 	// SlowLogHostStr only for slow_query table usage.
@@ -1833,7 +1835,7 @@ type SlowQueryLogItems struct {
 // The slow log output is like below:
 // # Time: 2019-04-28T15:24:04.309074+08:00
 // # Txn_start_ts: 406315658548871171
-// # User: root@127.0.0.1
+// # User@Host: root[root] @ localhost [127.0.0.1]
 // # Conn_ID: 6
 // # Query_time: 4.895492
 // # Process_time: 0.161 Request_count: 1 Total_keys: 100001 Processed_keys: 100000
@@ -1855,7 +1857,11 @@ func (s *SessionVars) SlowLogFormat(logItems *SlowQueryLogItems) string {
 
 	writeSlowLogItem(&buf, SlowLogTxnStartTSStr, strconv.FormatUint(logItems.TxnTS, 10))
 	if s.User != nil {
-		writeSlowLogItem(&buf, SlowLogUserStr, s.User.String())
+		hostAddress := s.User.Hostname
+		if s.ConnectionInfo != nil {
+			hostAddress = s.ConnectionInfo.ClientIP
+		}
+		writeSlowLogItem(&buf, SlowLogUserAndHostStr, fmt.Sprintf("%s[%s] @ %s [%s]", s.User.Username, s.User.Username, s.User.Hostname, hostAddress))
 	}
 	if s.ConnectionID != 0 {
 		writeSlowLogItem(&buf, SlowLogConnIDStr, strconv.FormatUint(s.ConnectionID, 10))

diff --git a/sessionctx/variable/session_test.go b/sessionctx/variable/session_test.go
@@ -129,6 +129,7 @@ func (*testSessionSuite) TestSlowLogFormat(c *C) {
 	c.Assert(seVar, NotNil)
 
 	seVar.User = &auth.UserIdentity{Username: "root", Hostname: "192.168.0.1"}
+	seVar.ConnectionInfo = &variable.ConnectionInfo{ClientIP: "192.168.0.1"}
 	seVar.ConnectionID = 1
 	seVar.CurrentDB = "test"
 	seVar.InRestrictedSQL = true
@@ -175,7 +176,7 @@ func (*testSessionSuite) TestSlowLogFormat(c *C) {
 	var memMax int64 = 2333
 	var diskMax int64 = 6666
 	resultString := `# Txn_start_ts: 406649736972468225
-# User: root@192.168.0.1
+# User@Host: root[root] @ 192.168.0.1 [192.168.0.1]
 # Conn_ID: 1
 # Query_time: 1
 # Parse_time: 0.00000001