badguardhome/querylog/querylog_file.go

package querylog

import (
	"bytes"
	"compress/gzip"
	"encoding/json"
	"fmt"
	"os"
	"sync"
	"time"

	"github.com/AdguardTeam/golibs/log"
	"github.com/go-test/deep"
	"github.com/miekg/dns"
)

var (
	fileWriteLock sync.Mutex
)

const enableGzip = false

// flushLogBuffer flushes the current buffer to file and resets the current buffer
func (l *queryLog) flushLogBuffer(fullFlush bool) error {
	l.fileFlushLock.Lock()
	defer l.fileFlushLock.Unlock()

	// flush remainder to file
	l.logBufferLock.Lock()
	needFlush := len(l.logBuffer) >= logBufferCap
	if !needFlush && !fullFlush {
		l.logBufferLock.Unlock()
		return nil
	}
	flushBuffer := l.logBuffer
	l.logBuffer = nil
	l.flushPending = false
	l.logBufferLock.Unlock()
	err := l.flushToFile(flushBuffer)
	if err != nil {
		log.Error("Saving querylog to file failed: %s", err)
		return err
	}
	return nil
}

// flushToFile saves the specified log entries to the query log file
func (l *queryLog) flushToFile(buffer []*logEntry) error {
	if len(buffer) == 0 {
		log.Debug("querylog: there's 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)))

	err := checkBuffer(buffer, b)
	if err != nil {
		log.Error("failed to check buffer: %s", err)
		return err
	}

	var zb bytes.Buffer
	filename := l.logFile

	// gzip enabled?
	if enableGzip {
		filename += ".gz"

		zw := gzip.NewWriter(&zb)
		zw.Name = l.logFile
		zw.ModTime = time.Now()

		_, err = zw.Write(b.Bytes())
		if err != nil {
			log.Error("Couldn't compress to gzip: %s", err)
			zw.Close()
			return err
		}

		if err = zw.Close(); err != nil {
			log.Error("Couldn't close gzip writer: %s", err)
			return err
		}
	} else {
		zb = b
	}

	fileWriteLock.Lock()
	defer fileWriteLock.Unlock()
	f, err := os.OpenFile(filename, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644)
	if err != nil {
		log.Error("failed to create file \"%s\": %s", filename, err)
		return err
	}
	defer f.Close()

	n, err := f.Write(zb.Bytes())
	if err != nil {
		log.Error("Couldn't write to file: %s", err)
		return err
	}

	log.Debug("ok \"%s\": %v bytes written", filename, n)

	return nil
}

func checkBuffer(buffer []*logEntry, b bytes.Buffer) error {
	l := len(buffer)
	d := json.NewDecoder(&b)

	i := 0
	for d.More() {
		entry := &logEntry{}
		err := d.Decode(entry)
		if err != nil {
			log.Error("Failed to decode: %s", err)
			return err
		}
		if diff := deep.Equal(entry, buffer[i]); diff != nil {
			log.Error("decoded buffer differs: %s", diff)
			return fmt.Errorf("decoded buffer differs: %s", diff)
		}
		i++
	}
	if i != l {
		err := fmt.Errorf("check fail: %d vs %d entries", l, i)
		log.Error("%v", err)
		return err
	}
	log.Debug("check ok: %d entries", i)

	return nil
}

func (l *queryLog) rotateQueryLog() error {
	from := l.logFile
	to := l.logFile + ".1"

	if enableGzip {
		from = l.logFile + ".gz"
		to = l.logFile + ".gz.1"
	}

	if _, err := os.Stat(from); os.IsNotExist(err) {
		// do nothing, file doesn't exist
		return nil
	}

	err := os.Rename(from, to)
	if err != nil {
		log.Error("Failed to rename querylog: %s", err)
		return err
	}

	log.Debug("Rotated from %s to %s successfully", from, to)

	return nil
}

func (l *queryLog) periodicQueryLogRotate() {
	for range time.Tick(time.Duration(l.conf.Interval) * time.Hour) {
		err := l.rotateQueryLog()
		if err != nil {
			log.Error("Failed to rotate querylog: %s", err)
			// do nothing, continue rotating
		}
	}
}

// Reader is the DB reader context
type Reader struct {
	f   *os.File
	jd  *json.Decoder
	now time.Time
	ql  *queryLog

	files []string
	ifile int

	count uint64 // returned elements counter
}

// OpenReader locks the file and returns reader object or nil on error
func (l *queryLog) OpenReader() *Reader {
	r := Reader{}
	r.ql = l
	r.now = time.Now()

	return &r
}

// Close closes the reader
func (r *Reader) Close() {
	elapsed := time.Since(r.now)
	var perunit time.Duration
	if r.count > 0 {
		perunit = elapsed / time.Duration(r.count)
	}
	log.Debug("querylog: read %d entries in %v, %v/entry",
		r.count, elapsed, perunit)

	if r.f != nil {
		r.f.Close()
	}
}

// BeginRead starts reading
func (r *Reader) BeginRead() {
	r.files = []string{
		r.ql.logFile,
		r.ql.logFile + ".1",
	}
}

// Next returns the next entry or nil if reading is finished
func (r *Reader) Next() *logEntry { // nolint
	var err error
	for {
		// open file if needed
		if r.f == nil {
			if r.ifile == len(r.files) {
				return nil
			}
			fn := r.files[r.ifile]
			r.f, err = os.Open(fn)
			if err != nil {
				log.Error("Failed to open file \"%s\": %s", fn, err)
				r.ifile++
				continue
			}
		}

		// open decoder if needed
		if r.jd == nil {
			r.jd = json.NewDecoder(r.f)
		}

		// check if there's data
		if !r.jd.More() {
			r.jd = nil
			r.f.Close()
			r.f = nil
			r.ifile++
			continue
		}

		// read data
		var entry logEntry
		err = r.jd.Decode(&entry)
		if err != nil {
			log.Error("Failed to decode: %s", err)
			// next entry can be fine, try more
			continue
		}
		r.count++
		return &entry
	}
}

// Total returns the total number of items
func (r *Reader) Total() int {
	return 0
}

// Fill cache from file
func (l *queryLog) fillFromFile() {
	now := time.Now()
	validFrom := now.Unix() - int64(l.conf.Interval*60*60)
	r := l.OpenReader()
	if r == nil {
		return
	}

	r.BeginRead()

	for {
		entry := r.Next()
		if entry == nil {
			break
		}

		if entry.Time.Unix() < validFrom {
			continue
		}

		if len(entry.Question) == 0 {
			log.Printf("entry question is absent, skipping")
			continue
		}

		if entry.Time.After(now) {
			log.Printf("t %v vs %v is in the future, ignoring", entry.Time, now)
			continue
		}

		q := new(dns.Msg)
		if err := q.Unpack(entry.Question); err != nil {
			log.Printf("failed to unpack dns message question: %s", err)
			continue
		}

		if len(q.Question) != 1 {
			log.Printf("malformed dns message, has no questions, skipping")
			continue
		}

		l.lock.Lock()
		l.cache = append(l.cache, entry)
		if len(l.cache) > queryLogSize {
			toremove := len(l.cache) - queryLogSize
			l.cache = l.cache[toremove:]
		}
		l.lock.Unlock()
	}

	r.Close()
}