Fix bad access log

integration/access_log_test.go

@@ -3,9 +3,7 @@ package integration
 import (
 	"fmt"
 	"io/ioutil"
-	"net"
 	"net/http"
-	"net/http/httptest"
 	"os"
 	"strings"
 	"time"
@@ -24,10 +22,26 @@ const (
 // AccessLogSuite
 type AccessLogSuite struct{ BaseSuite }
 
+type accessLogValue struct {
+	formatOnly  bool
+	code        string
+	value       string
+	backendName string
+}
+
+func (s *AccessLogSuite) SetUpSuite(c *check.C) {
+	s.createComposeProject(c, "access_log")
+	s.composeProject.Start(c)
+
+	s.composeProject.Container(c, "server0")
+	s.composeProject.Container(c, "server1")
+	s.composeProject.Container(c, "server2")
+	s.composeProject.Container(c, "server3")
+}
+
 func (s *AccessLogSuite) TestAccessLog(c *check.C) {
 	// Ensure working directory is clean
-	os.Remove(traefikTestAccessLogFile)
+	ensureWorkingDirectoryIsClean()
-	os.Remove(traefikTestLogFile)
 
 	// Start Traefik
 	cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
@@ -39,52 +53,446 @@ func (s *AccessLogSuite) TestAccessLog(c *check.C) {
 	defer os.Remove(traefikTestAccessLogFile)
 	defer os.Remove(traefikTestLogFile)
 
-	err = try.Do(1*time.Second, func() error {
+	waitForTraefik(c, "server1")
-		if _, errStat := os.Stat(traefikTestLogFile); errStat != nil {
+
-			return fmt.Errorf("could not get stats for log file: %s", errStat)
+	checkStatsForLogFile(c)
-		}
-		return nil
-	})
-	c.Assert(err, checker.IsNil)
 
 	// Verify Traefik started OK
-	traefikLog, err := ioutil.ReadFile(traefikTestLogFile)
+	traefikLog := checkTraefikStarted(c)
-	c.Assert(err, checker.IsNil)
-	if len(traefikLog) > 0 {
-		fmt.Printf("%s\n", string(traefikLog))
-		c.Assert(traefikLog, checker.HasLen, 0)
-	}
-
-	// Start test servers
-	ts1 := startAccessLogServer(8081)
-	defer ts1.Close()
-	ts2 := startAccessLogServer(8082)
-	defer ts2.Close()
-	ts3 := startAccessLogServer(8083)
-	defer ts3.Close()
 
 	// Make some requests
-	err = try.GetRequest("http://127.0.0.1:8000/test1", 500*time.Millisecond)
+	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8000/", nil)
 	c.Assert(err, checker.IsNil)
-	err = try.GetRequest("http://127.0.0.1:8000/test2", 500*time.Millisecond)
+	req.Host = "frontend1.docker.local"
+
+	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
 	c.Assert(err, checker.IsNil)
-	err = try.GetRequest("http://127.0.0.1:8000/test2", 500*time.Millisecond)
+
+	req, err = http.NewRequest(http.MethodGet, "http://127.0.0.1:8000/", nil)
+	c.Assert(err, checker.IsNil)
+	req.Host = "frontend2.docker.local"
+
+	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
+	c.Assert(err, checker.IsNil)
+	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
 	c.Assert(err, checker.IsNil)
 
 	// Verify access.log output as expected
-	accessLog, err := ioutil.ReadFile(traefikTestAccessLogFile)
+	count := checkAccessLogOutput(err, c)
-	c.Assert(err, checker.IsNil)
+
-	lines := strings.Split(string(accessLog), "\n")
-	count := 0
-	for i, line := range lines {
-		if len(line) > 0 {
-			count++
-			CheckAccessLogFormat(c, line, i)
-		}
-	}
 	c.Assert(count, checker.GreaterOrEqualThan, 3)
 
 	// Verify no other Traefik problems
+	checkNoOtherTraefikProblems(traefikLog, err, c)
+}
+
+func (s *AccessLogSuite) TestAccessLogAuthFrontend(c *check.C) {
+	// Ensure working directory is clean
+	ensureWorkingDirectoryIsClean()
+
+	expected := []accessLogValue{
+		{
+			formatOnly:  false,
+			code:        "401",
+			value:       "Auth for frontend-Host-frontend-auth-docker-local",
+			backendName: "-",
+		},
+	}
+
+	// Start Traefik
+	cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
+	defer display(c)
+	err := cmd.Start()
+	c.Assert(err, checker.IsNil)
+	defer cmd.Process.Kill()
+
+	defer os.Remove(traefikTestAccessLogFile)
+	defer os.Remove(traefikTestLogFile)
+
+	checkStatsForLogFile(c)
+
+	s.composeProject.Container(c, "authFrontend")
+
+	waitForTraefik(c, "authFrontend")
+
+	// Verify Traefik started OK
+	traefikLog := checkTraefikStarted(c)
+
+	// Test auth frontend
+	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8006/", nil)
+	c.Assert(err, checker.IsNil)
+	req.Host = "frontend.auth.docker.local"
+
+	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusUnauthorized), try.HasBody())
+	c.Assert(err, checker.IsNil)
+
+	// Verify access.log output as expected
+	count := checkAccessLogExactValuesOutput(err, c, expected)
+
+	c.Assert(count, checker.GreaterOrEqualThan, len(expected))
+
+	// Verify no other Traefik problems
+	checkNoOtherTraefikProblems(traefikLog, err, c)
+}
+
+func (s *AccessLogSuite) TestAccessLogAuthEntrypoint(c *check.C) {
+	// Ensure working directory is clean
+	ensureWorkingDirectoryIsClean()
+
+	expected := []accessLogValue{
+		{
+			formatOnly:  false,
+			code:        "401",
+			value:       "Auth for entrypoint",
+			backendName: "-",
+		},
+	}
+
+	// Start Traefik
+	cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
+	defer display(c)
+	err := cmd.Start()
+	c.Assert(err, checker.IsNil)
+	defer cmd.Process.Kill()
+
+	defer os.Remove(traefikTestAccessLogFile)
+	defer os.Remove(traefikTestLogFile)
+
+	checkStatsForLogFile(c)
+
+	s.composeProject.Container(c, "authEntrypoint")
+
+	waitForTraefik(c, "authEntrypoint")
+
+	// Verify Traefik started OK
+	traefikLog := checkTraefikStarted(c)
+
+	// Test auth entrypoint
+	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8004/", nil)
+	c.Assert(err, checker.IsNil)
+	req.Host = "entrypoint.auth.docker.local"
+
+	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusUnauthorized), try.HasBody())
+	c.Assert(err, checker.IsNil)
+
+	// Verify access.log output as expected
+	count := checkAccessLogExactValuesOutput(err, c, expected)
+
+	c.Assert(count, checker.GreaterOrEqualThan, len(expected))
+
+	// Verify no other Traefik problems
+	checkNoOtherTraefikProblems(traefikLog, err, c)
+}
+
+func (s *AccessLogSuite) TestAccessLogEntrypointRedirect(c *check.C) {
+	// Ensure working directory is clean
+	ensureWorkingDirectoryIsClean()
+
+	expected := []accessLogValue{
+		{
+			formatOnly:  false,
+			code:        "302",
+			value:       "entrypoint redirect for frontend-",
+			backendName: "-",
+		},
+		{
+			formatOnly: true,
+		},
+	}
+
+	// Start Traefik
+	cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
+	defer display(c)
+	err := cmd.Start()
+	c.Assert(err, checker.IsNil)
+	defer cmd.Process.Kill()
+
+	defer os.Remove(traefikTestAccessLogFile)
+	defer os.Remove(traefikTestLogFile)
+
+	checkStatsForLogFile(c)
+
+	s.composeProject.Container(c, "entrypointRedirect")
+
+	waitForTraefik(c, "entrypointRedirect")
+
+	// Verify Traefik started OK
+	traefikLog := checkTraefikStarted(c)
+
+	// Test entrypoint redirect
+	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8001/test", nil)
+	c.Assert(err, checker.IsNil)
+	req.Host = ""
+
+	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
+	c.Assert(err, checker.IsNil)
+
+	// Verify access.log output as expected
+	count := checkAccessLogExactValuesOutput(err, c, expected)
+
+	c.Assert(count, checker.GreaterOrEqualThan, len(expected))
+
+	// Verify no other Traefik problems
+	checkNoOtherTraefikProblems(traefikLog, err, c)
+}
+
+func (s *AccessLogSuite) TestAccessLogFrontendRedirect(c *check.C) {
+	// Ensure working directory is clean
+	ensureWorkingDirectoryIsClean()
+
+	expected := []accessLogValue{
+		{
+			formatOnly:  false,
+			code:        "302",
+			value:       "frontend redirect for frontend-Path-",
+			backendName: "-",
+		},
+		{
+			formatOnly: true,
+		},
+	}
+
+	// Start Traefik
+	cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
+	defer display(c)
+	err := cmd.Start()
+	c.Assert(err, checker.IsNil)
+	defer cmd.Process.Kill()
+
+	defer os.Remove(traefikTestAccessLogFile)
+	defer os.Remove(traefikTestLogFile)
+
+	checkStatsForLogFile(c)
+
+	s.composeProject.Container(c, "frontendRedirect")
+
+	waitForTraefik(c, "frontendRedirect")
+
+	// Verify Traefik started OK
+	traefikLog := checkTraefikStarted(c)
+
+	// Test frontend redirect
+	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8005/test", nil)
+	c.Assert(err, checker.IsNil)
+	req.Host = ""
+
+	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
+	c.Assert(err, checker.IsNil)
+
+	// Verify access.log output as expected
+	count := checkAccessLogExactValuesOutput(err, c, expected)
+
+	c.Assert(count, checker.GreaterOrEqualThan, len(expected))
+
+	// Verify no other Traefik problems
+	checkNoOtherTraefikProblems(traefikLog, err, c)
+}
+
+func (s *AccessLogSuite) TestAccessLogRateLimit(c *check.C) {
+	// Ensure working directory is clean
+	ensureWorkingDirectoryIsClean()
+
+	expected := []accessLogValue{
+		{
+			formatOnly: true,
+		},
+		{
+			formatOnly: true,
+		},
+		{
+			formatOnly:  false,
+			code:        "429",
+			value:       "rate limit for frontend-Host-ratelimit",
+			backendName: "/",
+		},
+	}
+
+	// Start Traefik
+	cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
+	defer display(c)
+	err := cmd.Start()
+	c.Assert(err, checker.IsNil)
+	defer cmd.Process.Kill()
+
+	defer os.Remove(traefikTestAccessLogFile)
+	defer os.Remove(traefikTestLogFile)
+
+	checkStatsForLogFile(c)
+
+	s.composeProject.Container(c, "rateLimit")
+
+	waitForTraefik(c, "rateLimit")
+
+	// Verify Traefik started OK
+	traefikLog := checkTraefikStarted(c)
+
+	// Test rate limit
+	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8007/", nil)
+	c.Assert(err, checker.IsNil)
+	req.Host = "ratelimit.docker.local"
+
+	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
+	c.Assert(err, checker.IsNil)
+	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
+	c.Assert(err, checker.IsNil)
+	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusTooManyRequests), try.HasBody())
+	c.Assert(err, checker.IsNil)
+
+	// Verify access.log output as expected
+	count := checkAccessLogExactValuesOutput(err, c, expected)
+
+	c.Assert(count, checker.GreaterOrEqualThan, len(expected))
+
+	// Verify no other Traefik problems
+	checkNoOtherTraefikProblems(traefikLog, err, c)
+}
+
+func (s *AccessLogSuite) TestAccessLogBackendNotFound(c *check.C) {
+	// Ensure working directory is clean
+	ensureWorkingDirectoryIsClean()
+
+	expected := []accessLogValue{
+		{
+			formatOnly:  false,
+			code:        "404",
+			value:       "backend not found",
+			backendName: "/",
+		},
+	}
+
+	// Start Traefik
+	cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
+	defer display(c)
+	err := cmd.Start()
+	c.Assert(err, checker.IsNil)
+	defer cmd.Process.Kill()
+
+	defer os.Remove(traefikTestAccessLogFile)
+	defer os.Remove(traefikTestLogFile)
+
+	waitForTraefik(c, "server1")
+
+	checkStatsForLogFile(c)
+
+	// Verify Traefik started OK
+	traefikLog := checkTraefikStarted(c)
+
+	// Test rate limit
+	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8000/", nil)
+	c.Assert(err, checker.IsNil)
+	req.Host = "backendnotfound.docker.local"
+
+	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusNotFound), try.HasBody())
+	c.Assert(err, checker.IsNil)
+
+	// Verify access.log output as expected
+	count := checkAccessLogExactValuesOutput(err, c, expected)
+
+	c.Assert(count, checker.GreaterOrEqualThan, len(expected))
+
+	// Verify no other Traefik problems
+	checkNoOtherTraefikProblems(traefikLog, err, c)
+}
+
+func (s *AccessLogSuite) TestAccessLogEntrypointWhitelist(c *check.C) {
+	// Ensure working directory is clean
+	ensureWorkingDirectoryIsClean()
+
+	expected := []accessLogValue{
+		{
+			formatOnly:  false,
+			code:        "403",
+			value:       "ipwhitelister for entrypoint httpWhitelistReject",
+			backendName: "-",
+		},
+	}
+
+	// Start Traefik
+	cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
+	defer display(c)
+	err := cmd.Start()
+	c.Assert(err, checker.IsNil)
+	defer cmd.Process.Kill()
+
+	defer os.Remove(traefikTestAccessLogFile)
+	defer os.Remove(traefikTestLogFile)
+
+	checkStatsForLogFile(c)
+
+	s.composeProject.Container(c, "entrypointWhitelist")
+
+	waitForTraefik(c, "entrypointWhitelist")
+
+	// Verify Traefik started OK
+	traefikLog := checkTraefikStarted(c)
+
+	// Test rate limit
+	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8002/", nil)
+	c.Assert(err, checker.IsNil)
+	req.Host = "entrypoint.whitelist.docker.local"
+
+	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusForbidden), try.HasBody())
+	c.Assert(err, checker.IsNil)
+
+	// Verify access.log output as expected
+	count := checkAccessLogExactValuesOutput(err, c, expected)
+
+	c.Assert(count, checker.GreaterOrEqualThan, len(expected))
+
+	// Verify no other Traefik problems
+	checkNoOtherTraefikProblems(traefikLog, err, c)
+}
+
+func (s *AccessLogSuite) TestAccessLogFrontendWhitelist(c *check.C) {
+	// Ensure working directory is clean
+	ensureWorkingDirectoryIsClean()
+
+	expected := []accessLogValue{
+		{
+			formatOnly:  false,
+			code:        "403",
+			value:       "ipwhitelister for frontend-Host-frontend-whitelist",
+			backendName: "-",
+		},
+	}
+
+	// Start Traefik
+	cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
+	defer display(c)
+	err := cmd.Start()
+	c.Assert(err, checker.IsNil)
+	defer cmd.Process.Kill()
+
+	defer os.Remove(traefikTestAccessLogFile)
+	defer os.Remove(traefikTestLogFile)
+
+	checkStatsForLogFile(c)
+
+	s.composeProject.Container(c, "frontendWhitelist")
+
+	waitForTraefik(c, "frontendWhitelist")
+
+	// Verify Traefik started OK
+	traefikLog := checkTraefikStarted(c)
+
+	// Test rate limit
+	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8000/", nil)
+	c.Assert(err, checker.IsNil)
+	req.Host = "frontend.whitelist.docker.local"
+
+	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusForbidden), try.HasBody())
+	c.Assert(err, checker.IsNil)
+
+	// Verify access.log output as expected
+	count := checkAccessLogExactValuesOutput(err, c, expected)
+
+	c.Assert(count, checker.GreaterOrEqualThan, len(expected))
+
+	// Verify no other Traefik problems
+	checkNoOtherTraefikProblems(traefikLog, err, c)
+}
+
+func checkNoOtherTraefikProblems(traefikLog []byte, err error, c *check.C) {
 	traefikLog, err = ioutil.ReadFile(traefikTestLogFile)
 	c.Assert(err, checker.IsNil)
 	if len(traefikLog) > 0 {
@@ -93,29 +501,95 @@ func (s *AccessLogSuite) TestAccessLog(c *check.C) {
 	}
 }
 
+func checkAccessLogOutput(err error, c *check.C) int {
+	lines := extractLines(err, c)
+	count := 0
+	for i, line := range lines {
+		if len(line) > 0 {
+			count++
+			CheckAccessLogFormat(c, line, i)
+		}
+	}
+	return count
+}
+
+func checkAccessLogExactValuesOutput(err error, c *check.C, values []accessLogValue) int {
+	lines := extractLines(err, c)
+	count := 0
+	for i, line := range lines {
+		fmt.Printf(line)
+		fmt.Println()
+		if len(line) > 0 {
+			count++
+			if values[i].formatOnly {
+				CheckAccessLogFormat(c, line, i)
+			} else {
+				checkAccessLogExactValues(c, line, i, values[i])
+			}
+		}
+	}
+	return count
+}
+
+func extractLines(err error, c *check.C) []string {
+	accessLog, err := ioutil.ReadFile(traefikTestAccessLogFile)
+	c.Assert(err, checker.IsNil)
+	lines := strings.Split(string(accessLog), "\n")
+	return lines
+}
+
+func checkStatsForLogFile(c *check.C) {
+	err := try.Do(1*time.Second, func() error {
+		if _, errStat := os.Stat(traefikTestLogFile); errStat != nil {
+			return fmt.Errorf("could not get stats for log file: %s", errStat)
+		}
+		return nil
+	})
+	c.Assert(err, checker.IsNil)
+}
+
+func ensureWorkingDirectoryIsClean() {
+	os.Remove(traefikTestAccessLogFile)
+	os.Remove(traefikTestLogFile)
+}
+
+func checkTraefikStarted(c *check.C) []byte {
+	traefikLog, err := ioutil.ReadFile(traefikTestLogFile)
+	c.Assert(err, checker.IsNil)
+	if len(traefikLog) > 0 {
+		fmt.Printf("%s\n", string(traefikLog))
+		c.Assert(traefikLog, checker.HasLen, 0)
+	}
+	return traefikLog
+}
+
 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[11], checker.HasPrefix, "Host-")
