From 638d9f3d6c74d9554dbcca9e60987b5a6004743b Mon Sep 17 00:00:00 2001 From: Caleb Doxsey Date: Tue, 25 Jul 2023 09:46:42 -0600 Subject: [PATCH] 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 | 4 +- authorize/evaluator/evaluator_test.go | 6 +-- authorize/grpc.go | 6 +-- authorize/log.go | 6 +-- config/envoyconfig/envoyconfig.go | 9 ++++ internal/controlplane/grpc_accesslog.go | 8 ++- internal/httputil/canonical.go | 8 +++ internal/log/access.go | 4 ++ internal/log/authorize.go | 6 ++- internal/log/headers.go | 65 +++++++++++++++++++++++++ internal/log/headers_test.go | 63 ++++++++++++++++++++++++ 11 files changed, 172 insertions(+), 13 deletions(-) create mode 100644 internal/httputil/canonical.go create mode 100644 internal/log/headers.go create mode 100644 internal/log/headers_test.go diff --git a/authorize/evaluator/evaluator.go b/authorize/evaluator/evaluator.go index c02707fab..14b07313d 100644 --- a/authorize/evaluator/evaluator.go +++ b/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) } diff --git a/authorize/evaluator/evaluator_test.go b/authorize/evaluator/evaluator_test.go index 06c3eee7c..fe020aa5b 100644 --- a/authorize/evaluator/evaluator_test.go +++ b/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", - http.CanonicalHeaderKey(httputil.HeaderPomeriumJWTAssertion): "identity-b", + httputil.CanonicalHeaderKey(httputil.HeaderPomeriumJWTAssertionFor): "identity-a", + httputil.CanonicalHeaderKey(httputil.HeaderPomeriumJWTAssertion): "identity-b", }, "identity-a"}, } for _, tc := range tcs { diff --git a/authorize/grpc.go b/authorize/grpc.go index 99b91d9a6..12b05c2ee 100644 --- a/authorize/grpc.go +++ b/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 := - attrs.GetMetadataContext().GetFilterMetadata()["com.pomerium.client-certificate-info"] + clientCertMetadata := 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 } diff --git a/authorize/log.go b/authorize/log.go index c67c704dc..7e1180707 100644 --- a/authorize/log.go +++ b/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: diff --git a/config/envoyconfig/envoyconfig.go b/config/envoyconfig/envoyconfig.go index 942ec9248..6e9c36b16 100644 --- a/config/envoyconfig/envoyconfig.go +++ b/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", diff --git a/internal/controlplane/grpc_accesslog.go b/internal/controlplane/grpc_accesslog.go index 5e1670577..f8d45744f 100644 --- a/internal/controlplane/grpc_accesslog.go +++ b/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") } } diff --git a/internal/httputil/canonical.go b/internal/httputil/canonical.go new file mode 100644 index 000000000..293446e96 --- /dev/null +++ b/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 diff --git a/internal/log/access.go b/internal/log/access.go index f6d79a713..a531aa86f 100644 --- a/internal/log/access.go +++ b/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) diff --git a/internal/log/authorize.go b/internal/log/authorize.go index 1a945bb87..b36254046 100644 --- a/internal/log/authorize.go +++ b/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) diff --git a/internal/log/headers.go b/internal/log/headers.go new file mode 100644 index 000000000..8b76ec105 --- /dev/null +++ b/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) +} diff --git a/internal/log/headers_test.go b/internal/log/headers_test.go new file mode 100644 index 000000000..7dd23d8c0 --- /dev/null +++ b/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())) + }) +}