Merge pull request #21301 from cpuguy83/cleaner_file_log

Fixes some issues with jsonfile write/read

daemon/logger/jsonfilelog/read.go

@@ -54,7 +54,6 @@ func (l *JSONFileLogger) readLogs(logWatcher *logger.LogWatcher, config logger.R
 			}
 			continue
 		}
-		defer f.Close()
 		files = append(files, f)
 	}
 
@@ -63,15 +62,19 @@ func (l *JSONFileLogger) readLogs(logWatcher *logger.LogWatcher, config logger.R
 		logWatcher.Err <- err
 		return
 	}
-	defer latestFile.Close()
-
-	files = append(files, latestFile)
-	tailer := ioutils.MultiReadSeeker(files...)
 
 	if config.Tail != 0 {
+		tailer := ioutils.MultiReadSeeker(append(files, latestFile)...)
 		tailFile(tailer, logWatcher, config.Tail, config.Since)
 	}
 
+	// close all the rotated files
+	for _, f := range files {
+		if err := f.(io.Closer).Close(); err != nil {
+			logrus.WithField("logger", "json-file").Warnf("error closing tailed log file: %v", err)
+		}
+	}
+
 	if !config.Follow {
 		return
 	}
@@ -129,7 +132,23 @@ func followLogs(f *os.File, logWatcher *logger.LogWatcher, notifyRotate chan int
 	if err != nil {
 		logWatcher.Err <- err
 	}
-	defer fileWatcher.Close()
+	defer func() {
+		f.Close()
+		fileWatcher.Close()
+	}()
+	name := f.Name()
+
+	if err := fileWatcher.Add(name); err != nil {
+		logrus.WithField("logger", "json-file").Warnf("falling back to file poller due to error: %v", err)
+		fileWatcher.Close()
+		fileWatcher = filenotify.NewPollingWatcher()
+
+		if err := fileWatcher.Add(name); err != nil {
+			logrus.Debugf("error watching log file for modifications: %v", err)
+			logWatcher.Err <- err
+			return
+		}
+	}
 
 	var retries int
 	for {
@@ -153,42 +172,42 @@ func followLogs(f *os.File, logWatcher *logger.LogWatcher, notifyRotate chan int
 					retries++
 					continue
 				}
-				logWatcher.Err <- err
+
 				return
 			}
 
-			logrus.WithField("logger", "json-file").Debugf("waiting for events")
-			if err := fileWatcher.Add(f.Name()); err != nil {
-				logrus.WithField("logger", "json-file").Warn("falling back to file poller")
-				fileWatcher.Close()
-				fileWatcher = filenotify.NewPollingWatcher()
-				if err := fileWatcher.Add(f.Name()); err != nil {
-					logrus.Errorf("error watching log file for modifications: %v", err)
-					logWatcher.Err <- err
-				}
-			}
 			select {
 			case <-fileWatcher.Events():
 				dec = json.NewDecoder(f)
-				fileWatcher.Remove(f.Name())
 				continue
 			case <-fileWatcher.Errors():
-				fileWatcher.Remove(f.Name())
 				logWatcher.Err <- err
 				return
 			case <-logWatcher.WatchClose():
-				fileWatcher.Remove(f.Name())
+				fileWatcher.Remove(name)
 				return
 			case <-notifyRotate:
-				f, err = os.Open(f.Name())
+				f.Close()
+				fileWatcher.Remove(name)
+
+				// retry when the file doesn't exist
+				for retries := 0; retries <= 5; retries++ {
+					f, err = os.Open(name)
+					if err == nil || !os.IsNotExist(err) {
+						break
+					}
+				}
+
+				if err = fileWatcher.Add(name); err != nil {
+					logWatcher.Err <- err
+					return
+				}
 				if err != nil {
 					logWatcher.Err <- err
 					return
 				}
 
 				dec = json.NewDecoder(f)
-				fileWatcher.Remove(f.Name())
-				fileWatcher.Add(f.Name())
 				continue
 			}
 		}

daemon/logger/loggerutils/rotatefilewriter.go

@@ -87,33 +87,17 @@ func rotate(name string, maxFiles int) error {
 	for i := maxFiles - 1; i > 1; i-- {
 		toPath := name + "." + strconv.Itoa(i)
 		fromPath := name + "." + strconv.Itoa(i-1)
-		if err := backup(fromPath, toPath); err != nil && !os.IsNotExist(err) {
+		if err := os.Rename(fromPath, toPath); err != nil && !os.IsNotExist(err) {
 			return err
 		}
 	}
 
-	if err := backup(name, name+".1"); err != nil {
+	if err := os.Rename(name, name+".1"); err != nil && !os.IsNotExist(err) {
 		return err
 	}
 	return nil
 }
 
-// backup renames a file from fromPath to toPath
-func backup(fromPath, toPath string) error {
-	if _, err := os.Stat(fromPath); os.IsNotExist(err) {
-		return err
-	}
-
-	if _, err := os.Stat(toPath); !os.IsNotExist(err) {
-		err := os.Remove(toPath)
-		if err != nil {
-			return err
-		}
-	}
-
-	return os.Rename(fromPath, toPath)
-}
-
 // LogPath returns the location the given writer logs to.
 func (w *RotateFileWriter) LogPath() string {
 	return w.f.Name()

integration-cli/docker_cli_logs_bench_test.go

@@ -0,0 +1,32 @@
+package main
+
+import (
+	"fmt"
+	"strings"
+	"time"
+
+	"github.com/go-check/check"
+)
+
+func (s *DockerSuite) BenchmarkLogsCLIRotateFollow(c *check.C) {
+	out, _ := dockerCmd(c, "run", "-d", "--log-opt", "max-size=1b", "--log-opt", "max-file=10", "busybox", "sh", "-c", "while true; do usleep 50000; echo hello; done")
+	id := strings.TrimSpace(out)
+	ch := make(chan error, 1)
+	go func() {
+		ch <- nil
+		out, _, _ := dockerCmdWithError("logs", "-f", id)
+		// if this returns at all, it's an error
+		ch <- fmt.Errorf(out)
+	}()
+
+	<-ch
+	select {
+	case <-time.After(30 * time.Second):
+		// ran for 30 seconds with no problem
+		return
+	case err := <-ch:
+		if err != nil {
+			c.Fatal(err)
+		}
+	}
+}