Move origin fields capture to service level

Co-authored-by: lbenguigui <lbenguigui@gmail.com>

docs/content/observability/access-logs.md

@@ -54,7 +54,7 @@ If the given format is unsupported, the default (CLF) is used instead.
 !!! info "Common Log Format"
 
     ```html
-    <remote_IP_address> - <client_user_name_if_available> [<timestamp>] "<request_method> <request_path> <request_protocol>" <origin_server_HTTP_status> <origin_server_content_size> "<request_referrer>" "<request_user_agent>" <number_of_requests_received_since_Traefik_started> "<Traefik_router_name>" "<Traefik_server_URL>" <request_duration_in_ms>ms
+    <remote_IP_address> - <client_user_name_if_available> [<timestamp>] "<request_method> <request_path> <request_protocol>" <HTTP_status> <content-length> "<request_referrer>" "<request_user_agent>" <number_of_requests_received_since_Traefik_started> "<Traefik_router_name>" "<Traefik_server_URL>" <request_duration_in_ms>ms
     ```
 
 ### `bufferingSize`
@@ -218,7 +218,7 @@ accessLog:
     | `RequestContentSize`    | The number of bytes in the request entity (a.k.a. body) sent by the client.                                                                                         |
     | `OriginDuration`        | The time taken (in nanoseconds) by the origin server ('upstream') to return its response.                                                                           |
     | `OriginContentSize`     | The content length specified by the origin server, or 0 if unspecified.                                                                                             |
-    | `OriginStatus`          | The HTTP status code returned by the origin server. If the request was handled by this Traefik instance (e.g. with a redirect), then this value will be absent.     |
+    | `OriginStatus`          | The HTTP status code returned by the origin server. If the request was handled by this Traefik instance (e.g. with a redirect), then this value will be absent (0). |
     | `OriginStatusLine`      | `OriginStatus` + Status code explanation                                                                                                                            |
     | `DownstreamStatus`      | The HTTP status code returned to the client.                                                                                                                        |
     | `DownstreamStatusLine`  | `DownstreamStatus` + Status code explanation                                                                                                                        |

integration/access_log_test.go

