Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Support handle invalid logs #19

Merged
merged 20 commits into from
Jul 10, 2020
Merged
Show file tree
Hide file tree
Changes from 7 commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion .github/workflows/test.yaml
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,7 @@ on:
- master

jobs:
release_packages:
test:
runs-on: ubuntu-latest
steps:
- uses: actions/checkout@v1
Expand Down
96 changes: 75 additions & 21 deletions search_log.go
Original file line number Diff line number Diff line change
Expand Up @@ -73,31 +73,25 @@ func resolveFiles(logFilePath string, beginTime, endTime int64) ([]logFile, erro
return nil
}
reader := bufio.NewReader(file)
// Skip this file if cannot read the first line
firstLine, err := readLine(reader)
if err != nil && err != io.EOF {
skipFiles = append(skipFiles, file)
return nil
}
// Skip this file if the first line is not a valid log message
firstItem, err := parseLogItem(firstLine)

firstItem, err := readFirstValidLog(reader, 0)
if err != nil {
skipFiles = append(skipFiles, file)
return nil
}
// Skip this file if cannot read the last line
lastLine := readLastLine(file)
// Skip this file if the last line is not a valid log message
lastItem, err := parseLogItem(lastLine)

lastItem, err := readLastValidLog(file, 0)
if err != nil {
skipFiles = append(skipFiles, file)
return nil
}

// Reset position to the start and skip this file if cannot seek to start
if _, err := file.Seek(0, io.SeekStart); err != nil {
skipFiles = append(skipFiles, file)
return nil
}

if beginTime > lastItem.Time || endTime < firstItem.Time {
skipFiles = append(skipFiles, file)
} else {
Expand All @@ -109,18 +103,63 @@ func resolveFiles(logFilePath string, beginTime, endTime int64) ([]logFile, erro
}
return nil
})

defer func() {
for _, f := range skipFiles {
_ = f.Close()
}
}()

// Sort by start time
sort.Slice(logFiles, func(i, j int) bool {
return logFiles[i].begin < logFiles[j].begin
})
return logFiles, err
}

// parameter tryLines: if value is 0, means unlimited
func readFirstValidLog(reader *bufio.Reader, tryLines int64) (*pb.LogMessage, error) {
var tried int64
for {
line, err := readLine(reader)
if err != nil {
return nil, err
}
item, err := parseLogItem(line)
if err == nil {
return item, nil
}
tried++
if tryLines > 0 && tried >= tryLines {
break
}
}
return nil, errors.New("not a valid log file")
}

// parameter tryLines: if value is 0, means unlimited
func readLastValidLog(file *os.File, tryLines int64) (*pb.LogMessage, error) {
var tried int64
var endCursor int64
for {
line := readLineReverse(file, endCursor)
// read out the file
if len(line) == 0 {
break
}
endCursor -= int64(len(line))
item, err := parseLogItem(line)
if err == nil {
return item, nil
}
tried++
if tryLines > 0 && tried >= tryLines {
break
}
}
return nil, errors.New("not a valid log file")
}

