From dab3e40a3b30671d41fc03074f7db7477f8cfe63 Mon Sep 17 00:00:00 2001
From: baurine <2008.hbl@gmail.com>
Date: Fri, 3 Jul 2020 23:41:17 +0800
Subject: [PATCH 01/19] support to handle invalid logs in the file beginning
 and end

---
 search_log.go      | 74 +++++++++++++++++++++++++++++++++++-----------
 search_log_test.go |  4 +++
 2 files changed, 61 insertions(+), 17 deletions(-)

diff --git a/search_log.go b/search_log.go
index fde4f91..c902b48 100644
--- a/search_log.go
+++ b/search_log.go
@@ -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 {
@@ -109,11 +103,13 @@ 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
@@ -121,6 +117,49 @@ func resolveFiles(logFilePath string, beginTime, endTime int64) ([]logFile, erro
 	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
@@ -136,20 +175,21 @@ 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.
+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)
 
 		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])
@@ -163,7 +203,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 {
diff --git a/search_log_test.go b/search_log_test.go
index 1af5155..d8cbbcc 100644
--- a/search_log_test.go
+++ b/search_log_test.go
@@ -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

From d2fbf9ccdf99b489e8bf7a84c88cd6a4499dbb23 Mon Sep 17 00:00:00 2001
From: baurine <2008.hbl@gmail.com>
Date: Mon, 6 Jul 2020 11:15:49 +0800
Subject: [PATCH 02/19] support invalid log in the middle of log file

---
 search_log.go | 19 +++++++++++++------
 service.go    | 13 ++++++++++++-
 2 files changed, 25 insertions(+), 7 deletions(-)

diff --git a/search_log.go b/search_log.go
index c902b48..4be94cb 100644
--- a/search_log.go
+++ b/search_log.go
@@ -176,6 +176,7 @@ func readLine(reader *bufio.Reader) (string, error) {
 }
 
 // Read a line from the end of a file.
+// TODO: byte by byte read is low effiency, we can improve it
 func readLineReverse(file *os.File, endCursor int64) string {
 	var line []byte
 	var cursor = endCursor
@@ -314,21 +315,27 @@ 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
+			// handle invalid log
+			// make whole line as log message with 0 time and 0 level
+			item = &pb.LogMessage{
+				Time:    0,
+				Level:   0,
+				Message: line,
+			}
 		}
-		if item.Time > iter.end {
+		if item.Time > 0 && item.Time > iter.end {
 			return nil, io.EOF
 		}
-		if item.Time < iter.begin {
+		if item.Time > 0 && item.Time < iter.begin {
 			continue
 		}
-		if iter.levelFlag != 0 && iter.levelFlag&(1<<item.Level) == 0 {
+		if item.Level > 0 && iter.levelFlag != 0 && iter.levelFlag&(1<<item.Level) == 0 {
 			continue
 		}
 		if len(iter.patterns) > 0 {
diff --git a/service.go b/service.go
index be3d633..8ac396f 100644
--- a/service.go
+++ b/service.go
@@ -73,18 +73,29 @@ func (d *DiagnosticsServer) SearchLog(req *pb.SearchLogRequest, stream pb.Diagno
 	}
 	defer iter.close()
 
+	var preMessage *pb.LogMessage
 	for {
 		var messages []*pb.LogMessage
 		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
 			}
 			if err != nil {
 				return err
 			}
+			// invalid log
+			if item.Time == 0 {
+				if preMessage == nil {
+					continue
+				}
+				// use the previous message's time and level
+				item.Time = preMessage.Time
+				item.Level = preMessage.Level
+			}
+			preMessage = item
 			messages = append(messages, item)
 		}
 		res := &pb.SearchLogResponse{

From ca397ce41884c362ddddc605aeccb68a0b8e4f5b Mon Sep 17 00:00:00 2001
From: baurine <2008.hbl@gmail.com>
Date: Mon, 6 Jul 2020 11:43:48 +0800
Subject: [PATCH 03/19] refine

---
 search_log.go | 19 +++++++++++++------
 service.go    | 11 -----------
 2 files changed, 13 insertions(+), 17 deletions(-)

diff --git a/search_log.go b/search_log.go
index 4be94cb..738f68a 100644
--- a/search_log.go
+++ b/search_log.go
@@ -285,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.
@@ -321,21 +322,27 @@ nextLine:
 		}
 		item, err := parseLogItem(line)
 		if err != nil {
+			if iter.preTime == 0 {
+				continue
+			}
 			// handle invalid log
-			// make whole line as log message with 0 time and 0 level
+			// make whole line as log message with pre time and unknown log_level
 			item = &pb.LogMessage{
-				Time:    0,
-				Level:   0,
+				Time:    iter.preTime,
+				Level:   pb.LogLevel_UNKNOWN,
 				Message: line,
 			}
+		} else {
+			iter.preTime = item.Time
 		}
-		if item.Time > 0 && item.Time > iter.end {
+		if item.Time > iter.end {
 			return nil, io.EOF
 		}
-		if item.Time > 0 && item.Time < iter.begin {
+		if item.Time < iter.begin {
 			continue
 		}
-		if item.Level > 0 && 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 {
diff --git a/service.go b/service.go
index 8ac396f..4abc0a3 100644
--- a/service.go
+++ b/service.go
@@ -73,7 +73,6 @@ func (d *DiagnosticsServer) SearchLog(req *pb.SearchLogRequest, stream pb.Diagno
 	}
 	defer iter.close()
 
-	var preMessage *pb.LogMessage
 	for {
 		var messages []*pb.LogMessage
 		var drained bool
@@ -86,16 +85,6 @@ func (d *DiagnosticsServer) SearchLog(req *pb.SearchLogRequest, stream pb.Diagno
 			if err != nil {
 				return err
 			}
-			// invalid log
-			if item.Time == 0 {
-				if preMessage == nil {
-					continue
-				}
-				// use the previous message's time and level
-				item.Time = preMessage.Time
-				item.Level = preMessage.Level
-			}
-			preMessage = item
 			messages = append(messages, item)
 		}
 		res := &pb.SearchLogResponse{

From e1084ade75e42b4613e231da08c0a70ded321309 Mon Sep 17 00:00:00 2001
From: baurine <2008.hbl@gmail.com>
Date: Mon, 6 Jul 2020 12:10:08 +0800
Subject: [PATCH 04/19] update test

---
 search_log_test.go | 22 ++++++++++++++++++++++
 1 file changed, 22 insertions(+)

diff --git a/search_log_test.go b/search_log_test.go
index d8cbbcc..5a2860f 100644
--- a/search_log_test.go
+++ b/search_log_test.go
@@ -213,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."]`,
 	})
 
@@ -231,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."]`,
@@ -258,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."]`,
@@ -277,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."]`,
@@ -298,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."]`,
 			},
 		},
@@ -309,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."]`,
@@ -323,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."]`,
 			},
 		},
@@ -346,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
@@ -355,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
@@ -363,6 +375,8 @@ 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
@@ -370,7 +384,9 @@ func (s *searchLogSuite) TestLogIterator(c *C) {
 			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
@@ -378,9 +394,11 @@ func (s *searchLogSuite) TestLogIterator(c *C) {
 			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
@@ -388,7 +406,9 @@ func (s *searchLogSuite) TestLogIterator(c *C) {
 			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."]`,
 			},
 		},
@@ -398,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
@@ -406,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."]`,
 			},

From f53e8a872d48e2c74c7d78037803ce64140879f7 Mon Sep 17 00:00:00 2001
From: baurine <2008.hbl@gmail.com>
Date: Mon, 6 Jul 2020 13:51:08 +0800
Subject: [PATCH 05/19] update CI job name

---
 .github/workflows/test.yaml | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/.github/workflows/test.yaml b/.github/workflows/test.yaml
index 1293e67..0591fb9 100644
--- a/.github/workflows/test.yaml
+++ b/.github/workflows/test.yaml
@@ -6,7 +6,7 @@ on:
       - master
 
 jobs:
-  release_packages:
+  test:
     runs-on: ubuntu-latest
     steps:
       - uses: actions/checkout@v1

From b08939af26c651ad6a56380ab99b3a9ea66e7b74 Mon Sep 17 00:00:00 2001
From: baurine <2008.hbl@gmail.com>
Date: Mon, 6 Jul 2020 14:11:11 +0800
Subject: [PATCH 06/19] update comment

---
 search_log.go | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/search_log.go b/search_log.go
index 738f68a..71fef7a 100644
--- a/search_log.go
+++ b/search_log.go
@@ -176,7 +176,7 @@ func readLine(reader *bufio.Reader) (string, error) {
 }
 
 // Read a line from the end of a file.
-// TODO: byte by byte read is low effiency, we can improve it
+// TODO: read byte by byte is low efficiency, we can improve it, for example, read 1024 bytes one time
 func readLineReverse(file *os.File, endCursor int64) string {
 	var line []byte
 	var cursor = endCursor

From f386b970799345fd56c004d4aa067273f3997e98 Mon Sep 17 00:00:00 2001
From: baurine <2008.hbl@gmail.com>
Date: Mon, 6 Jul 2020 22:33:48 +0800
Subject: [PATCH 07/19] keep invalid log time and level same as previous one

---
 search_log.go      | 10 +++++-----
 search_log_test.go | 33 +++++++++++++--------------------
 2 files changed, 18 insertions(+), 25 deletions(-)

diff --git a/search_log.go b/search_log.go
index 71fef7a..c0e07d1 100644
--- a/search_log.go
+++ b/search_log.go
@@ -285,7 +285,7 @@ type logIterator struct {
 	fileIndex int
 	reader    *bufio.Reader
 	pending   []*os.File
-	preTime   int64
+	preLog    *pb.LogMessage
 }
 
 // The Close method close all resources the iterator has.
@@ -322,18 +322,18 @@ nextLine:
 		}
 		item, err := parseLogItem(line)
 		if err != nil {
-			if iter.preTime == 0 {
+			if iter.preLog == nil {
 				continue
 			}
 			// handle invalid log
 			// make whole line as log message with pre time and unknown log_level
 			item = &pb.LogMessage{
-				Time:    iter.preTime,
-				Level:   pb.LogLevel_UNKNOWN,
+				Time:    iter.preLog.Time,
+				Level:   iter.preLog.Level,
 				Message: line,
 			}
 		} else {
-			iter.preTime = item.Time
+			iter.preLog = item
 		}
 		if item.Time > iter.end {
 			return nil, io.EOF
diff --git a/search_log_test.go b/search_log_test.go
index 5a2860f..3295504 100644
--- a/search_log_test.go
+++ b/search_log_test.go
@@ -260,13 +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:16.011 -04:00] [DEBUG] 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] [INFO] 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."]`,
@@ -281,13 +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:16.011 -04:00] [DEBUG] 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] [INFO] 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."]`,
@@ -304,7 +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:16.011 -04:00] [DEBUG] This is an invalid log blablabla`,
 				`[2019/08/26 06:19:17.011 -04:00] [TRACE] [printer.go:41] ["Welcome to TiDB."]`,
 			},
 		},
@@ -316,7 +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] [INFO] 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."]`,
@@ -331,13 +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:16.011 -04:00] [DEBUG] 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] [INFO] This is also an invalid log contains partern ...`,
 				`[2019/08/26 06:22:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`,
 			},
 		},
@@ -356,7 +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`,
+				`[2019/08/26 06:19:16.011 -04:00] [DEBUG] This is an invalid log blablabla`,
 			},
 		},
 		// 7
