all: sync with master

internal/querylog/querylogfile.go

@@ -2,6 +2,7 @@ package querylog
 
 import (
 	"bytes"
+	"context"
 	"encoding/json"
 	"fmt"
 	"os"
@@ -9,28 +10,30 @@ import (
 
 	"github.com/AdguardTeam/AdGuardHome/internal/aghos"
 	"github.com/AdguardTeam/golibs/errors"
-	"github.com/AdguardTeam/golibs/log"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
+	"github.com/c2h5oh/datasize"
 )
 
 // flushLogBuffer flushes the current buffer to file and resets the current
 // buffer.
-func (l *queryLog) flushLogBuffer() (err error) {
+func (l *queryLog) flushLogBuffer(ctx context.Context) (err error) {
 	defer func() { err = errors.Annotate(err, "flushing log buffer: %w") }()
+
 	l.fileFlushLock.Lock()
 	defer l.fileFlushLock.Unlock()
 
-	b, err := l.encodeEntries()
+	b, err := l.encodeEntries(ctx)
 	if err != nil {
 		// Don't wrap the error since it's informative enough as is.
 		return err
 	}
 
-	return l.flushToFile(b)
+	return l.flushToFile(ctx, b)
 }
 
 // encodeEntries returns JSON encoded log entries, logs estimated time, clears
 // the log buffer.
-func (l *queryLog) encodeEntries() (b *bytes.Buffer, err error) {
+func (l *queryLog) encodeEntries(ctx context.Context) (b *bytes.Buffer, err error) {
 	l.bufferLock.Lock()
 	defer l.bufferLock.Unlock()
 
@@ -55,8 +58,17 @@ func (l *queryLog) encodeEntries() (b *bytes.Buffer, err error) {
 		return nil, err
 	}
 
+	size := b.Len()
 	elapsed := time.Since(start)
-	log.Debug("%d elements serialized via json in %v: %d kB, %v/entry, %v/entry", bufLen, elapsed, b.Len()/1024, float64(b.Len())/float64(bufLen), elapsed/time.Duration(bufLen))
+	l.logger.DebugContext(
+		ctx,
+		"serialized elements via json",
+		"count", bufLen,
+		"elapsed", elapsed,
+		"size", datasize.ByteSize(size),
+		"size_per_entry", datasize.ByteSize(float64(size)/float64(bufLen)),
+		"time_per_entry", elapsed/time.Duration(bufLen),
+	)
 
 	l.buffer.Clear()
 	l.flushPending = false
@@ -65,13 +77,13 @@ func (l *queryLog) encodeEntries() (b *bytes.Buffer, err error) {
 }
 
 // flushToFile saves the encoded log entries to the query log file.
-func (l *queryLog) flushToFile(b *bytes.Buffer) (err error) {
+func (l *queryLog) flushToFile(ctx context.Context, b *bytes.Buffer) (err error) {
 	l.fileWriteLock.Lock()
 	defer l.fileWriteLock.Unlock()
 
 	filename := l.logFile
 
-	f, err := aghos.OpenFile(filename, os.O_WRONLY|os.O_CREATE|os.O_APPEND, aghos.DefaultPermFile)
+	f, err := os.OpenFile(filename, os.O_WRONLY|os.O_CREATE|os.O_APPEND, aghos.DefaultPermFile)
 	if err != nil {
 		return fmt.Errorf("creating file %q: %w", filename, err)
 	}
@@ -83,19 +95,19 @@ func (l *queryLog) flushToFile(b *bytes.Buffer) (err error) {
 		return fmt.Errorf("writing to file %q: %w", filename, err)
 	}
 
-	log.Debug("querylog: ok %q: %v bytes written", filename, n)
+	l.logger.DebugContext(ctx, "flushed to file", "file", filename, "size", datasize.ByteSize(n))
 
 	return nil
 }
 
-func (l *queryLog) rotate() error {
+func (l *queryLog) rotate(ctx context.Context) 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")
+			l.logger.DebugContext(ctx, "no log to rotate")
 
 			return nil
 		}
@@ -103,12 +115,12 @@ func (l *queryLog) rotate() error {
 		return fmt.Errorf("failed to rename old file: %w", err)
 	}
 
-	log.Debug("querylog: renamed %s into %s", from, to)
+	l.logger.DebugContext(ctx, "renamed log file", "from", from, "to", to)
 
 	return nil
 }
 
-func (l *queryLog) readFileFirstTimeValue() (first time.Time, err error) {
+func (l *queryLog) readFileFirstTimeValue(ctx context.Context) (first time.Time, err error) {
 	var f *os.File
 	f, err = os.Open(l.logFile)
 	if err != nil {
@@ -130,15 +142,15 @@ func (l *queryLog) readFileFirstTimeValue() (first time.Time, err error) {
 		return time.Time{}, err
 	}
 
-	log.Debug("querylog: the oldest log entry: %s", val)
+	l.logger.DebugContext(ctx, "oldest log entry", "entry_time", val)
 
 	return t, nil
 }
 
-func (l *queryLog) periodicRotate() {
-	defer log.OnPanic("querylog: rotating")
+func (l *queryLog) periodicRotate(ctx context.Context) {
+	defer slogutil.RecoverAndLog(ctx, l.logger)
 
-	l.checkAndRotate()
+	l.checkAndRotate(ctx)
 
 	// rotationCheckIvl is the period of time between checking the need for
 	// rotating log files.  It's smaller of any available rotation interval to
@@ -151,13 +163,13 @@ func (l *queryLog) periodicRotate() {
 	defer rotations.Stop()
 
 	for range rotations.C {
-		l.checkAndRotate()
+		l.checkAndRotate(ctx)
 	}
 }
 
 // checkAndRotate rotates log files if those are older than the specified
 // rotation interval.
-func (l *queryLog) checkAndRotate() {
+func (l *queryLog) checkAndRotate(ctx context.Context) {
 	var rotationIvl time.Duration
 	func() {
 		l.confMu.RLock()
@@ -166,29 +178,30 @@ func (l *queryLog) checkAndRotate() {
 		rotationIvl = l.conf.RotationIvl
 	}()
 
-	oldest, err := l.readFileFirstTimeValue()
+	oldest, err := l.readFileFirstTimeValue(ctx)
 	if err != nil && !errors.Is(err, os.ErrNotExist) {
-		log.Error("querylog: reading oldest record for rotation: %s", err)
+		l.logger.ErrorContext(ctx, "reading oldest record for rotation", slogutil.KeyError, err)
 
 		return
 	}
 
 	if rotTime, now := oldest.Add(rotationIvl), time.Now(); rotTime.After(now) {
-		log.Debug(
-			"querylog: %s <= %s, not rotating",
-			now.Format(time.RFC3339),
-			rotTime.Format(time.RFC3339),
+		l.logger.DebugContext(
+			ctx,
+			"not rotating",
+			"now", now.Format(time.RFC3339),
+			"rotate_time", rotTime.Format(time.RFC3339),
 		)
 
 		return
 	}
 
-	err = l.rotate()
+	err = l.rotate(ctx)
 	if err != nil {
-		log.Error("querylog: rotating: %s", err)
+		l.logger.ErrorContext(ctx, "rotating", slogutil.KeyError, err)
 
 		return
 	}
 
-	log.Debug("querylog: rotated successfully")
+	l.logger.DebugContext(ctx, "rotated successfully")
 }