From 85ca823b8c086b46ef69e6127cdb75d6f90a1a2a Mon Sep 17 00:00:00 2001 From: Robbie Lankford Date: Fri, 1 Nov 2024 09:13:37 -0700 Subject: [PATCH 1/3] logging middleware to honor logRequestHeaders config Signed-off-by: Robbie Lankford --- middleware/logging.go | 25 ++++++++++++++++++++----- 1 file changed, 20 insertions(+), 5 deletions(-) diff --git a/middleware/logging.go b/middleware/logging.go index c2306292b..920976b3c 100644 --- a/middleware/logging.go +++ b/middleware/logging.go @@ -94,14 +94,25 @@ func (l Log) Wrap(next http.Handler) http.Handler { if writeErr != nil { if errors.Is(writeErr, context.Canceled) { if l.LogRequestAtInfoLevel { - level.Info(requestLog).Log("msg", dskit_log.LazySprintf("%s %s %s, request cancelled: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers)) + if l.LogRequestHeaders && headers != nil { + level.Info(requestLog).Log("msg", dskit_log.LazySprintf("%s %s %s, request cancelled: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers)) + } else { + level.Info(requestLog).Log("msg", dskit_log.LazySprintf("%s %s %s, request cancelled: %s ws: %v", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r))) + } } else { - level.Debug(requestLog).Log("msg", dskit_log.LazySprintf("%s %s %s, request cancelled: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers)) + if l.LogRequestHeaders && headers != nil { + level.Debug(requestLog).Log("msg", dskit_log.LazySprintf("%s %s %s, request cancelled: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers)) + } else { + level.Debug(requestLog).Log("msg", dskit_log.LazySprintf("%s %s %s, request cancelled: %s ws: %v", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r))) + } } } else { - level.Warn(requestLog).Log("msg", dskit_log.LazySprintf("%s %s %s, error: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers)) + if l.LogRequestHeaders && headers != nil { + level.Warn(requestLog).Log("msg", dskit_log.LazySprintf("%s %s %s, error: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers)) + } else { + level.Warn(requestLog).Log("msg", dskit_log.LazySprintf("%s %s %s, error: %s ws: %v", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r))) + } } - return } @@ -125,7 +136,11 @@ func (l Log) Wrap(next http.Handler) http.Handler { } } default: - level.Warn(requestLog).Log("msg", dskit_log.LazySprintf("%s %s (%d) %s Response: %q ws: %v; %s", r.Method, uri, statusCode, time.Since(begin), buf.Bytes(), IsWSHandshakeRequest(r), headers)) + if l.LogRequestHeaders && headers != nil { + level.Warn(requestLog).Log("msg", dskit_log.LazySprintf("%s %s (%d) %s Response: %q ws: %v; %s", r.Method, uri, statusCode, time.Since(begin), buf.Bytes(), IsWSHandshakeRequest(r), headers)) + } else { + level.Warn(requestLog).Log("msg", dskit_log.LazySprintf("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin))) + } } }) } From 1254595b012d73ced045d00c1813529d2e93c6c3 Mon Sep 17 00:00:00 2001 From: Robbie Lankford Date: Mon, 4 Nov 2024 11:31:34 -0800 Subject: [PATCH 2/3] update tests and changelog --- CHANGELOG.md | 1 + middleware/logging.go | 1 + middleware/logging_test.go | 25 +++++++++++++++++++++---- 3 files changed, 23 insertions(+), 4 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index f9cb11448..d90ec93d1 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,6 @@ ## Changelog +* [CHANGE] Log middleware updated to honor `logRequestHeaders` in all logging scenarios. #615 * [CHANGE] Roll back the gRPC dependency to v1.65.0 to allow downstream projects to avoid a performance regression and maybe a bug in v1.66.0. #581 * [CHANGE] Update the gRPC dependency to v1.66.0 and deprecate the `grpc_server_recv_buffer_pools_enabled` option that is no longer supported by it. #580 * [CHANGE] `ring.DoBatchWithOptions` (and `ring.DoBatch`) reports the cancelation cause when the context is canceled instead of `context.Canceled`. diff --git a/middleware/logging.go b/middleware/logging.go index 920976b3c..797d9a45d 100644 --- a/middleware/logging.go +++ b/middleware/logging.go @@ -136,6 +136,7 @@ func (l Log) Wrap(next http.Handler) http.Handler { } } default: + level.Warn(requestLog).Log("msg", dskit_log.LazySprintf("%s %s (%d) %s Response: %q ws: %v; %s", r.Method, uri, statusCode, time.Since(begin), buf.Bytes(), IsWSHandshakeRequest(r), headers)) if l.LogRequestHeaders && headers != nil { level.Warn(requestLog).Log("msg", dskit_log.LazySprintf("%s %s (%d) %s Response: %q ws: %v; %s", r.Method, uri, statusCode, time.Since(begin), buf.Bytes(), IsWSHandshakeRequest(r), headers)) } else { diff --git a/middleware/logging_test.go b/middleware/logging_test.go index e3449248a..574ef078c 100644 --- a/middleware/logging_test.go +++ b/middleware/logging_test.go @@ -149,32 +149,49 @@ func TestLoggingRequestWithExcludedHeaders(t *testing.T) { setHeaderList []string excludeHeaderList []string mustNotContain []string + statusCode int + logRequestHeaders bool }{ { - name: "Default excluded headers are excluded", - setHeaderList: defaultHeaders, - mustNotContain: defaultHeaders, + name: "Default excluded headers are excluded", + setHeaderList: defaultHeaders, + mustNotContain: defaultHeaders, + statusCode: http.StatusOK, + logRequestHeaders: true, }, { name: "Extra configured header is also excluded", setHeaderList: append(defaultHeaders, "X-Secret-Header"), excludeHeaderList: []string{"X-Secret-Header"}, mustNotContain: append(defaultHeaders, "X-Secret-Header"), + statusCode: http.StatusOK, + logRequestHeaders: true, }, { name: "Multiple extra configured headers are also excluded", setHeaderList: append(defaultHeaders, "X-Secret-Header", "X-Secret-Header-2"), excludeHeaderList: []string{"X-Secret-Header", "X-Secret-Header-2"}, mustNotContain: append(defaultHeaders, "X-Secret-Header", "X-Secret-Header-2"), + statusCode: http.StatusOK, + logRequestHeaders: true, + }, + { + name: "Log request headers disabled and status code 500", + setHeaderList: append(defaultHeaders, "X-Secret-Header"), + excludeHeaderList: []string{}, + mustNotContain: append(defaultHeaders, "X-Secret-Header"), + statusCode: http.StatusInternalServerError, + logRequestHeaders: false, }, } { t.Run(tc.name, func(t *testing.T) { buf := bytes.NewBuffer(nil) - loggingMiddleware := NewLogMiddleware(log.NewGoKitWithWriter(log.LogfmtFormat, buf), true, false, nil, tc.excludeHeaderList) + loggingMiddleware := NewLogMiddleware(log.NewGoKitWithWriter(log.LogfmtFormat, buf), tc.logRequestHeaders, false, nil, tc.excludeHeaderList) handler := func(w http.ResponseWriter, _ *http.Request) { _, _ = io.WriteString(w, "Hello world!") + w.WriteHeader(tc.statusCode) } loggingHandler := loggingMiddleware.Wrap(http.HandlerFunc(handler)) From 3655057c7e1a0689ce1adb29a731772e1bee1573 Mon Sep 17 00:00:00 2001 From: Robbie Lankford Date: Mon, 4 Nov 2024 11:49:30 -0800 Subject: [PATCH 3/3] remove extra log line --- middleware/logging.go | 1 - 1 file changed, 1 deletion(-) diff --git a/middleware/logging.go b/middleware/logging.go index 797d9a45d..920976b3c 100644 --- a/middleware/logging.go +++ b/middleware/logging.go @@ -136,7 +136,6 @@ func (l Log) Wrap(next http.Handler) http.Handler { } } default: - level.Warn(requestLog).Log("msg", dskit_log.LazySprintf("%s %s (%d) %s Response: %q ws: %v; %s", r.Method, uri, statusCode, time.Since(begin), buf.Bytes(), IsWSHandshakeRequest(r), headers)) if l.LogRequestHeaders && headers != nil { level.Warn(requestLog).Log("msg", dskit_log.LazySprintf("%s %s (%d) %s Response: %q ws: %v; %s", r.Method, uri, statusCode, time.Since(begin), buf.Bytes(), IsWSHandshakeRequest(r), headers)) } else {