@@ -366,7 +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`,
+				`[2019/08/26 06:19:16.011 -04:00] [DEBUG] This is an invalid log blablabla`,
 			},
 		},
 		// 8
@@ -375,8 +375,7 @@ 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 ...`,
+				`[2019/08/26 06:19:16.011 -04:00] [DEBUG] This is an invalid log blablabla`,
 			},
 		},
 		// 9
@@ -384,9 +383,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) {
 			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
@@ -394,11 +391,10 @@ func (s *searchLogSuite) TestLogIterator(c *C) {
 			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 ...`,
+				`[2019/08/26 06:22:14.011 -04:00] [INFO] This is also an invalid log contains partern ...`,
 			},
 		},
 		// 11
@@ -406,9 +402,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) {
 			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."]`,
 			},
 		},
@@ -418,7 +412,6 @@ 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
@@ -427,7 +420,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:22:14.011 -04:00] [INFO] 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."]`,
 			},

From b5ead576cfe477c2423165b404a7331bc03b5c92 Mon Sep 17 00:00:00 2001
From: baurine <2008.hbl@gmail.com>
Date: Tue, 7 Jul 2020 09:18:16 +0800
Subject: [PATCH 08/19] set max lines to read for get valid log to 10

---
 search_log.go | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/search_log.go b/search_log.go
