Skip to content

Commit

Permalink
executor: remove default search time range of cluster_log when query …
Browse files Browse the repository at this point in the history 
…without time range. (#16938) (#17003)
  • Loading branch information
@sre-bot
sre-bot authored May 14, 2020
1 parent 12aac54 commit 528c0d3
Show file tree
Hide file tree
Showing 4 changed files with 65 additions and 65 deletions.
28 changes: 12 additions & 16 deletions executor/memtable_reader.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand All @@ -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,
}
Expand Down
66 changes: 48 additions & 18 deletions executor/memtable_reader_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -570,35 +570,19 @@ 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,
},
{
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]"},
Expand All @@ -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{
Expand All @@ -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{
Expand All @@ -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{
Expand All @@ -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{
Expand All @@ -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{
Expand All @@ -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{
Expand All @@ -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{
Expand All @@ -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{
Expand All @@ -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{
Expand All @@ -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')",
},
Expand All @@ -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')",
},
Expand All @@ -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%'",
},
Expand All @@ -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%'",
Expand All @@ -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%'",
Expand All @@ -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.*'",
},
Expand All @@ -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]$'",
Expand All @@ -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.*'",
Expand All @@ -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.*')",
},
Expand Down Expand Up @@ -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)")
}
32 changes: 5 additions & 27 deletions planner/core/memtable_predicate_extractor.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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)))
}
Expand All @@ -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
Expand Down
4 changes: 0 additions & 4 deletions planner/core/memtable_predicate_extractor_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -15,7 +15,6 @@ package core_test

import (
"context"
"math"
"regexp"
"sort"
"time"
Expand Down Expand Up @@ -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'",
Expand Down Expand Up @@ -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.*"},
},
{
Expand Down

0 comments on commit 528c0d3

Please sign in to comment.