-	c.Assert(tokens[12], checker.HasPrefix, "http://127.0.0.1:808")
+	c.Assert(tokens[12], checker.HasPrefix, "http://")
 	c.Assert(tokens[13], checker.Matches, `^\d+ms$`)
 }
 
-func startAccessLogServer(port int) (ts *httptest.Server) {
+func checkAccessLogExactValues(c *check.C, line string, i int, v accessLogValue) {
-	handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+	tokens, err := shellwords.Parse(line)
-		fmt.Fprintf(w, "Received query %s!\n", r.URL.Path[1:])
+	c.Assert(err, checker.IsNil)
-	})
+	c.Assert(tokens, checker.HasLen, 14)
-	if listener, err := net.Listen("tcp", fmt.Sprintf("127.0.0.1:%d", port)); err != nil {
+	c.Assert(tokens[6], checker.Equals, v.code)
-		panic(err)
+	c.Assert(tokens[10], checker.Equals, fmt.Sprintf("%d", i+1))
-	} else {
+	c.Assert(tokens[11], checker.HasPrefix, v.value)
-		ts = &httptest.Server{
+	c.Assert(tokens[12], checker.Equals, v.backendName)
-			Listener: listener,
+	c.Assert(tokens[13], checker.Matches, `^\d+ms$`)
-			Config:   &http.Server{Handler: handler},
+}
-		}
+
-		ts.Start()
+func waitForTraefik(c *check.C, containerName string) {
-	}
+	// Wait for Traefik to turn ready.
-	return
+	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8080/api", nil)
+	c.Assert(err, checker.IsNil)
+
+	err = try.Request(req, 2*time.Second, try.StatusCodeIs(http.StatusOK), try.BodyContains(containerName))
+	c.Assert(err, checker.IsNil)
 }

