diff --git a/integration/access_log_test.go b/integration/access_log_test.go index cb1ab8896..699e8153f 100644 --- a/integration/access_log_test.go +++ b/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) - os.Remove(traefikTestLogFile) + ensureWorkingDirectoryIsClean() // 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 { - 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) + waitForTraefik(c, "server1") + + checkStatsForLogFile(c) // Verify Traefik started OK - 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) - } - - // Start test servers - ts1 := startAccessLogServer(8081) - defer ts1.Close() - ts2 := startAccessLogServer(8082) - defer ts2.Close() - ts3 := startAccessLogServer(8083) - defer ts3.Close() + traefikLog := checkTraefikStarted(c) // 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) - 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) - } - } + count := checkAccessLogOutput(err, c) + 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[12], checker.HasPrefix, "http://127.0.0.1:808") + c.Assert(tokens[11], checker.HasPrefix, "Host-") + c.Assert(tokens[12], checker.HasPrefix, "http://") 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:]) - }) - if listener, err := net.Listen("tcp", fmt.Sprintf("127.0.0.1:%d", port)); err != nil { - panic(err) - } else { - ts = &httptest.Server{ - Listener: listener, - Config: &http.Server{Handler: handler}, - } - ts.Start() - } - return +func checkAccessLogExactValues(c *check.C, line string, i int, v accessLogValue) { + tokens, err := shellwords.Parse(line) + c.Assert(err, checker.IsNil) + c.Assert(tokens, checker.HasLen, 14) + c.Assert(tokens[6], checker.Equals, v.code) + c.Assert(tokens[10], checker.Equals, fmt.Sprintf("%d", i+1)) + c.Assert(tokens[11], checker.HasPrefix, v.value) + c.Assert(tokens[12], checker.Equals, v.backendName) + c.Assert(tokens[13], checker.Matches, `^\d+ms$`) +} + +func waitForTraefik(c *check.C, containerName string) { + // Wait for Traefik to turn ready. + 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) } diff --git a/integration/fixtures/access_log_config.toml b/integration/fixtures/access_log_config.toml index ed49e68af..46b44ecf7 100644 --- a/integration/fixtures/access_log_config.toml +++ b/integration/fixtures/access_log_config.toml @@ -1,48 +1,42 @@ ################################################################ # Global configuration ################################################################ -traefikLogsFile = "traefik.log" -accessLogsFile = "access.log" +[traefikLog] + 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 -################################################################ -# Web configuration backend -################################################################ -[web] -address = ":7888" +[api] + dashboard = false -################################################################ -# File configuration backend -################################################################ -[file] - -################################################################ -# 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" +[docker] + exposedByDefault = false + domain = "docker.local" + watch = true \ No newline at end of file diff --git a/integration/fixtures/traefik_log_config.toml b/integration/fixtures/traefik_log_config.toml index 6ab0de24a..74a46ace0 100644 --- a/integration/fixtures/traefik_log_config.toml +++ b/integration/fixtures/traefik_log_config.toml @@ -1,8 +1,12 @@ ################################################################ # Global configuration ################################################################ -traefikLogsFile = "traefik.log" -accessLogsFile = "access.log" +[traefikLog] + 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 \ No newline at end of file diff --git a/integration/log_rotation_test.go b/integration/log_rotation_test.go index a0a97d8fd..986e6f7be 100644 --- a/integration/log_rotation_test.go +++ b/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 - ts1 := startAccessLogServer(8081) - defer ts1.Close() - - // Allow time to startup - time.Sleep(1 * time.Second) + waitForTraefik(c, "server1") // 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 - err = try.GetRequest("http://127.0.0.1:8000/test1", 500*time.Millisecond) - c.Assert(err, checker.IsNil) + waitForTraefik(c, "server1") // Rename traefik log err = os.Rename(traefikTestLogFile, traefikTestLogFile+".rotated") diff --git a/integration/resources/compose/access_log.yml b/integration/resources/compose/access_log.yml new file mode 100644 index 000000000..4e51865e9 --- /dev/null +++ b/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 diff --git a/middlewares/accesslog/logger_formatters.go b/middlewares/accesslog/logger_formatters.go index fcc63e6c9..e36fc3a74 100644 --- a/middlewares/accesslog/logger_formatters.go +++ b/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[OriginContentSize]), - toLog(entry.Data["request_Referer"]), - toLog(entry.Data["request_User-Agent"]), - toLog(entry.Data[RequestCount]), - toLog(entry.Data[FrontendName]), - toLog(entry.Data[BackendURL]), + toLog(entry.Data[OriginStatus], defaultValue), + toLog(entry.Data[OriginContentSize], defaultValue), + toLog(entry.Data["request_Referer"], `"-"`), + toLog(entry.Data["request_User-Agent"], `"-"`), + toLog(entry.Data[RequestCount], defaultValue), + toLog(entry.Data[FrontendName], defaultValue), + 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 } diff --git a/middlewares/accesslog/logger_formatters_test.go b/middlewares/accesslog/logger_formatters_test.go index 051d73850..277f8aa63 100644 --- a/middlewares/accesslog/logger_formatters_test.go +++ b/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) }) diff --git a/middlewares/accesslog/save_backend.go b/middlewares/accesslog/save_backend.go index 9f931702b..353adbe71 100644 --- a/middlewares/accesslog/save_backend.go +++ b/middlewares/accesslog/save_backend.go @@ -64,18 +64,13 @@ func (sb *SaveFrontend) ServeHTTP(rw http.ResponseWriter, r *http.Request) { sb.next.ServeHTTP(rw, r) } -//------------------------------------------------------------------------------------------------- -// 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. +// SaveNegroniFrontend sends the frontend name to the logger. 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() +} diff --git a/server/server.go b/server/server.go index d656dab06..52e10d441 100644 --- a/server/server.go +++ b/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) - s.configureBackends(configuration.Backends) + configureFrontends(configuration.Frontends, s.globalConfiguration.DefaultEntryPoints) + 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 { - saveFrontend := accesslog.NewSaveNegroniFrontend(handler, frontendName) - n.Use(saveFrontend) - redirectHandlers[entryPointName] = saveFrontend - } else { - n.Use(handler) - redirectHandlers[entryPointName] = handler - } + handlerToUse := s.wrapNegroniHandlerWithAccessLog(handler, fmt.Sprintf("entrypoint redirect for %s", frontendName)) + n.Use(handlerToUse) + redirectHandlers[entryPointName] = handlerToUse } } 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 +} diff --git a/server/server_test.go b/server/server_test.go index 4e99d4c96..4340f62ed 100644 --- a/server/server_test.go +++ b/server/server_test.go @@ -742,8 +742,7 @@ func TestConfigureBackends(t *testing.T) { LoadBalancer: test.lb, } - srv := Server{} - srv.configureBackends(map[string]*types.Backend{ + configureBackends(map[string]*types.Backend{ "backend": backend, })