Fix bad access log

traefik · Jan 11, 2018 · 709d508 · 709d508
1 parent ee71b4b
commit 709d508
Show file tree

Hide file tree

Showing 10 changed files with 755 additions and 135 deletions.
diff --git a/integration/access_log_test.go b/integration/access_log_test.go
diff --git 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"
-
-################################################################
-# File configuration backend
-################################################################
-[file]
+[api]
+  dashboard = false
 
-################################################################
-# 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
diff --git 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
diff --git 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
@@ -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
@@ -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
@@ -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
@@ -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()
+}