From 4690229d815b5f6fc25410c8d85be6fa99c1db7b Mon Sep 17 00:00:00 2001 From: Ainar Garipov Date: Thu, 19 Nov 2020 12:53:31 +0300 Subject: [PATCH] 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 90388050ed495286cdfed6574dd438abd4a33baa Author: Ainar Garipov Date: Thu Nov 19 12:37:00 2020 +0300 all: changelog commit bbdeabbb550c7e98f579e2a68c71de7a66624203 Author: Ainar Garipov Date: Thu Nov 19 12:33:21 2020 +0300 querylog: improve error reporting commit 807b23aa74d0e39f5ef51910e5b91c9b95a8c341 Author: Ainar Garipov Date: Wed Nov 18 19:39:22 2020 +0300 querylog: improve docs commit 65a8f4f3323192c872b3389d2b3420e072a01297 Author: Ainar Garipov Date: Wed Nov 18 19:36:28 2020 +0300 querylog: use better error signaling --- CHANGELOG.md | 2 ++ internal/querylog/qlog_file.go | 34 ++++++++++++------------ internal/querylog/qlog_file_test.go | 37 ++++++++++++++++++++++++--- internal/querylog/qlog_reader.go | 18 ++++++++++--- internal/querylog/qlog_reader_test.go | 8 +++--- internal/querylog/querylog_search.go | 4 --- 6 files changed, 71 insertions(+), 32 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index b7e8f4d5..4502a81a 100644 --- a/CHANGELOG.md +++ b/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). diff --git a/internal/querylog/qlog_file.go b/internal/querylog/qlog_file.go index 31f034ec..13754427 100644 --- a/internal/querylog/qlog_file.go +++ b/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,15 +103,18 @@ 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 @@ -119,9 +122,8 @@ func (q *QLogFile) Seek(timestamp int64) (int64, int, error) { // 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) } } diff --git a/internal/querylog/qlog_file_test.go b/internal/querylog/qlog_file_test.go index de402e8b..b458e071 100644 --- a/internal/querylog/qlog_file_test.go +++ b/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) +} diff --git a/internal/querylog/qlog_reader.go b/internal/querylog/qlog_reader.go index 4cf65f7c..dbb058c6 100644 --- a/internal/querylog/qlog_reader.go +++ b/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 } } diff --git a/internal/querylog/qlog_reader_test.go b/internal/querylog/qlog_reader_test.go index af59eb10..f1802a0a 100644 --- a/internal/querylog/qlog_reader_test.go +++ b/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 { diff --git a/internal/querylog/querylog_search.go b/internal/querylog/querylog_search.go index 133a1dba..2e8ce333 100644 --- a/internal/querylog/querylog_search.go +++ b/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 } }