proxy: add support for logging http request headers (#4388)

* config: add customization options for logging

* config: validate log fields

* proxy: add support for logging http request headers

* log subset of headers

* fix test name

* dont use log.HTTPHeaders for access logs

* canonicalize http/2 headers

authorize/evaluator/evaluator.go

@@ -311,13 +311,13 @@ func safeEval(ctx context.Context, q rego.PreparedEvalQuery, options ...rego.Eva
 // carryOverJWTAssertion copies assertion JWT from request to response
 // note that src keys are expected to be http.CanonicalHeaderKey
 func carryOverJWTAssertion(dst http.Header, src map[string]string) {
-	jwtForKey := http.CanonicalHeaderKey(httputil.HeaderPomeriumJWTAssertionFor)
+	jwtForKey := httputil.CanonicalHeaderKey(httputil.HeaderPomeriumJWTAssertionFor)
 	jwtFor, ok := src[jwtForKey]
 	if ok && jwtFor != "" {
 		dst.Add(jwtForKey, jwtFor)
 		return
 	}
-	jwtFor, ok = src[http.CanonicalHeaderKey(httputil.HeaderPomeriumJWTAssertion)]
+	jwtFor, ok = src[httputil.CanonicalHeaderKey(httputil.HeaderPomeriumJWTAssertion)]
 	if ok && jwtFor != "" {
 		dst.Add(jwtForKey, jwtFor)
 	}

authorize/evaluator/evaluator_test.go

@@ -422,11 +422,11 @@ func TestEvaluator(t *testing.T) {
 		}{
 			{map[string]string{}, ""},
 			{map[string]string{
-				http.CanonicalHeaderKey(httputil.HeaderPomeriumJWTAssertion): "identity-a",
+				httputil.CanonicalHeaderKey(httputil.HeaderPomeriumJWTAssertion): "identity-a",
 			}, "identity-a"},
 			{map[string]string{
-				http.CanonicalHeaderKey(httputil.HeaderPomeriumJWTAssertionFor): "identity-a",
+				httputil.CanonicalHeaderKey(httputil.HeaderPomeriumJWTAssertionFor): "identity-a",
-				http.CanonicalHeaderKey(httputil.HeaderPomeriumJWTAssertion):    "identity-b",
+				httputil.CanonicalHeaderKey(httputil.HeaderPomeriumJWTAssertion):    "identity-b",
 			}, "identity-a"},
 		}
 		for _, tc := range tcs {

authorize/grpc.go

@@ -14,6 +14,7 @@ import (
 	"github.com/pomerium/pomerium/authorize/evaluator"
 	"github.com/pomerium/pomerium/config"
 	"github.com/pomerium/pomerium/config/envoyconfig"
+	"github.com/pomerium/pomerium/internal/httputil"
 	"github.com/pomerium/pomerium/internal/log"
 	"github.com/pomerium/pomerium/internal/sessions"
 	"github.com/pomerium/pomerium/internal/telemetry/requestid"
@@ -97,8 +98,7 @@ func (a *Authorize) getEvaluatorRequestFromCheckRequest(
 ) (*evaluator.Request, error) {
 	requestURL := getCheckRequestURL(in)
 	attrs := in.GetAttributes()
-	clientCertMetadata :=
+	clientCertMetadata := attrs.GetMetadataContext().GetFilterMetadata()["com.pomerium.client-certificate-info"]
-		attrs.GetMetadataContext().GetFilterMetadata()["com.pomerium.client-certificate-info"]
 	req := &evaluator.Request{
 		IsInternal: envoyconfig.ExtAuthzContextExtensionsIsInternal(attrs.GetContextExtensions()),
 		HTTP: evaluator.NewRequestHTTP(
@@ -152,7 +152,7 @@ func getCheckRequestHeaders(req *envoy_service_auth_v3.CheckRequest) map[string]
 	hdrs := make(map[string]string)
 	ch := req.GetAttributes().GetRequest().GetHttp().GetHeaders()
 	for k, v := range ch {
-		hdrs[http.CanonicalHeaderKey(k)] = v
+		hdrs[httputil.CanonicalHeaderKey(k)] = v
 	}
 	return hdrs
 }

authorize/log.go

@@ -31,9 +31,11 @@ func (a *Authorize) logAuthorizeCheck(
 	impersonateDetails := a.getImpersonateDetails(ctx, s)
 
 	evt := log.Info(ctx).Str("service", "authorize")
-	for _, field := range a.currentOptions.Load().GetAuthorizeLogFields() {
+	fields := a.currentOptions.Load().GetAuthorizeLogFields()
+	for _, field := range fields {
 		evt = populateLogEvent(ctx, field, evt, in, s, u, hdrs, impersonateDetails)
 	}
+	evt = log.HTTPHeaders(evt, fields, hdrs)
 
 	// result
 	if res != nil {
@@ -155,8 +157,6 @@ func populateLogEvent(
 		return evt.Str(string(field), hdrs["X-Request-Id"])
 	case log.AuthorizeLogFieldEmail:
 		return evt.Str(string(field), u.GetEmail())
-	case log.AuthorizeLogFieldHeaders:
-		return evt.Interface(string(field), hdrs)
 	case log.AuthorizeLogFieldHost:
 		return evt.Str(string(field), in.GetAttributes().GetRequest().GetHttp().GetHost())
 	case log.AuthorizeLogFieldImpersonateEmail:

config/envoyconfig/envoyconfig.go

@@ -32,6 +32,7 @@ import (
 
 	"github.com/pomerium/pomerium/config"
 	"github.com/pomerium/pomerium/internal/fileutil"
+	"github.com/pomerium/pomerium/internal/httputil"
 	"github.com/pomerium/pomerium/internal/log"
 	"github.com/pomerium/pomerium/pkg/cryptutil"
 )
@@ -92,6 +93,13 @@ func buildAccessLogs(options *config.Options) []*envoy_config_accesslog_v3.Acces
 		return nil
 	}
 
+	var additionalRequestHeaders []string
+	for _, field := range options.AccessLogFields {
+		if headerName, ok := log.GetHeaderField(field); ok {
+			additionalRequestHeaders = append(additionalRequestHeaders, httputil.CanonicalHeaderKey(headerName))
+		}
+	}
+
 	tc := marshalAny(&envoy_extensions_access_loggers_grpc_v3.HttpGrpcAccessLogConfig{
 		CommonConfig: &envoy_extensions_access_loggers_grpc_v3.CommonGrpcAccessLogConfig{
 			LogName: "ingress-http",
@@ -104,6 +112,7 @@ func buildAccessLogs(options *config.Options) []*envoy_config_accesslog_v3.Acces
 			},
 			TransportApiVersion: envoy_config_core_v3.ApiVersion_V3,
 		},
+		AdditionalRequestHeadersToLog: additionalRequestHeaders,
 	})
 	return []*envoy_config_accesslog_v3.AccessLog{{
 		Name:       "envoy.access_loggers.http_grpc",

internal/controlplane/grpc_accesslog.go

@@ -32,9 +32,15 @@ func (srv *Server) StreamAccessLogs(stream envoy_service_accesslog_v3.AccessLogS
 				evt = log.Info(stream.Context())
 			}
 			evt = evt.Str("service", "envoy")
-			for _, field := range srv.currentConfig.Load().Config.Options.GetAccessLogFields() {
+
+			fields := srv.currentConfig.Load().Config.Options.GetAccessLogFields()
+			for _, field := range fields {
 				evt = populateLogEvent(field, evt, entry)
 			}
+			// headers are selected in the envoy access logs config, so we can log all of them here
+			if len(entry.GetRequest().GetRequestHeaders()) > 0 {
+				evt = evt.Interface("headers", entry.GetRequest().GetRequestHeaders())
+			}
 			evt.Msg("http-request")
 		}
 	}

internal/httputil/canonical.go

@@ -0,0 +1,8 @@
+package httputil
+
+import (
+	"github.com/pomerium/pomerium/internal/log"
+)
+
+// CanonicalHeaderKey re-exports the log.CanonicalHeaderKey function to avoid an import cycle.
+var CanonicalHeaderKey = log.CanonicalHeaderKey

internal/log/access.go

@@ -64,6 +64,10 @@ var accessLogFieldLookup = map[AccessLogField]struct{}{
 
 // Validate returns an error if the access log field is invalid.
 func (field AccessLogField) Validate() error {
+	if _, ok := GetHeaderField(field); ok {
+		return nil
+	}
+
 	_, ok := accessLogFieldLookup[field]
 	if !ok {
 		return fmt.Errorf("%w: %s", ErrUnknownAccessLogField, field)

internal/log/authorize.go

@@ -14,7 +14,7 @@ type AuthorizeLogField string
 const (
 	AuthorizeLogFieldCheckRequestID       AuthorizeLogField = "check-request-id"
 	AuthorizeLogFieldEmail                AuthorizeLogField = "email"
-	AuthorizeLogFieldHeaders              AuthorizeLogField = "headers"
+	AuthorizeLogFieldHeaders                                = AuthorizeLogField(headersFieldName)
 	AuthorizeLogFieldHost                 AuthorizeLogField = "host"
 	AuthorizeLogFieldImpersonateEmail     AuthorizeLogField = "impersonate-email"
 	AuthorizeLogFieldImpersonateSessionID AuthorizeLogField = "impersonate-session-id"
@@ -79,6 +79,10 @@ var authorizeLogFieldLookup = map[AuthorizeLogField]struct{}{
 
 // Validate returns an error if the authorize log field is invalid.
 func (field AuthorizeLogField) Validate() error {
+	if _, ok := GetHeaderField(field); ok {
+		return nil
+	}
+
 	_, ok := authorizeLogFieldLookup[field]
 	if !ok {
 		return fmt.Errorf("%w: %s", ErrUnknownAuthorizeLogField, field)

internal/log/headers.go

@@ -0,0 +1,65 @@
+package log
+
+import (
+	"net/http"
+	"strings"
+
+	"github.com/rs/zerolog"
+
+	"github.com/pomerium/pomerium/internal/sets"
+)
+
+const (
+	headersFieldName   = "headers"
+	headersFieldPrefix = headersFieldName + "."
+)
+
+// GetHeaderField returns the header name for a field that represents logging a header value.
+func GetHeaderField[TField interface{ ~string }](field TField) (headerName string, ok bool) {
+	if strings.HasPrefix(string(field), headersFieldPrefix) {
+		return string(field)[len(headersFieldPrefix):], true
+	}
+
+	return "", false
+}
+
+// HTTPHeaders logs http headers based on supplied fields and a map of all headers.
+func HTTPHeaders[TField interface{ ~string }](
+	evt *zerolog.Event,
+	fields []TField,
+	src map[string]string,
+) *zerolog.Event {
+	all := false
+	include := sets.NewHash[string]()
+	for _, field := range fields {
+		if field == headersFieldName {
+			all = true
+			break
+		} else if strings.HasPrefix(string(field), headersFieldPrefix) {
+			include.Add(CanonicalHeaderKey(string(field[len(headersFieldPrefix):])))
+		}
+	}
+
+	// nothing to log
+	if include.Size() == 0 && !all {
+		return evt
+	}
+
+	hdrs := map[string]string{}
+	for k, v := range src {
+		h := CanonicalHeaderKey(k)
+		if all || include.Has(h) {
+			hdrs[h] = v
+		}
+	}
+	return evt.Interface(headersFieldName, hdrs)
+}
+
+// CanonicalHeaderKey converts a header name into its canonical form using http.CanonicalHeaderKey.
+// It also supports HTTP/2 headers that start with : by lowercasing them.
+func CanonicalHeaderKey(k string) string {
+	if strings.HasPrefix(k, ":") {
+		return strings.ToLower(k)
+	}
+	return http.CanonicalHeaderKey(k)
+}

internal/log/headers_test.go

@@ -0,0 +1,63 @@
+package log
+
+import (
+	"bytes"
+	"strings"
+	"testing"
+
+	"github.com/rs/zerolog"
+	"github.com/stretchr/testify/assert"
+)
+
+func TestHTTPHeaders(t *testing.T) {
+	t.Parallel()
+
+	type A = []string
+	type M = map[string]string
+
+	t.Run("all", func(t *testing.T) {
+		t.Parallel()
+
+		var buf bytes.Buffer
+		log := zerolog.New(&buf)
+		evt := log.Info()
+		evt = HTTPHeaders(evt, A{"headers"}, M{
+			"a": "1",
+			"b": "2",
+			"c": "3",
+		})
+		evt.Send()
+
+		assert.Equal(t, `{"level":"info","headers":{"A":"1","B":"2","C":"3"}}`, strings.TrimSpace(buf.String()))
+	})
+	t.Run("none", func(t *testing.T) {
+		t.Parallel()
+
+		var buf bytes.Buffer
+		log := zerolog.New(&buf)
+		evt := log.Info()
+		evt = HTTPHeaders(evt, A{"a", "b", "c"}, M{
+			"a": "1",
+			"b": "2",
+			"c": "3",
+		})
+		evt.Send()
+
+		assert.Equal(t, `{"level":"info"}`, strings.TrimSpace(buf.String()))
+	})
+	t.Run("two", func(t *testing.T) {
+		t.Parallel()
+
+		var buf bytes.Buffer
+		log := zerolog.New(&buf)
+		evt := log.Info()
+		evt = HTTPHeaders(evt, A{"headers.a", "headers.C"}, M{
+			"a": "1",
+			"b": "2",
+			"c": "3",
+		})
+		evt.Send()
+
+		assert.Equal(t, `{"level":"info","headers":{"A":"1","C":"3"}}`, strings.TrimSpace(buf.String()))
+	})
+}