2018-12-05 11:03:41 +00:00
package dnsforward
import (
"bytes"
"compress/gzip"
"encoding/json"
"fmt"
"os"
"sync"
"time"
2019-02-25 13:44:22 +00:00
"github.com/AdguardTeam/golibs/log"
2018-12-05 11:03:41 +00:00
"github.com/go-test/deep"
)
var (
fileWriteLock sync . Mutex
)
const enableGzip = false
2019-02-11 11:22:36 +00:00
// flushLogBuffer flushes the current buffer to file and resets the current buffer
2019-05-15 11:11:36 +01:00
func ( l * queryLog ) flushLogBuffer ( fullFlush bool ) error {
l . fileFlushLock . Lock ( )
defer l . fileFlushLock . Unlock ( )
2019-02-10 17:47:43 +00:00
// flush remainder to file
l . logBufferLock . Lock ( )
2019-05-15 11:11:36 +01:00
needFlush := len ( l . logBuffer ) >= logBufferCap
if ! needFlush && ! fullFlush {
l . logBufferLock . Unlock ( )
return nil
}
2019-02-10 17:47:43 +00:00
flushBuffer := l . logBuffer
l . logBuffer = nil
2019-05-15 11:11:36 +01:00
l . flushPending = false
2019-02-10 17:47:43 +00:00
l . logBufferLock . Unlock ( )
err := l . flushToFile ( flushBuffer )
if err != nil {
2019-02-25 13:44:22 +00:00
log . Error ( "Saving querylog to file failed: %s" , err )
2019-02-10 17:47:43 +00:00
return err
}
return nil
}
// flushToFile saves the specified log entries to the query log file
func ( l * queryLog ) flushToFile ( buffer [ ] * logEntry ) error {
2018-12-05 11:03:41 +00:00
if len ( buffer ) == 0 {
2019-05-08 08:43:47 +01:00
log . Debug ( "querylog: there's nothing to write to a file" )
2018-12-05 11:03:41 +00:00
return nil
}
start := time . Now ( )
var b bytes . Buffer
e := json . NewEncoder ( & b )
for _ , entry := range buffer {
err := e . Encode ( entry )
if err != nil {
2019-02-25 13:44:22 +00:00
log . Error ( "Failed to marshal entry: %s" , err )
2018-12-05 11:03:41 +00:00
return err
}
}
elapsed := time . Since ( start )
2019-02-25 13:44:22 +00:00
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 ) ) )
2018-12-05 11:03:41 +00:00
err := checkBuffer ( buffer , b )
if err != nil {
2019-02-25 13:44:22 +00:00
log . Error ( "failed to check buffer: %s" , err )
2018-12-05 11:03:41 +00:00
return err
}
var zb bytes . Buffer
2019-02-10 17:47:43 +00:00
filename := l . logFile
2018-12-05 11:03:41 +00:00
// gzip enabled?
if enableGzip {
filename += ".gz"
zw := gzip . NewWriter ( & zb )
2019-02-10 17:47:43 +00:00
zw . Name = l . logFile
2018-12-05 11:03:41 +00:00
zw . ModTime = time . Now ( )
_ , err = zw . Write ( b . Bytes ( ) )
if err != nil {
2019-02-25 13:44:22 +00:00
log . Error ( "Couldn't compress to gzip: %s" , err )
2018-12-05 11:03:41 +00:00
zw . Close ( )
return err
}
if err = zw . Close ( ) ; err != nil {
2019-02-25 13:44:22 +00:00
log . Error ( "Couldn't close gzip writer: %s" , err )
2018-12-05 11:03:41 +00:00
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 {
2019-02-25 13:44:22 +00:00
log . Error ( "failed to create file \"%s\": %s" , filename , err )
2018-12-05 11:03:41 +00:00
return err
}
defer f . Close ( )
n , err := f . Write ( zb . Bytes ( ) )
if err != nil {
2019-02-25 13:44:22 +00:00
log . Error ( "Couldn't write to file: %s" , err )
2018-12-05 11:03:41 +00:00
return err
}
2019-02-25 13:44:22 +00:00
log . Debug ( "ok \"%s\": %v bytes written" , filename , n )
2018-12-05 11:03:41 +00:00
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 {
2019-02-25 13:44:22 +00:00
log . Error ( "Failed to decode: %s" , err )
2018-12-05 11:03:41 +00:00
return err
}
if diff := deep . Equal ( entry , buffer [ i ] ) ; diff != nil {
2019-02-25 13:44:22 +00:00
log . Error ( "decoded buffer differs: %s" , diff )
2018-12-05 11:03:41 +00:00
return fmt . Errorf ( "decoded buffer differs: %s" , diff )
}
i ++
}
if i != l {
err := fmt . Errorf ( "check fail: %d vs %d entries" , l , i )
2019-02-25 13:44:22 +00:00
log . Error ( "%v" , err )
2018-12-05 11:03:41 +00:00
return err
}
2019-02-25 13:44:22 +00:00
log . Debug ( "check ok: %d entries" , i )
2018-12-05 11:03:41 +00:00
return nil
}
2019-02-10 17:47:43 +00:00
func ( l * queryLog ) rotateQueryLog ( ) error {
from := l . logFile
to := l . logFile + ".1"
2018-12-05 11:03:41 +00:00
if enableGzip {
2019-02-10 17:47:43 +00:00
from = l . logFile + ".gz"
to = l . logFile + ".gz.1"
2018-12-05 11:03:41 +00:00
}
if _ , err := os . Stat ( from ) ; os . IsNotExist ( err ) {
// do nothing, file doesn't exist
return nil
}
err := os . Rename ( from , to )
if err != nil {
2019-02-25 13:44:22 +00:00
log . Error ( "Failed to rename querylog: %s" , err )
2018-12-05 11:03:41 +00:00
return err
}
2019-02-25 13:44:22 +00:00
log . Debug ( "Rotated from %s to %s successfully" , from , to )
2018-12-05 11:03:41 +00:00
return nil
}
2019-02-10 17:47:43 +00:00
func ( l * queryLog ) periodicQueryLogRotate ( ) {
2018-12-05 11:03:41 +00:00
for range time . Tick ( queryLogRotationPeriod ) {
2019-02-10 17:47:43 +00:00
err := l . rotateQueryLog ( )
2018-12-05 11:03:41 +00:00
if err != nil {
2019-02-25 13:44:22 +00:00
log . Error ( "Failed to rotate querylog: %s" , err )
2018-12-05 11:03:41 +00:00
// do nothing, continue rotating
}
}
}
2019-02-10 17:47:43 +00:00
func ( l * queryLog ) genericLoader ( onEntry func ( entry * logEntry ) error , needMore func ( ) bool , timeWindow time . Duration ) error {
2018-12-05 11:03:41 +00:00
now := time . Now ( )
// read from querylog files, try newest file first
2019-01-24 17:11:01 +00:00
var files [ ] string
2018-12-05 11:03:41 +00:00
if enableGzip {
files = [ ] string {
2019-02-10 17:47:43 +00:00
l . logFile + ".gz" ,
l . logFile + ".gz.1" ,
2018-12-05 11:03:41 +00:00
}
} else {
files = [ ] string {
2019-02-10 17:47:43 +00:00
l . logFile ,
l . logFile + ".1" ,
2018-12-05 11:03:41 +00:00
}
}
// read from all files
for _ , file := range files {
if ! needMore ( ) {
break
}
if _ , err := os . Stat ( file ) ; os . IsNotExist ( err ) {
// do nothing, file doesn't exist
continue
}
f , err := os . Open ( file )
if err != nil {
2019-02-25 13:44:22 +00:00
log . Error ( "Failed to open file \"%s\": %s" , file , err )
2018-12-05 11:03:41 +00:00
// try next file
continue
}
defer f . Close ( )
var d * json . Decoder
if enableGzip {
zr , err := gzip . NewReader ( f )
if err != nil {
2019-02-25 13:44:22 +00:00
log . Error ( "Failed to create gzip reader: %s" , err )
2018-12-05 11:03:41 +00:00
continue
}
defer zr . Close ( )
d = json . NewDecoder ( zr )
} else {
d = json . NewDecoder ( f )
}
i := 0
over := 0
max := 10000 * time . Second
var sum time . Duration
// entries on file are in oldest->newest order
// we want maxLen newest
for d . More ( ) {
if ! needMore ( ) {
break
}
var entry logEntry
err := d . Decode ( & entry )
if err != nil {
2019-02-25 13:44:22 +00:00
log . Error ( "Failed to decode: %s" , err )
2018-12-05 11:03:41 +00:00
// next entry can be fine, try more
continue
}
if now . Sub ( entry . Time ) > timeWindow {
2018-12-29 14:23:42 +00:00
// log.Tracef("skipping entry") // debug logging
2018-12-05 11:03:41 +00:00
continue
}
if entry . Elapsed > max {
over ++
} else {
sum += entry . Elapsed
}
i ++
err = onEntry ( & entry )
if err != nil {
return err
}
}
elapsed := time . Since ( now )
var perunit time . Duration
var avg time . Duration
if i > 0 {
perunit = elapsed / time . Duration ( i )
avg = sum / time . Duration ( i )
}
2019-02-25 13:44:22 +00:00
log . Debug ( "file \"%s\": read %d entries in %v, %v/entry, %v over %v, %v avg" , file , i , elapsed , perunit , over , max , avg )
2018-12-05 11:03:41 +00:00
}
return nil
}