From 4e5fcac9cb2e566b54d6ad014c09455627035080 Mon Sep 17 00:00:00 2001 From: Richard Shepherd Date: Fri, 11 Aug 2017 11:04:58 +0100 Subject: [PATCH] Add log file close and reopen on receipt of SIGUSR1 --- cmd/traefik/traefik.go | 7 +- docs/basics.md | 8 + integration/access_log_test.go | 20 ++- integration/fixtures/log_rotation_config.toml | 34 +++++ integration/fixtures/traefik_log_config.toml | 11 ++ integration/integration_test.go | 1 + integration/log_rotation_test.go | 141 ++++++++++++++++++ log/logger.go | 49 +++++- middlewares/accesslog/logger.go | 23 ++- server/server.go | 10 +- server/server_signals.go | 38 +++++ server/server_signals_windows.go | 26 ++++ 12 files changed, 343 insertions(+), 25 deletions(-) create mode 100644 integration/fixtures/log_rotation_config.toml create mode 100644 integration/fixtures/traefik_log_config.toml create mode 100644 integration/log_rotation_test.go create mode 100644 server/server_signals.go create mode 100644 server/server_signals_windows.go diff --git a/cmd/traefik/traefik.go b/cmd/traefik/traefik.go index f15f99aaa..842629eb2 100644 --- a/cmd/traefik/traefik.go +++ b/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 { diff --git a/docs/basics.md b/docs/basics.md index 720ce41ac..8416d37a2 100644 --- a/docs/basics.md +++ b/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. + diff --git a/integration/access_log_test.go b/integration/access_log_test.go index 1da047515..f049cccc9 100644 --- a/integration/access_log_test.go +++ b/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:]) diff --git a/integration/fixtures/log_rotation_config.toml b/integration/fixtures/log_rotation_config.toml new file mode 100644 index 000000000..70758386b --- /dev/null +++ b/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" diff --git a/integration/fixtures/traefik_log_config.toml b/integration/fixtures/traefik_log_config.toml new file mode 100644 index 000000000..d615c0064 --- /dev/null +++ b/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" diff --git a/integration/integration_test.go b/integration/integration_test.go index 4ff958b1b..e0cbb3ff5 100644 --- a/integration/integration_test.go +++ b/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" diff --git a/integration/log_rotation_test.go b/integration/log_rotation_test.go new file mode 100644 index 000000000..8ff02159e --- /dev/null +++ b/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 +} diff --git a/log/logger.go b/log/logger.go index 82a1f00bf..448713c37 100644 --- a/log/logger.go +++ b/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) diff --git a/middlewares/accesslog/logger.go b/middlewares/accesslog/logger.go index 84f45300b..698e80e59 100644 --- a/middlewares/accesslog/logger.go +++ b/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 { diff --git a/server/server.go b/server/server.go index 23d6a1850..95fef10df 100644 --- a/server/server.go +++ b/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") diff --git a/server/server_signals.go b/server/server_signals.go new file mode 100644 index 000000000..443fb6f76 --- /dev/null +++ b/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() + } + } +} diff --git a/server/server_signals_windows.go b/server/server_signals_windows.go new file mode 100644 index 000000000..54bfc4cb1 --- /dev/null +++ b/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() + } + } +}