Add log file close and reopen on receipt of SIGUSR1

cmd/traefik/traefik.go

@@ -254,16 +254,15 @@ func run(traefikConfiguration *server.TraefikConfiguration) {
 			log.Errorf("Failed to create log path %s: %s", dir, err)
 		}
 
-		fi, err := os.OpenFile(globalConfiguration.TraefikLogsFile, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0666)
+		err = log.OpenFile(globalConfiguration.TraefikLogsFile)
 		defer func() {
-			if err := fi.Close(); err != nil {
-				log.Error("Error closing file", err)
+			if err := log.CloseFile(); err != nil {
+				log.Error("Error closing log", err)
 			}
 		}()
 		if err != nil {
 			log.Error("Error opening file", err)
 		} else {
-			log.SetOutput(fi)
 			log.SetFormatter(&logrus.TextFormatter{DisableColors: true, FullTimestamp: true, DisableSorting: true})
 		}
 	} else {

docs/basics.md

@@ -537,3 +537,11 @@ $ traefik bug
 ```
 
 See https://www.youtube.com/watch?v=Lyz62L8m93I.
+
+# Log Rotation
+
+Traefik will close and reopen its log files, assuming they're configured, on receipt of a USR1 signal.  This allows the logs
+to be rotated and processed by an external program, such as `logrotate`.
+
+Note that this does not work on Windows due to the lack of USR signals.
+

integration/access_log_test.go

@@ -78,14 +78,7 @@ func (s *AccessLogSuite) TestAccessLog(c *check.C) {
 	for i, line := range lines {
 		if len(line) > 0 {
 			count++
-			tokens, err := shellwords.Parse(line)
-			c.Assert(err, checker.IsNil)
-			c.Assert(tokens, checker.HasLen, 14)
-			c.Assert(tokens[6], checker.Matches, `^\d{3}$`)
-			c.Assert(tokens[10], checker.Equals, fmt.Sprintf("%d", i+1))
-			c.Assert(tokens[11], checker.HasPrefix, "frontend")
-			c.Assert(tokens[12], checker.HasPrefix, "http://127.0.0.1:808")
-			c.Assert(tokens[13], checker.Matches, `^\d+ms$`)
+			CheckAccessLogFormat(c, line, i)
 		}
 	}
 	c.Assert(count, checker.GreaterOrEqualThan, 3)
@@ -99,6 +92,17 @@ func (s *AccessLogSuite) TestAccessLog(c *check.C) {
 	}
 }
 
+func CheckAccessLogFormat(c *check.C, line string, i int) {
+	tokens, err := shellwords.Parse(line)
+	c.Assert(err, checker.IsNil)
+	c.Assert(tokens, checker.HasLen, 14)
+	c.Assert(tokens[6], checker.Matches, `^\d{3}$`)
+	c.Assert(tokens[10], checker.Equals, fmt.Sprintf("%d", i+1))
+	c.Assert(tokens[11], checker.HasPrefix, "frontend")
+	c.Assert(tokens[12], checker.HasPrefix, "http://127.0.0.1:808")
+	c.Assert(tokens[13], checker.Matches, `^\d+ms$`)
+}
+
 func startAccessLogServer(port int) (ts *httptest.Server) {
 	handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		fmt.Fprintf(w, "Received query %s!\n", r.URL.Path[1:])

integration/fixtures/log_rotation_config.toml

@@ -0,0 +1,34 @@
+################################################################
+# Global configuration
+################################################################
+traefikLogsFile = "traefik.log"
+accessLogsFile = "access.log"
+logLevel = "ERROR"
+defaultEntryPoints = ["http"]
+[entryPoints]
+  [entryPoints.http]
+  address = ":8000"
+
+################################################################
+# Web configuration backend
+################################################################
+[web]
+address = ":7888"
+
+################################################################
+# File configuration backend
+################################################################
+[file]
+
+################################################################
+# rules
+################################################################
+ [backends]
+   [backends.backend1]
+     [backends.backend1.servers.server1]
+       url = "http://127.0.0.1:8081"
+  [frontends]
+   [frontends.frontend1]
+   backend = "backend1"
+     [frontends.frontend1.routes.test_1]
+     rule = "Path: /test1"

integration/fixtures/traefik_log_config.toml

@@ -0,0 +1,11 @@
+################################################################
+# Global configuration
+################################################################
+traefikLogsFile = "traefik.log"
+accessLogsFile = "access.log"
+logLevel = "DEBUG"
+checkNewVersion = false
+defaultEntryPoints = ["http"]
+[entryPoints]
+  [entryPoints.http]
+  address = ":8000"

integration/integration_test.go

@@ -40,6 +40,7 @@ func init() {
 	check.Suite(&ErrorPagesSuite{})
 	check.Suite(&WebsocketSuite{})
 	check.Suite(&GRPCSuite{})
+	check.Suite(&LogRotationSuite{})
 }
 
 var traefikBinary = "../dist/traefik"

integration/log_rotation_test.go

@@ -0,0 +1,141 @@
+// +build !windows
+
+package integration
+
+import (
+	"bufio"
+	"io/ioutil"
+	"net/http"
+	"os"
+	"syscall"
+	"time"
+
+	"github.com/containous/traefik/integration/try"
+	"github.com/go-check/check"
+	checker "github.com/vdemeester/shakers"
+)
+
+// Log rotation integration test suite
+type LogRotationSuite struct{ BaseSuite }
+
+func (s *LogRotationSuite) TestAccessLogRotation(c *check.C) {
+	// Start Traefik
+	cmd, _ := s.cmdTraefik(withConfigFile("fixtures/access_log_config.toml"))
+	err := cmd.Start()
+	c.Assert(err, checker.IsNil)
+	defer cmd.Process.Kill()
+	defer os.Remove(traefikTestAccessLogFile)
+	defer os.Remove(traefikTestLogFile)
+
+	// Verify Traefik started ok
+	verifyEmptyErrorLog(c, "traefik.log")
+
+	// Start test servers
+	ts1 := startAccessLogServer(8081)
+	defer ts1.Close()
+
+	// Allow time to startup
+	time.Sleep(1 * time.Second)
+
+	// Make some requests
+	err = try.GetRequest("http://127.0.0.1:8000/test1", 500*time.Millisecond)
+	c.Assert(err, checker.IsNil)
+
+	// Rename access log
+	err = os.Rename(traefikTestAccessLogFile, traefikTestAccessLogFile+".rotated")
+	c.Assert(err, checker.IsNil)
+
+	// in the midst of the requests, issue SIGUSR1 signal to server process
+	err = cmd.Process.Signal(syscall.SIGUSR1)
+	c.Assert(err, checker.IsNil)
+
+	// continue issuing requests
+	_, err = http.Get("http://127.0.0.1:8000/test1")
+	c.Assert(err, checker.IsNil)
+	_, err = http.Get("http://127.0.0.1:8000/test1")
+	c.Assert(err, checker.IsNil)
+
+	// Verify access.log.rotated output as expected
+	lineCount := verifyLogLines(c, traefikTestAccessLogFile+".rotated", 0, true)
+	c.Assert(lineCount, checker.GreaterOrEqualThan, 1)
+
+	// Verify access.log output as expected
+	lineCount = verifyLogLines(c, traefikTestAccessLogFile, lineCount, true)
+	c.Assert(lineCount, checker.Equals, 3)
+
+	verifyEmptyErrorLog(c, traefikTestLogFile)
+}
+
+func (s *LogRotationSuite) TestTraefikLogRotation(c *check.C) {
+	// Start Traefik
+	cmd, _ := s.cmdTraefik(withConfigFile("fixtures/traefik_log_config.toml"))
+	err := cmd.Start()
+	c.Assert(err, checker.IsNil)
+	defer cmd.Process.Kill()
+	defer os.Remove(traefikTestAccessLogFile)
+	defer os.Remove(traefikTestLogFile)
+
+	// Ensure Traefik has started
+	err = try.GetRequest("http://127.0.0.1:8000/test1", 500*time.Millisecond)
+	c.Assert(err, checker.IsNil)
+
+	// Rename traefik log
+	err = os.Rename(traefikTestLogFile, traefikTestLogFile+".rotated")
+	c.Assert(err, checker.IsNil)
+
+	// issue SIGUSR1 signal to server process
+	err = cmd.Process.Signal(syscall.SIGUSR1)
+	c.Assert(err, checker.IsNil)
+
+	err = cmd.Process.Signal(syscall.SIGTERM)
+	c.Assert(err, checker.IsNil)
+
+	// Allow time for switch to be processed
+	err = try.Do(3*time.Second, func() error {
+		_, err = os.Stat(traefikTestLogFile)
+		return err
+	})
+	c.Assert(err, checker.IsNil)
+
+	// we have at least 6 lines in traefik.log.rotated
+	lineCount := verifyLogLines(c, traefikTestLogFile+".rotated", 0, false)
+
+	// GreaterOrEqualThan used to ensure test doesn't break
+	// If more log entries are output on startup
+	c.Assert(lineCount, checker.GreaterOrEqualThan, 6)
+
+	//Verify traefik.log output as expected
+	lineCount = verifyLogLines(c, traefikTestLogFile, lineCount, false)
+	c.Assert(lineCount, checker.GreaterOrEqualThan, 7)
+}
+
+func verifyEmptyErrorLog(c *check.C, name string) {
+	err := try.Do(5*time.Second, func() error {
+		traefikLog, e2 := ioutil.ReadFile(name)
+		if e2 != nil {
+			return e2
+		}
+		c.Assert(traefikLog, checker.HasLen, 0)
+		return nil
+	})
+	c.Assert(err, checker.IsNil)
+}
+
+func verifyLogLines(c *check.C, fileName string, countInit int, accessLog bool) int {
+	rotated, err := os.Open(fileName)
+	c.Assert(err, checker.IsNil)
+	rotatedLog := bufio.NewScanner(rotated)
+	count := countInit
+	for rotatedLog.Scan() {
+		line := rotatedLog.Text()
+		c.Log(line)
+		if accessLog {
+			if len(line) > 0 {
+				CheckAccessLogFormat(c, line, count)
+			}
+		}
+		count++
+	}
+
+	return count
+}

log/logger.go

@@ -2,14 +2,18 @@ package log
 
 import (
 	"bufio"
+	"fmt"
 	"io"
+	"os"
 	"runtime"
 
 	"github.com/Sirupsen/logrus"
 )
 
 var (
-	logger *logrus.Entry
+	logger      *logrus.Entry
+	logFilePath string
+	logFile     *os.File
 )
 
 func init() {
@@ -190,6 +194,49 @@ func Fatalln(args ...interface{}) {
 	logger.Fatalln(args...)
 }
 
+// OpenFile opens the log file using the specified path
+func OpenFile(path string) error {
+	logFilePath = path
+	var err error
+	logFile, err = os.OpenFile(logFilePath, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0666)
+
+	if err == nil {
+		SetOutput(logFile)
+	}
+
+	return err
+}
+
+// CloseFile closes the log and sets the Output to stdout
+func CloseFile() error {
+	logrus.SetOutput(os.Stdout)
+
+	if logFile != nil {
+		return logFile.Close()
+	}
+	return nil
+}
+
+// RotateFile closes and reopens the log file to allow for rotation
+// by an external source.  If the log isn't backed by a file then
+// it does nothing.
+func RotateFile() error {
+	if logFile == nil && logFilePath == "" {
+		Debug("Traefik log is not writing to a file, ignoring rotate request")
+		return nil
+	}
+
+	if err := CloseFile(); err != nil {
+		return fmt.Errorf("error closing log file: %s", err)
+	}
+
+	if err := OpenFile(logFilePath); err != nil {
+		return fmt.Errorf("error opening log file: %s", err)
+	}
+
+	return nil
+}
+
 // Writer logs writer (Level Info)
 func Writer() *io.PipeWriter {
 	return WriterLevel(logrus.InfoLevel)

middlewares/accesslog/logger.go

@@ -31,8 +31,9 @@ const (
 
 // LogHandler will write each request and its response to the access log.
 type LogHandler struct {
-	logger *logrus.Logger
-	file   *os.File
+	logger   *logrus.Logger
+	file     *os.File
+	filePath string
 }
 
 // NewLogHandler creates a new LogHandler
@@ -63,7 +64,7 @@ func NewLogHandler(config *types.AccessLog) (*LogHandler, error) {
 		Hooks:     make(logrus.LevelHooks),
 		Level:     logrus.InfoLevel,
 	}
-	return &LogHandler{logger: logger, file: file}, nil
+	return &LogHandler{logger: logger, file: file, filePath: config.FilePath}, nil
 }
 
 func openAccessLogFile(filePath string) (*os.File, error) {
@@ -139,6 +140,22 @@ func (l *LogHandler) Close() error {
 	return l.file.Close()
 }
 
+// Rotate closes and reopens the log file to allow for rotation
+// by an external source.
+func (l *LogHandler) Rotate() error {
+	var err error
+	if err = l.Close(); err != nil {
+		return err
+	}
+
+	l.file, err = os.OpenFile(l.filePath, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0664)
+	if err != nil {
+		return err
+	}
+	l.logger.Out = l.file
+	return nil
+}
+
 func silentSplitHostPort(value string) (host string, port string) {
 	host, port, err := net.SplitHostPort(value)
 	if err != nil {

server/server.go

@@ -15,7 +15,6 @@ import (
 	"regexp"
 	"sort"
 	"sync"
-	"syscall"
 	"time"
 
 	"github.com/containous/mux"
@@ -78,7 +77,7 @@ func NewServer(globalConfiguration GlobalConfiguration) *Server {
 	server.signals = make(chan os.Signal, 1)
 	server.stopChan = make(chan bool, 1)
 	server.providers = []provider.Provider{}
-	signal.Notify(server.signals, syscall.SIGINT, syscall.SIGTERM)
+	server.configureSignals()
 	currentConfigurations := make(configs)
 	server.currentConfigurations.Set(currentConfigurations)
 	server.globalConfiguration = globalConfiguration
@@ -426,13 +425,6 @@ func (server *Server) startProviders() {
 	}
 }
 
-func (server *Server) listenSignals() {
-	sig := <-server.signals
-	log.Infof("I have to go... %+v", sig)
-	log.Info("Stopping server")
-	server.Stop()
-}
-
 func createClientTLSConfig(tlsOption *TLS) (*tls.Config, error) {
 	if tlsOption == nil {
 		return nil, errors.New("no TLS provided")

server/server_signals.go

@@ -0,0 +1,38 @@
+// +build !windows
+
+package server
+
+import (
+	"os/signal"
+	"syscall"
+
+	"github.com/containous/traefik/log"
+)
+
+func (server *Server) configureSignals() {
+	signal.Notify(server.signals, syscall.SIGINT, syscall.SIGTERM, syscall.SIGUSR1)
+}
+
+func (server *Server) listenSignals() {
+	for {
+		sig := <-server.signals
+		switch sig {
+		case syscall.SIGUSR1:
+			log.Infof("Closing and re-opening log files for rotation: %+v", sig)
+
+			if server.accessLoggerMiddleware != nil {
+				if err := server.accessLoggerMiddleware.Rotate(); err != nil {
+					log.Errorf("Error rotating access log: %s", err)
+				}
+			}
+
+			if err := log.RotateFile(); err != nil {
+				log.Errorf("Error rotating error log: %s", err)
+			}
+		default:
+			log.Infof("I have to go... %+v", sig)
+			log.Info("Stopping server")
+			server.Stop()
+		}
+	}
+}

server/server_signals_windows.go

@@ -0,0 +1,26 @@
+// +build windows
+
+package server
+
+import (
+	"os/signal"
+	"syscall"
+
+	"github.com/containous/traefik/log"
+)
+
+func (server *Server) configureSignals() {
+	signal.Notify(server.signals, syscall.SIGINT, syscall.SIGTERM)
+}
+
+func (server *Server) listenSignals() {
+	for {
+		sig := <-server.signals
+		switch sig {
+		default:
+			log.Infof("I have to go... %+v", sig)
+			log.Info("Stopping server")
+			server.Stop()
+		}
+	}
+}