Pull request: querylog: use better error signaling

Merge in DNS/adguard-home from 2325-querylog-suffering to master

Closes #2325.

Squashed commit of the following:

commit 9038805
Author: Ainar Garipov <A.Garipov@AdGuard.COM>
Date:   Thu Nov 19 12:37:00 2020 +0300

    all: changelog

commit bbdeabb
Author: Ainar Garipov <A.Garipov@AdGuard.COM>
Date:   Thu Nov 19 12:33:21 2020 +0300

    querylog: improve error reporting

commit 807b23a
Author: Ainar Garipov <A.Garipov@AdGuard.COM>
Date:   Wed Nov 18 19:39:22 2020 +0300

    querylog: improve docs

commit 65a8f4f
Author: Ainar Garipov <A.Garipov@AdGuard.COM>
Date:   Wed Nov 18 19:36:28 2020 +0300

    querylog: use better error signaling

CHANGELOG.md

@@ -20,6 +20,8 @@ and this project adheres to
 
 ### Fixed
 
+- Query logs from file not loading after the ones buffered in memory (#2325).
+- Unnecessary errors in query logs when switching between log files (#2324).
 - `404 Not Found` errors on the DHCP settings page on *Windows*.  The page now
   correctly shows that DHCP is not currently available on that OS (#2295).
 - Infinite loop in `/dhcp/find_active_dhcp` (#2301).

internal/querylog/qlog_file.go

@@ -11,12 +11,12 @@ import (
 	"github.com/AdguardTeam/golibs/log"
 )
 
-// ErrSeekNotFound is returned from Seek if when it fails to find the requested
-// record.
-const ErrSeekNotFound agherr.Error = "seek: record not found"
-
-// ErrEndOfLog is returned from Seek when the end of the current log is reached.
-const ErrEndOfLog agherr.Error = "seek: end of log"
+// Timestamp not found errors.
+const (
+	ErrTSNotFound agherr.Error = "ts not found"
+	ErrTSTooLate  agherr.Error = "ts too late"
+	ErrTSTooEarly agherr.Error = "ts too early"
+)
 
 // TODO: Find a way to grow buffer instead of relying on this value when reading strings
 const maxEntrySize = 16 * 1024
@@ -69,7 +69,7 @@ func NewQLogFile(path string) (*QLogFile, error) {
 // * It returns the position of the the line with the timestamp we were looking for
 // so that when we call "ReadNext" this line was returned.
 // * Depth of the search (how many times we compared timestamps).
-// * If we could not find it, it returns ErrSeekNotFound
+// * If we could not find it, it returns one of the errors described above.
 func (q *QLogFile) Seek(timestamp int64) (int64, int, error) {
 	q.lock.Lock()
 	defer q.lock.Unlock()
@@ -103,25 +103,27 @@ func (q *QLogFile) Seek(timestamp int64) (int64, int, error) {
 		if err != nil {
 			return 0, depth, err
 		}
-		if lineIdx < start || lineEndIdx > end || lineIdx == lastProbeLineIdx {
+
+		if lineIdx == lastProbeLineIdx {
+			if lineIdx == 0 {
+				return 0, depth, ErrTSTooEarly
+			}
+
 			// If we're testing the same line twice then most likely
 			// the scope is too narrow and we won't find anything
 			// anymore in any other file.
-			return 0, depth, fmt.Errorf("couldn't find timestamp %v: %w", timestamp, ErrSeekNotFound)
-		} else if lineIdx == end && lineEndIdx == end {
-			// If both line beginning and line ending indices point
-			// at the end of the file, we apparently reached it.
-			return 0, depth, ErrEndOfLog
+			return 0, depth, fmt.Errorf("looking up timestamp %d in %q: %w", timestamp, q.file.Name(), ErrTSNotFound)
+		} else if lineIdx == fileInfo.Size() {
+			return 0, depth, ErrTSTooLate
 		}
 
 		// Save the last found idx
 		lastProbeLineIdx = lineIdx
 
 		// Get the timestamp from the query log record
 		ts := readQLogTimestamp(line)
-
 		if ts == 0 {
-			return 0, depth, fmt.Errorf("couldn't get timestamp: %w", ErrSeekNotFound)
+			return 0, depth, fmt.Errorf("looking up timestamp %d in %q: record %q has empty timestamp", timestamp, q.file.Name(), line)
 		}
 
 		if ts == timestamp {
@@ -143,7 +145,7 @@ func (q *QLogFile) Seek(timestamp int64) (int64, int, error) {
 
 		depth++
 		if depth >= 100 {
-			return 0, depth, fmt.Errorf("seek depth is too high, aborting. File %s, timestamp %v: %w", q.file.Name(), timestamp, ErrSeekNotFound)
+			return 0, depth, fmt.Errorf("looking up timestamp %d in %q: depth %d too high: %w", timestamp, q.file.Name(), depth, ErrTSNotFound)
 		}
 	}
 

internal/querylog/qlog_file_test.go

@@ -243,10 +243,10 @@ func prepareTestFiles(dir string, filesCount, linesCount int) []string {
 	lineTime, _ := time.Parse(time.RFC3339Nano, "2020-02-18T22:36:35.920973+03:00")
 	lineIP := uint32(0)
 
-	files := make([]string, 0)
+	files := make([]string, filesCount)
 	for j := 0; j < filesCount; j++ {
 		f, _ := ioutil.TempFile(dir, "*.txt")
-		files = append(files, f.Name())
+		files[filesCount-j-1] = f.Name()
 
 		for i := 0; i < linesCount; i++ {
 			lineIP += 1
@@ -289,7 +289,7 @@ func TestQLogSeek(t *testing.T) {
 	assert.Equal(t, 1, depth)
 }
 
-func TestQLogSeek_ErrEndOfLog(t *testing.T) {
+func TestQLogSeek_ErrTSTooLate(t *testing.T) {
 	testDir := prepareTestDir()
 	t.Cleanup(func() {
 		_ = os.RemoveAll(testDir)
@@ -314,6 +314,35 @@ func TestQLogSeek_ErrEndOfLog(t *testing.T) {
 	assert.Nil(t, err)
 
 	_, depth, err := q.Seek(target.UnixNano() + int64(time.Second))
-	assert.Equal(t, ErrEndOfLog, err)
+	assert.Equal(t, ErrTSTooLate, err)
 	assert.Equal(t, 2, depth)
 }
+
+func TestQLogSeek_ErrTSTooEarly(t *testing.T) {
+	testDir := prepareTestDir()
+	t.Cleanup(func() {
+		_ = os.RemoveAll(testDir)
+	})
+
+	d := `{"T":"2020-08-31T18:44:23.911246629+03:00","QH":"wfqvjymurpwegyv","QT":"A","QC":"IN","CP":"","Answer":"","Result":{},"Elapsed":66286385,"Upstream":"tls://dns-unfiltered.adguard.com:853"}
+{"T":"2020-08-31T18:44:25.376690873+03:00"}
+{"T":"2020-08-31T18:44:25.382540454+03:00"}
+`
+	f, err := ioutil.TempFile(testDir, "*.txt")
+	assert.Nil(t, err)
+	defer f.Close()
+
+	_, err = f.WriteString(d)
+	assert.Nil(t, err)
+
+	q, err := NewQLogFile(f.Name())
+	assert.Nil(t, err)
+	defer q.Close()
+
+	target, err := time.Parse(time.RFC3339, "2020-08-31T18:44:23.911246629+03:00")
+	assert.Nil(t, err)
+
+	_, depth, err := q.Seek(target.UnixNano() - int64(time.Second))
+	assert.Equal(t, ErrTSTooEarly, err)
+	assert.Equal(t, 1, depth)
+}

internal/querylog/qlog_reader.go

@@ -51,16 +51,26 @@ func NewQLogReader(files []string) (*QLogReader, error) {
 // Returns nil if the record is successfully found.
 // Returns an error if for some reason we could not find a record with the specified timestamp.
 func (r *QLogReader) Seek(timestamp int64) (err error) {
-	for i, q := range r.qFiles {
+	for i := len(r.qFiles) - 1; i >= 0; i-- {
+		q := r.qFiles[i]
 		_, _, err = q.Seek(timestamp)
 		if err == nil {
 			// Search is finished, and the searched element have
 			// been found. Update currentFile only, position is
 			// already set properly in QLogFile.
 			r.currentFile = i
-			return err
-		}
-		if errors.Is(err, ErrSeekNotFound) {
+
+			return nil
+		} else if errors.Is(err, ErrTSTooEarly) {
+			// Look at the next file, since we've reached the end of
+			// this one.
+			continue
+		} else if errors.Is(err, ErrTSTooLate) {
+			// Just seek to the start then.  timestamp is probably
+			// between the end of the previous one and the start of
+			// this one.
+			return r.SeekStart()
+		} else if errors.Is(err, ErrTSNotFound) {
 			break
 		}
 	}

internal/querylog/qlog_reader_test.go

@@ -131,15 +131,15 @@ func TestQLogReader_Seek(t *testing.T) {
 	}, {
 		name: "non-existent_long_ago",
 		time: "2000-02-19T01:23:16.920973+03:00",
-		want: ErrSeekNotFound,
+		want: ErrTSTooEarly,
 	}, {
 		name: "non-existent_far_ahead",
 		time: "2100-02-19T01:23:16.920973+03:00",
-		want: ErrEndOfLog,
+		want: nil,
 	}, {
 		name: "non-existent_but_could",
-		time: "2020-02-19T03:00:00.000000+03:00",
-		want: ErrSeekNotFound,
+		time: "2020-02-18T22:36:37.000000+03:00",
+		want: ErrTSNotFound,
 	}}
 
 	for _, tc := range testCases {

internal/querylog/querylog_search.go

@@ -1,7 +1,6 @@
 package querylog
 
 import (
-	"errors"
 	"io"
 	"time"
 
@@ -95,9 +94,6 @@ func (l *queryLog) searchFiles(params *searchParams) ([]*logEntry, time.Time, in
 			// The one that was specified in the "oldest" param is not needed,
 			// we need only the one next to it
 			_, err = r.ReadNext()
-		} else if errors.Is(err, ErrEndOfLog) {
-			// We've reached the end of the log.
-			return entries, time.Time{}, 0
 		}
 	}