Merge: dns query log: robust file flushing mechanism #708

* commit 'd5f6dd1a46446ebb440811691a6ee8ce2443320d':
  - dns query log: robust file flushing mechanism
  * improve logging

app.go

@@ -372,6 +372,7 @@ func cleanupAlways() {
 	if len(pidFileName) != 0 {
 		os.Remove(pidFileName)
 	}
+	log.Info("Stopped")
 }
 
 // command-line arguments

dnsforward/dnsforward.go

@@ -236,7 +236,7 @@ func (s *Server) stopInternal() error {
 	}
 
 	// flush remainder to file
-	return s.queryLog.flushLogBuffer()
+	return s.queryLog.flushLogBuffer(true)
 }
 
 // IsRunning returns true if the DNS server is running

dnsforward/querylog.go

@@ -30,6 +30,8 @@ type queryLog struct {
 
 	logBufferLock sync.RWMutex
 	logBuffer     []*logEntry
+	fileFlushLock sync.Mutex // synchronize a file-flushing goroutine and main thread
+	flushPending  bool       // don't start another goroutine while the previous one is still running
 
 	queryLogCache []*logEntry
 	queryLogLock  sync.RWMutex
@@ -91,13 +93,15 @@ func (l *queryLog) logRequest(question *dns.Msg, answer *dns.Msg, result *dnsfil
 		IP:       ip,
 		Upstream: upstream,
 	}
-	var flushBuffer []*logEntry
 
 	l.logBufferLock.Lock()
 	l.logBuffer = append(l.logBuffer, &entry)
-	if len(l.logBuffer) >= logBufferCap {
-		flushBuffer = l.logBuffer
-		l.logBuffer = nil
+	needFlush := false
+	if !l.flushPending {
+		needFlush = len(l.logBuffer) >= logBufferCap
+		if needFlush {
+			l.flushPending = true
+		}
 	}
 	l.logBufferLock.Unlock()
 	l.queryLogLock.Lock()
@@ -116,15 +120,10 @@ func (l *queryLog) logRequest(question *dns.Msg, answer *dns.Msg, result *dnsfil
 	}
 
 	// if buffer needs to be flushed to disk, do it now
-	if len(flushBuffer) > 0 {
+	if needFlush {
 		// write to file
 		// do it in separate goroutine -- we are stalling DNS response this whole time
-		go func() {
-			err := l.flushToFile(flushBuffer)
-			if err != nil {
-				log.Printf("Failed to flush the query log: %s", err)
-			}
-		}()
+		go l.flushLogBuffer(false)
 	}
 
 	return &entry

dnsforward/querylog_file.go

@@ -20,11 +20,20 @@ var (
 const enableGzip = false
 
 // flushLogBuffer flushes the current buffer to file and resets the current buffer
-func (l *queryLog) flushLogBuffer() error {
+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 {
@@ -37,6 +46,7 @@ func (l *queryLog) flushLogBuffer() error {
 // 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()