envoy: log mtls failures (#5210)

envoy: log mtls failures

This implements limited listener-based access logging for downstream
transport failures, only enabled when downstream_mtls.enforcement is
set to 'reject_connection'. Client certificate details and the error
message will be logged.

Additionally, the new key 'client-certificate' can be set in the
access_log_fields list in the configuration, which will add peer
certificate properties (issuer, subject, SANs) to the existing
per-request http logs.

---------

Co-authored-by: Kenneth Jenkins <51246568+kenjenkins@users.noreply.github.com>

config/envoyconfig/listeners.go

@@ -12,9 +12,11 @@ import (
 	"strings"
 	"time"
 
+	envoy_config_accesslog_v3 "github.com/envoyproxy/go-control-plane/envoy/config/accesslog/v3"
 	envoy_config_core_v3 "github.com/envoyproxy/go-control-plane/envoy/config/core/v3"
 	envoy_config_listener_v3 "github.com/envoyproxy/go-control-plane/envoy/config/listener/v3"
 	envoy_config_route_v3 "github.com/envoyproxy/go-control-plane/envoy/config/route/v3"
+	envoy_extensions_access_loggers_grpc_v3 "github.com/envoyproxy/go-control-plane/envoy/extensions/access_loggers/grpc/v3"
 	envoy_http_connection_manager "github.com/envoyproxy/go-control-plane/envoy/extensions/filters/network/http_connection_manager/v3"
 	envoy_extensions_transport_sockets_tls_v3 "github.com/envoyproxy/go-control-plane/envoy/extensions/transport_sockets/tls/v3"
 	envoy_type_v3 "github.com/envoyproxy/go-control-plane/envoy/type/v3"
@@ -123,6 +125,28 @@ func (b *Builder) buildTLSSocket(ctx context.Context, cfg *config.Config, certs
 	}, nil
 }
 
+func listenerAccessLog() []*envoy_config_accesslog_v3.AccessLog {
+	cc := &envoy_extensions_access_loggers_grpc_v3.CommonGrpcAccessLogConfig{
+		LogName: "ingress-http-listener",
+		GrpcService: &envoy_config_core_v3.GrpcService{
+			TargetSpecifier: &envoy_config_core_v3.GrpcService_EnvoyGrpc_{
+				EnvoyGrpc: &envoy_config_core_v3.GrpcService_EnvoyGrpc{
+					ClusterName: "pomerium-control-plane-grpc",
+				},
+			},
+		},
+		TransportApiVersion: envoy_config_core_v3.ApiVersion_V3,
+	}
+	tcp := marshalAny(
+		&envoy_extensions_access_loggers_grpc_v3.TcpGrpcAccessLogConfig{CommonConfig: cc})
+	return []*envoy_config_accesslog_v3.AccessLog{
+		{
+			Name:       "envoy.access_loggers.tcp_grpc",
+			ConfigType: &envoy_config_accesslog_v3.AccessLog_TypedConfig{TypedConfig: tcp},
+		},
+	}
+}
+
 func (b *Builder) buildMainListener(
 	ctx context.Context,
 	cfg *config.Config,
@@ -133,6 +157,10 @@ func (b *Builder) buildMainListener(
 		li.ListenerFilters = append(li.ListenerFilters, ProxyProtocolFilter())
 	}
 
+	if cfg.Options.DownstreamMTLS.Enforcement == config.MTLSEnforcementRejectConnection {
+		li.AccessLog = listenerAccessLog()
+	}
+
 	if cfg.Options.InsecureServer {
 		li.Address = buildAddress(cfg.Options.Addr, 80)
 

internal/controlplane/grpc_accesslog.go

@@ -1,6 +1,7 @@
 package controlplane
 
 import (
+	"context"
 	"strings"
 
 	envoy_data_accesslog_v3 "github.com/envoyproxy/go-control-plane/envoy/data/accesslog/v3"
@@ -16,6 +17,7 @@ func (srv *Server) registerAccessLogHandlers() {
 
 // StreamAccessLogs receives logs from envoy and prints them to stdout.
 func (srv *Server) StreamAccessLogs(stream envoy_service_accesslog_v3.AccessLogService_StreamAccessLogsServer) error {
+	var logName string
 	for {
 		msg, err := stream.Recv()
 		if err != nil {
@@ -23,26 +25,59 @@ func (srv *Server) StreamAccessLogs(stream envoy_service_accesslog_v3.AccessLogS
 			return err
 		}
 
-		for _, entry := range msg.GetHttpLogs().LogEntry {
-			reqPath := entry.GetRequest().GetPath()
-			var evt *zerolog.Event
-			if reqPath == "/ping" || reqPath == "/healthz" {
-				evt = log.Debug(stream.Context())
-			} else {
-				evt = log.Info(stream.Context())
-			}
-			evt = evt.Str("service", "envoy")
-
-			fields := srv.currentConfig.Load().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")
+		if msg.Identifier != nil {
+			logName = msg.Identifier.LogName
 		}
+
+		if logName == "ingress-http-listener" {
+			accessLogListener(stream.Context(), msg)
+		} else {
+			srv.accessLogHTTP(stream.Context(), msg)
+		}
+	}
+}
+
+func accessLogListener(
+	ctx context.Context, msg *envoy_service_accesslog_v3.StreamAccessLogsMessage,
+) {
+	for _, entry := range msg.GetTcpLogs().GetLogEntry() {
+		failure := entry.GetCommonProperties().GetDownstreamTransportFailureReason()
+		if failure == "" {
+			continue
+		}
+		e := log.Info(ctx).Str("service", "envoy")
+		dict := zerolog.Dict()
+		populateCertEventDict(entry.GetCommonProperties().GetTlsProperties().GetPeerCertificateProperties(), dict)
+		e.Dict("client-certificate", dict)
+		e.Str("ip", entry.GetCommonProperties().GetDownstreamRemoteAddress().GetSocketAddress().GetAddress())
+		e.Str("tls-sni-hostname", entry.GetCommonProperties().GetTlsProperties().GetTlsSniHostname())
+		e.Str("downstream-transport-failure-reason", failure)
+		e.Msg("listener connection failure")
+	}
+}
+
+func (srv *Server) accessLogHTTP(
+	ctx context.Context, msg *envoy_service_accesslog_v3.StreamAccessLogsMessage,
+) {
+	for _, entry := range msg.GetHttpLogs().LogEntry {
+		reqPath := entry.GetRequest().GetPath()
+		var evt *zerolog.Event
+		if reqPath == "/ping" || reqPath == "/healthz" {
+			evt = log.Debug(ctx)
+		} else {
+			evt = log.Info(ctx)
+		}
+		evt = evt.Str("service", "envoy")
+
+		fields := srv.currentConfig.Load().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")
 	}
 }
 
@@ -84,7 +119,34 @@ func populateLogEvent(
 		return evt.Str(string(field), entry.GetCommonProperties().GetUpstreamCluster())
 	case log.AccessLogFieldUserAgent:
 		return evt.Str(string(field), entry.GetRequest().GetUserAgent())
+	case log.AccessLogFieldClientCertificate:
+		dict := zerolog.Dict()
+		populateCertEventDict(entry.GetCommonProperties().GetTlsProperties().GetPeerCertificateProperties(), dict)
+		return evt.Dict(string(field), dict)
 	default:
 		return evt
 	}
 }
+
+func populateCertEventDict(cert *envoy_data_accesslog_v3.TLSProperties_CertificateProperties, dict *zerolog.Event) {
+	if cert.Issuer != "" {
+		dict.Str("issuer", cert.Issuer)
+	}
+	if cert.Subject != "" {
+		dict.Str("subject", cert.Subject)
+	}
+	if len(cert.SubjectAltName) > 0 {
+		arr := zerolog.Arr()
+		for _, san := range cert.SubjectAltName {
+			// follow openssl GENERAL_NAME_print formatting
+			// envoy only provides dns and uri SANs at the moment
+			switch san := san.GetSan().(type) {
+			case *envoy_data_accesslog_v3.TLSProperties_CertificateProperties_SubjectAltName_Dns:
+				arr.Str("DNS:" + san.Dns)
+			case *envoy_data_accesslog_v3.TLSProperties_CertificateProperties_SubjectAltName_Uri:
+				arr.Str("URI:" + san.Uri)
+			}
+		}
+		dict.Array("subjectAltName", arr)
+	}
+}

internal/log/access.go

@@ -24,6 +24,7 @@ const (
 	AccessLogFieldSize                AccessLogField = "size"
 	AccessLogFieldUpstreamCluster     AccessLogField = "upstream-cluster"
 	AccessLogFieldUserAgent           AccessLogField = "user-agent"
+	AccessLogFieldClientCertificate   AccessLogField = "client-certificate"
 )
 
 var defaultAccessLogFields = []AccessLogField{
@@ -64,6 +65,7 @@ var accessLogFieldLookup = map[AccessLogField]struct{}{
 	AccessLogFieldSize:                {},
 	AccessLogFieldUpstreamCluster:     {},
 	AccessLogFieldUserAgent:           {},
+	AccessLogFieldClientCertificate:   {},
 }
 
 // Validate returns an error if the access log field is invalid.