From 528c0d3798f35a81b5e612b6ef0946756e70eb86 Mon Sep 17 00:00:00 2001 From: pingcap-github-bot Date: Thu, 14 May 2020 13:40:23 +0800 Subject: [PATCH] executor: remove default search time range of cluster_log when query without time range. (#16938) (#17003) --- executor/memtable_reader.go | 28 ++++---- executor/memtable_reader_test.go | 66 ++++++++++++++----- planner/core/memtable_predicate_extractor.go | 32 ++------- .../core/memtable_predicate_extractor_test.go | 4 -- 4 files changed, 65 insertions(+), 65 deletions(-) diff --git a/executor/memtable_reader.go b/executor/memtable_reader.go index 986c58409d81f..1f5a88e516982 100644 --- a/executor/memtable_reader.go +++ b/executor/memtable_reader.go @@ -467,16 +467,12 @@ func (h *logResponseHeap) Pop() interface{} { } func (e *clusterLogRetriever) initialize(ctx context.Context, sctx sessionctx.Context) ([]chan logStreamResult, error) { - isFailpointTestModeSkipCheck := false serversInfo, err := infoschema.GetClusterServerInfo(sctx) failpoint.Inject("mockClusterLogServerInfo", func(val failpoint.Value) { // erase the error err = nil if s := val.(string); len(s) > 0 { serversInfo = parseFailpointServerInfo(s) - isFailpointTestModeSkipCheck = true - } else { - isFailpointTestModeSkipCheck = false } }) if err != nil { @@ -492,22 +488,22 @@ func (e *clusterLogRetriever) initialize(ctx context.Context, sctx sessionctx.Co levels = append(levels, sysutil.ParseLogLevel(l)) } - startTime, endTime := e.extractor.GetTimeRange(isFailpointTestModeSkipCheck) + // To avoid search log interface overload, the user should specify the time range, and at least one pattern + // in normally SQL. + if e.extractor.StartTime == 0 { + return nil, errors.New("denied to scan logs, please specified the start time, such as `time > '2020-01-01 00:00:00'`") + } + if e.extractor.EndTime == 0 { + return nil, errors.New("denied to scan logs, please specified the end time, such as `time < '2020-01-01 00:00:00'`") + } patterns := e.extractor.Patterns - - // There is no performance issue to check this variable because it will - // be eliminated in non-failpoint mode. - if !isFailpointTestModeSkipCheck { - // To avoid search log interface overload, the user should specify at least one pattern - // in normally SQL. (But in test mode we should relax this limitation) - if len(patterns) == 0 && len(levels) == 0 && len(instances) == 0 && len(nodeTypes) == 0 { - return nil, errors.New("denied to scan full logs (use `SELECT * FROM cluster_log WHERE message LIKE '%'` explicitly if intentionally)") - } + if len(patterns) == 0 && len(levels) == 0 && len(instances) == 0 && len(nodeTypes) == 0 { + return nil, errors.New("denied to scan full logs (use `SELECT * FROM cluster_log WHERE message LIKE '%'` explicitly if intentionally)") } req := &diagnosticspb.SearchLogRequest{ - StartTime: startTime, - EndTime: endTime, + StartTime: e.extractor.StartTime, + EndTime: e.extractor.EndTime, Levels: levels, Patterns: patterns, } diff --git a/executor/memtable_reader_test.go b/executor/memtable_reader_test.go index a5d5192dba3ed..830c8ca474382 100644 --- a/executor/memtable_reader_test.go +++ b/executor/memtable_reader_test.go @@ -570,28 +570,11 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { conditions []string expected [][]string }{ - // all log items - { - conditions: []string{}, - expected: fullLogs, - }, - { - conditions: []string{ - "time>='2019/08/26 06:18:13.011'", - }, - expected: fullLogs, - }, - { - conditions: []string{ - "time>='2019/08/26 06:18:13.011'", - "time<='2019/08/26 06:28:19.011'", - }, - expected: fullLogs, - }, { conditions: []string{ "time>='2019/08/26 06:18:13.011'", "time<='2099/08/26 06:28:19.011'", + "message like '%'", }, expected: fullLogs, }, @@ -599,6 +582,7 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { conditions: []string{ "time>='2019/08/26 06:19:13.011'", "time<='2019/08/26 06:21:15.011'", + "message like '%'", }, expected: [][]string{ {"2019/08/26 06:19:13.011", "tidb", "INFO", "[test log message tidb 1, foo]"}, @@ -617,6 +601,7 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { conditions: []string{ "time>='2019/08/26 06:19:13.011'", "time<='2019/08/26 06:21:15.011'", + "message like '%'", "type='pd'", }, expected: [][]string{ @@ -642,6 +627,7 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { "time>='2019/08/26 06:18:13.011'", "time>='2019/08/26 06:19:13.011'", "time='2019/08/26 06:19:14.011'", + "message like '%'", "type='pd'", }, expected: [][]string{ @@ -652,6 +638,7 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { conditions: []string{ "time>='2019/08/26 06:19:13.011'", "time<='2019/08/26 06:21:15.011'", + "message like '%'", "type='tidb'", }, expected: [][]string{ @@ -666,6 +653,7 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { conditions: []string{ "time>='2019/08/26 06:19:13.011'", "time<='2019/08/26 06:21:15.011'", + "message like '%'", "type='tikv'", }, expected: [][]string{ @@ -678,6 +666,7 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { conditions: []string{ "time>='2019/08/26 06:19:13.011'", "time<='2019/08/26 06:21:15.011'", + "message like '%'", fmt.Sprintf("instance='%s'", testServers["pd"].address), }, expected: [][]string{ @@ -689,6 +678,7 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { conditions: []string{ "time>='2019/08/26 06:19:13.011'", "time<='2019/08/26 06:21:15.011'", + "message like '%'", fmt.Sprintf("instance='%s'", testServers["tidb"].address), }, expected: [][]string{ @@ -703,6 +693,7 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { conditions: []string{ "time>='2019/08/26 06:19:13.011'", "time<='2019/08/26 06:21:15.011'", + "message like '%'", fmt.Sprintf("instance='%s'", testServers["tikv"].address), }, expected: [][]string{ @@ -715,6 +706,7 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { conditions: []string{ "time>='2019/08/26 06:19:13.011'", "time<='2019/08/26 06:21:15.011'", + "message like '%'", fmt.Sprintf("instance in ('%s', '%s')", testServers["pd"].address, testServers["tidb"].address), }, expected: [][]string{ @@ -729,6 +721,9 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { }, { conditions: []string{ + "time>='2019/08/26 06:18:13.011'", + "time<='2019/08/26 06:28:19.011'", + "message like '%'", "level='critical'", }, expected: [][]string{ @@ -742,6 +737,9 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { }, { conditions: []string{ + "time>='2019/08/26 06:18:13.011'", + "time<='2019/08/26 06:28:19.011'", + "message like '%'", "level='critical'", "type in ('pd', 'tikv')", }, @@ -754,6 +752,9 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { }, { conditions: []string{ + "time>='2019/08/26 06:18:13.011'", + "time<='2019/08/26 06:28:19.011'", + "message like '%'", "level='critical'", "(type='pd' or type='tikv')", }, @@ -766,6 +767,8 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { }, { conditions: []string{ + "time>='2019/08/26 06:18:13.011'", + "time<='2019/08/26 06:28:19.011'", "level='critical'", "message like '%pd%'", }, @@ -776,6 +779,8 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { }, { conditions: []string{ + "time>='2019/08/26 06:18:13.011'", + "time<='2019/08/26 06:28:19.011'", "level='critical'", "message like '%pd%'", "message like '%5%'", @@ -786,6 +791,8 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { }, { conditions: []string{ + "time>='2019/08/26 06:18:13.011'", + "time<='2019/08/26 06:28:19.011'", "level='critical'", "message like '%pd%'", "message like '%5%'", @@ -795,6 +802,8 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { }, { conditions: []string{ + "time>='2019/08/26 06:18:13.011'", + "time<='2019/08/26 06:28:19.011'", "level='critical'", "message regexp '.*pd.*'", }, @@ -805,6 +814,8 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { }, { conditions: []string{ + "time>='2019/08/26 06:18:13.011'", + "time<='2019/08/26 06:28:19.011'", "level='critical'", "message regexp '.*pd.*'", "message regexp '.*foo]$'", @@ -815,6 +826,8 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { }, { conditions: []string{ + "time>='2019/08/26 06:18:13.011'", + "time<='2019/08/26 06:28:19.011'", "level='critical'", "message regexp '.*pd.*'", "message regexp '.*5.*'", @@ -824,6 +837,8 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLog(c *C) { }, { conditions: []string{ + "time>='2019/08/26 06:18:13.011'", + "time<='2019/08/26 06:28:19.011'", "level='critical'", "(message regexp '.*pd.*' or message regexp '.*tidb.*')", }, @@ -875,9 +890,24 @@ func (s *testMemTableReaderSuite) TestTiDBClusterLogError(c *C) { c.Assert(failpoint.Enable(fpName, `return("")`), IsNil) defer func() { c.Assert(failpoint.Disable(fpName), IsNil) }() + // Test without start time error. rs, err := tk.Exec("select * from information_schema.cluster_log") c.Assert(err, IsNil) _, err = session.ResultSetToStringSlice(context.Background(), tk.Se, rs) c.Assert(err, NotNil) + c.Assert(err.Error(), Equals, "denied to scan logs, please specified the start time, such as `time > '2020-01-01 00:00:00'`") + + // Test without end time error. + rs, err = tk.Exec("select * from information_schema.cluster_log where time>='2019/08/26 06:18:13.011'") + c.Assert(err, IsNil) + _, err = session.ResultSetToStringSlice(context.Background(), tk.Se, rs) + c.Assert(err, NotNil) + c.Assert(err.Error(), Equals, "denied to scan logs, please specified the end time, such as `time < '2020-01-01 00:00:00'`") + + // Test without specified message error. + rs, err = tk.Exec("select * from information_schema.cluster_log where time>='2019/08/26 06:18:13.011' and time<'2019/08/26 16:18:13.011'") + c.Assert(err, IsNil) + _, err = session.ResultSetToStringSlice(context.Background(), tk.Se, rs) + c.Assert(err, NotNil) c.Assert(err.Error(), Equals, "denied to scan full logs (use `SELECT * FROM cluster_log WHERE message LIKE '%'` explicitly if intentionally)") } diff --git a/planner/core/memtable_predicate_extractor.go b/planner/core/memtable_predicate_extractor.go index 0c4099dd639a3..9d9995b465d14 100644 --- a/planner/core/memtable_predicate_extractor.go +++ b/planner/core/memtable_predicate_extractor.go @@ -593,12 +593,11 @@ func (e *ClusterLogTableExtractor) Extract( // The time unit for search log is millisecond. startTime = startTime / int64(time.Millisecond) endTime = endTime / int64(time.Millisecond) - if endTime == 0 { - endTime = math.MaxInt64 - } e.StartTime = startTime e.EndTime = endTime - e.SkipRequest = startTime > endTime + if startTime != 0 && endTime != 0 { + e.SkipRequest = startTime > endTime + } if e.SkipRequest { return nil @@ -614,12 +613,12 @@ func (e *ClusterLogTableExtractor) explainInfo(p *PhysicalMemTable) string { return "skip_request: true" } r := new(bytes.Buffer) - st, et := e.GetTimeRange(false) + st, et := e.StartTime, e.EndTime if st > 0 { st := time.Unix(0, st*1e6) r.WriteString(fmt.Sprintf("start_time:%v, ", st.In(p.ctx.GetSessionVars().StmtCtx.TimeZone).Format(MetricTableTimeFormat))) } - if et < math.MaxInt64 { + if et > 0 { et := time.Unix(0, et*1e6) r.WriteString(fmt.Sprintf("end_time:%v, ", et.In(p.ctx.GetSessionVars().StmtCtx.TimeZone).Format(MetricTableTimeFormat))) } @@ -641,27 +640,6 @@ func (e *ClusterLogTableExtractor) explainInfo(p *PhysicalMemTable) string { return s } -// GetTimeRange extract startTime and endTime -func (e *ClusterLogTableExtractor) GetTimeRange(isFailpointTestModeSkipCheck bool) (int64, int64) { - startTime := e.StartTime - endTime := e.EndTime - if endTime == 0 { - endTime = math.MaxInt64 - } - if !isFailpointTestModeSkipCheck { - // Just search the recent half an hour logs if the user doesn't specify the start time - const defaultSearchLogDuration = 30 * time.Minute / time.Millisecond - if startTime == 0 { - if endTime == math.MaxInt64 { - startTime = time.Now().UnixNano()/int64(time.Millisecond) - int64(defaultSearchLogDuration) - } else { - startTime = endTime - int64(defaultSearchLogDuration) - } - } - } - return startTime, endTime -} - // MetricTableExtractor is used to extract some predicates of metrics_schema tables. type MetricTableExtractor struct { extractHelper diff --git a/planner/core/memtable_predicate_extractor_test.go b/planner/core/memtable_predicate_extractor_test.go index 8a4f22cbdf075..8f176d99d4218 100644 --- a/planner/core/memtable_predicate_extractor_test.go +++ b/planner/core/memtable_predicate_extractor_test.go @@ -15,7 +15,6 @@ package core_test import ( "context" - "math" "regexp" "sort" "time" @@ -451,14 +450,12 @@ func (s *extractorSuite) TestClusterLogTableExtractor(c *C) { nodeTypes: set.NewStringSet(), instances: set.NewStringSet(), startTime: timestamp(c, "2019-10-10 10:10:10"), - endTime: math.MaxInt64, }, { sql: "select * from information_schema.cluster_log where time>='2019-10-10 10:10:10' and time>='2019-10-11 10:10:10' and time>='2019-10-12 10:10:10'", nodeTypes: set.NewStringSet(), instances: set.NewStringSet(), startTime: timestamp(c, "2019-10-12 10:10:10"), - endTime: math.MaxInt64, }, { sql: "select * from information_schema.cluster_log where time>='2019-10-10 10:10:10' and time>='2019-10-11 10:10:10' and time>='2019-10-12 10:10:10' and time='2019-10-13 10:10:10'", @@ -487,7 +484,6 @@ func (s *extractorSuite) TestClusterLogTableExtractor(c *C) { nodeTypes: set.NewStringSet(), instances: set.NewStringSet(), startTime: timestamp(c, "2019-10-10 10:10:10"), - endTime: math.MaxInt64, patterns: []string{".*a.*"}, }, {