From b966215e6c65d36d4a568c78981ef24a90918c43 Mon Sep 17 00:00:00 2001 From: Romain Date: Wed, 27 Sep 2023 15:22:06 +0200 Subject: [PATCH] Move origin fields capture to service level Co-authored-by: lbenguigui --- docs/content/observability/access-logs.md | 4 +- integration/access_log_test.go | 66 +++++++++++++++++++ .../fixtures/access_log_json_config.toml | 32 +++++++++ pkg/middlewares/accesslog/field_middleware.go | 16 +++-- .../accesslog/logger_formatters.go | 4 +- .../accesslog/logger_formatters_test.go | 14 ++-- pkg/server/router/router.go | 2 +- 7 files changed, 121 insertions(+), 17 deletions(-) create mode 100644 integration/fixtures/access_log_json_config.toml diff --git a/docs/content/observability/access-logs.md b/docs/content/observability/access-logs.md index c8e4f1d95..73c581ece 100644 --- a/docs/content/observability/access-logs.md +++ b/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 - - [] " " "" "" "" "" 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 | diff --git a/integration/access_log_test.go b/integration/access_log_test.go index 458a491f6..d279f993f 100644 --- a/integration/access_log_test.go +++ b/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() diff --git a/integration/fixtures/access_log_json_config.toml b/integration/fixtures/access_log_json_config.toml new file mode 100644 index 000000000..1d4a8c832 --- /dev/null +++ b/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 diff --git a/pkg/middlewares/accesslog/field_middleware.go b/pkg/middlewares/accesslog/field_middleware.go index 17ed9d2ff..b490ffafa 100644 --- a/pkg/middlewares/accesslog/field_middleware.go +++ b/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) +} diff --git a/pkg/middlewares/accesslog/logger_formatters.go b/pkg/middlewares/accesslog/logger_formatters.go index 5bda8eef9..c714ef146 100644 --- a/pkg/middlewares/accesslog/logger_formatters.go +++ b/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, OriginContentSize, defaultValue, true), + toLog(entry.Data, DownstreamStatus, 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), diff --git a/pkg/middlewares/accesslog/logger_formatters_test.go b/pkg/middlewares/accesslog/logger_formatters_test.go index 74a86b2a4..cfa4281ec 100644 --- a/pkg/middlewares/accesslog/logger_formatters_test.go +++ b/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, - OriginContentSize: nil, + DownstreamStatus: 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, - OriginContentSize: 132, + DownstreamStatus: 123, + 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, - OriginContentSize: 132, + DownstreamStatus: 123, + DownstreamContentSize: 132, RequestRefererHeader: "referer", RequestUserAgentHeader: "agent", RequestCount: nil, diff --git a/pkg/server/router/router.go b/pkg/server/router/router.go index 6359102de..46b6f3cac 100644 --- a/pkg/server/router/router.go +++ b/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)