From cf387d5a6da4407ce4bb7981615a2a6950db26f8 Mon Sep 17 00:00:00 2001 From: Marco Jantke Date: Fri, 15 Sep 2017 15:02:03 +0200 Subject: [PATCH] Enable loss less rotation of log files --- log/logger.go | 6 ++- log/logger_test.go | 79 +++++++++++++++++++++++++++ middlewares/accesslog/logger.go | 13 ++++- middlewares/accesslog/logger_test.go | 80 ++++++++++++++++++++++++++++ server/server_signals.go | 2 +- 5 files changed, 175 insertions(+), 5 deletions(-) create mode 100644 log/logger_test.go diff --git a/log/logger.go b/log/logger.go index c60b08acb..9ded03bff 100644 --- a/log/logger.go +++ b/log/logger.go @@ -227,8 +227,10 @@ func RotateFile() error { return nil } - if err := CloseFile(); err != nil { - return fmt.Errorf("error closing log file: %s", err) + if logFile != nil { + defer func(f *os.File) { + f.Close() + }(logFile) } if err := OpenFile(logFilePath); err != nil { diff --git a/log/logger_test.go b/log/logger_test.go new file mode 100644 index 000000000..c91202167 --- /dev/null +++ b/log/logger_test.go @@ -0,0 +1,79 @@ +package log + +import ( + "io/ioutil" + "os" + "strings" + "testing" + "time" +) + +func TestLogRotation(t *testing.T) { + tempDir, err := ioutil.TempDir("", "traefik_") + if err != nil { + t.Fatalf("Error setting up temporary directory: %s", err) + } + + fileName := tempDir + "traefik.log" + if err := OpenFile(fileName); err != nil { + t.Fatalf("Error opening temporary file %s: %s", fileName, err) + } + defer CloseFile() + + rotatedFileName := fileName + ".rotated" + + iterations := 20 + halfDone := make(chan bool) + writeDone := make(chan bool) + go func() { + for i := 0; i < iterations; i++ { + Println("Test log line") + if i == iterations/2 { + halfDone <- true + } + } + writeDone <- true + }() + + <-halfDone + err = os.Rename(fileName, rotatedFileName) + if err != nil { + t.Fatalf("Error renaming file: %s", err) + } + + err = RotateFile() + if err != nil { + t.Fatalf("Error rotating file: %s", err) + } + + select { + case <-writeDone: + gotLineCount := lineCount(t, fileName) + lineCount(t, rotatedFileName) + if iterations != gotLineCount { + t.Errorf("Wanted %d written log lines, got %d", iterations, gotLineCount) + } + case <-time.After(500 * time.Millisecond): + t.Fatalf("test timed out") + } + + close(halfDone) + close(writeDone) +} + +func lineCount(t *testing.T, fileName string) int { + t.Helper() + fileContents, err := ioutil.ReadFile(fileName) + if err != nil { + t.Fatalf("Error reading from file %s: %s", fileName, err) + } + + count := 0 + for _, line := range strings.Split(string(fileContents), "\n") { + if strings.TrimSpace(line) == "" { + continue + } + count++ + } + + return count +} diff --git a/middlewares/accesslog/logger.go b/middlewares/accesslog/logger.go index fc5d52adf..8d6cdbbe1 100644 --- a/middlewares/accesslog/logger.go +++ b/middlewares/accesslog/logger.go @@ -8,6 +8,7 @@ import ( "net/url" "os" "path/filepath" + "sync" "sync/atomic" "time" @@ -34,6 +35,7 @@ type LogHandler struct { logger *logrus.Logger file *os.File filePath string + mu sync.Mutex } // NewLogHandler creates a new LogHandler @@ -148,14 +150,19 @@ func (l *LogHandler) Close() error { // by an external source. func (l *LogHandler) Rotate() error { var err error - if err = l.Close(); err != nil { - return err + + if l.file != nil { + defer func(f *os.File) { + f.Close() + }(l.file) } l.file, err = os.OpenFile(l.filePath, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0664) if err != nil { return err } + l.mu.Lock() + defer l.mu.Unlock() l.logger.Out = l.file return nil } @@ -226,6 +233,8 @@ func (l *LogHandler) logTheRoundTrip(logDataTable *LogData, crr *captureRequestR fields["downstream_"+k] = logDataTable.DownstreamResponse.Get(k) } + l.mu.Lock() + defer l.mu.Unlock() l.logger.WithFields(fields).Println() } diff --git a/middlewares/accesslog/logger_test.go b/middlewares/accesslog/logger_test.go index e6854a539..61aa16343 100644 --- a/middlewares/accesslog/logger_test.go +++ b/middlewares/accesslog/logger_test.go @@ -10,7 +10,9 @@ import ( "os" "path/filepath" "regexp" + "strings" "testing" + "time" "github.com/containous/traefik/types" shellwords "github.com/mattn/go-shellwords" @@ -36,6 +38,84 @@ var ( testRetryAttempts = 2 ) +func TestLogRotation(t *testing.T) { + tempDir, err := ioutil.TempDir("", "traefik_") + if err != nil { + t.Fatalf("Error setting up temporary directory: %s", err) + } + + fileName := tempDir + "traefik.log" + rotatedFileName := fileName + ".rotated" + + config := &types.AccessLog{FilePath: fileName, Format: CommonFormat} + logHandler, err := NewLogHandler(config) + if err != nil { + t.Fatalf("Error creating new log handler: %s", err) + } + defer logHandler.Close() + + recorder := httptest.NewRecorder() + req := httptest.NewRequest(http.MethodGet, "http://localhost", nil) + next := func(rw http.ResponseWriter, req *http.Request) { + rw.WriteHeader(http.StatusOK) + } + + iterations := 20 + halfDone := make(chan bool) + writeDone := make(chan bool) + go func() { + for i := 0; i < iterations; i++ { + logHandler.ServeHTTP(recorder, req, next) + if i == iterations/2 { + halfDone <- true + } + } + writeDone <- true + }() + + <-halfDone + err = os.Rename(fileName, rotatedFileName) + if err != nil { + t.Fatalf("Error renaming file: %s", err) + } + + err = logHandler.Rotate() + if err != nil { + t.Fatalf("Error rotating file: %s", err) + } + + select { + case <-writeDone: + gotLineCount := lineCount(t, fileName) + lineCount(t, rotatedFileName) + if iterations != gotLineCount { + t.Errorf("Wanted %d written log lines, got %d", iterations, gotLineCount) + } + case <-time.After(500 * time.Millisecond): + t.Fatalf("test timed out") + } + + close(halfDone) + close(writeDone) +} + +func lineCount(t *testing.T, fileName string) int { + t.Helper() + fileContents, err := ioutil.ReadFile(fileName) + if err != nil { + t.Fatalf("Error reading from file %s: %s", fileName, err) + } + + count := 0 + for _, line := range strings.Split(string(fileContents), "\n") { + if strings.TrimSpace(line) == "" { + continue + } + count++ + } + + return count +} + func TestLoggerCLF(t *testing.T) { tmpDir := createTempDir(t, CommonFormat) defer os.RemoveAll(tmpDir) diff --git a/server/server_signals.go b/server/server_signals.go index 443fb6f76..7de108b67 100644 --- a/server/server_signals.go +++ b/server/server_signals.go @@ -27,7 +27,7 @@ func (server *Server) listenSignals() { } if err := log.RotateFile(); err != nil { - log.Errorf("Error rotating error log: %s", err) + log.Errorf("Error rotating traefik log: %s", err) } default: log.Infof("I have to go... %+v", sig)