diff --git a/executor/slow_query.go b/executor/slow_query.go index f9c8f828424a1..7bf41c5d84853 100644 --- 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 index fc5090ffd4d29..c1eef75f692d9 100644 --- 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 index b4c4f7e9d4ce1..3ae5a982ae1c0 100644 --- 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 index 9cc94bbfc04ea..7e5b5948ebf59 100644 --- 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 index 5966a8ca8c7c3..c4eafee63dc2e 100644 --- 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