AdGuardHome/internal/querylog/querylogfile.go
Ainar Garipov 3575aa0570 Pull request 1796: 5661-opt-more-lock
Updates #5661.

Squashed commit of the following:

commit 0a1425df0ea1278c73ac88cbee053897d3daaf1b
Author: Ainar Garipov <A.Garipov@AdGuard.COM>
Date:   Fri Mar 31 18:31:19 2023 +0300

    querylog: opt locks more
2023-03-31 18:44:51 +03:00

198 lines
4.1 KiB
Go

package querylog
import (
"bytes"
"encoding/json"
"fmt"
"os"
"time"
"github.com/AdguardTeam/golibs/errors"
"github.com/AdguardTeam/golibs/log"
)
// flushLogBuffer flushes the current buffer to file and resets the current
// buffer.
func (l *queryLog) flushLogBuffer(fullFlush bool) (err error) {
if !l.conf.FileEnabled {
return nil
}
l.fileFlushLock.Lock()
defer l.fileFlushLock.Unlock()
// Flush the remainder to file.
var flushBuffer []*logEntry
needFlush := fullFlush
func() {
l.bufferLock.Lock()
defer l.bufferLock.Unlock()
needFlush = needFlush || len(l.buffer) >= int(l.conf.MemSize)
if needFlush {
flushBuffer = l.buffer
l.buffer = nil
l.flushPending = false
}
}()
if !needFlush {
return nil
}
err = l.flushToFile(flushBuffer)
if err != nil {
log.Error("querylog: writing to file: %s", err)
return err
}
return nil
}
// flushToFile saves the specified log entries to the query log file
func (l *queryLog) flushToFile(buffer []*logEntry) (err error) {
if len(buffer) == 0 {
log.Debug("querylog: nothing to write to a file")
return nil
}
start := time.Now()
var b bytes.Buffer
e := json.NewEncoder(&b)
for _, entry := range buffer {
err = e.Encode(entry)
if err != nil {
log.Error("Failed to marshal entry: %s", err)
return err
}
}
elapsed := time.Since(start)
log.Debug("%d elements serialized via json in %v: %d kB, %v/entry, %v/entry", len(buffer), elapsed, b.Len()/1024, float64(b.Len())/float64(len(buffer)), elapsed/time.Duration(len(buffer)))
var zb bytes.Buffer
filename := l.logFile
zb = b
l.fileWriteLock.Lock()
defer l.fileWriteLock.Unlock()
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
}
defer func() { err = errors.WithDeferred(err, f.Close()) }()
n, err := f.Write(zb.Bytes())
if err != nil {
log.Error("Couldn't write to file: %s", err)
return err
}
log.Debug("querylog: ok \"%s\": %v bytes written", filename, n)
return nil
}
func (l *queryLog) rotate() error {
from := l.logFile
to := l.logFile + ".1"
err := os.Rename(from, to)
if err != nil {
if errors.Is(err, os.ErrNotExist) {
log.Debug("querylog: no log to rotate")
return nil
}
return fmt.Errorf("failed to rename old file: %w", err)
}
log.Debug("querylog: renamed %s into %s", from, to)
return nil
}
func (l *queryLog) readFileFirstTimeValue() (first time.Time, err error) {
var f *os.File
f, err = os.Open(l.logFile)
if err != nil {
return time.Time{}, err
}
defer func() { err = errors.WithDeferred(err, f.Close()) }()
buf := make([]byte, 512)
var r int
r, err = f.Read(buf)
if err != nil {
return time.Time{}, err
}
val := readJSONValue(string(buf[:r]), `"T":"`)
t, err := time.Parse(time.RFC3339Nano, val)
if err != nil {
return time.Time{}, err
}
log.Debug("querylog: the oldest log entry: %s", val)
return t, nil
}
func (l *queryLog) periodicRotate() {
defer log.OnPanic("querylog: rotating")
l.checkAndRotate()
// rotationCheckIvl is the period of time between checking the need for
// rotating log files. It's smaller of any available rotation interval to
// increase time accuracy.
//
// See https://github.com/AdguardTeam/AdGuardHome/issues/3823.
const rotationCheckIvl = 1 * time.Hour
rotations := time.NewTicker(rotationCheckIvl)
defer rotations.Stop()
for range rotations.C {
l.checkAndRotate()
}
}
// checkAndRotate rotates log files if those are older than the specified
// rotation interval.
func (l *queryLog) checkAndRotate() {
l.confMu.RLock()
defer l.confMu.RUnlock()
oldest, err := l.readFileFirstTimeValue()
if err != nil && !errors.Is(err, os.ErrNotExist) {
log.Error("querylog: reading oldest record for rotation: %s", err)
return
}
if rot, now := oldest.Add(l.conf.RotationIvl), time.Now(); rot.After(now) {
log.Debug(
"querylog: %s <= %s, not rotating",
now.Format(time.RFC3339),
rot.Format(time.RFC3339),
)
return
}
err = l.rotate()
if err != nil {
log.Error("querylog: rotating: %s", err)
return
}
log.Debug("querylog: rotated successfully")
}