From 6e615c6eaacab342c2ed1bf949aa664d1fa1a2a7 Mon Sep 17 00:00:00 2001 From: Ainar Garipov Date: Mon, 30 Nov 2020 13:32:58 +0300 Subject: [PATCH] Pull request: querylog: resort buffers Merge in DNS/adguard-home from 2293-log-sort to master Updates #2293. Squashed commit of the following: commit f8961e5c52f82befe23ab1f7603a867243186498 Author: Ainar Garipov Date: Sat Nov 28 17:19:15 2020 +0300 all: document changes commit c92c53307f1ed4a1c3196bdc19d23a775876b106 Author: Ainar Garipov Date: Sat Nov 28 16:44:01 2020 +0300 querylog: resort buffers --- CHANGELOG.md | 3 + internal/querylog/{qlog_http.go => http.go} | 2 +- internal/querylog/json.go | 6 +- internal/querylog/qlog_test.go | 74 ++++++++++++++++++- internal/querylog/querylog_file.go | 2 +- .../{querylog_search.go => search.go} | 9 +++ internal/querylog/search_criteria.go | 2 +- 7 files changed, 91 insertions(+), 7 deletions(-) rename internal/querylog/{qlog_http.go => http.go} (99%) rename internal/querylog/{querylog_search.go => search.go} (94%) diff --git a/CHANGELOG.md b/CHANGELOG.md index 74355e71141..cdd806a0fb7 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -40,10 +40,13 @@ and this project adheres to ### Fixed +- A mitigation against records being shown in the wrong order on the query log + page [#2293]. - A JSON parsing error in query log [#2345]. - Incorrect detection of the IPv6 address of an interface as well as another infinite loop in the `/dhcp/find_active_dhcp` HTTP API [#2355]. +[#2293]: https://github.com/AdguardTeam/AdGuardHome/issues/2293 [#2345]: https://github.com/AdguardTeam/AdGuardHome/issues/2345 [#2355]: https://github.com/AdguardTeam/AdGuardHome/issues/2355 diff --git a/internal/querylog/qlog_http.go b/internal/querylog/http.go similarity index 99% rename from internal/querylog/qlog_http.go rename to internal/querylog/http.go index 473df2a491b..9bc63b7e865 100644 --- a/internal/querylog/qlog_http.go +++ b/internal/querylog/http.go @@ -47,7 +47,7 @@ func (l *queryLog) handleQueryLog(w http.ResponseWriter, r *http.Request) { entries, oldest := l.search(params) // convert log entries to JSON - var data = l.entriesToJSON(entries, oldest) + data := l.entriesToJSON(entries, oldest) jsonVal, err := json.Marshal(data) if err != nil { diff --git a/internal/querylog/json.go b/internal/querylog/json.go index 46f3ea0bbb8..4130ce9e729 100644 --- a/internal/querylog/json.go +++ b/internal/querylog/json.go @@ -32,7 +32,7 @@ func (l *queryLog) getClientIP(clientIP string) string { // entriesToJSON - converts log entries to JSON func (l *queryLog) entriesToJSON(entries []*logEntry, oldest time.Time) map[string]interface{} { // init the response object - var data = []map[string]interface{}{} + data := []map[string]interface{}{} // the elements order is already reversed (from newer to older) for i := 0; i < len(entries); i++ { @@ -41,7 +41,7 @@ func (l *queryLog) entriesToJSON(entries []*logEntry, oldest time.Time) map[stri data = append(data, jsonEntry) } - var result = map[string]interface{}{} + result := map[string]interface{}{} result["oldest"] = "" if !oldest.IsZero() { result["oldest"] = oldest.Format(time.RFC3339Nano) @@ -123,7 +123,7 @@ func answerToMap(a *dns.Msg) []map[string]interface{} { return nil } - var answers = []map[string]interface{}{} + answers := []map[string]interface{}{} for _, k := range a.Answer { header := k.Header() answer := map[string]interface{}{ diff --git a/internal/querylog/qlog_test.go b/internal/querylog/qlog_test.go index 4dec517505e..b6651158c63 100644 --- a/internal/querylog/qlog_test.go +++ b/internal/querylog/qlog_test.go @@ -1,9 +1,12 @@ package querylog import ( + "math/rand" "net" "os" + "sort" "testing" + "time" "github.com/AdguardTeam/dnsproxy/proxyutil" @@ -20,7 +23,7 @@ func TestMain(m *testing.M) { func prepareTestDir() string { const dir = "./agh-test" _ = os.RemoveAll(dir) - _ = os.MkdirAll(dir, 0755) + _ = os.MkdirAll(dir, 0o755) return dir } @@ -263,3 +266,72 @@ func assertLogEntry(t *testing.T, entry *logEntry, host, answer, client string) assert.Equal(t, answer, ip.String()) return true } + +func testEntries() (entries []*logEntry) { + rsrc := rand.NewSource(time.Now().UnixNano()) + rgen := rand.New(rsrc) + + entries = make([]*logEntry, 1000) + for i := range entries { + min := rgen.Intn(60) + sec := rgen.Intn(60) + entries[i] = &logEntry{ + Time: time.Date(2020, 1, 1, 0, min, sec, 0, time.UTC), + } + } + + return entries +} + +// logEntriesByTimeDesc is a wrapper over []*logEntry for sorting. +// +// NOTE(a.garipov): Weirdly enough, on my machine this gets consistently +// outperformed by sort.Slice, see the benchmark below. I'm leaving this +// implementation here, in tests, in case we want to make sure it outperforms on +// most machines, but for now this is unused in the actual code. +type logEntriesByTimeDesc []*logEntry + +// Len implements the sort.Interface interface for logEntriesByTimeDesc. +func (les logEntriesByTimeDesc) Len() (n int) { return len(les) } + +// Less implements the sort.Interface interface for logEntriesByTimeDesc. +func (les logEntriesByTimeDesc) Less(i, j int) (less bool) { + return les[i].Time.After(les[j].Time) +} + +// Swap implements the sort.Interface interface for logEntriesByTimeDesc. +func (les logEntriesByTimeDesc) Swap(i, j int) { les[i], les[j] = les[j], les[i] } + +func BenchmarkLogEntry_sort(b *testing.B) { + b.Run("methods", func(b *testing.B) { + for i := 0; i < b.N; i++ { + b.StopTimer() + entries := testEntries() + b.StartTimer() + + sort.Stable(logEntriesByTimeDesc(entries)) + } + }) + + b.Run("reflect", func(b *testing.B) { + for i := 0; i < b.N; i++ { + b.StopTimer() + entries := testEntries() + b.StartTimer() + + sort.SliceStable(entries, func(i, j int) (less bool) { + return entries[i].Time.After(entries[j].Time) + }) + } + }) +} + +func TestLogEntriesByTime_sort(t *testing.T) { + entries := testEntries() + sort.Sort(logEntriesByTimeDesc(entries)) + + for i := 1; i < len(entries); i++ { + assert.False(t, entries[i].Time.After(entries[i-1].Time), + "%s %s", entries[i].Time, entries[i-1].Time) + } +} diff --git a/internal/querylog/querylog_file.go b/internal/querylog/querylog_file.go index 42e1ddf9e5f..c6d48235012 100644 --- a/internal/querylog/querylog_file.go +++ b/internal/querylog/querylog_file.go @@ -65,7 +65,7 @@ func (l *queryLog) flushToFile(buffer []*logEntry) error { l.fileWriteLock.Lock() defer l.fileWriteLock.Unlock() - f, err := os.OpenFile(filename, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644) + f, err := os.OpenFile(filename, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0o644) if err != nil { log.Error("failed to create file \"%s\": %s", filename, err) return err diff --git a/internal/querylog/querylog_search.go b/internal/querylog/search.go similarity index 94% rename from internal/querylog/querylog_search.go rename to internal/querylog/search.go index 2e8ce3336ed..0b9aa7d27ef 100644 --- a/internal/querylog/querylog_search.go +++ b/internal/querylog/search.go @@ -2,6 +2,7 @@ package querylog import ( "io" + "sort" "time" "github.com/AdguardTeam/AdGuardHome/internal/util" @@ -46,6 +47,14 @@ func (l *queryLog) search(params *searchParams) ([]*logEntry, time.Time) { entries = entries[:totalLimit] } + // Resort entries on start time to partially mitigate query log looking + // weird on the frontend. + // + // See https://github.com/AdguardTeam/AdGuardHome/issues/2293. + sort.SliceStable(entries, func(i, j int) (less bool) { + return entries[i].Time.After(entries[j].Time) + }) + if params.offset > 0 { if len(entries) > params.offset { entries = entries[params.offset:] diff --git a/internal/querylog/search_criteria.go b/internal/querylog/search_criteria.go index 73f2497ef7c..bb573ea6689 100644 --- a/internal/querylog/search_criteria.go +++ b/internal/querylog/search_criteria.go @@ -58,7 +58,7 @@ func (c *searchCriteria) quickMatch(line string) bool { } // quickMatchJSONValue - helper used by quickMatch -func (c *searchCriteria) quickMatchJSONValue(line string, propertyName string) bool { +func (c *searchCriteria) quickMatchJSONValue(line, propertyName string) bool { val := readJSONValue(line, propertyName) if len(val) == 0 { return false