integration/fixtures/access_log_config.toml

@@ -1,48 +1,42 @@
 ################################################################
 # Global configuration
 ################################################################
-traefikLogsFile = "traefik.log"
+[traefikLog]
-accessLogsFile = "access.log"
+  filePath = "traefik.log"
+
+[accessLog]
+  filePath = "access.log"
+
 logLevel = "ERROR"
 defaultEntryPoints = ["http"]
+
 [entryPoints]
   [entryPoints.http]
-  address = ":8000"
+    address = ":8000"
+  [entryPoints.httpRedirect]
+    address = ":8001"
+    [entryPoints.httpRedirect.redirect]
+      entryPoint = "http"
+  [entryPoints.httpWhitelistReject]
+    address = ":8002"
+    whiteListSourceRange = ["8.8.8.8/32"]
+  [entryPoints.httpAuth]
+    address = ":8004"
+    [entryPoints.httpAuth.auth.basic]
+        users = ["test:$apr1$H6uskkkW$IgXLP6ewTrSuBkTrqE8wj/", "test2:$apr1$d9hr9HBB$4HxwgUir3HP4EsggP/QNo0"]
+  [entryPoints.frontendRedirect]
+    address = ":8005"
+  [entryPoints.httpFrontendAuth]
+    address = ":8006"
+  [entryPoints.httpRateLimit]
+    address = ":8007"
 
 checkNewVersion = false
 
