feat: redact sensitive headers and body content in debug logs (#217)

**Commit Message**:

This commit introduces functions to redact sensitive headers and body
content before logging, ensuring that sensitive information such as
authorization tokens is not exposed in debug logs. The new
filterSensitiveHeaders function redacts specified headers, replacing
their values with [REDACTED], while filterSensitiveBody ensures that
sensitive content in request bodies is also redacted before being
logged.

Additionally, the logging behavior has been updated so that request
headers and body content are only logged when the DEBUG level is
enabled, further improving security and performance.

Unit tests have been added to verify the functionality of both
filterSensitiveHeaders and filterSensitiveBody, ensuring that sensitive
data is properly redacted and that the logging behavior works as
expected.

Signed-off-by: Sébastien Han <seb@redhat.com>

---------

Signed-off-by: Sébastien Han <seb@redhat.com>

internal/extproc/server.go

@@ -6,7 +6,10 @@ import (
 	"fmt"
 	"io"
 	"log/slog"
+	"slices"
+	"strings"
 
+	corev3 "github.com/envoyproxy/go-control-plane/envoy/config/core/v3"
 	extprocv3 "github.com/envoyproxy/go-control-plane/envoy/service/ext_proc/v3"
 	"github.com/google/cel-go/cel"
 	"google.golang.org/grpc/codes"
@@ -21,6 +24,12 @@ import (
 	"github.com/envoyproxy/ai-gateway/internal/llmcostcel"
 )
 
+const (
+	redactedKey = "[REDACTED]"
+)
+
+var sensitiveHeaderKeys = []string{"authorization"}
+
 // Server implements the external process server.
 type Server[P ProcessorIface] struct {
 	logger       *slog.Logger
@@ -133,7 +142,11 @@ func (s *Server[P]) processMsg(ctx context.Context, p P, req *extprocv3.Processi
 	switch value := req.Request.(type) {
 	case *extprocv3.ProcessingRequest_RequestHeaders:
 		requestHdrs := req.GetRequestHeaders().Headers
-		s.logger.Debug("request headers processing", slog.Any("request_headers", requestHdrs))
+		// If DEBUG log level is enabled, filter sensitive headers before logging.
+		if s.logger.Enabled(ctx, slog.LevelDebug) {
+			filteredHdrs := filterSensitiveHeaders(requestHdrs, s.logger, sensitiveHeaderKeys)
+			s.logger.Debug("request headers processing", slog.Any("request_headers", filteredHdrs))
+		}
 		resp, err := p.ProcessRequestHeaders(ctx, requestHdrs)
 		if err != nil {
 			return nil, fmt.Errorf("cannot process request headers: %w", err)
@@ -143,7 +156,11 @@ func (s *Server[P]) processMsg(ctx context.Context, p P, req *extprocv3.Processi
 	case *extprocv3.ProcessingRequest_RequestBody:
 		s.logger.Debug("request body processing", slog.Any("request", req))
 		resp, err := p.ProcessRequestBody(ctx, value.RequestBody)
-		s.logger.Debug("request body processed", slog.Any("response", resp))
+		// If DEBUG log level is enabled, filter sensitive body before logging.
+		if s.logger.Enabled(ctx, slog.LevelDebug) {
+			filteredBody := filterSensitiveBody(resp, s.logger, sensitiveHeaderKeys)
+			s.logger.Debug("request body processed", slog.Any("response", filteredBody))
+		}
 		if err != nil {
 			return nil, fmt.Errorf("cannot process request body: %w", err)
 		}
@@ -180,3 +197,58 @@ func (s *Server[P]) Check(context.Context, *grpc_health_v1.HealthCheckRequest) (
 func (s *Server[P]) Watch(*grpc_health_v1.HealthCheckRequest, grpc_health_v1.Health_WatchServer) error {
 	return status.Error(codes.Unimplemented, "Watch is not implemented")
 }
+
+// filterSensitiveHeaders filters out sensitive headers from the provided HeaderMap.
+// Specifically, it redacts the value of the "authorization" header and logs this action.
+// The function returns a new HeaderMap with the filtered headers.
+func filterSensitiveHeaders(headers *corev3.HeaderMap, logger *slog.Logger, sensitiveKeys []string) *corev3.HeaderMap {
+	if headers == nil {
+		logger.Debug("received nil HeaderMap, returning empty HeaderMap")
+		return &corev3.HeaderMap{}
+	}
+	filteredHeaders := &corev3.HeaderMap{}
+	for _, header := range headers.Headers {
+		// We convert the header key to lowercase to make the comparison case-insensitive but we don't modify the original header.
+		if slices.Contains(sensitiveKeys, strings.ToLower(header.GetKey())) {
+			logger.Debug("filtering sensitive header", slog.String("header_key", header.Key))
+			filteredHeaders.Headers = append(filteredHeaders.Headers, &corev3.HeaderValue{
+				Key:   header.Key,
+				Value: redactedKey,
+			})
+		} else {
+			filteredHeaders.Headers = append(filteredHeaders.Headers, header)
+		}
+	}
+	return filteredHeaders
+}
+
+// filterSensitiveBody filters out sensitive information from the response body.
+// It creates a copy of the response body to avoid modifying the original body,
+// as the API Key is needed for the request. The function returns a new
+// ProcessingResponse with the filtered body for logging.
+func filterSensitiveBody(resp *extprocv3.ProcessingResponse, logger *slog.Logger, sensitiveKeys []string) *extprocv3.ProcessingResponse {
+	if resp == nil {
+		logger.Debug("received nil ProcessingResponse, returning empty ProcessingResponse")
+		return &extprocv3.ProcessingResponse{}
+	}
+	filteredResp := &extprocv3.ProcessingResponse{
+		Response: &extprocv3.ProcessingResponse_RequestBody{
+			RequestBody: &extprocv3.BodyResponse{
+				Response: &extprocv3.CommonResponse{
+					HeaderMutation:  resp.Response.(*extprocv3.ProcessingResponse_RequestBody).RequestBody.Response.GetHeaderMutation(),
+					BodyMutation:    resp.Response.(*extprocv3.ProcessingResponse_RequestBody).RequestBody.Response.GetBodyMutation(),
+					ClearRouteCache: resp.Response.(*extprocv3.ProcessingResponse_RequestBody).RequestBody.Response.GetClearRouteCache(),
+				},
+			},
+		},
+		ModeOverride: resp.ModeOverride,
+	}
+	for _, setHeader := range filteredResp.Response.(*extprocv3.ProcessingResponse_RequestBody).RequestBody.Response.GetHeaderMutation().GetSetHeaders() {
+		// We convert the header key to lowercase to make the comparison case-insensitive but we don't modify the original header.
+		if slices.Contains(sensitiveKeys, strings.ToLower(setHeader.Header.GetKey())) {
+			logger.Debug("filtering sensitive header", slog.String("header_key", setHeader.Header.Key))
+			setHeader.Header.RawValue = []byte(redactedKey)
+		}
+	}
+	return filteredResp
+}

internal/extproc/server_test.go

@@ -260,3 +260,51 @@ func TestServer_Process(t *testing.T) {
 		require.Error(t, err, "context canceled")
 	})
 }
+
+func TestFilterSensitiveHeaders(t *testing.T) {
+	logger, buf := newTestLoggerWithBuffer()
+	hm := &corev3.HeaderMap{Headers: []*corev3.HeaderValue{{Key: "foo", Value: "bar"}, {Key: "authorization", Value: "sensitive"}}}
+	filtered := filterSensitiveHeaders(hm, logger, []string{"authorization"})
+	require.Len(t, filtered.Headers, 2)
+	for _, h := range filtered.Headers {
+		if h.Key == "authorization" {
+			require.Equal(t, "[REDACTED]", h.Value)
+		} else {
+			require.Equal(t, "bar", h.Value)
+		}
+	}
+	require.Contains(t, buf.String(), "filtering sensitive header")
+}
+
+func TestFilterSensitiveBody(t *testing.T) {
+	logger, buf := newTestLoggerWithBuffer()
+	resp := &extprocv3.ProcessingResponse{
+		Response: &extprocv3.ProcessingResponse_RequestBody{
+			RequestBody: &extprocv3.BodyResponse{
+				Response: &extprocv3.CommonResponse{
+					HeaderMutation: &extprocv3.HeaderMutation{
+						SetHeaders: []*corev3.HeaderValueOption{
+							{Header: &corev3.HeaderValue{
+								Key:   ":path",
+								Value: "/model/some-random-model/converse",
+							}},
+							{Header: &corev3.HeaderValue{
+								Key:   "Authorization",
+								Value: "sensitive",
+							}},
+						},
+					},
+					BodyMutation: &extprocv3.BodyMutation{},
+				},
+			},
+		},
+	}
+	filtered := filterSensitiveBody(resp, logger, []string{"authorization"})
+	require.NotNil(t, filtered)
+	for _, h := range filtered.Response.(*extprocv3.ProcessingResponse_RequestBody).RequestBody.Response.GetHeaderMutation().GetSetHeaders() {
+		if h.Header.Key == "Authorization" {
+			require.Equal(t, "[REDACTED]", string(h.Header.RawValue))
+		}
+	}
+	require.Contains(t, buf.String(), "filtering sensitive header")
+}