// Read a line from a reader.
func readLine(reader *bufio.Reader) (string, error) {
var line, b []byte
Expand All @@ -136,20 +175,22 @@ func readLine(reader *bufio.Reader) (string, error) {
return string(line), nil
}

func readLastLine(file *os.File) string {
// Read a line from the end of a file.
// TODO: read byte by byte is low efficiency, we can improve it, for example, read 1024 bytes one time
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we refine by this way? (not sure whether it has some pitfalls.)

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sure, we can add a todo here.

func readLineReverse(file *os.File, endCursor int64) string {
var line []byte
var cursor int64
var cursor = endCursor
stat, _ := file.Stat()
filesize := stat.Size()
for {
cursor -= 1
cursor--
file.Seek(cursor, io.SeekEnd)
Copy link
Contributor Author

@baurine baurine Jul 6, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What if the log has appended some new logs after the file is opened when calling file.seek(0, io.SeekEnd), does it work same as file.seek(filesize, io.SeekStart)?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice catch, I think we should add some tests for these scenarios.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ok, I will do some tests to check it.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hi @lonng , add a test method TestReadAndAppendLogFile to test this case, it seems we will read the unexcepted result from the end when new contents is appending to the file. But we can try to resolve it in another PR.

企业微信20200707120345

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

will continue to fix it in this PR.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed it by file.Seek(cursor, io.SeekStart).


char := make([]byte, 1)
file.Read(char)

// stop if we find a line
if cursor != -1 && (char[0] == 10 || char[0] == 13) {
if cursor != endCursor-1 && (char[0] == 10 || char[0] == 13) {
break
}
line = append(line, char[0])
Expand All @@ -163,7 +204,7 @@ func readLastLine(file *os.File) string {
return string(line)
}

// Returns LogLevel from string and return LogLevel_Info if
// ParseLogLevel returns LogLevel from string and return LogLevel_Info if
// the string is an invalid level string
func ParseLogLevel(s string) pb.LogLevel {
switch s {
Expand Down Expand Up @@ -244,6 +285,7 @@ type logIterator struct {
fileIndex int
reader *bufio.Reader
pending []*os.File
preTime int64
}

// The Close method close all resources the iterator has.
Expand Down Expand Up @@ -274,21 +316,33 @@ nextLine:
iter.reader.Reset(iter.pending[iter.fileIndex])
continue
}
if len(line) < len(TimeStampLayout) {
line = strings.TrimSpace(line)
if len(line) == 0 {
continue
}
// Skip invalid log item
item, err := parseLogItem(line)
if err != nil {
continue
if iter.preTime == 0 {
continue
}
// handle invalid log
// make whole line as log message with pre time and unknown log_level
baurine marked this conversation as resolved.
Show resolved Hide resolved
item = &pb.LogMessage{
Time: iter.preTime,
Level: pb.LogLevel_UNKNOWN,
Message: line,
}
} else {
iter.preTime = item.Time
}
if item.Time > iter.end {
return nil, io.EOF
}
if item.Time < iter.begin {
continue
}
if iter.levelFlag != 0 && iter.levelFlag&(1<<item.Level) == 0 {
// always keep unknown log_level
if item.Level > pb.LogLevel_UNKNOWN && iter.levelFlag != 0 && iter.levelFlag&(1<<item.Level) == 0 {
continue
}
if len(iter.patterns) > 0 {
Expand Down
26 changes: 26 additions & 0 deletions search_log_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -73,11 +73,15 @@ func (s *searchLogSuite) writeTmpFile(c *C, filename string, lines []string) {

func (s *searchLogSuite) TestResoveFiles(c *C) {
s.writeTmpFile(c, "tidb.log", []string{
`20/08/26 06:19:13.011 -04:00 [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`hello TiDB`,
`[2019/08/26 06:19:13.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`20/08/26 06:19:13.011 -04:00 [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`hello TiDB`,
})

// single line file
Expand Down Expand Up @@ -209,6 +213,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) {
`[2019/08/26 06:19:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`,
`This is an invalid log blablabla`,
`[2019/08/26 06:19:17.011 -04:00] [TRACE] [printer.go:41] ["Welcome to TiDB."]`,
})

Expand All @@ -227,6 +232,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) {
s.writeTmpFile(c, "rpc.tidb-3.log", []string{``})
s.writeTmpFile(c, "rpc.tidb-4.log", []string{
`[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`This is also an invalid log contains partern ...`,
`[2019/08/26 06:22:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`,
Expand Down Expand Up @@ -254,11 +260,13 @@ func (s *searchLogSuite) TestLogIterator(c *C) {
`[2019/08/26 06:19:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`,
`[2019/08/26 06:19:17.011 -04:00] [TRACE] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:20:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:21:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:21:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`,
`[2019/08/26 06:22:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`,
Expand All @@ -273,11 +281,13 @@ func (s *searchLogSuite) TestLogIterator(c *C) {
`[2019/08/26 06:19:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`,
`[2019/08/26 06:19:17.011 -04:00] [TRACE] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:20:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:21:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:21:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`,
`[2019/08/26 06:22:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`,
Expand All @@ -294,6 +304,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) {
`[2019/08/26 06:19:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`,
`[2019/08/26 06:19:17.011 -04:00] [TRACE] [printer.go:41] ["Welcome to TiDB."]`,
},
},
Expand All @@ -305,6 +316,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) {
`[2019/08/26 06:21:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:21:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`,
`[2019/08/26 06:22:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`,
Expand All @@ -319,11 +331,13 @@ func (s *searchLogSuite) TestLogIterator(c *C) {
expect: []string{
`[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`,
`[2019/08/26 06:19:17.011 -04:00] [TRACE] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:20:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:21:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:21:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`,
`[2019/08/26 06:22:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`,
},
},
Expand All @@ -342,6 +356,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) {
`[2019/08/26 06:19:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`,
},
},
// 7
Expand All @@ -351,6 +366,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) {
`[2019/08/26 06:19:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`,
},
},
// 8
Expand All @@ -359,32 +375,40 @@ func (s *searchLogSuite) TestLogIterator(c *C) {
levels: []pb.LogLevel{pb.LogLevel_Debug},
expect: []string{
`[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`,
`[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`,
},
},
// 9
{
search: timeRange{"2019/08/26 06:19:15.011 -04:00", "2019/08/26 06:22:14.011 -04:00"},
levels: []pb.LogLevel{pb.LogLevel_Trace},
expect: []string{
`[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`,
`[2019/08/26 06:19:17.011 -04:00] [TRACE] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`,
},
},
// 10
{
search: timeRange{"2019/08/26 06:19:15.011 -04:00", "2019/08/26 06:22:14.011 -04:00"},
levels: []pb.LogLevel{pb.LogLevel_Info},
expect: []string{
`[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`,
`[2019/08/26 06:20:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:21:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`,
},
},
// 11
{
search: timeRange{"2019/08/26 06:19:15.011 -04:00", "2019/08/26 06:22:14.011 -04:00"},
levels: []pb.LogLevel{pb.LogLevel_Warn},
expect: []string{
`[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`,
`[2019/08/26 06:21:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`,
`[2019/08/26 06:22:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`,
},
},
Expand All @@ -394,6 +418,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) {
levels: []pb.LogLevel{pb.LogLevel_Error},
expect: []string{
`[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`,
`[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`,
},
},
// 13
Expand All @@ -402,6 +427,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) {
levels: []pb.LogLevel{pb.LogLevel_Info},
patterns: []string{".*partern.*"},
expect: []string{
`[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`,
`[2019/08/26 06:23:14.011 -04:00] [INFO] [printer.go:41] ["partern test to TiDB."]`,
`[2019/08/27 06:23:14.011 -04:00] [INFO] [printer.go:41] ["partern test txn to TiDB."]`,
},
Expand Down
2 changes: 1 addition & 1 deletion service.go
Original file line number Diff line number Diff line change
Expand Up @@ -78,7 +78,7 @@ func (d *DiagnosticsServer) SearchLog(req *pb.SearchLogRequest, stream pb.Diagno
var drained bool
for i := 0; i < 1024; i++ {
item, err := iter.next()
if err != nil && err == io.EOF {
if err == io.EOF {
drained = true
break
}
Expand Down