From 40614d9a7b7582564b5423710419d1ec9e2d7279 Mon Sep 17 00:00:00 2001 From: Eugene Burkov Date: Wed, 18 Nov 2020 15:43:28 +0300 Subject: [PATCH] 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 Date: Wed Nov 18 15:35:42 2020 +0300 Merge branch 'master' into 2324-querylog-bug-fix commit 8103f9e42a398f43682ee30d09b3afdab0e9e177 Author: Eugene Burkov Date: Wed Nov 18 14:28:29 2020 +0300 querylog: fix the file ordering bug commit 2c4e8fcc5b8593be1614480508dfd600fc676e64 Author: Eugene Burkov Date: Tue Nov 17 20:57:45 2020 +0300 querylog: wrap errors to clarify error trace commit 3733062b494817696e4443f153774bb01cea1b06 Author: Eugene Burkov Date: Tue Nov 17 18:55:17 2020 +0300 querylog: fix logger output bug --- internal/agherr/agherr_test.go | 2 +- internal/querylog/qlog_file.go | 15 ++-- internal/querylog/qlog_reader.go | 23 +++--- internal/querylog/qlog_reader_test.go | 111 ++++++++++++++++++++++++++ 4 files changed, 132 insertions(+), 19 deletions(-) diff --git a/internal/agherr/agherr_test.go b/internal/agherr/agherr_test.go index 3940bdee..8ef2f51f 100644 --- a/internal/agherr/agherr_test.go +++ b/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 { diff --git a/internal/querylog/qlog_file.go b/internal/querylog/qlog_file.go index 5c5b8fc9..31f034ec 100644 --- a/internal/querylog/qlog_file.go +++ b/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) } } diff --git a/internal/querylog/qlog_reader.go b/internal/querylog/qlog_reader.go index 41677c3e..4cf65f7c 100644 --- a/internal/querylog/qlog_reader.go +++ b/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 diff --git a/internal/querylog/qlog_reader_test.go b/internal/querylog/qlog_reader_test.go index 357b4f9d..af59eb10 100644 --- a/internal/querylog/qlog_reader_test.go +++ b/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