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 <A.Garipov@AdGuard.COM>
Date:   Thu Nov 19 12:37:00 2020 +0300

    all: changelog

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

    querylog: improve error reporting

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

    querylog: improve docs

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

    querylog: use better error signaling
This commit is contained in:
Ainar Garipov 2020-11-19 12:53:31 +03:00
parent de257b73aa
commit 4690229d81
6 changed files with 71 additions and 32 deletions

View File

@ -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).

View File

@ -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)
}
}

View File

@ -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)
}

View File

@ -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
}
}

View File

@ -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 {

View File

@ -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
}
}