diff --git a/AGHTechDoc.md b/AGHTechDoc.md index 91d17472..e5e582ec 100644 --- a/AGHTechDoc.md +++ b/AGHTechDoc.md @@ -1439,6 +1439,11 @@ When UI asks for data from query log (see "API: Get query log"), server reads th We store data for a limited amount of time - the log file is automatically rotated. +* On AGH startup read the first line from query logs and store its time value +* If there's no log file yet, set the time value of the first log event when the file is created +* If this time value is older than our time limit, perform file rotate procedure +* While AGH is running, check the previous condition every 24 hours + ### API: Get query log diff --git a/querylog/qlog_file.go b/querylog/qlog_file.go index c1eeefa2..8005e430 100644 --- a/querylog/qlog_file.go +++ b/querylog/qlog_file.go @@ -86,8 +86,10 @@ func (q *QLogFile) Seek(timestamp int64) (int64, int, error) { end := fileInfo.Size() // end of the search interval (position in the file) probe := (end - start) / 2 // probe -- approximate index of the line we'll try to check var line string - var lineIdx int64 // index of the probe line in the file + var lineIdx int64 // index of the probe line in the file + var lineEndIdx int64 var lastProbeLineIdx int64 // index of the last probe line + lastProbeLineIdx = -1 // Count seek depth in order to detect mistakes // If depth is too large, we should stop the search @@ -95,11 +97,21 @@ func (q *QLogFile) Seek(timestamp int64) (int64, int, error) { for { // Get the line at the specified position - line, lineIdx, err = q.readProbeLine(probe) + line, lineIdx, lineEndIdx, err = q.readProbeLine(probe) 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 + } + + // Save the last found idx + lastProbeLineIdx = lineIdx + // Get the timestamp from the query log record ts := readQLogTimestamp(line) @@ -112,27 +124,17 @@ func (q *QLogFile) Seek(timestamp int64) (int64, int, error) { break } - if lastProbeLineIdx == lineIdx { - // If we're testing the same line twice then most likely - // the scope is too narrow and we won't find anything anymore - return 0, depth, ErrSeekNotFound - } - - // Save the last found idx - lastProbeLineIdx = lineIdx - // Narrow the scope and repeat the search if ts > timestamp { // If the timestamp we're looking for is OLDER than what we found // Then the line is somewhere on the LEFT side from the current probe position - end = probe - probe = start + (end-start)/2 + end = lineIdx } else { // If the timestamp we're looking for is NEWER than what we found // Then the line is somewhere on the RIGHT side from the current probe position - start = probe - probe = start + (end-start)/2 + start = lineEndIdx } + probe = start + (end-start)/2 depth++ if depth >= 100 { @@ -267,7 +269,7 @@ func (q *QLogFile) initBuffer(position int64) error { // readProbeLine reads a line that includes the specified position // this method is supposed to be used when we use binary search in the Seek method // in the case of consecutive reads, use readNext (it uses a better buffer) -func (q *QLogFile) readProbeLine(position int64) (string, int64, error) { +func (q *QLogFile) readProbeLine(position int64) (string, int64, int64, error) { // First of all, we should read a buffer that will include the query log line // In order to do this, we'll define the boundaries seekPosition := int64(0) @@ -280,14 +282,14 @@ func (q *QLogFile) readProbeLine(position int64) (string, int64, error) { // Seek to this position _, err := q.file.Seek(seekPosition, io.SeekStart) if err != nil { - return "", 0, err + return "", 0, 0, err } // The buffer size is 2*maxEntrySize buffer := make([]byte, maxEntrySize*2) bufferLen, err := q.file.Read(buffer) if err != nil { - return "", 0, err + return "", 0, 0, err } // Now start looking for the new line character starting @@ -301,16 +303,18 @@ func (q *QLogFile) readProbeLine(position int64) (string, int64, error) { } // Looking for the end of line now var endLine = int64(bufferLen) + lineEndIdx := endLine + seekPosition for i := relativePos; i < int64(bufferLen); i++ { if buffer[i] == '\n' { endLine = i + lineEndIdx = endLine + seekPosition + 1 break } } // Finally we can return the string we were looking for lineIdx := startLine + seekPosition - return string(buffer[startLine:endLine]), lineIdx, nil + return string(buffer[startLine:endLine]), lineIdx, lineEndIdx, nil } // readQLogTimestamp reads the timestamp field from the query log line diff --git a/querylog/qlog_file_test.go b/querylog/qlog_file_test.go index a0fa07f1..0329ceb5 100644 --- a/querylog/qlog_file_test.go +++ b/querylog/qlog_file_test.go @@ -266,3 +266,25 @@ func prepareTestFiles(dir string, filesCount, linesCount int) []string { return files } + +func TestQLogSeek(t *testing.T) { + testDir := prepareTestDir() + defer 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, _ := ioutil.TempFile(testDir, "*.txt") + _, _ = f.WriteString(d) + defer f.Close() + + q, err := NewQLogFile(f.Name()) + assert.Nil(t, err) + defer q.Close() + + target, _ := time.Parse(time.RFC3339, "2020-08-31T18:44:25.376690873+03:00") + + _, depth, err := q.Seek(target.UnixNano()) + assert.Nil(t, err) + assert.Equal(t, 1, depth) +} diff --git a/querylog/querylog_file.go b/querylog/querylog_file.go index e1544fff..42e1ddf9 100644 --- a/querylog/querylog_file.go +++ b/querylog/querylog_file.go @@ -78,7 +78,7 @@ func (l *queryLog) flushToFile(buffer []*logEntry) error { return err } - log.Debug("ok \"%s\": %v bytes written", filename, n) + log.Debug("querylog: ok \"%s\": %v bytes written", filename, n) return nil } @@ -94,20 +94,46 @@ func (l *queryLog) rotate() error { err := os.Rename(from, to) if err != nil { - log.Error("Failed to rename querylog: %s", err) + log.Error("querylog: failed to rename file: %s", err) return err } - log.Debug("Rotated from %s to %s successfully", from, to) + log.Debug("querylog: renamed %s -> %s", from, to) return nil } +func (l *queryLog) readFileFirstTimeValue() int64 { + f, err := os.Open(l.logFile) + if err != nil { + return -1 + } + defer f.Close() + + buf := make([]byte, 500) + r, err := f.Read(buf) + if err != nil { + return -1 + } + buf = buf[:r] + + val := readJSONValue(string(buf), "T") + t, err := time.Parse(time.RFC3339Nano, val) + if err != nil { + return -1 + } + + log.Debug("querylog: the oldest log entry: %s", val) + return t.Unix() +} + func (l *queryLog) periodicRotate() { - for range time.Tick(time.Duration(l.conf.Interval) * 24 * time.Hour) { - err := l.rotate() - if err != nil { - log.Error("Failed to rotate querylog: %s", err) - // do nothing, continue rotating + intervalSeconds := uint64(l.conf.Interval) * 24 * 60 * 60 + for { + oldest := l.readFileFirstTimeValue() + if uint64(oldest)+intervalSeconds <= uint64(time.Now().Unix()) { + _ = l.rotate() } + + time.Sleep(24 * time.Hour) } }