index c0e07d1..389128e 100644
--- a/search_log.go
+++ b/search_log.go
@@ -74,13 +74,13 @@ func resolveFiles(logFilePath string, beginTime, endTime int64) ([]logFile, erro
 		}
 		reader := bufio.NewReader(file)
 
-		firstItem, err := readFirstValidLog(reader, 0)
+		firstItem, err := readFirstValidLog(reader, 10)
 		if err != nil {
 			skipFiles = append(skipFiles, file)
 			return nil
 		}
 
-		lastItem, err := readLastValidLog(file, 0)
+		lastItem, err := readLastValidLog(file, 10)
 		if err != nil {
 			skipFiles = append(skipFiles, file)
 			return nil

From 2f47a32186a173b4b7b069efd1ba46c8226fd229 Mon Sep 17 00:00:00 2001
From: baurine <2008.hbl@gmail.com>
Date: Tue, 7 Jul 2020 11:02:17 +0800
Subject: [PATCH 09/19] test read and append log file

---
 export_test.go     |  9 +++--
 search_log.go      | 10 +++--
 search_log_test.go | 99 ++++++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 111 insertions(+), 7 deletions(-)

diff --git a/export_test.go b/export_test.go
index b5a4443..4fbe786 100644
--- a/export_test.go
+++ b/export_test.go
@@ -15,8 +15,9 @@ package sysutil
 
 // Export some function to for test purpose
 var (
-	ParseLogItem   = parseLogItem
-	ReadLine       = readLine
-	ParseTimeStamp = parseTimeStamp
-	ResolveFiles   = resolveFiles
+	ParseLogItem    = parseLogItem
+	ReadLine        = readLine
+	ReadLineReverse = readLineReverse
+	ParseTimeStamp  = parseTimeStamp
+	ResolveFiles    = resolveFiles
 )
diff --git a/search_log.go b/search_log.go
index 389128e..0ef497b 100644
--- a/search_log.go
+++ b/search_log.go
@@ -182,7 +182,14 @@ func readLineReverse(file *os.File, endCursor int64) string {
 	var cursor = endCursor
 	stat, _ := file.Stat()
 	filesize := stat.Size()
+	fmt.Println("current filesize:", filesize)
 	for {
+		// stop if we are at the begining
+		// check it in the start to avoid read beyond the size
+		if cursor <= -filesize {
+			break
+		}
+
 		cursor--
 		file.Seek(cursor, io.SeekEnd)
 
@@ -194,9 +201,6 @@ func readLineReverse(file *os.File, endCursor int64) string {
 			break
 		}
 		line = append(line, char[0])
-		if cursor == -filesize { // stop if we are at the begining
-			break
-		}
 	}
 	for i, j := 0, len(line)-1; i < j; i, j = i+1, j-1 {
 		line[i], line[j] = line[j], line[i]
diff --git a/search_log_test.go b/search_log_test.go
index 3295504..41b2476 100644
--- a/search_log_test.go
+++ b/search_log_test.go
@@ -534,3 +534,102 @@ func (s *searchLogSuite) TestParseLogItem(c *C) {
 		c.Assert(item.Message, Equals, cas.message)
 	}
 }
+
+func (s *searchLogSuite) TestReadAndAppendLogFile(c *C) {
+	// step 1. initial a log file
+	s.writeTmpFile(c, "tidb.log", []string{
+		`[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] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
+		`[2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
+		`[2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
+		`[2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n",
+	})
+
+	// step 2. open it as read only mode
+	path := filepath.Join(s.tmpDir, "tidb.log")
+	fmt.Println("path: ", path)
+	file, err := os.OpenFile(path, os.O_RDONLY, os.ModePerm)
+	c.Assert(err, IsNil, Commentf("open file %s failed", path))
+	defer file.Close()
+
+	stat, _ := file.Stat()
+	filesize := stat.Size()
+	fmt.Println("initial filesize: ", filesize)
+
+	// step 3. run a goroutine to append some new logs to the file
+	go func() {
+		file_append, err := os.OpenFile(path, os.O_APPEND|os.O_WRONLY, os.ModeAppend)
+		c.Assert(err, IsNil, Commentf("open file as append mode %s failed", path))
+		defer file_append.Close()
+
+		for i := 40; i < 45; i++ {
+			line := fmt.Sprintf("[2020/07/07 06:%d:17.011 -04:00] [INFO] appended logs\n", i)
+			_, err := file_append.WriteString(line)
+			c.Assert(err, IsNil, Commentf("write %s failed", line))
+			fmt.Print("write line: ", line)
+
+			time.Sleep(50 * time.Millisecond)
+		}
+	}()
+
+	// step 4. keep calling readLineReverse util it is empty
+	var endCursor int64
+	for {
+		line := sysutil.ReadLineReverse(file, endCursor)
+		fmt.Print("read line: ", line)
+		// read out the file
+		if len(line) == 0 {
+			break
+		}
+		endCursor -= int64(len(line))
+
+		time.Sleep(60 * time.Millisecond)
+	}
+
+	// print final content
+	file.Seek(0, io.SeekStart)
+	var content = make([]byte, 1024)
+	file.Read(content)
+	fmt.Println("final content:\n", string(content))
+}
+
+// result: (may be different every time)
+// path:  /var/folders/8z/_463bq6100qgyt1ns0zsf3x00000gn/T/sysutil584451097/tidb.log
+// initial filesize:  385
+// current filesize: 385
+// write line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs
+// read line: [2020/07/07 0FO] [printer.go:41] ["Welcome to TiDB."]
+// write line: [2020/07/07 06:41:17.011 -04:00] [INFO] appended logs
+// current filesize: 493
+// read line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs
+// write line: [2020/07/07 06:42:17.011 -04:00] [INFO] appended logs
+// current filesize: 547
+// read line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs
+// write line: [2020/07/07 06:43:17.011 -04:00] [INFO] appended logs
+// current filesize: 601
+// read line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs
+// write line: [2020/07/07 06:44:17.011 -04:00] [INFO] appended logs
+// current filesize: 655
+// read line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs
+// current filesize: 655
+// read line: [2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]
+// current filesize: 655
+// read line: [2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]
+// current filesize: 655
+// read line: [2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]
+// current filesize: 655
+// read line: [2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]
+// current filesize: 655
+// read line: [2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]
+// current filesize: 655
+// read line: final content:
+//  [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] [INFO] [printer.go:41] ["Welcome to TiDB."]
+// [2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]
+// [2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]
+// [2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]
+// [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs
+// [2020/07/07 06:41:17.011 -04:00] [INFO] appended logs
+// [2020/07/07 06:42:17.011 -04:00] [INFO] appended logs
+// [2020/07/07 06:43:17.011 -04:00] [INFO] appended logs
+// [2020/07/07 06:44:17.011 -04:00] [INFO] appended logs

From b935fdb1a4b47de65d19db7f215b653a2a1a16d8 Mon Sep 17 00:00:00 2001
From: baurine <2008.hbl@gmail.com>
Date: Tue, 7 Jul 2020 13:51:00 +0800
Subject: [PATCH 10/19] fix readLineReverse to avoid race

- read from file io.SeekEnd will read incorrect content when other threads append logs
---
 search_log.go      | 20 +++++++-------
 search_log_test.go | 65 +++++++++-------------------------------------
 2 files changed, 21 insertions(+), 64 deletions(-)

diff --git a/search_log.go b/search_log.go
index 0ef497b..6aeb824 100644
--- a/search_log.go
+++ b/search_log.go
@@ -140,7 +140,8 @@ func readFirstValidLog(reader *bufio.Reader, tryLines int64) (*pb.LogMessage, er
 // parameter tryLines: if value is 0, means unlimited
 func readLastValidLog(file *os.File, tryLines int64) (*pb.LogMessage, error) {
 	var tried int64
-	var endCursor int64
+	stat, _ := file.Stat()
+	endCursor := stat.Size()
 	for {
 		line := readLineReverse(file, endCursor)
 		// read out the file
@@ -175,29 +176,26 @@ func readLine(reader *bufio.Reader) (string, error) {
 	return string(line), nil
 }
 
-// Read a line from the end of a file.
+// Read a line from the end of a file
+// startCursor initial value should be the filesize
 // TODO: read byte by byte is low efficiency, we can improve it, for example, read 1024 bytes one time
-func readLineReverse(file *os.File, endCursor int64) string {
+func readLineReverse(file *os.File, startCursor int64) string {
 	var line []byte
-	var cursor = endCursor
-	stat, _ := file.Stat()
-	filesize := stat.Size()
-	fmt.Println("current filesize:", filesize)
+	var cursor = startCursor
 	for {
 		// stop if we are at the begining
 		// check it in the start to avoid read beyond the size
-		if cursor <= -filesize {
+		if cursor <= 0 {
 			break
 		}
 
 		cursor--
-		file.Seek(cursor, io.SeekEnd)
-
+		file.Seek(cursor, io.SeekStart)
 		char := make([]byte, 1)
 		file.Read(char)
 
 		// stop if we find a line
-		if cursor != endCursor-1 && (char[0] == 10 || char[0] == 13) {
+		if cursor != startCursor-1 && (char[0] == 10 || char[0] == 13) {
 			break
 		}
 		line = append(line, char[0])
diff --git a/search_log_test.go b/search_log_test.go
index 41b2476..ba3b4d0 100644
--- a/search_log_test.go
+++ b/search_log_test.go
@@ -547,14 +547,12 @@ func (s *searchLogSuite) TestReadAndAppendLogFile(c *C) {
 
 	// step 2. open it as read only mode
 	path := filepath.Join(s.tmpDir, "tidb.log")
-	fmt.Println("path: ", path)
 	file, err := os.OpenFile(path, os.O_RDONLY, os.ModePerm)
 	c.Assert(err, IsNil, Commentf("open file %s failed", path))
 	defer file.Close()
 
 	stat, _ := file.Stat()
 	filesize := stat.Size()
-	fmt.Println("initial filesize: ", filesize)
 
 	// step 3. run a goroutine to append some new logs to the file
 	go func() {
@@ -566,70 +564,31 @@ func (s *searchLogSuite) TestReadAndAppendLogFile(c *C) {
 			line := fmt.Sprintf("[2020/07/07 06:%d:17.011 -04:00] [INFO] appended logs\n", i)
 			_, err := file_append.WriteString(line)
 			c.Assert(err, IsNil, Commentf("write %s failed", line))
-			fmt.Print("write line: ", line)
 
 			time.Sleep(50 * time.Millisecond)
 		}
 	}()
 
-	// step 4. keep calling readLineReverse util it is empty
-	var endCursor int64
+	// step 4. keep calling readLineReverse until it is empty
+	expected := []string{
+		`[2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n",
+		`[2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n",
+		`[2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n",
+		`[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n",
+		`[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n",
+	}
+	i := 0
+	endCursor := filesize
 	for {
 		line := sysutil.ReadLineReverse(file, endCursor)
-		fmt.Print("read line: ", line)
 		// read out the file
 		if len(line) == 0 {
 			break
 		}
+		c.Assert(line, Equals, expected[i], Commentf("expected: %v, got: %v", expected[i], line))
+		i++
 		endCursor -= int64(len(line))
 
 		time.Sleep(60 * time.Millisecond)
 	}
-
-	// print final content
-	file.Seek(0, io.SeekStart)
-	var content = make([]byte, 1024)
-	file.Read(content)
-	fmt.Println("final content:\n", string(content))
 }
-
-// result: (may be different every time)
-// path:  /var/folders/8z/_463bq6100qgyt1ns0zsf3x00000gn/T/sysutil584451097/tidb.log
-// initial filesize:  385
-// current filesize: 385
-// write line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs
-// read line: [2020/07/07 0FO] [printer.go:41] ["Welcome to TiDB."]
-// write line: [2020/07/07 06:41:17.011 -04:00] [INFO] appended logs
-// current filesize: 493
-// read line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs
-// write line: [2020/07/07 06:42:17.011 -04:00] [INFO] appended logs
-// current filesize: 547
-// read line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs
-// write line: [2020/07/07 06:43:17.011 -04:00] [INFO] appended logs
-// current filesize: 601
-// read line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs
-// write line: [2020/07/07 06:44:17.011 -04:00] [INFO] appended logs
-// current filesize: 655
-// read line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs
-// current filesize: 655
-// read line: [2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]
-// current filesize: 655
-// read line: [2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]
-// current filesize: 655
-// read line: [2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]
-// current filesize: 655
-// read line: [2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]
-// current filesize: 655
-// read line: [2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]
-// current filesize: 655
-// read line: final content:
-//  [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] [INFO] [printer.go:41] ["Welcome to TiDB."]
-// [2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]
-// [2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]
-// [2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]
-// [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs
-// [2020/07/07 06:41:17.011 -04:00] [INFO] appended logs
-// [2020/07/07 06:42:17.011 -04:00] [INFO] appended logs
-// [2020/07/07 06:43:17.011 -04:00] [INFO] appended logs
-// [2020/07/07 06:44:17.011 -04:00] [INFO] appended logs

From f43ae9342653346a5f11558c14bef98b4a8af264 Mon Sep 17 00:00:00 2001
From: baurine <2008.hbl@gmail.com>
Date: Tue, 7 Jul 2020 15:23:25 +0800
Subject: [PATCH 11/19] improve performance for reading content from the end of
 log file

- read 512 bytes once instead of just 1 byte
---
 export_test.go     | 10 +++----
 search_log.go      | 65 ++++++++++++++++++++++++++--------------------
 search_log_test.go | 14 +++++-----
 3 files changed, 49 insertions(+), 40 deletions(-)

diff --git a/export_test.go b/export_test.go
index 4fbe786..28a368a 100644
--- a/export_test.go
+++ b/export_test.go
@@ -15,9 +15,9 @@ package sysutil
 
 // Export some function to for test purpose
 var (
-	ParseLogItem    = parseLogItem
-	ReadLine        = readLine
-	ReadLineReverse = readLineReverse
-	ParseTimeStamp  = parseTimeStamp
-	ResolveFiles    = resolveFiles
+	ParseLogItem   = parseLogItem
+	ReadLine       = readLine
+	ReadLastLines  = readLastLines
+	ParseTimeStamp = parseTimeStamp
+	ResolveFiles   = resolveFiles
 )
diff --git a/search_log.go b/search_log.go
index 6aeb824..1b4b361 100644
--- a/search_log.go
+++ b/search_log.go
@@ -117,7 +117,6 @@ func resolveFiles(logFilePath string, beginTime, endTime int64) ([]logFile, erro
 	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 {
@@ -130,31 +129,33 @@ func readFirstValidLog(reader *bufio.Reader, tryLines int64) (*pb.LogMessage, er
 			return item, nil
 		}
 		tried++
-		if tryLines > 0 && tried >= tryLines {
+		if 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
+func readLastValidLog(file *os.File, tryLines int) (*pb.LogMessage, error) {
+	var tried int
 	stat, _ := file.Stat()
 	endCursor := stat.Size()
 	for {
-		line := readLineReverse(file, endCursor)
+		lines := readLastLines(file, endCursor)
 		// read out the file
-		if len(line) == 0 {
+		if len(lines) == 0 {
 			break
 		}
-		endCursor -= int64(len(line))
-		item, err := parseLogItem(line)
-		if err == nil {
-			return item, nil
+		endCursor -= int64(len(lines))
+		linesSlice := strings.FieldsFunc(lines, func(c rune) bool { return c == '\n' || c == '\r' })
+		for i := len(linesSlice) - 1; i >= 0; i-- {
+			item, err := parseLogItem(linesSlice[i])
+			if err == nil {
+				return item, nil
+			}
 		}
-		tried++
-		if tryLines > 0 && tried >= tryLines {
+		tried += len(linesSlice)
+		if tried >= tryLines {
 			break
 		}
 	}
@@ -176,11 +177,10 @@ func readLine(reader *bufio.Reader) (string, error) {
 	return string(line), nil
 }
 
-// Read a line from the end of a file
+// Read lines from the end of a file
 // startCursor initial value should be the filesize
-// TODO: read byte by byte is low efficiency, we can improve it, for example, read 1024 bytes one time
-func readLineReverse(file *os.File, startCursor int64) string {
-	var line []byte
+func readLastLines(file *os.File, startCursor int64) string {
+	var lines []byte
 	var cursor = startCursor
 	for {
 		// stop if we are at the begining
@@ -189,21 +189,30 @@ func readLineReverse(file *os.File, startCursor int64) string {
 			break
 		}
 
-		cursor--
+		var size int64 = 512
+		if cursor < size {
+			size = cursor
+		}
+		cursor -= size
+
 		file.Seek(cursor, io.SeekStart)
-		char := make([]byte, 1)
-		file.Read(char)
+		chars := make([]byte, size)
+		file.Read(chars)
+		lines = append(chars, lines...)
 
-		// stop if we find a line
-		if cursor != startCursor-1 && (char[0] == 10 || char[0] == 13) {
-			break
+		// find first '\n' or '\r'
+		for i := 0; i < len(chars); i++ {
+			// reach the line end
+			if i >= len(lines)-1 {
+				break
+			}
+
+			if (chars[i] == 10 || chars[i] == 13) && chars[i+1] != 10 && chars[i+1] != 13 {
+				return string(lines[i+1:])
+			}
 		}
-		line = append(line, char[0])
-	}
-	for i, j := 0, len(line)-1; i < j; i, j = i+1, j-1 {
-		line[i], line[j] = line[j], line[i]
 	}
-	return string(line)
+	return string(lines)
 }
 
 // ParseLogLevel returns LogLevel from string and return LogLevel_Info if
diff --git a/search_log_test.go b/search_log_test.go
index ba3b4d0..a4e4d35 100644
--- a/search_log_test.go
+++ b/search_log_test.go
@@ -565,22 +565,22 @@ func (s *searchLogSuite) TestReadAndAppendLogFile(c *C) {
 			_, err := file_append.WriteString(line)
 			c.Assert(err, IsNil, Commentf("write %s failed", line))
 
-			time.Sleep(50 * time.Millisecond)
+			time.Sleep(10 * time.Millisecond)
 		}
 	}()
 
 	// step 4. keep calling readLineReverse until it is empty
 	expected := []string{
-		`[2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n",
-		`[2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n",
-		`[2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n",
-		`[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n",
+		`[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n" +
+			`[2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n" +
+			`[2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n" +
+			`[2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n",
 		`[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n",
 	}
 	i := 0
 	endCursor := filesize
 	for {
-		line := sysutil.ReadLineReverse(file, endCursor)
+		line := sysutil.ReadLastLines(file, endCursor)
 		// read out the file
 		if len(line) == 0 {
 			break
@@ -589,6 +589,6 @@ func (s *searchLogSuite) TestReadAndAppendLogFile(c *C) {
 		i++
 		endCursor -= int64(len(line))
 
-		time.Sleep(60 * time.Millisecond)
+		time.Sleep(15 * time.Millisecond)
 	}
 }

From b3464a12b75a69d48aede72c9d0aaa18ceaf31d1 Mon Sep 17 00:00:00 2001
From: baurine <2008.hbl@gmail.com>
Date: Tue, 7 Jul 2020 15:34:56 +0800
Subject: [PATCH 12/19] refine

---
 search_log.go      | 6 +++---
 search_log_test.go | 6 +++---
 2 files changed, 6 insertions(+), 6 deletions(-)

diff --git a/search_log.go b/search_log.go
index 1b4b361..8649427 100644
--- a/search_log.go
+++ b/search_log.go
@@ -178,10 +178,10 @@ func readLine(reader *bufio.Reader) (string, error) {
 }
 
 // Read lines from the end of a file
-// startCursor initial value should be the filesize
-func readLastLines(file *os.File, startCursor int64) string {
+// endCursor initial value should be the filesize
+func readLastLines(file *os.File, endCursor int64) string {
 	var lines []byte
-	var cursor = startCursor
+	var cursor = endCursor
 	for {
 		// stop if we are at the begining
 		// check it in the start to avoid read beyond the size
diff --git a/search_log_test.go b/search_log_test.go
index a4e4d35..b1d88ce 100644
--- a/search_log_test.go
+++ b/search_log_test.go
@@ -538,7 +538,7 @@ func (s *searchLogSuite) TestParseLogItem(c *C) {
 func (s *searchLogSuite) TestReadAndAppendLogFile(c *C) {
 	// step 1. initial a log file
 	s.writeTmpFile(c, "tidb.log", []string{
-		`[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
+		`[2019/08/26 06:22:13.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:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
 		`[2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
@@ -569,13 +569,13 @@ func (s *searchLogSuite) TestReadAndAppendLogFile(c *C) {
 		}
 	}()
 
-	// step 4. keep calling readLineReverse until it is empty
+	// step 4. keep calling ReadLastLines until reach the beginning
 	expected := []string{
 		`[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n" +
 			`[2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n" +
 			`[2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n" +
 			`[2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n",
-		`[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n",
+		`[2019/08/26 06:22:13.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n",
 	}
 	i := 0
 	endCursor := filesize

From 650740ff2011b947c457799647c429de3d8d53b9 Mon Sep 17 00:00:00 2001
From: Sparkle <1284531+baurine@users.noreply.github.com>
Date: Wed, 8 Jul 2020 11:39:50 +0800
Subject: [PATCH 13/19] Update search_log.go

Co-authored-by: Wenxuan <hi@breeswish.org>
---
 search_log.go | 5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

diff --git a/search_log.go b/search_log.go
index 8649427..5cb0573 100644
--- a/search_log.go
+++ b/search_log.go
@@ -191,9 +191,10 @@ func readLastLines(file *os.File, endCursor int64) string {
 
 		var size int64 = 512
 		if cursor < size {
-			size = cursor
+			cursor = 0
+		} else {
+			cursor -= size
 		}
-		cursor -= size
 
 		file.Seek(cursor, io.SeekStart)
 		chars := make([]byte, size)

From f628718daf0ec3d7dcf6582ca926544de6e8584d Mon Sep 17 00:00:00 2001
From: baurine <2008.hbl@gmail.com>
Date: Wed, 8 Jul 2020 12:53:18 +0800
Subject: [PATCH 14/19] Revert "Update search_log.go"

This reverts commit 650740ff2011b947c457799647c429de3d8d53b9.
---
 search_log.go | 5 ++---
 1 file changed, 2 insertions(+), 3 deletions(-)

diff --git a/search_log.go b/search_log.go
index 5cb0573..8649427 100644
--- a/search_log.go
+++ b/search_log.go
@@ -191,10 +191,9 @@ func readLastLines(file *os.File, endCursor int64) string {
 
 		var size int64 = 512
 		if cursor < size {
-			cursor = 0
-		} else {
-			cursor -= size
+			size = cursor
 		}
+		cursor -= size
 
 		file.Seek(cursor, io.SeekStart)
 		chars := make([]byte, size)

From 56008cfa4c27cfb4a69b06de9d718faab2edf81d Mon Sep 17 00:00:00 2001
From: baurine <2008.hbl@gmail.com>
Date: Wed, 8 Jul 2020 13:32:59 +0800
Subject: [PATCH 15/19] add benchmark for readLastLines

---
 search_log_test.go | 34 ++++++++++++++++++++++++++++++++++
 1 file changed, 34 insertions(+)

diff --git a/search_log_test.go b/search_log_test.go
index b1d88ce..12a22d8 100644
--- a/search_log_test.go
+++ b/search_log_test.go
@@ -592,3 +592,37 @@ func (s *searchLogSuite) TestReadAndAppendLogFile(c *C) {
 		time.Sleep(15 * time.Millisecond)
 	}
 }
+
+func (s *searchLogSuite) BenchmarkReadLastLines(c *C) {
+	// step 1. initial a log file
+	s.writeTmpFile(c, "tidb.log", []string{
+		`[2019/08/26 06:22:13.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:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
+		`[2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
+		`[2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`,
+	})
+
+	// step 2. open it as read only mode
+	path := filepath.Join(s.tmpDir, "tidb.log")
+	file, err := os.OpenFile(path, os.O_RDONLY, os.ModePerm)
+	c.Assert(err, IsNil, Commentf("open file %s failed", path))
+	defer file.Close()
+
+	stat, _ := file.Stat()
+	filesize := stat.Size()
+
+	// step 3. start to benchmark
+	c.ResetTimer()
+	for i := 0; i < c.N; i++ {
+		sysutil.ReadLastLines(file, filesize)
+	}
+}
+
+// run benchmark by `go test -check.b`
+// result:
+// searchLogSuite.BenchmarkReadLastLines      1000000              1920 ns/op
+// searchLogSuite.BenchmarkReadLastLines      1000000              1892 ns/op
+// result for the old readLastLine method:
+// searchLogSuite.BenchmarkReadLastLine        10000            124423 ns/op
+// searchLogSuite.BenchmarkReadLastLine        10000            126135 ns/op

From 6921c86d26194dc0cfbe870041aa71bfcb7492f3 Mon Sep 17 00:00:00 2001
From: baurine <2008.hbl@gmail.com>
Date: Wed, 8 Jul 2020 15:08:32 +0800
Subject: [PATCH 16/19] make readLastLines return slice instead of string

---
 search_log.go      | 27 ++++++++++++++++-----------
 search_log_test.go | 12 ++++++------
 2 files changed, 22 insertions(+), 17 deletions(-)

diff --git a/search_log.go b/search_log.go
index 8649427..a903525 100644
--- a/search_log.go
+++ b/search_log.go
@@ -141,20 +141,19 @@ func readLastValidLog(file *os.File, tryLines int) (*pb.LogMessage, error) {
 	stat, _ := file.Stat()
 	endCursor := stat.Size()
 	for {
-		lines := readLastLines(file, endCursor)
+		lines, readBytes := readLastLines(file, endCursor)
 		// read out the file
-		if len(lines) == 0 {
+		if readBytes == 0 {
 			break
 		}
-		endCursor -= int64(len(lines))
-		linesSlice := strings.FieldsFunc(lines, func(c rune) bool { return c == '\n' || c == '\r' })
-		for i := len(linesSlice) - 1; i >= 0; i-- {
-			item, err := parseLogItem(linesSlice[i])
+		endCursor -= int64(readBytes)
+		for i := len(lines) - 1; i >= 0; i-- {
+			item, err := parseLogItem(lines[i])
 			if err == nil {
 				return item, nil
 			}
 		}
-		tried += len(linesSlice)
+		tried += len(lines)
 		if tried >= tryLines {
 			break
 		}
@@ -179,8 +178,9 @@ func readLine(reader *bufio.Reader) (string, error) {
 
 // Read lines from the end of a file
 // endCursor initial value should be the filesize
-func readLastLines(file *os.File, endCursor int64) string {
+func readLastLines(file *os.File, endCursor int64) ([]string, int) {
 	var lines []byte
+	var firstNonNewlinePos int
 	var cursor = endCursor
 	for {
 		// stop if we are at the begining
@@ -203,16 +203,21 @@ func readLastLines(file *os.File, endCursor int64) string {
 		// find first '\n' or '\r'
 		for i := 0; i < len(chars); i++ {
 			// reach the line end
+			// the first newline may be in the line end at the first round
 			if i >= len(lines)-1 {
 				break
 			}
-
 			if (chars[i] == 10 || chars[i] == 13) && chars[i+1] != 10 && chars[i+1] != 13 {
-				return string(lines[i+1:])
+				firstNonNewlinePos = i + 1
+				break
 			}
 		}
+		if firstNonNewlinePos > 0 {
+			break
+		}
 	}
-	return string(lines)
+	finalStr := string(lines[firstNonNewlinePos:])
+	return strings.Split(strings.ReplaceAll(finalStr, "\r\n", "\n"), "\n"), len(finalStr)
 }
 
 // ParseLogLevel returns LogLevel from string and return LogLevel_Info if
diff --git a/search_log_test.go b/search_log_test.go
index 12a22d8..5aeb280 100644
--- a/search_log_test.go
+++ b/search_log_test.go
@@ -580,14 +580,14 @@ func (s *searchLogSuite) TestReadAndAppendLogFile(c *C) {
 	i := 0
 	endCursor := filesize
 	for {
-		line := sysutil.ReadLastLines(file, endCursor)
+		lines, readBytes := sysutil.ReadLastLines(file, endCursor)
 		// read out the file
-		if len(line) == 0 {
+		if readBytes == 0 {
 			break
 		}
-		c.Assert(line, Equals, expected[i], Commentf("expected: %v, got: %v", expected[i], line))
+		c.Assert(strings.Join(lines, "\n"), Equals, expected[i], Commentf("expected: %v, got: %v", expected[i], lines))
 		i++
-		endCursor -= int64(len(line))
+		endCursor -= int64(readBytes)
 
 		time.Sleep(15 * time.Millisecond)
 	}
@@ -621,8 +621,8 @@ func (s *searchLogSuite) BenchmarkReadLastLines(c *C) {
 
 // run benchmark by `go test -check.b`
 // result:
-// searchLogSuite.BenchmarkReadLastLines      1000000              1920 ns/op
-// searchLogSuite.BenchmarkReadLastLines      1000000              1892 ns/op
+// searchLogSuite.BenchmarkReadLastLines      1000000              2008 ns/op
+// searchLogSuite.BenchmarkReadLastLines      1000000              2193 ns/op
 // result for the old readLastLine method:
 // searchLogSuite.BenchmarkReadLastLine        10000            124423 ns/op
 // searchLogSuite.BenchmarkReadLastLine        10000            126135 ns/op

From 35d98d71b552b2abaf66b8f957de77a3cfe8a06f Mon Sep 17 00:00:00 2001
From: baurine <2008.hbl@gmail.com>
Date: Wed, 8 Jul 2020 15:31:48 +0800
Subject: [PATCH 17/19] update comment

---
 search_log_test.go | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/search_log_test.go b/search_log_test.go
index 5aeb280..5e067fc 100644
--- a/search_log_test.go
+++ b/search_log_test.go
@@ -623,6 +623,9 @@ func (s *searchLogSuite) BenchmarkReadLastLines(c *C) {
 // result:
 // searchLogSuite.BenchmarkReadLastLines      1000000              2008 ns/op
 // searchLogSuite.BenchmarkReadLastLines      1000000              2193 ns/op
-// result for the old readLastLine method:
+// result for the old readLastLine method when last line is 76 bytes long:
 // searchLogSuite.BenchmarkReadLastLine        10000            124423 ns/op
 // searchLogSuite.BenchmarkReadLastLine        10000            126135 ns/op
+// result for the old readLastLine method when last line is 76*2 bytes long:
+// searchLogSuite.BenchmarkReadLastLine        10000            247836 ns/op
+// searchLogSuite.BenchmarkReadLastLine        10000            251958 ns/op

From 82bb8b1e547f82996d9a30431ca9834c757bd0a3 Mon Sep 17 00:00:00 2001
From: Sparkle <1284531+baurine@users.noreply.github.com>
Date: Thu, 9 Jul 2020 16:15:41 +0800
Subject: [PATCH 18/19] Update search_log.go

Co-authored-by: Wenxuan <hi@breeswish.org>
---
 search_log.go | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/search_log.go b/search_log.go
index a903525..b018ed5 100644
--- a/search_log.go
+++ b/search_log.go
@@ -342,7 +342,7 @@ nextLine:
 				continue
 			}
 			// handle invalid log
-			// make whole line as log message with pre time and unknown log_level
+			// make whole line as log message with pre time and pre log_level
 			item = &pb.LogMessage{
 				Time:    iter.preLog.Time,
 				Level:   iter.preLog.Level,

From f25244b6a32de1bdb28edc73297519d635368c8b Mon Sep 17 00:00:00 2001
From: baurine <2008.hbl@gmail.com>
Date: Thu, 9 Jul 2020 21:17:00 +0800
Subject: [PATCH 19/19] slightly refine

---
 search_log.go | 13 ++++++-------
 1 file changed, 6 insertions(+), 7 deletions(-)

diff --git a/search_log.go b/search_log.go
index b018ed5..3ed9a2e 100644
--- a/search_log.go
+++ b/search_log.go
@@ -271,22 +271,21 @@ func parseLogItem(s string) (*pb.LogMessage, error) {
 	return item, nil
 }
 
-const TimeStampLayout = "2006/01/02 15:04:05.000 -07:00"
+const (
+	timeStampLayout    = "2006/01/02 15:04:05.000 -07:00"
+	timeStampLayoutLen = len(timeStampLayout)
+)
 
 // TiDB / TiKV / PD unified log format
 // [2019/03/04 17:04:24.614 +08:00] ...
 func parseTimeStamp(s string) (int64, error) {
-	t, err := time.Parse(TimeStampLayout, s)
+	t, err := time.Parse(timeStampLayout, s)
 	if err != nil {
 		return 0, err
 	}
 	return t.UnixNano() / int64(time.Millisecond), nil
 }
 
-// Only enable seek when position range is more than SEEK_THRESHOLD.
-// The suggested value of SEEK_THRESHOLD is the biggest log size.
-const SEEK_THRESHOLD = 1024 * 1024
-
 // logIterator implements Iterator and IteratorWithPeek interface.
 // It's used for reading logs from log files one by one by their
 // time.
@@ -333,7 +332,7 @@ nextLine:
 			continue
 		}
 		line = strings.TrimSpace(line)
-		if len(line) == 0 {
+		if iter.preLog == nil && len(line) < timeStampLayoutLen {
 			continue
 		}
 		item, err := parseLogItem(line)