diff --git a/logging/access.go b/logging/access.go index 60feb08ccd..24c81c4317 100644 --- a/logging/access.go +++ b/logging/access.go @@ -54,8 +54,9 @@ type AccessEntry struct { } type AccessLogger struct { - log *logrus.Logger - stripQuery bool + log *logrus.Logger + stripQuery bool + defaultText bool } // strip port from addresses with hostname, ipv4 or ipv6 @@ -93,6 +94,14 @@ func omitWhitespace(h string) string { } func (f *accessLogFormatter) Format(e *logrus.Entry) ([]byte, error) { + if len(e.Data) == 0 && e.Message != "" { + if e.Buffer == nil { + return []byte(e.Message), nil + } + _, _ = e.Buffer.WriteString(e.Message) + return e.Buffer.Bytes(), nil + } + keys := []string{ "host", "auth-user", "timestamp", "method", "uri", "proto", "status", "response-size", "referer", "user-agent", @@ -181,6 +190,32 @@ func (alog *AccessLogger) LogAccess(entry *AccessEntry, additional map[string]an auditHeader = entry.Request.Header.Get(logFilter.UnverifiedAuditHeader) } + if alog.defaultText && len(additional) == 0 { + message := fmt.Sprintf( + accessLogFormat, + omitWhitespace(host), + omitWhitespace(authUser), + omitWhitespace(ts), + omitWhitespace(method), + omitWhitespace(uri), + omitWhitespace(proto), + status, + responseSize, + omitWhitespace(referer), + omitWhitespace(userAgent), + duration, + omitWhitespace(requestedHost), + omitWhitespace(flowID), + omitWhitespace(auditHeader), + ) + if entry.Request != nil { + alog.log.WithContext(entry.Request.Context()).Info(message) + } else { + alog.log.Info(message) + } + return + } + logData := logrus.Fields{ "timestamp": ts, "host": host, diff --git a/logging/access_test.go b/logging/access_test.go index f11f50680a..0828c0516c 100644 --- a/logging/access_test.go +++ b/logging/access_test.go @@ -22,6 +22,19 @@ const logExtendedJSONOutput = `{"audit":"","auth-user":"","duration":42,"extra": type accessCustomFormatter struct{} type accessLogContextKey struct{} +type accessEntryHook struct { + context context.Context + status any + hasStatus bool +} + +func (h *accessEntryHook) Levels() []logrus.Level { return []logrus.Level{logrus.InfoLevel} } +func (h *accessEntryHook) Fire(entry *logrus.Entry) error { + h.context = entry.Context + h.status, h.hasStatus = entry.Data["status"] + return nil +} + func (c accessCustomFormatter) Format(entry *logrus.Entry) ([]byte, error) { if entry.Context != nil { @@ -114,6 +127,25 @@ func TestAccessLogFormatFull(t *testing.T) { testAccessLogDefault(t, testAccessEntry(), logOutput) } +func TestAccessLogDefaultRetainsRequestContext(t *testing.T) { + entry := testAccessEntry() + ctx := context.WithValue(entry.Request.Context(), accessLogContextKey{}, "default-text") + entry.Request = entry.Request.WithContext(ctx) + + var buf bytes.Buffer + logger := NewAccessLogger(Options{AccessLogOutput: &buf}) + hook := &accessEntryHook{} + logger.log.AddHook(hook) + logger.LogAccess(entry, nil) + + if hook.context != ctx { + t.Fatal("access log entry did not keep the incoming request context") + } + if got := buf.Bytes(); len(got) == 0 || got[len(got)-1] != '\n' { + t.Fatalf("access log line has no newline: %q", got) + } +} + func TestAccessLogFormatJSON(t *testing.T) { testAccessLog(t, testAccessEntry(), logJSONOutput, Options{AccessLogJSONEnabled: true}) } @@ -135,6 +167,43 @@ func TestAccessLogFormatJSONWithMaskedQueryParameters(t *testing.T) { ) } +func TestAccessLogDefaultWithAdditionalData(t *testing.T) { + entry := testAccessEntryWithQueryParameters(url.Values{"foo": {"bar"}}) + additional := map[string]any{ + al.KeyMaskedQueryParams: map[string]struct{}{"foo": {}}, + "status": http.StatusCreated, + "response-size": int64(10), + } + + var buf bytes.Buffer + logger := NewAccessLogger(Options{AccessLogOutput: &buf}) + logger.LogAccess(entry, additional) + + if _, ok := additional[al.KeyMaskedQueryParams]; ok { + t.Fatal("masked query data was not removed from the supplemental map") + } + + const want = `127.0.0.1 - - [10/Oct/2000:13:55:36 -0700] "GET /apache_pb.gif?foo=5234164152756840025 HTTP/1.1" 201 10 "-" "-" 42 example.com - -` + "\n" + if got := buf.String(); got != want { + t.Errorf("got %q, want %q", got, want) + } +} + +func TestAccessLogDefaultRejectsUnsupportedAdditionalValue(t *testing.T) { + var buf bytes.Buffer + logger := NewAccessLogger(Options{AccessLogOutput: &buf}) + hook := &accessEntryHook{} + logger.log.AddHook(hook) + logger.LogAccess(testAccessEntry(), map[string]any{"status": func() {}}) + + if hook.hasStatus { + t.Fatalf("unsupported status value reached the log entry: %v", hook.status) + } + if got := buf.Bytes(); len(got) == 0 || got[len(got)-1] != '\n' { + t.Fatalf("access log line has no newline: %q", got) + } +} + func TestAccessLogIgnoresEmptyEntry(t *testing.T) { testAccessLogDefault(t, nil, "") } diff --git a/logging/log.go b/logging/log.go index ec13fb04df..4922fd1a2d 100644 --- a/logging/log.go +++ b/logging/log.go @@ -78,6 +78,7 @@ func initApplicationLog(o Options) { func createAccessLog(o Options) *AccessLogger { l := logrus.New() + defaultText := false if o.AccessLogFormatter != nil { l.Formatter = o.AccessLogFormatter } else if o.AccessLogJSONEnabled { @@ -88,13 +89,15 @@ func createAccessLog(o Options) *AccessLogger { } } else { l.Formatter = &accessLogFormatter{accessLogFormat} + defaultText = true } l.Out = o.AccessLogOutput l.Level = logrus.InfoLevel return &AccessLogger{ - stripQuery: o.AccessLogStripQuery, - log: l, + stripQuery: o.AccessLogStripQuery, + log: l, + defaultText: defaultText, } } diff --git a/proxy/accesslog_benchmark_test.go b/proxy/accesslog_benchmark_test.go new file mode 100644 index 0000000000..c1fa89eb0e --- /dev/null +++ b/proxy/accesslog_benchmark_test.go @@ -0,0 +1,213 @@ +package proxy + +import ( + "bufio" + "fmt" + "io" + "net/http" + "net/http/httptest" + "os" + "strings" + "testing" + + "github.com/zalando/skipper/logging" +) + +const loggedAccessLocalResponse = "Hello world!" + +type loggedAccessBenchmarkCase struct { + name string + route string + target string + host string + status int + responseBody string + location string + userAgent string + accept string + localBackend bool +} + +func BenchmarkAccessLogWithOutput(b *testing.B) { + for _, tc := range []loggedAccessBenchmarkCase{ + { + name: "inline_status200_10B", + route: `inline: Path("/hello") -> status(200) -> inlineContent("some bytes") -> `, + target: "/hello", + host: "www.example.org", + status: http.StatusOK, + responseBody: "some bytes", + }, + { + name: "inline_status200_enabled_10B", + route: `inline: Path("/hello") -> enableAccessLog(1, 200, 3) -> status(200) -> inlineContent("some bytes") -> `, + target: "/hello", + host: "www.example.org", + status: http.StatusOK, + responseBody: "some bytes", + }, + { + name: "inline_status418_28B", + route: `inline: * -> status(418) -> inlineContent("Would you like a cup of tea?") -> `, + target: "/", + host: "www.example.org", + status: http.StatusTeapot, + responseBody: "Would you like a cup of tea?", + }, + { + name: "query_setQuery_local12B", + target: "/", + host: "localhost:8080", + status: http.StatusOK, + responseBody: loggedAccessLocalResponse, + userAgent: "curl/7.49.0", + accept: "*/*", + localBackend: true, + }, + { + name: "redirect_status308", + route: `redirect: * -> redirectTo(308, "http://127.0.0.1:9999") -> `, + target: "/foo", + host: "localhost:8080", + status: http.StatusPermanentRedirect, + location: "http://127.0.0.1:9999/foo", + userAgent: "curl/7.49.0", + accept: "*/*", + }, + { + name: "redirect_modPath_status308", + route: `redirect: * -> modPath("/", "/my/new/base/") -> redirectTo(308, "http://127.0.0.1:9999") -> `, + target: "/foo", + host: "localhost:8080", + status: http.StatusPermanentRedirect, + location: "http://127.0.0.1:9999/my/new/base/foo", + userAgent: "curl/7.49.0", + accept: "*/*", + }, + } { + tc := tc + b.Run(tc.name, func(b *testing.B) { + benchmarkAccessLogWithOutput(b, tc) + }) + } +} + +func benchmarkAccessLogWithOutput(b *testing.B, tc loggedAccessBenchmarkCase) { + b.Helper() + + route := tc.route + var backend *httptest.Server + if tc.localBackend { + backend = httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.Header().Set("Content-Type", "text/plain; charset=utf-8") + w.Header().Set("Content-Length", "12") + w.Header().Set("Server", "Skipper") + _, _ = io.WriteString(w, loggedAccessLocalResponse) + })) + defer backend.Close() + route = fmt.Sprintf(`forward: * -> setQuery("lang", "pt") -> %q`, backend.URL) + } + + logFile, err := os.CreateTemp(b.TempDir(), "access-log-*.log") + if err != nil { + b.Fatal(err) + } + defer logFile.Close() + info, err := logFile.Stat() + if err != nil || !info.Mode().IsRegular() { + b.Fatalf("access log output is not a regular file: %v", err) + } + + accessLogger := logging.NewAccessLogger(logging.Options{AccessLogOutput: logFile}) + tp, err := newTestProxyWithParams(route, Params{ + AccessLogDisabled: false, + AccessLogger: accessLogger, + }) + if err != nil { + b.Fatal(err) + } + defer tp.close() + + request := httptest.NewRequest(http.MethodGet, "http://"+tc.host+tc.target, nil) + request.RequestURI = tc.target + if tc.userAgent != "" { + request.Header.Set("User-Agent", tc.userAgent) + } + if tc.accept != "" { + request.Header.Set("Accept", tc.accept) + } + originalPath := request.URL.Path + originalQuery := request.URL.RawQuery + + if tc.localBackend { + // Populate the proxy transport's persistent loopback connection before timing. + warmResponse := httptest.NewRecorder() + tp.proxy.ServeHTTP(warmResponse, request) + assertLoggedAccessBenchmarkResponse(b, warmResponse, tc) + if err := logFile.Truncate(0); err != nil { + b.Fatal(err) + } + if _, err := logFile.Seek(0, io.SeekStart); err != nil { + b.Fatal(err) + } + } + + b.ReportAllocs() + var lastResponse *httptest.ResponseRecorder + for b.Loop() { + request.URL.Path = originalPath + request.URL.RawQuery = originalQuery + request.RequestURI = tc.target + lastResponse = httptest.NewRecorder() + tp.proxy.ServeHTTP(lastResponse, request) + } + b.StopTimer() + + if lastResponse == nil { + b.Fatal("benchmark did not serve a request") + } + assertLoggedAccessBenchmarkResponse(b, lastResponse, tc) + verifyLoggedAccessBenchmarkOutput(b, logFile, tc) +} + +func assertLoggedAccessBenchmarkResponse(b *testing.B, response *httptest.ResponseRecorder, tc loggedAccessBenchmarkCase) { + b.Helper() + if response.Code != tc.status { + b.Fatalf("response status = %d, want %d", response.Code, tc.status) + } + if got := response.Body.String(); got != tc.responseBody { + b.Fatalf("response body = %q, want %q", got, tc.responseBody) + } + if tc.location != "" { + if got := response.Header().Get("Location"); got != tc.location { + b.Fatalf("Location = %q, want %q", got, tc.location) + } + } +} + +func verifyLoggedAccessBenchmarkOutput(b *testing.B, logFile *os.File, tc loggedAccessBenchmarkCase) { + b.Helper() + if _, err := logFile.Seek(0, io.SeekStart); err != nil { + b.Fatal(err) + } + + want := fmt.Sprintf(`"GET %s HTTP/1.1" %d %d`, tc.target, tc.status, len(tc.responseBody)) + scanner := bufio.NewScanner(logFile) + count := 0 + for scanner.Scan() { + line := scanner.Text() + if !strings.Contains(line, want) { + b.Fatalf("access log line %q does not contain %q", line, want) + } + if tc.userAgent != "" && !strings.Contains(line, `"`+tc.userAgent+`"`) { + b.Fatalf("access log line %q does not contain user agent %q", line, tc.userAgent) + } + count++ + } + if err := scanner.Err(); err != nil { + b.Fatal(err) + } + if count != b.N { + b.Fatalf("wrote %d access lines for %d requests", count, b.N) + } +} diff --git a/proxy/proxy_test.go b/proxy/proxy_test.go index 5f9407a62c..b8ce60ca9d 100644 --- a/proxy/proxy_test.go +++ b/proxy/proxy_test.go @@ -2160,6 +2160,112 @@ func TestAccessLogOnFailedRequest(t *testing.T) { } } +func TestConcurrentAccessLogValueCopy(t *testing.T) { + var output bytes.Buffer + accessLogger := logging.NewAccessLogger(logging.Options{AccessLogOutput: &output}) + accessLoggerCopy := *accessLogger + + doc := ` + fast: Path("/fast") -> status(200) -> inlineContent("some bytes") -> ; + masked: Path("/masked") -> maskAccessLogQuery("token") -> status(200) -> inlineContent("some bytes") -> ; + ` + tp, err := newTestProxyWithParams(doc, Params{ + AccessLogDisabled: false, + AccessLogger: &accessLoggerCopy, + Flags: FlagsNone, + }) + if err != nil { + t.Fatal(err) + } + defer tp.close() + + const requestsPerPath = 16 + start := make(chan struct{}) + var wg sync.WaitGroup + startRequest := func(fn func()) { + wg.Add(1) + go func() { + defer wg.Done() + <-start + fn() + }() + } + + for i := 0; i < requestsPerPath; i++ { + i := i + startRequest(func() { + r := httptest.NewRequest(http.MethodGet, fmt.Sprintf("http://example.org/fast?request=%d", i), nil) + r.RequestURI = r.URL.RequestURI() + w := httptest.NewRecorder() + tp.proxy.ServeHTTP(w, r) + if w.Code != http.StatusOK || w.Body.String() != "some bytes" { + t.Errorf("fast response = %d %q", w.Code, w.Body.String()) + } + }) + startRequest(func() { + r := httptest.NewRequest(http.MethodGet, fmt.Sprintf("http://example.org/masked?request=%d&token=secret-%d", i, i), nil) + r.RequestURI = r.URL.RequestURI() + w := httptest.NewRecorder() + tp.proxy.ServeHTTP(w, r) + if w.Code != http.StatusOK || w.Body.String() != "some bytes" { + t.Errorf("masked response = %d %q", w.Code, w.Body.String()) + } + }) + startRequest(func() { + r := httptest.NewRequest(http.MethodGet, fmt.Sprintf("http://example.org/direct/%d", i), nil) + r.RequestURI = r.URL.RequestURI() + accessLogger.LogAccess(&logging.AccessEntry{ + Request: r, + StatusCode: http.StatusOK, + ResponseSize: int64(len("some bytes")), + RequestTime: time.Now(), + Duration: time.Millisecond, + }, nil) + }) + } + close(start) + wg.Wait() + + text := output.String() + if !strings.HasSuffix(text, "\n") { + t.Fatalf("access log output is not newline-terminated: %q", text) + } + lines := strings.Split(strings.TrimSuffix(text, "\n"), "\n") + if len(lines) != 3*requestsPerPath { + t.Fatalf("got %d log lines, want %d", len(lines), 3*requestsPerPath) + } + + counts := map[string]int{"direct": 0, "fast": 0, "masked": 0} + seen := make(map[string]struct{}, len(lines)) + for _, line := range lines { + if !strings.Contains(line, `HTTP/1.1" 200 10 `) { + t.Errorf("incomplete access log line: %q", line) + } + if strings.Contains(line, "secret-") { + t.Errorf("masked query value leaked in access log line: %q", line) + } + if _, ok := seen[line]; ok { + t.Errorf("duplicate access log line: %q", line) + } + seen[line] = struct{}{} + switch { + case strings.Contains(line, `"GET /direct/`): + counts["direct"]++ + case strings.Contains(line, `"GET /fast?request=`): + counts["fast"]++ + case strings.Contains(line, `"GET /masked?request=`): + counts["masked"]++ + default: + t.Errorf("unexpected access log line: %q", line) + } + } + for path, count := range counts { + if count != requestsPerPath { + t.Errorf("got %d %s log lines, want %d", count, path, requestsPerPath) + } + } +} + func TestHopHeaderRemovalDisabled(t *testing.T) { payload := []byte("Hello World!")