2019-08-26 11:54:38 +03:00
package querylog
2018-12-05 14:03:41 +03:00
import (
"bytes"
"encoding/json"
2021-10-29 13:43:08 +03:00
"fmt"
2018-12-05 14:03:41 +03:00
"os"
"time"
2021-05-24 17:28:11 +03:00
"github.com/AdguardTeam/golibs/errors"
2019-02-25 16:44:22 +03:00
"github.com/AdguardTeam/golibs/log"
2018-12-05 14:03:41 +03:00
)
2023-04-12 14:48:42 +03:00
// flushLogBuffer flushes the current buffer to file and resets the current
// buffer.
func ( l * queryLog ) flushLogBuffer ( ) ( err error ) {
2019-05-15 13:11:36 +03:00
l . fileFlushLock . Lock ( )
defer l . fileFlushLock . Unlock ( )
2023-04-12 14:48:42 +03:00
var flushBuffer [ ] * logEntry
func ( ) {
l . bufferLock . Lock ( )
defer l . bufferLock . Unlock ( )
flushBuffer = l . buffer
l . buffer = nil
l . flushPending = false
} ( )
err = l . flushToFile ( flushBuffer )
return errors . Annotate ( err , "writing to file: %w" )
2019-02-10 20:47:43 +03:00
}
// flushToFile saves the specified log entries to the query log file
2021-05-24 17:28:11 +03:00
func ( l * queryLog ) flushToFile ( buffer [ ] * logEntry ) ( err error ) {
2018-12-05 14:03:41 +03:00
if len ( buffer ) == 0 {
2023-04-12 14:48:42 +03:00
log . Debug ( "querylog: nothing to write to a file" )
2018-12-05 14:03:41 +03:00
return nil
}
2023-04-12 14:48:42 +03:00
2018-12-05 14:03:41 +03:00
start := time . Now ( )
var b bytes . Buffer
e := json . NewEncoder ( & b )
for _ , entry := range buffer {
2021-05-24 17:28:11 +03:00
err = e . Encode ( entry )
2018-12-05 14:03:41 +03:00
if err != nil {
2019-02-25 16:44:22 +03:00
log . Error ( "Failed to marshal entry: %s" , err )
2021-05-24 17:28:11 +03:00
2018-12-05 14:03:41 +03:00
return err
}
}
elapsed := time . Since ( start )
2019-02-25 16:44:22 +03: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 14:03:41 +03:00
var zb bytes . Buffer
2019-02-10 20:47:43 +03:00
filename := l . logFile
2020-02-20 21:12:51 +03:00
zb = b
2018-12-05 14:03:41 +03:00
2019-09-27 18:58:57 +03:00
l . fileWriteLock . Lock ( )
defer l . fileWriteLock . Unlock ( )
2020-11-30 13:32:58 +03:00
f , err := os . OpenFile ( filename , os . O_WRONLY | os . O_CREATE | os . O_APPEND , 0 o644 )
2018-12-05 14:03:41 +03:00
if err != nil {
2019-02-25 16:44:22 +03:00
log . Error ( "failed to create file \"%s\": %s" , filename , err )
2018-12-05 14:03:41 +03:00
return err
}
2021-05-24 17:28:11 +03:00
defer func ( ) { err = errors . WithDeferred ( err , f . Close ( ) ) } ( )
2018-12-05 14:03:41 +03:00
n , err := f . Write ( zb . Bytes ( ) )
if err != nil {
2019-02-25 16:44:22 +03:00
log . Error ( "Couldn't write to file: %s" , err )
2018-12-05 14:03:41 +03:00
return err
}
2020-09-02 19:42:26 +03:00
log . Debug ( "querylog: ok \"%s\": %v bytes written" , filename , n )
2018-12-05 14:03:41 +03:00
return nil
}
2019-09-27 18:58:57 +03:00
func ( l * queryLog ) rotate ( ) error {
2019-02-10 20:47:43 +03:00
from := l . logFile
to := l . logFile + ".1"
2018-12-05 14:03:41 +03:00
err := os . Rename ( from , to )
if err != nil {
2021-01-27 18:32:13 +03:00
if errors . Is ( err , os . ErrNotExist ) {
2021-10-29 13:43:08 +03:00
log . Debug ( "querylog: no log to rotate" )
2021-01-27 18:32:13 +03:00
return nil
}
2021-10-29 13:43:08 +03:00
return fmt . Errorf ( "failed to rename old file: %w" , err )
2018-12-05 14:03:41 +03:00
}
2021-10-29 13:43:08 +03:00
log . Debug ( "querylog: renamed %s into %s" , from , to )
2021-01-27 18:32:13 +03:00
2018-12-05 14:03:41 +03:00
return nil
}
2021-07-01 18:50:28 +03:00
func ( l * queryLog ) readFileFirstTimeValue ( ) ( first time . Time , err error ) {
var f * os . File
f , err = os . Open ( l . logFile )
2020-09-02 19:42:26 +03:00
if err != nil {
2021-07-01 18:50:28 +03:00
return time . Time { } , err
2020-09-02 19:42:26 +03:00
}
2021-07-01 18:50:28 +03:00
defer func ( ) { err = errors . WithDeferred ( err , f . Close ( ) ) } ( )
buf := make ( [ ] byte , 512 )
var r int
r , err = f . Read ( buf )
2020-09-02 19:42:26 +03:00
if err != nil {
2021-07-01 18:50:28 +03:00
return time . Time { } , err
2020-09-02 19:42:26 +03:00
}
2021-07-01 18:50:28 +03:00
val := readJSONValue ( string ( buf [ : r ] ) , ` "T":" ` )
2020-09-02 19:42:26 +03:00
t , err := time . Parse ( time . RFC3339Nano , val )
if err != nil {
2021-07-01 18:50:28 +03:00
return time . Time { } , err
2020-09-02 19:42:26 +03:00
}
log . Debug ( "querylog: the oldest log entry: %s" , val )
2021-07-01 18:50:28 +03:00
return t , nil
2020-09-02 19:42:26 +03:00
}
2019-09-27 18:58:57 +03:00
func ( l * queryLog ) periodicRotate ( ) {
2021-07-01 18:50:28 +03:00
defer log . OnPanic ( "querylog: rotating" )
2021-11-09 17:17:57 +03:00
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 )
2021-10-29 13:43:08 +03:00
defer rotations . Stop ( )
for range rotations . C {
2021-11-09 17:17:57 +03:00
l . checkAndRotate ( )
}
}
2021-10-29 13:43:08 +03:00
2021-11-09 17:17:57 +03:00
// checkAndRotate rotates log files if those are older than the specified
// rotation interval.
func ( l * queryLog ) checkAndRotate ( ) {
2023-04-12 14:48:42 +03:00
var rotationIvl time . Duration
func ( ) {
l . confMu . RLock ( )
defer l . confMu . RUnlock ( )
rotationIvl = l . conf . RotationIvl
} ( )
2023-02-15 16:53:29 +03:00
2021-11-09 17:17:57 +03:00
oldest , err := l . readFileFirstTimeValue ( )
if err != nil && ! errors . Is ( err , os . ErrNotExist ) {
log . Error ( "querylog: reading oldest record for rotation: %s" , err )
2021-07-01 18:50:28 +03:00
2021-11-09 17:17:57 +03:00
return
}
2021-10-29 13:43:08 +03:00
2023-04-12 14:48:42 +03:00
if rotTime , now := oldest . Add ( rotationIvl ) , time . Now ( ) ; rotTime . After ( now ) {
2021-11-09 17:17:57 +03:00
log . Debug (
"querylog: %s <= %s, not rotating" ,
now . Format ( time . RFC3339 ) ,
2023-04-12 14:48:42 +03:00
rotTime . Format ( time . RFC3339 ) ,
2021-11-09 17:17:57 +03:00
)
2021-10-29 13:43:08 +03:00
2021-11-09 17:17:57 +03:00
return
}
2021-10-29 13:43:08 +03:00
2021-11-09 17:17:57 +03:00
err = l . rotate ( )
if err != nil {
log . Error ( "querylog: rotating: %s" , err )
2020-09-02 19:42:26 +03:00
2021-11-09 17:17:57 +03:00
return
2018-12-05 14:03:41 +03:00
}
2021-11-09 17:17:57 +03:00
log . Debug ( "querylog: rotated successfully" )
2018-12-05 14:03:41 +03:00
}