-################################################################
+[api]
-# Web configuration backend
+  dashboard = false
-################################################################
-[web]
-address = ":7888"
 
-################################################################
+[docker]
-# File configuration backend
+  exposedByDefault = false
-################################################################
+  domain = "docker.local"
-[file]
+  watch = true
-
-################################################################
-# rules
-################################################################
- [backends]
-   [backends.backend1]
-     [backends.backend1.servers.server1]
-       url = "http://127.0.0.1:8081"
-   [backends.backend2]
-     [backends.backend2.LoadBalancer]
-       method = "drr"
-     [backends.backend2.servers.server1]
-       url = "http://127.0.0.1:8082"
-     [backends.backend2.servers.server2]
-       url = "http://127.0.0.1:8083"
-  [frontends]
-   [frontends.frontend1]
-   backend = "backend1"
-     [frontends.frontend1.routes.test_1]
-     rule = "Path: /test1"
-   [frontends.frontend2]
-   backend = "backend2"
-   passHostHeader = true
-     [frontends.frontend2.routes.test_2]
-     rule = "Path: /test2"

integration/fixtures/traefik_log_config.toml

@@ -1,8 +1,12 @@
 ################################################################
 # Global configuration
 ################################################################
-traefikLogsFile = "traefik.log"
+[traefikLog]
-accessLogsFile = "access.log"
+  filePath = "traefik.log"
+
+[accessLog]
+  filePath = "access.log"
+
 logLevel = "DEBUG"
 defaultEntryPoints = ["http"]
 
