Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add log file close and reopen on receipt of SIGUSR1 #1761

Merged
merged 1 commit into from
Aug 11, 2017
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
7 changes: 3 additions & 4 deletions cmd/traefik/traefik.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
8 changes: 8 additions & 0 deletions docs/basics.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.

20 changes: 12 additions & 8 deletions integration/access_log_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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:])
Expand Down
34 changes: 34 additions & 0 deletions integration/fixtures/log_rotation_config.toml
Original file line number Diff line number Diff line change
@@ -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"
11 changes: 11 additions & 0 deletions integration/fixtures/traefik_log_config.toml
Original file line number Diff line number Diff line change
@@ -0,0 +1,11 @@
################################################################
# Global configuration
################################################################
traefikLogsFile = "traefik.log"
accessLogsFile = "access.log"
logLevel = "DEBUG"
checkNewVersion = false
defaultEntryPoints = ["http"]
[entryPoints]
[entryPoints.http]
address = ":8000"
1 change: 1 addition & 0 deletions integration/integration_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -40,6 +40,7 @@ func init() {
check.Suite(&ErrorPagesSuite{})
check.Suite(&WebsocketSuite{})
check.Suite(&GRPCSuite{})
check.Suite(&LogRotationSuite{})
}

var traefikBinary = "../dist/traefik"
Expand Down
141 changes: 141 additions & 0 deletions integration/log_rotation_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,141 @@
// +build !windows

package integration
Copy link
Contributor

@timoreimann timoreimann Jul 19, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could we use a build tag here to avoid running the test on Windows (where it would always fail to my understanding)? Users may want to run the tests natively, i.e., outside of our Linux-based build container).

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes - added


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
}
49 changes: 48 additions & 1 deletion log/logger.go
Original file line number Diff line number Diff line change
Expand Up @@ -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() {
Expand Down Expand Up @@ -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)
Expand Down
23 changes: 20 additions & 3 deletions middlewares/accesslog/logger.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should suffice to be declared on line 150 only if we also scope err on line 147 to the if statement?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I couldn't get that to work.

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 {
Expand Down
Loading