Pull request: querylog bug fix

Merge in DNS/adguard-home from 2324-querylog-bug-fix to master

Closes #2324.

Squashed commit of the following:

commit fdd584a218e1edc3e45ab5b00ceed0a3be681e32
Merge: 8103f9e42 f2eda6d19
Author: Eugene Burkov <e.burkov@adguard.com>
Date:   Wed Nov 18 15:35:42 2020 +0300

    Merge branch 'master' into 2324-querylog-bug-fix

commit 8103f9e42a398f43682ee30d09b3afdab0e9e177
Author: Eugene Burkov <e.burkov@adguard.com>
Date:   Wed Nov 18 14:28:29 2020 +0300

    querylog: fix the file ordering bug

commit 2c4e8fcc5b8593be1614480508dfd600fc676e64
Author: Eugene Burkov <e.burkov@adguard.com>
Date:   Tue Nov 17 20:57:45 2020 +0300

    querylog: wrap errors to clarify error trace

commit 3733062b494817696e4443f153774bb01cea1b06
Author: Eugene Burkov <e.burkov@adguard.com>
Date:   Tue Nov 17 18:55:17 2020 +0300

    querylog: fix logger output bug

internal/agherr/agherr_test.go

@@ -48,7 +48,7 @@ func TestError_Unwrap(t *testing.T) {
 	)
 	errs := []error{
 		errSimple:  errors.New("a"),
-		errWrapped: fmt.Errorf("%w", errors.New("nested")),
+		errWrapped: fmt.Errorf("err: %w", errors.New("nested")),
 		errNil:     nil,
 	}
 	testCases := []struct {

internal/querylog/qlog_file.go

@@ -1,6 +1,7 @@
 package querylog
 
 import (
+	"fmt"
 	"io"
 	"os"
 	"sync"
@@ -102,13 +103,14 @@ func (q *QLogFile) Seek(timestamp int64) (int64, int, error) {
 		if err != nil {
 			return 0, depth, err
 		}
-
 		if lineIdx < start || lineEndIdx > end || lineIdx == lastProbeLineIdx {
 			// If we're testing the same line twice then most likely
-			// the scope is too narrow and we won't find anything anymore
-			log.Error("querylog: didn't find timestamp:%v", timestamp)
-			return 0, depth, ErrSeekNotFound
+			// 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
 		}
 
@@ -119,7 +121,7 @@ func (q *QLogFile) Seek(timestamp int64) (int64, int, error) {
 		ts := readQLogTimestamp(line)
 
 		if ts == 0 {
-			return 0, depth, ErrSeekNotFound
+			return 0, depth, fmt.Errorf("couldn't get timestamp: %w", ErrSeekNotFound)
 		}
 
 		if ts == timestamp {
@@ -141,8 +143,7 @@ func (q *QLogFile) Seek(timestamp int64) (int64, int, error) {
 
 		depth++
 		if depth >= 100 {
-			log.Error("Seek depth is too high, aborting. File %s, ts %v", q.file.Name(), timestamp)
-			return 0, depth, ErrSeekNotFound
+			return 0, depth, fmt.Errorf("seek depth is too high, aborting. File %s, timestamp %v: %w", q.file.Name(), timestamp, ErrSeekNotFound)
 		}
 	}
 

internal/querylog/qlog_reader.go

@@ -2,6 +2,7 @@ package querylog
 
 import (
 	"errors"
+	"fmt"
 	"io"
 
 	"github.com/AdguardTeam/AdGuardHome/internal/agherr"
@@ -49,22 +50,22 @@ 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) error {
-	for i := len(r.qFiles) - 1; i >= 0; i-- {
-		q := r.qFiles[i]
-		_, _, err := q.Seek(timestamp)
-		if err == nil || errors.Is(err, ErrEndOfLog) {
-			// Our search is finished, and we either found the
-			// element we were looking for or reached the end of the
-			// log.  Update currentFile only, position is already
-			// set properly in QLogFile.
+func (r *QLogReader) Seek(timestamp int64) (err error) {
+	for i, q := range r.qFiles {
+		_, _, 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) {
+			break
+		}
 	}
 
-	return ErrSeekNotFound
+	return fmt.Errorf("querylog: %w", err)
 }
 
 // SeekStart changes the current position to the end of the newest file

internal/querylog/qlog_reader_test.go

@@ -1,6 +1,7 @@
 package querylog
 
 import (
+	"errors"
 	"io"
 	"os"
 	"testing"
@@ -90,6 +91,116 @@ func TestQLogReaderMultipleFiles(t *testing.T) {
 	assert.Equal(t, io.EOF, err)
 }
 
+func TestQLogReader_Seek(t *testing.T) {
+	count := 10000
+	filesCount := 2
+
+	testDir := prepareTestDir()
+	t.Cleanup(func() {
+		_ = os.RemoveAll(testDir)
+	})
+	testFiles := prepareTestFiles(testDir, filesCount, count)
+
+	r, err := NewQLogReader(testFiles)
+	assert.Nil(t, err)
+	assert.NotNil(t, r)
+	t.Cleanup(func() {
+		_ = r.Close()
+	})
+
+	testCases := []struct {
+		name string
+		time string
+		want error
+	}{{
+		name: "not_too_old",
+		time: "2020-02-19T04:04:56.920973+03:00",
+		want: nil,
+	}, {
+		name: "old",
+		time: "2020-02-19T01:28:16.920973+03:00",
+		want: nil,
+	}, {
+		name: "first",
+		time: "2020-02-19T04:09:55.920973+03:00",
+		want: nil,
+	}, {
+		name: "last",
+		time: "2020-02-19T01:23:16.920973+03:00",
+		want: nil,
+	}, {
+		name: "non-existent_long_ago",
+		time: "2000-02-19T01:23:16.920973+03:00",
+		want: ErrSeekNotFound,
+	}, {
+		name: "non-existent_far_ahead",
+		time: "2100-02-19T01:23:16.920973+03:00",
+		want: ErrEndOfLog,
+	}, {
+		name: "non-existent_but_could",
+		time: "2020-02-19T03:00:00.000000+03:00",
+		want: ErrSeekNotFound,
+	}}
+
+	for _, tc := range testCases {
+		t.Run(tc.name, func(t *testing.T) {
+			timestamp, err := time.Parse(time.RFC3339Nano, tc.time)
+			assert.Nil(t, err)
+
+			err = r.Seek(timestamp.UnixNano())
+			assert.True(t, errors.Is(err, tc.want), err)
+		})
+	}
+}
+
+func TestQLogReader_ReadNext(t *testing.T) {
+	count := 10
+	filesCount := 1
+
+	testDir := prepareTestDir()
+	t.Cleanup(func() {
+		_ = os.RemoveAll(testDir)
+	})
+	testFiles := prepareTestFiles(testDir, filesCount, count)
+
+	r, err := NewQLogReader(testFiles)
+	assert.Nil(t, err)
+	assert.NotNil(t, r)
+	t.Cleanup(func() {
+		_ = r.Close()
+	})
+
+	testCases := []struct {
+		name  string
+		start int
+		want  error
+	}{{
+		name:  "ok",
+		start: 0,
+		want:  nil,
+	}, {
+		name:  "too_big",
+		start: count + 1,
+		want:  io.EOF,
+	}}
+
+	for _, tc := range testCases {
+		t.Run(tc.name, func(t *testing.T) {
+			err := r.SeekStart()
+			assert.Nil(t, err, err)
+
+			for i := 1; i < tc.start; i++ {
+				_, err := r.ReadNext()
+				assert.Nil(t, err)
+			}
+
+			_, err = r.ReadNext()
+			assert.Equal(t, tc.want, err)
+		})
+	}
+}
+
+// TODO(e.burkov): Remove the tests below.  Make tests above more compelling.
 func TestQLogReaderSeek(t *testing.T) {
 	// more or less big file
 	count := 10000