@@ -3,6 +3,7 @@ package integration
 import (
 	"crypto/md5"
 	"crypto/rand"
+	"encoding/json"
 	"fmt"
 	"io"
 	"net/http"
@@ -335,6 +336,71 @@ func (s *AccessLogSuite) TestAccessLogFrontendRedirect(c *check.C) {
 	checkNoOtherTraefikProblems(c)
 }
 
+func (s *AccessLogSuite) TestAccessLogJSONFrontendRedirect(c *check.C) {
+	ensureWorkingDirectoryIsClean()
+
+	type logLine struct {
+		DownstreamStatus int    `json:"downstreamStatus"`
+		OriginStatus     int    `json:"originStatus"`
+		RouterName       string `json:"routerName"`
+		ServiceName      string `json:"serviceName"`
+	}
+
+	expected := []logLine{
+		{
+			DownstreamStatus: 302,
+			OriginStatus:     0,
+			RouterName:       "rt-frontendRedirect@docker",
+			ServiceName:      "",
+		},
+		{
+			DownstreamStatus: 200,
+			OriginStatus:     200,
+			RouterName:       "rt-server0@docker",
+			ServiceName:      "service1@docker",
+		},
+	}
+
+	// Start Traefik
+	cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_json_config.toml"))
+	defer display(c)
+
+	err := cmd.Start()
+	c.Assert(err, checker.IsNil)
+	defer s.killCmd(cmd)
+
+	checkStatsForLogFile(c)
+
+	waitForTraefik(c, "frontendRedirect")
+
+	// Verify Traefik started OK
+	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)
+
+	lines := extractLines(c)
+	c.Assert(len(lines), checker.GreaterOrEqualThan, len(expected))
+
+	for i, line := range lines {
+		if line == "" {
+			continue
+		}
+		var logline logLine
+		err := json.Unmarshal([]byte(line), &logline)
+		c.Assert(err, checker.IsNil)
+		c.Assert(logline.DownstreamStatus, checker.Equals, expected[i].DownstreamStatus)
+		c.Assert(logline.OriginStatus, checker.Equals, expected[i].OriginStatus)
+		c.Assert(logline.RouterName, checker.Equals, expected[i].RouterName)
+		c.Assert(logline.ServiceName, checker.Equals, expected[i].ServiceName)
+	}
+}
+
 func (s *AccessLogSuite) TestAccessLogRateLimit(c *check.C) {
 	ensureWorkingDirectoryIsClean()
 

integration/fixtures/access_log_json_config.toml

@@ -0,0 +1,32 @@
+[global]
+  checkNewVersion = false
+  sendAnonymousUsage = false
+
+[log]
+  level = "ERROR"
+  filePath = "traefik.log"
+
+[accessLog]
+  format = "json"
+  filePath = "access.log"
+
+[entryPoints]
+  [entryPoints.web]
+    address = ":8000"
+  [entryPoints.frontendRedirect]
+    address = ":8005"
+  [entryPoints.httpFrontendAuth]
+    address = ":8006"
+  [entryPoints.httpRateLimit]
+    address = ":8007"
+  [entryPoints.digestAuth]
+    address = ":8008"
+
+[api]
+  insecure = true
+
+[providers]
+  [providers.docker]
+    exposedByDefault = false
+    defaultRule = "Host(`{{ normalize .Name }}.docker.local`)"
+    watch = true

pkg/middlewares/accesslog/field_middleware.go

@@ -46,11 +46,6 @@ func AddServiceFields(rw http.ResponseWriter, req *http.Request, next http.Handl
 	data.Core[ServiceURL] = req.URL // note that this is *not* the original incoming URL
 	data.Core[ServiceAddr] = req.URL.Host
 
-	next.ServeHTTP(rw, req)
-}
-
-// AddOriginFields add origin fields.
-func AddOriginFields(rw http.ResponseWriter, req *http.Request, next http.Handler, data *LogData) {
 	start := time.Now().UTC()
 
 	next.ServeHTTP(rw, req)
@@ -72,3 +67,14 @@ func AddOriginFields(rw http.ResponseWriter, req *http.Request, next http.Handle
 	data.Core[OriginStatus] = capt.StatusCode()
 	data.Core[OriginContentSize] = capt.ResponseSize()
 }
+
+// InitServiceFields init service fields.
+func InitServiceFields(rw http.ResponseWriter, req *http.Request, next http.Handler, data *LogData) {
+	// Because they are expected to be initialized when the logger is processing the data table,
+	// the origin fields are initialized in case the response is returned by Traefik itself, and not a service.
+	data.Core[OriginDuration] = time.Duration(0)
+	data.Core[OriginStatus] = 0
+	data.Core[OriginContentSize] = int64(0)
+
+	next.ServeHTTP(rw, req)
+}

pkg/middlewares/accesslog/logger_formatters.go

@@ -40,8 +40,8 @@ func (f *CommonLogFormatter) Format(entry *logrus.Entry) ([]byte, error) {
 		toLog(entry.Data, RequestMethod, defaultValue, false),
 		toLog(entry.Data, RequestPath, defaultValue, false),
 		toLog(entry.Data, RequestProtocol, defaultValue, false),
-		toLog(entry.Data, OriginStatus, defaultValue, true),
+		toLog(entry.Data, DownstreamStatus, defaultValue, true),
-		toLog(entry.Data, OriginContentSize, defaultValue, true),
+		toLog(entry.Data, DownstreamContentSize, defaultValue, true),
 		toLog(entry.Data, "request_Referer", `"-"`, true),
 		toLog(entry.Data, "request_User-Agent", `"-"`, true),
 		toLog(entry.Data, RequestCount, defaultValue, true),

pkg/middlewares/accesslog/logger_formatters_test.go

@@ -18,7 +18,7 @@ func TestCommonLogFormatter_Format(t *testing.T) {
 		expectedLog string
 	}{
 		{
-			name: "OriginStatus & OriginContentSize are nil",
+			name: "DownstreamStatus & DownstreamContentSize are nil",
 			data: map[string]interface{}{
 				StartUTC:               time.Date(2009, time.November, 10, 23, 0, 0, 0, time.UTC),
 				Duration:               123 * time.Second,
@@ -27,8 +27,8 @@ func TestCommonLogFormatter_Format(t *testing.T) {
 				RequestMethod:          http.MethodGet,
 				RequestPath:            "/foo",
 				RequestProtocol:        "http",
-				OriginStatus:           nil,
+				DownstreamStatus:       nil,
-				OriginContentSize:      nil,
+				DownstreamContentSize:  nil,
 				RequestRefererHeader:   "",
 				RequestUserAgentHeader: "",
 				RequestCount:           0,
@@ -48,8 +48,8 @@ func TestCommonLogFormatter_Format(t *testing.T) {
 				RequestMethod:          http.MethodGet,
 				RequestPath:            "/foo",
 				RequestProtocol:        "http",
-				OriginStatus:           123,
+				DownstreamStatus:       123,
-				OriginContentSize:      132,
+				DownstreamContentSize:  132,
 				RequestRefererHeader:   "referer",
 				RequestUserAgentHeader: "agent",
 				RequestCount:           nil,
@@ -69,8 +69,8 @@ func TestCommonLogFormatter_Format(t *testing.T) {
 				RequestMethod:          http.MethodGet,
 				RequestPath:            "/foo",
 				RequestProtocol:        "http",
-				OriginStatus:           123,
+				DownstreamStatus:       123,
-				OriginContentSize:      132,
+				DownstreamContentSize:  132,
 				RequestRefererHeader:   "referer",
 				RequestUserAgentHeader: "agent",
 				RequestCount:           nil,

pkg/server/router/router.go

@@ -76,7 +76,7 @@ func (m *Manager) BuildHandlers(rootCtx context.Context, entryPoints []string, t
 		}
 
 		handlerWithAccessLog, err := alice.New(func(next http.Handler) (http.Handler, error) {
-			return accesslog.NewFieldHandler(next, log.EntryPointName, entryPointName, accesslog.AddOriginFields), nil
+			return accesslog.NewFieldHandler(next, log.EntryPointName, entryPointName, accesslog.InitServiceFields), nil
 		}).Then(handler)
 		if err != nil {
 			log.FromContext(ctx).Error(err)