traefik/integration/access_log_test.go

632 lines
16 KiB
Go
Raw Normal View History

package integration
2016-04-20 18:54:57 +00:00
import (
2018-01-24 17:18:03 +00:00
"crypto/md5"
"crypto/rand"
2016-04-20 18:54:57 +00:00
"fmt"
2018-01-24 17:18:03 +00:00
"io"
2016-04-20 18:54:57 +00:00
"io/ioutil"
"net/http"
"os"
"strings"
"time"
"github.com/containous/traefik/integration/try"
2019-03-15 08:42:03 +00:00
"github.com/containous/traefik/pkg/log"
"github.com/containous/traefik/pkg/middlewares/accesslog"
2016-04-20 18:54:57 +00:00
"github.com/go-check/check"
checker "github.com/vdemeester/shakers"
)
const (
traefikTestLogFile = "traefik.log"
traefikTestAccessLogFile = "access.log"
)
2016-04-20 18:54:57 +00:00
// AccessLogSuite
type AccessLogSuite struct{ BaseSuite }
2018-01-11 09:04:03 +00:00
type accessLogValue struct {
formatOnly bool
code string
user string
routerName string
serviceURL string
2018-01-11 09:04:03 +00:00
}
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")
}
2018-02-05 08:48:03 +00:00
func (s *AccessLogSuite) TearDownTest(c *check.C) {
displayTraefikLogFile(c, traefikTestLogFile)
os.Remove(traefikTestAccessLogFile)
}
2016-04-20 18:54:57 +00:00
func (s *AccessLogSuite) TestAccessLog(c *check.C) {
2018-01-11 09:04:03 +00:00
ensureWorkingDirectoryIsClean()
2016-04-20 18:54:57 +00:00
// Start Traefik
cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
defer display(c)
2018-02-05 08:48:03 +00:00
defer func() {
traefikLog, err := ioutil.ReadFile(traefikTestLogFile)
c.Assert(err, checker.IsNil)
log.Info(string(traefikLog))
}()
2016-04-20 18:54:57 +00:00
err := cmd.Start()
c.Assert(err, checker.IsNil)
defer cmd.Process.Kill()
2018-01-11 09:04:03 +00:00
waitForTraefik(c, "server1")
checkStatsForLogFile(c)
// Verify Traefik started OK
2018-02-05 08:48:03 +00:00
checkTraefikStarted(c)
2018-01-11 09:04:03 +00:00
// Make some requests
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)
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
2018-02-05 08:48:03 +00:00
count := checkAccessLogOutput(c)
2018-01-11 09:04:03 +00:00
c.Assert(count, checker.GreaterOrEqualThan, 3)
// Verify no other Traefik problems
2018-02-05 08:48:03 +00:00
checkNoOtherTraefikProblems(c)
2018-01-11 09:04:03 +00:00
}
func (s *AccessLogSuite) TestAccessLogAuthFrontend(c *check.C) {
ensureWorkingDirectoryIsClean()
expected := []accessLogValue{
{
formatOnly: false,
code: "401",
user: "-",
routerName: "rt-authFrontend",
serviceURL: "-",
2018-01-11 09:04:03 +00:00
},
}
// Start Traefik
cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
defer display(c)
2018-02-05 08:48:03 +00:00
2018-01-11 09:04:03 +00:00
err := cmd.Start()
c.Assert(err, checker.IsNil)
2018-01-11 09:04:03 +00:00
defer cmd.Process.Kill()
checkStatsForLogFile(c)
s.composeProject.Container(c, "authFrontend")
waitForTraefik(c, "authFrontend")
2016-04-20 18:54:57 +00:00
// Verify Traefik started OK
2018-02-05 08:48:03 +00:00
checkTraefikStarted(c)
2018-01-11 09:04:03 +00:00
// Test auth frontend
req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8006/", nil)
c.Assert(err, checker.IsNil)
2018-01-11 09:04:03 +00:00
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
2018-02-05 08:48:03 +00:00
count := checkAccessLogExactValuesOutput(c, expected)
2018-01-11 09:04:03 +00:00
c.Assert(count, checker.GreaterOrEqualThan, len(expected))
// Verify no other Traefik problems
2018-02-05 08:48:03 +00:00
checkNoOtherTraefikProblems(c)
2018-01-11 09:04:03 +00:00
}
func (s *AccessLogSuite) TestAccessLogDigestAuthMiddleware(c *check.C) {
2018-01-11 09:04:03 +00:00
ensureWorkingDirectoryIsClean()
expected := []accessLogValue{
{
formatOnly: false,
code: "401",
user: "-",
routerName: "rt-digestAuthMiddleware",
serviceURL: "-",
2018-01-11 09:04:03 +00:00
},
2018-01-24 17:18:03 +00:00
{
formatOnly: false,
code: "200",
user: "test",
routerName: "rt-digestAuthMiddleware",
serviceURL: "http://172.17.0",
2018-01-24 17:18:03 +00:00
},
}
// Start Traefik
cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
defer display(c)
2018-02-05 08:48:03 +00:00
2018-01-24 17:18:03 +00:00
err := cmd.Start()
c.Assert(err, checker.IsNil)
defer cmd.Process.Kill()
checkStatsForLogFile(c)
s.composeProject.Container(c, "digestAuthMiddleware")
2018-01-24 17:18:03 +00:00
waitForTraefik(c, "digestAuthMiddleware")
2018-01-24 17:18:03 +00:00
// Verify Traefik started OK
2018-02-05 08:48:03 +00:00
checkTraefikStarted(c)
2018-01-24 17:18:03 +00:00
// Test auth entrypoint
req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8008/", nil)
c.Assert(err, checker.IsNil)
req.Host = "entrypoint.digest.auth.docker.local"
resp, err := try.ResponseUntilStatusCode(req, 500*time.Millisecond, http.StatusUnauthorized)
c.Assert(err, checker.IsNil)
digestParts := digestParts(resp)
digestParts["uri"] = "/"
digestParts["method"] = http.MethodGet
digestParts["username"] = "test"
digestParts["password"] = "test"
req.Header.Set("Authorization", getDigestAuthorization(digestParts))
req.Header.Set("Content-Type", "application/json")
err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
c.Assert(err, checker.IsNil)
// Verify access.log output as expected
2018-02-05 08:48:03 +00:00
count := checkAccessLogExactValuesOutput(c, expected)
2018-01-24 17:18:03 +00:00
c.Assert(count, checker.GreaterOrEqualThan, len(expected))
// Verify no other Traefik problems
2018-02-05 08:48:03 +00:00
checkNoOtherTraefikProblems(c)
2018-01-24 17:18:03 +00:00
}
// Thanks to mvndaai for digest authentication
// https://stackoverflow.com/questions/39474284/how-do-you-do-a-http-post-with-digest-authentication-in-golang/39481441#39481441
func digestParts(resp *http.Response) map[string]string {
result := map[string]string{}
if len(resp.Header["Www-Authenticate"]) > 0 {
wantedHeaders := []string{"nonce", "realm", "qop", "opaque"}
responseHeaders := strings.Split(resp.Header["Www-Authenticate"][0], ",")
for _, r := range responseHeaders {
for _, w := range wantedHeaders {
if strings.Contains(r, w) {
result[w] = strings.Split(r, `"`)[1]
}
}
}
}
return result
}
func getMD5(data string) string {
digest := md5.New()
2018-08-06 18:00:03 +00:00
if _, err := digest.Write([]byte(data)); err != nil {
log.Error(err)
}
2018-01-24 17:18:03 +00:00
return fmt.Sprintf("%x", digest.Sum(nil))
}
func getCnonce() string {
b := make([]byte, 8)
2018-08-06 18:00:03 +00:00
if _, err := io.ReadFull(rand.Reader, b); err != nil {
log.Error(err)
}
2018-01-24 17:18:03 +00:00
return fmt.Sprintf("%x", b)[:16]
}
func getDigestAuthorization(digestParts map[string]string) string {
d := digestParts
ha1 := getMD5(d["username"] + ":" + d["realm"] + ":" + d["password"])
ha2 := getMD5(d["method"] + ":" + d["uri"])
nonceCount := "00000001"
cnonce := getCnonce()
response := getMD5(fmt.Sprintf("%s:%s:%s:%s:%s:%s", ha1, d["nonce"], nonceCount, cnonce, d["qop"], ha2))
authorization := fmt.Sprintf(`Digest username="%s", realm="%s", nonce="%s", uri="%s", cnonce="%s", nc=%s, qop=%s, response="%s", opaque="%s", algorithm="MD5"`,
d["username"], d["realm"], d["nonce"], d["uri"], cnonce, nonceCount, d["qop"], response, d["opaque"])
return authorization
}
2018-01-11 09:04:03 +00:00
func (s *AccessLogSuite) TestAccessLogFrontendRedirect(c *check.C) {
ensureWorkingDirectoryIsClean()
expected := []accessLogValue{
{
formatOnly: false,
code: "302",
user: "-",
routerName: "rt-frontendRedirect",
serviceURL: "-",
2018-01-11 09:04:03 +00:00
},
{
formatOnly: true,
},
}
// Start Traefik
cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
defer display(c)
2018-02-05 08:48:03 +00:00
2018-01-11 09:04:03 +00:00
err := cmd.Start()
c.Assert(err, checker.IsNil)
2018-01-11 09:04:03 +00:00
defer cmd.Process.Kill()
checkStatsForLogFile(c)
s.composeProject.Container(c, "frontendRedirect")
waitForTraefik(c, "frontendRedirect")
// Verify Traefik started OK
2018-02-05 08:48:03 +00:00
checkTraefikStarted(c)
2018-01-11 09:04:03 +00:00
// 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
2018-02-05 08:48:03 +00:00
count := checkAccessLogExactValuesOutput(c, expected)
2018-01-11 09:04:03 +00:00
c.Assert(count, checker.GreaterOrEqualThan, len(expected))
// Verify no other Traefik problems
2018-02-05 08:48:03 +00:00
checkNoOtherTraefikProblems(c)
2018-01-11 09:04:03 +00:00
}
func (s *AccessLogSuite) TestAccessLogRateLimit(c *check.C) {
ensureWorkingDirectoryIsClean()
expected := []accessLogValue{
{
formatOnly: true,
},
{
formatOnly: true,
},
{
formatOnly: false,
code: "429",
user: "-",
routerName: "rt-rateLimit",
serviceURL: "-",
2018-01-11 09:04:03 +00:00
},
}
// Start Traefik
cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
defer display(c)
2018-02-05 08:48:03 +00:00
2018-01-11 09:04:03 +00:00
err := cmd.Start()
c.Assert(err, checker.IsNil)
defer cmd.Process.Kill()
checkStatsForLogFile(c)
s.composeProject.Container(c, "rateLimit")
waitForTraefik(c, "rateLimit")
// Verify Traefik started OK
2018-02-05 08:48:03 +00:00
checkTraefikStarted(c)
2018-01-11 09:04:03 +00:00
// 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
2018-02-05 08:48:03 +00:00
count := checkAccessLogExactValuesOutput(c, expected)
2018-01-11 09:04:03 +00:00
c.Assert(count, checker.GreaterOrEqualThan, len(expected))
// Verify no other Traefik problems
2018-02-05 08:48:03 +00:00
checkNoOtherTraefikProblems(c)
2018-01-11 09:04:03 +00:00
}
func (s *AccessLogSuite) TestAccessLogBackendNotFound(c *check.C) {
ensureWorkingDirectoryIsClean()
expected := []accessLogValue{
{
formatOnly: false,
code: "404",
user: "-",
routerName: "-",
serviceURL: "-",
2018-01-11 09:04:03 +00:00
},
}
// Start Traefik
cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
defer display(c)
2018-02-05 08:48:03 +00:00
2018-01-11 09:04:03 +00:00
err := cmd.Start()
c.Assert(err, checker.IsNil)
defer cmd.Process.Kill()
waitForTraefik(c, "server1")
checkStatsForLogFile(c)
// Verify Traefik started OK
2018-02-05 08:48:03 +00:00
checkTraefikStarted(c)
2018-01-11 09:04:03 +00:00
// 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
2018-02-05 08:48:03 +00:00
count := checkAccessLogExactValuesOutput(c, expected)
2018-01-11 09:04:03 +00:00
c.Assert(count, checker.GreaterOrEqualThan, len(expected))
// Verify no other Traefik problems
2018-02-05 08:48:03 +00:00
checkNoOtherTraefikProblems(c)
2018-01-11 09:04:03 +00:00
}
func (s *AccessLogSuite) TestAccessLogFrontendWhitelist(c *check.C) {
ensureWorkingDirectoryIsClean()
expected := []accessLogValue{
{
formatOnly: false,
code: "403",
user: "-",
routerName: "rt-frontendWhitelist",
serviceURL: "-",
2018-01-11 09:04:03 +00:00
},
}
// Start Traefik
cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
defer display(c)
2018-02-05 08:48:03 +00:00
2018-01-11 09:04:03 +00:00
err := cmd.Start()
c.Assert(err, checker.IsNil)
defer cmd.Process.Kill()
checkStatsForLogFile(c)
s.composeProject.Container(c, "frontendWhitelist")
waitForTraefik(c, "frontendWhitelist")
// Verify Traefik started OK
2018-02-05 08:48:03 +00:00
checkTraefikStarted(c)
2018-01-11 09:04:03 +00:00
// 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
2018-02-05 08:48:03 +00:00
count := checkAccessLogExactValuesOutput(c, expected)
2018-01-11 09:04:03 +00:00
c.Assert(count, checker.GreaterOrEqualThan, len(expected))
// Verify no other Traefik problems
2018-02-05 08:48:03 +00:00
checkNoOtherTraefikProblems(c)
2018-01-11 09:04:03 +00:00
}
2018-10-25 16:00:05 +00:00
func (s *AccessLogSuite) TestAccessLogAuthFrontendSuccess(c *check.C) {
ensureWorkingDirectoryIsClean()
expected := []accessLogValue{
{
formatOnly: false,
code: "200",
user: "test",
routerName: "rt-authFrontend",
serviceURL: "http://172.17.0",
2018-10-25 16:00:05 +00:00
},
}
// 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()
checkStatsForLogFile(c)
s.composeProject.Container(c, "authFrontend")
waitForTraefik(c, "authFrontend")
// Verify Traefik started OK
checkTraefikStarted(c)
// Test auth entrypoint
req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8006/", nil)
c.Assert(err, checker.IsNil)
req.Host = "frontend.auth.docker.local"
req.SetBasicAuth("test", "test")
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(c, expected)
c.Assert(count, checker.GreaterOrEqualThan, len(expected))
// Verify no other Traefik problems
checkNoOtherTraefikProblems(c)
}
2018-02-05 08:48:03 +00:00
func checkNoOtherTraefikProblems(c *check.C) {
traefikLog, err := ioutil.ReadFile(traefikTestLogFile)
2018-01-11 09:04:03 +00:00
c.Assert(err, checker.IsNil)
if len(traefikLog) > 0 {
fmt.Printf("%s\n", string(traefikLog))
c.Assert(traefikLog, checker.HasLen, 0)
}
}
2018-02-05 08:48:03 +00:00
func checkAccessLogOutput(c *check.C) int {
lines := extractLines(c)
count := 0
for i, line := range lines {
if len(line) > 0 {
count++
CheckAccessLogFormat(c, line, i)
2016-04-20 18:54:57 +00:00
}
}
2018-01-11 09:04:03 +00:00
return count
}
2016-04-20 18:54:57 +00:00
2018-02-05 08:48:03 +00:00
func checkAccessLogExactValuesOutput(c *check.C, values []accessLogValue) int {
lines := extractLines(c)
2018-01-11 09:04:03 +00:00
count := 0
for i, line := range lines {
fmt.Println(line)
2018-01-11 09:04:03 +00:00
if len(line) > 0 {
count++
if values[i].formatOnly {
CheckAccessLogFormat(c, line, i)
} else {
checkAccessLogExactValues(c, line, i, values[i])
}
}
}
return count
}
2018-02-05 08:48:03 +00:00
func extractLines(c *check.C) []string {
2018-01-11 09:04:03 +00:00
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 {
2016-04-20 18:54:57 +00:00
fmt.Printf("%s\n", string(traefikLog))
c.Assert(traefikLog, checker.HasLen, 0)
2016-04-20 18:54:57 +00:00
}
2018-01-11 09:04:03 +00:00
return traefikLog
2016-04-20 18:54:57 +00:00
}
func CheckAccessLogFormat(c *check.C, line string, i int) {
2018-03-14 13:12:04 +00:00
results, err := accesslog.ParseAccessLog(line)
c.Assert(err, checker.IsNil)
c.Assert(results, checker.HasLen, 14)
c.Assert(results[accesslog.OriginStatus], checker.Matches, `^(-|\d{3})$`)
c.Assert(results[accesslog.RequestCount], checker.Equals, fmt.Sprintf("%d", i+1))
c.Assert(results[accesslog.RouterName], checker.HasPrefix, "\"docker@rt-")
c.Assert(results[accesslog.ServiceURL], checker.HasPrefix, "\"http://")
2018-03-14 13:12:04 +00:00
c.Assert(results[accesslog.Duration], checker.Matches, `^\d+ms$`)
}
2018-01-11 09:04:03 +00:00
func checkAccessLogExactValues(c *check.C, line string, i int, v accessLogValue) {
2018-03-14 13:12:04 +00:00
results, err := accesslog.ParseAccessLog(line)
// c.Assert(nil, checker.Equals, line)
2018-01-11 09:04:03 +00:00
c.Assert(err, checker.IsNil)
2018-03-14 13:12:04 +00:00
c.Assert(results, checker.HasLen, 14)
2018-01-24 17:18:03 +00:00
if len(v.user) > 0 {
2018-03-14 13:12:04 +00:00
c.Assert(results[accesslog.ClientUsername], checker.Equals, v.user)
2018-01-24 17:18:03 +00:00
}
2018-03-14 13:12:04 +00:00
c.Assert(results[accesslog.OriginStatus], checker.Equals, v.code)
c.Assert(results[accesslog.RequestCount], checker.Equals, fmt.Sprintf("%d", i+1))
c.Assert(results[accesslog.RouterName], checker.Matches, `^"?(docker@)?`+v.routerName+`.*$`)
c.Assert(results[accesslog.ServiceURL], checker.Matches, `^"?`+v.serviceURL+`.*$`)
2018-03-14 13:12:04 +00:00
c.Assert(results[accesslog.Duration], checker.Matches, `^\d+ms$`)
2018-01-11 09:04:03 +00:00
}
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/rawdata", nil)
2018-01-11 09:04:03 +00:00
c.Assert(err, checker.IsNil)
err = try.Request(req, 2*time.Second, try.StatusCodeIs(http.StatusOK), try.BodyContains(containerName))
c.Assert(err, checker.IsNil)
2016-04-20 18:54:57 +00:00
}
2018-02-05 08:48:03 +00:00
func displayTraefikLogFile(c *check.C, path string) {
if c.Failed() {
if _, err := os.Stat(path); !os.IsNotExist(err) {
content, errRead := ioutil.ReadFile(path)
fmt.Printf("%s: Traefik logs: \n", c.TestName())
if errRead == nil {
fmt.Println(content)
} else {
fmt.Println(errRead)
}
} else {
fmt.Printf("%s: No Traefik logs.\n", c.TestName())
}
errRemove := os.Remove(path)
if errRemove != nil {
fmt.Println(errRemove)
}
}
}