From 8a76ac4c23656c306ba087c8574c38774e9addd9 Mon Sep 17 00:00:00 2001 From: Yuanjia Zhang Date: Mon, 22 Jun 2020 11:20:24 +0800 Subject: [PATCH 1/6] make user and host fields in slow logs be compatible with MySQL --- executor/slow_query.go | 24 +++++++++++++++++++----- executor/slow_query_test.go | 3 ++- server/server.go | 6 ++---- sessionctx/variable/session.go | 10 ++++++++-- sessionctx/variable/session_test.go | 3 ++- 5 files changed, 33 insertions(+), 13 deletions(-) diff --git a/executor/slow_query.go b/executor/slow_query.go index f9c8f828424a1..436aaa3129462 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 { @@ -373,13 +384,16 @@ func (st *slowQueryTuple) setFieldValue(tz *time.Location, field, value string, } case variable.SlowLogTxnStartTSStr: st.txnStartTs, err = strconv.ParseUint(value, 10, 64) - case variable.SlowLogUserStr: + case variable.SlowLogUserAndHostStr: + // root[root] @ localhost [127.0.0.1] fields := strings.SplitN(value, "@", 2) - if len(field) > 0 { - st.user = fields[0] + if len(fields) > 0 { + tmp := strings.Split(fields[0], "[") + st.user = strings.TrimSpace(tmp[0]) } - if len(field) > 1 { - st.host = fields[1] + if len(fields) > 1 { + tmp := strings.Split(fields[1], "[") + st.host = strings.TrimSpace(tmp[0]) } if checker != nil { valid = checker.hasPrivilege(st.user) 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/server/server.go b/server/server.go index 24a664db554c5..a0b949eee96cd 100644 --- a/server/server.go +++ b/server/server.go @@ -365,8 +365,8 @@ func (s *Server) Close() { func (s *Server) onConn(conn *clientConn) { ctx := logutil.WithConnID(context.Background(), conn.connectionID) if err := conn.handshake(ctx); err != nil { + conn.ctx.GetSessionVars().ConnectionInfo = conn.connectInfo() if plugin.IsEnable(plugin.Audit) && conn.ctx != nil { - conn.ctx.GetSessionVars().ConnectionInfo = conn.connectInfo() err = plugin.ForeachPlugin(plugin.Audit, func(p *plugin.Plugin) error { authPlugin := plugin.DeclareAuditManifest(p.Manifest) if authPlugin.OnConnectionEvent != nil { @@ -397,9 +397,7 @@ func (s *Server) onConn(conn *clientConn) { metrics.ConnGauge.Set(float64(connections)) sessionVars := conn.ctx.GetSessionVars() - if plugin.IsEnable(plugin.Audit) { - sessionVars.ConnectionInfo = conn.connectInfo() - } + sessionVars.ConnectionInfo = conn.connectInfo() err := plugin.ForeachPlugin(plugin.Audit, func(p *plugin.Plugin) error { authPlugin := plugin.DeclareAuditManifest(p.Manifest) if authPlugin.OnConnectionEvent != nil { diff --git a/sessionctx/variable/session.go b/sessionctx/variable/session.go index 80ebf8e147a96..9372885d70e3b 100644 --- a/sessionctx/variable/session.go +++ b/sessionctx/variable/session.go @@ -1525,6 +1525,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. @@ -1648,7 +1650,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 @@ -1670,7 +1672,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..25130267b030c 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 From 31c49f53c98d0a2af8cd054f2450985b95084409 Mon Sep 17 00:00:00 2001 From: Yuanjia Zhang Date: Mon, 22 Jun 2020 13:54:31 +0800 Subject: [PATCH 2/6] refmt --- sessionctx/variable/session_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sessionctx/variable/session_test.go b/sessionctx/variable/session_test.go index 25130267b030c..c4eafee63dc2e 100644 --- a/sessionctx/variable/session_test.go +++ b/sessionctx/variable/session_test.go @@ -129,7 +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.ConnectionInfo = &variable.ConnectionInfo{ClientIP: "192.168.0.1"} seVar.ConnectionID = 1 seVar.CurrentDB = "test" seVar.InRestrictedSQL = true From 56099feebaaed3e368cf53bc74e43936a84c4809 Mon Sep 17 00:00:00 2001 From: Yuanjia Zhang Date: Mon, 22 Jun 2020 15:54:46 +0800 Subject: [PATCH 3/6] fix CI --- infoschema/tables_test.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/infoschema/tables_test.go b/infoschema/tables_test.go index b4c4f7e9d4ce1..b6c06a60ca9bd 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) From fa2d836eab0e1c23ea35e0b4dacfd070945fc7bb Mon Sep 17 00:00:00 2001 From: Yuanjia Zhang Date: Mon, 22 Jun 2020 16:17:26 +0800 Subject: [PATCH 4/6] fix CI --- infoschema/tables_test.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/infoschema/tables_test.go b/infoschema/tables_test.go index b6c06a60ca9bd..3ae5a982ae1c0 100644 --- a/infoschema/tables_test.go +++ b/infoschema/tables_test.go @@ -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; From 72855858507ce090e77ef289eb1fbccc3b2b4713 Mon Sep 17 00:00:00 2001 From: Yuanjia Zhang Date: Mon, 22 Jun 2020 16:26:02 +0800 Subject: [PATCH 5/6] avoid nil pointer --- server/server.go | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/server/server.go b/server/server.go index a0b949eee96cd..24a664db554c5 100644 --- a/server/server.go +++ b/server/server.go @@ -365,8 +365,8 @@ func (s *Server) Close() { func (s *Server) onConn(conn *clientConn) { ctx := logutil.WithConnID(context.Background(), conn.connectionID) if err := conn.handshake(ctx); err != nil { - conn.ctx.GetSessionVars().ConnectionInfo = conn.connectInfo() if plugin.IsEnable(plugin.Audit) && conn.ctx != nil { + conn.ctx.GetSessionVars().ConnectionInfo = conn.connectInfo() err = plugin.ForeachPlugin(plugin.Audit, func(p *plugin.Plugin) error { authPlugin := plugin.DeclareAuditManifest(p.Manifest) if authPlugin.OnConnectionEvent != nil { @@ -397,7 +397,9 @@ func (s *Server) onConn(conn *clientConn) { metrics.ConnGauge.Set(float64(connections)) sessionVars := conn.ctx.GetSessionVars() - sessionVars.ConnectionInfo = conn.connectInfo() + if plugin.IsEnable(plugin.Audit) { + sessionVars.ConnectionInfo = conn.connectInfo() + } err := plugin.ForeachPlugin(plugin.Audit, func(p *plugin.Plugin) error { authPlugin := plugin.DeclareAuditManifest(p.Manifest) if authPlugin.OnConnectionEvent != nil { From cd62633b7d71eb88d886870aa911f523132be152 Mon Sep 17 00:00:00 2001 From: Yuanjia Zhang Date: Thu, 2 Jul 2020 17:14:29 +0800 Subject: [PATCH 6/6] address comment --- executor/slow_query.go | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/executor/slow_query.go b/executor/slow_query.go index 436aaa3129462..7bf41c5d84853 100644 --- a/executor/slow_query.go +++ b/executor/slow_query.go @@ -384,8 +384,20 @@ 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] + } + if len(field) > 1 { + st.host = fields[1] + } + if checker != nil { + valid = checker.hasPrivilege(st.user) + } case variable.SlowLogUserAndHostStr: - // root[root] @ localhost [127.0.0.1] + // 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], "[")