@@ -11,3 +15,11 @@ checkNewVersion = false
 [entryPoints]
   [entryPoints.http]
   address = ":8000"
+
+[api]
+  dashboard = false
+
+[docker]
+  exposedByDefault = false
+  domain = "docker.local"
+  watch = true

integration/log_rotation_test.go

@@ -18,6 +18,13 @@ import (
 // Log rotation integration test suite
 type LogRotationSuite struct{ BaseSuite }
 
+func (s *LogRotationSuite) SetUpSuite(c *check.C) {
+	s.createComposeProject(c, "access_log")
+	s.composeProject.Start(c)
+
+	s.composeProject.Container(c, "server1")
+}
+
 func (s *LogRotationSuite) TestAccessLogRotation(c *check.C) {
 	// Start Traefik
 	cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
@@ -31,15 +38,14 @@ func (s *LogRotationSuite) TestAccessLogRotation(c *check.C) {
 	// Verify Traefik started ok
 	verifyEmptyErrorLog(c, "traefik.log")
 
-	// Start test servers
+	waitForTraefik(c, "server1")
-	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)
+	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8000/", nil)
+	c.Assert(err, checker.IsNil)
+	req.Host = "frontend1.docker.local"
+
+	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
 	c.Assert(err, checker.IsNil)
 
 	// Rename access log
@@ -51,9 +57,9 @@ func (s *LogRotationSuite) TestAccessLogRotation(c *check.C) {
 	c.Assert(err, checker.IsNil)
 
 	// continue issuing requests
-	_, err = http.Get("http://127.0.0.1:8000/test1")
+	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
 	c.Assert(err, checker.IsNil)
-	_, err = http.Get("http://127.0.0.1:8000/test1")
+	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
 	c.Assert(err, checker.IsNil)
 
 	// Verify access.log.rotated output as expected
@@ -86,9 +92,7 @@ func (s *LogRotationSuite) TestTraefikLogRotation(c *check.C) {
 	defer os.Remove(traefikTestAccessLogFile)
 	defer os.Remove(traefikTestLogFile)
 
-	// Ensure Traefik has started
+	waitForTraefik(c, "server1")
-	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")

integration/resources/compose/access_log.yml

@@ -0,0 +1,99 @@
+server0:
+  image: emilevauge/whoami
+  labels:
+    - traefik.enable=true
+    - traefik.port=80
+    - traefik.backend=backend1
+    - traefik.frontend.entryPoints=http
+    - traefik.frontend.rule=Path:/test
+server1:
+  image: emilevauge/whoami
+  labels:
+    - traefik.enable=true
+    - traefik.port=80
+    - traefik.backend=backend1
+    - traefik.frontend.entryPoints=http
+    - traefik.frontend.rule=Host:frontend1.docker.local
+server2:
+  image: emilevauge/whoami
+  labels:
+    - traefik.enable=true
+    - traefik.port=80
+    - traefik.backend=backend2
+    - traefik.frontend.entryPoints=http
+    - traefik.frontend.rule=Host:frontend2.docker.local
+    - traefik.frontend.passHostHeader=true
+    - backend.loadbalancer.method=drr
+server3:
+  image: emilevauge/whoami
+  labels:
+    - traefik.enable=true
+    - traefik.port=80
+    - traefik.backend=backend2
+    - traefik.frontend.entryPoints=http
+    - traefik.frontend.rule=Host:frontend2.docker.local
+    - traefik.frontend.passHostHeader=true
+    - backend.loadbalancer.method=drr
+authFrontend:
+  image: emilevauge/whoami
+  labels:
+    - traefik.enable=true
+    - traefik.port=80
+    - traefik.backend=backend3
+    - traefik.frontend.entryPoints=httpFrontendAuth
+    - traefik.frontend.rule=Host:frontend.auth.docker.local
+    - traefik.frontend.auth.basic=test:$$apr1$$H6uskkkW$$IgXLP6ewTrSuBkTrqE8wj/
+authEntrypoint:
+  image: emilevauge/whoami
+  labels:
+    - traefik.enable=true
+    - traefik.port=80
+    - traefik.backend=backend3
+    - traefik.frontend.entryPoints=httpAuth
+    - traefik.frontend.rule=Host:entrypoint.auth.docker.local
+entrypointRedirect:
+  image: emilevauge/whoami
+  labels:
+    - traefik.enable=true
+    - traefik.port=80
+    - traefik.backend=backend3
+    - traefik.frontend.entryPoints=httpRedirect
+    - traefik.frontend.rule=Path:/test
+frontendRedirect:
+  image: emilevauge/whoami
+  labels:
+    - traefik.enable=true
+    - traefik.port=80
+    - traefik.backend=backend3
+    - traefik.frontend.entryPoints=frontendRedirect
+    - traefik.frontend.rule=Path:/test
+    - traefik.frontend.redirect.entryPoint=http
+rateLimit:
+  image: emilevauge/whoami
+  labels:
+    - traefik.enable=true
+    - traefik.port=80
+    - traefik.backend=backend3
+    - traefik.frontend.entryPoints=httpRateLimit
+    - traefik.frontend.rule=Host:ratelimit.docker.local
+    - traefik.frontend.rateLimit.extractorFunc=client.ip
+    - traefik.frontend.rateLimit.rateSet.powpow.period=3s
+    - traefik.frontend.rateLimit.rateSet.powpow.average=1
+    - traefik.frontend.rateLimit.rateSet.powpow.burst=2
+entrypointWhitelist:
+  image: emilevauge/whoami
+  labels:
+    - traefik.enable=true
+    - traefik.port=80
+    - traefik.backend=backend3
+    - traefik.frontend.entryPoints=httpWhitelistReject
+    - traefik.frontend.rule=Host:entrypoint.whitelist.docker.local
+frontendWhitelist:
+  image: emilevauge/whoami
+  labels:
+    - traefik.enable=true
+    - traefik.port=80
+    - traefik.backend=backend3
+    - traefik.frontend.whitelistSourceRange=8.8.8.8/32
+    - traefik.frontend.entryPoints=http
+    - traefik.frontend.rule=Host:frontend.whitelist.docker.local

middlewares/accesslog/logger_formatters.go

@@ -31,19 +31,19 @@ func (f *CommonLogFormatter) Format(entry *logrus.Entry) ([]byte, error) {
 		entry.Data[RequestMethod],
 		entry.Data[RequestPath],
 		entry.Data[RequestProtocol],
-		toLog(entry.Data[OriginStatus]),
+		toLog(entry.Data[OriginStatus], defaultValue),
-		toLog(entry.Data[OriginContentSize]),
+		toLog(entry.Data[OriginContentSize], defaultValue),
-		toLog(entry.Data["request_Referer"]),
+		toLog(entry.Data["request_Referer"], `"-"`),
-		toLog(entry.Data["request_User-Agent"]),
+		toLog(entry.Data["request_User-Agent"], `"-"`),
-		toLog(entry.Data[RequestCount]),
+		toLog(entry.Data[RequestCount], defaultValue),
-		toLog(entry.Data[FrontendName]),
+		toLog(entry.Data[FrontendName], defaultValue),
-		toLog(entry.Data[BackendURL]),
+		toLog(entry.Data[BackendURL], defaultValue),
 		elapsedMillis)
 
 	return b.Bytes(), err
 }
 
-func toLog(v interface{}) interface{} {
+func toLog(v interface{}, defaultValue string) interface{} {
 	if v == nil {
 		return defaultValue
 	}

middlewares/accesslog/logger_formatters_test.go

@@ -35,7 +35,7 @@ func TestCommonLogFormatter_Format(t *testing.T) {
 				FrontendName:         "",
 				BackendURL:           "",
 			},
-			expectedLog: `10.0.0.1 - Client [10/Nov/2009:23:00:00 +0000] "GET /foo http" - - - - 0 - - 123000ms
+			expectedLog: `10.0.0.1 - Client [10/Nov/2009:23:00:00 +0000] "GET /foo http" - - "-" "-" 0 - - 123000ms
 `,
 		},
 		{
@@ -106,7 +106,7 @@ func Test_toLog(t *testing.T) {
 		t.Run(test.name, func(t *testing.T) {
 			t.Parallel()
 
-			lg := toLog(test.value)
+			lg := toLog(test.value, defaultValue)
 
 			assert.Equal(t, test.expectedLog, lg)
 		})

middlewares/accesslog/save_backend.go

@@ -64,18 +64,13 @@ func (sb *SaveFrontend) ServeHTTP(rw http.ResponseWriter, r *http.Request) {
 	sb.next.ServeHTTP(rw, r)
 }
 
-//-------------------------------------------------------------------------------------------------
+// SaveNegroniFrontend sends the frontend name to the logger.
-// the next 3 function (SaveNegroniFrontend, NewSaveNegroniFrontend, ServeHTTP) are temporary,
-// DON'T USE THIS FUNCTION, MUST BE SUPPRESS BEFORE MERGING #1485
-
-// SaveNegroniFrontend sends the frontend name to the logger. These are sometimes used with a corresponding
-// SaveBackend handler, but not always. For example, redirected requests don't reach a backend.
 type SaveNegroniFrontend struct {
 	next         negroni.Handler
 	frontendName string
 }
 
-// NewSaveNegroniFrontend creates a SaveFrontend handler.
+// NewSaveNegroniFrontend creates a SaveNegroniFrontend handler.
 func NewSaveNegroniFrontend(next negroni.Handler, frontendName string) negroni.Handler {
 	return &SaveNegroniFrontend{next, frontendName}
 }
@@ -87,4 +82,32 @@ func (sb *SaveNegroniFrontend) ServeHTTP(rw http.ResponseWriter, r *http.Request
 	sb.next.ServeHTTP(rw, r, next)
 }
 
-//-------------------------------------------------------------------------------------------------
+// SaveNegroniBackend sends the backend name to the logger.
+type SaveNegroniBackend struct {
+	next        negroni.Handler
+	backendName string
+}
+
+// NewSaveNegroniBackend creates a SaveBackend handler.
+func NewSaveNegroniBackend(next negroni.Handler, backendName string) negroni.Handler {
+	return &SaveNegroniBackend{next, backendName}
+}
+
+func (sb *SaveNegroniBackend) ServeHTTP(rw http.ResponseWriter, r *http.Request, next http.HandlerFunc) {
+	table := GetLogDataTable(r)
+	table.Core[BackendName] = sb.backendName
+
+	crw := &captureResponseWriter{rw: rw}
+	start := time.Now().UTC()
+
+	sb.next.ServeHTTP(crw, r, next)
+
+	// use UTC to handle switchover of daylight saving correctly
+	table.Core[OriginDuration] = time.Now().UTC().Sub(start)
+	table.Core[OriginStatus] = crw.Status()
+	table.Core[OriginStatusLine] = fmt.Sprintf("%03d %s", crw.Status(), http.StatusText(crw.Status()))
+	// make copy of headers so we can ensure there is no subsequent mutation during response processing
+	table.OriginResponse = make(http.Header)
+	utils.CopyHeaders(table.OriginResponse, crw.Header())
+	table.Core[OriginContentSize] = crw.Size()
+}

server/server.go

@@ -322,7 +322,7 @@ func (s *Server) setupServerEntryPoint(newServerEntryPointName string, newServer
 		if err != nil {
 			log.Fatal("Error starting server: ", err)
 		}
-		serverMiddlewares = append(serverMiddlewares, authMiddleware)
+		serverMiddlewares = append(serverMiddlewares, s.wrapNegroniHandlerWithAccessLog(authMiddleware, fmt.Sprintf("Auth for entrypoint %s", newServerEntryPointName)))
 		serverInternalMiddlewares = append(serverInternalMiddlewares, authMiddleware)
 	}
 	if s.globalConfiguration.EntryPoints[newServerEntryPointName].Compress {
@@ -333,7 +333,7 @@ func (s *Server) setupServerEntryPoint(newServerEntryPointName string, newServer
 		if err != nil {
 			log.Fatal("Error starting server: ", err)
 		}
-		serverMiddlewares = append(serverMiddlewares, ipWhitelistMiddleware)
+		serverMiddlewares = append(serverMiddlewares, s.wrapNegroniHandlerWithAccessLog(ipWhitelistMiddleware, fmt.Sprintf("ipwhitelister for entrypoint %s", newServerEntryPointName)))
 		serverInternalMiddlewares = append(serverInternalMiddlewares, ipWhitelistMiddleware)
 	}
 	newSrv, listener, err := s.prepareServer(newServerEntryPointName, s.globalConfiguration.EntryPoints[newServerEntryPointName], newServerEntryPoint.httpRouter, serverMiddlewares, serverInternalMiddlewares)
@@ -418,8 +418,8 @@ func (s *Server) defaultConfigurationValues(configuration *types.Configuration)
 	if configuration == nil || configuration.Frontends == nil {
 		return
 	}
-	s.configureFrontends(configuration.Frontends)
+	configureFrontends(configuration.Frontends, s.globalConfiguration.DefaultEntryPoints)
-	s.configureBackends(configuration.Backends)
+	configureBackends(configuration.Backends)
 }
 
 func (s *Server) listenConfigurations(stop chan bool) {
@@ -965,14 +965,9 @@ func (s *Server) loadConfig(configurations types.Configurations, globalConfigura
 						log.Errorf("Skipping frontend %s...", frontendName)
 						continue frontend
 					} else {
-						if s.accessLoggerMiddleware != nil {
+						handlerToUse := s.wrapNegroniHandlerWithAccessLog(handler, fmt.Sprintf("entrypoint redirect for %s", frontendName))
-							saveFrontend := accesslog.NewSaveNegroniFrontend(handler, frontendName)
+						n.Use(handlerToUse)
-							n.Use(saveFrontend)
+						redirectHandlers[entryPointName] = handlerToUse
-							redirectHandlers[entryPointName] = saveFrontend
-						} else {
-							n.Use(handler)
-							redirectHandlers[entryPointName] = handler
-						}
 					}
 				}
 				if backends[entryPointName+frontend.Backend] == nil {
@@ -1116,6 +1111,7 @@ func (s *Server) loadConfig(configurations types.Configurations, globalConfigura
 
 					if frontend.RateLimit != nil && len(frontend.RateLimit.RateSet) > 0 {
 						lb, err = s.buildRateLimiter(lb, frontend.RateLimit)
+						lb = s.wrapHTTPHandlerWithAccessLog(lb, fmt.Sprintf("rate limit for %s", frontendName))
 						if err != nil {
 							log.Errorf("Error creating rate limiter: %v", err)
 							log.Errorf("Skipping frontend %s...", frontendName)
@@ -1133,6 +1129,7 @@ func (s *Server) loadConfig(configurations types.Configurations, globalConfigura
 						}
 						log.Debugf("Creating load-balancer connlimit")
 						lb, err = connlimit.New(lb, extractFunc, maxConns.Amount)
+						lb = s.wrapHTTPHandlerWithAccessLog(lb, fmt.Sprintf("connection limit for %s", frontendName))
 						if err != nil {
 							log.Errorf("Error creating connlimit: %v", err)
 							log.Errorf("Skipping frontend %s...", frontendName)
@@ -1153,6 +1150,7 @@ func (s *Server) loadConfig(configurations types.Configurations, globalConfigura
 					if err != nil {
 						log.Errorf("Error creating IP Whitelister: %s", err)
 					} else if ipWhitelistMiddleware != nil {
+						ipWhitelistMiddleware = s.wrapNegroniHandlerWithAccessLog(ipWhitelistMiddleware, fmt.Sprintf("ipwhitelister for %s", frontendName))
 						n.Use(s.tracingMiddleware.NewNegroniHandlerWrapper("IP whitelist", ipWhitelistMiddleware, false))
 						log.Infof("Configured IP Whitelists: %s", frontend.WhitelistSourceRange)
 					}
@@ -1162,7 +1160,7 @@ func (s *Server) loadConfig(configurations types.Configurations, globalConfigura
 						if err != nil {
 							log.Errorf("Error creating Frontend Redirect: %v", err)
 						}
-						n.Use(rewrite)
+						n.Use(s.wrapNegroniHandlerWithAccessLog(rewrite, fmt.Sprintf("frontend redirect for %s", frontendName)))
 						log.Debugf("Frontend %s redirect created", frontendName)
 					}
 
@@ -1180,7 +1178,7 @@ func (s *Server) loadConfig(configurations types.Configurations, globalConfigura
 						if err != nil {
 							log.Errorf("Error creating Auth: %s", err)
 						} else {
-							n.Use(authMiddleware)
+							n.Use(s.wrapNegroniHandlerWithAccessLog(authMiddleware, fmt.Sprintf("Auth for %s", frontendName)))
 						}
 					}
 
@@ -1370,7 +1368,7 @@ func (s *Server) buildRedirect(entryPointName string) (string, string, error) {
 
 func (s *Server) buildDefaultHTTPRouter() *mux.Router {
 	router := mux.NewRouter()
-	router.NotFoundHandler = http.HandlerFunc(notFoundHandler)
+	router.NotFoundHandler = s.wrapHTTPHandlerWithAccessLog(http.HandlerFunc(notFoundHandler), "backend not found")
 	router.StrictSlash(true)
 	router.SkipClean(true)
 	return router
@@ -1422,16 +1420,16 @@ func sortedFrontendNamesForConfig(configuration *types.Configuration) []string {
 	return keys
 }
 
-func (s *Server) configureFrontends(frontends map[string]*types.Frontend) {
+func configureFrontends(frontends map[string]*types.Frontend, defaultEntrypoints []string) {
 	for _, frontend := range frontends {
 		// default endpoints if not defined in frontends
 		if len(frontend.EntryPoints) == 0 {
-			frontend.EntryPoints = s.globalConfiguration.DefaultEntryPoints
+			frontend.EntryPoints = defaultEntrypoints
 		}
 	}
 }
 
-func (*Server) configureBackends(backends map[string]*types.Backend) {
+func configureBackends(backends map[string]*types.Backend) {
 	for backendName := range backends {
 		backend := backends[backendName]
 		if backend.LoadBalancer != nil && backend.LoadBalancer.Sticky {
@@ -1534,3 +1532,20 @@ func (s *Server) buildRetryMiddleware(handler http.Handler, globalConfig configu
 
 	return s.tracingMiddleware.NewHTTPHandlerWrapper("Retry", middlewares.NewRetry(retryAttempts, handler, retryListeners), false)
 }
+func (s *Server) wrapNegroniHandlerWithAccessLog(handler negroni.Handler, frontendName string) negroni.Handler {
+	if s.accessLoggerMiddleware != nil {
+		saveBackend := accesslog.NewSaveNegroniBackend(handler, "Træfik")
+		saveFrontend := accesslog.NewSaveNegroniFrontend(saveBackend, frontendName)
+		return saveFrontend
+	}
+	return handler
+}
+
+func (s *Server) wrapHTTPHandlerWithAccessLog(handler http.Handler, frontendName string) http.Handler {
+	if s.accessLoggerMiddleware != nil {
+		saveBackend := accesslog.NewSaveBackend(handler, "Træfik")
+		saveFrontend := accesslog.NewSaveFrontend(saveBackend, frontendName)
+		return saveFrontend
+	}
+	return handler
+}

server/server_test.go

@@ -742,8 +742,7 @@ func TestConfigureBackends(t *testing.T) {
 				LoadBalancer: test.lb,
 			}
 
-			srv := Server{}
+			configureBackends(map[string]*types.Backend{
-			srv.configureBackends(map[string]*types.Backend{
 				"backend": backend,
 			})