pkg/config, pkg/internal: support custom Envoy JSON fields (#3059)

Add support for custon Envoy JSON fields via use of `=` in the field
name.

See [design doc](design/envoy-json-logging-custom-fields-design.md) for
more information.

Fixes #3032, #1507

Signed-off-by: Mikael Manukyan <mmanukyan@vmware.com>
Co-authored-by: Clay Kauzlaric <ckauzlaric@vmware.com>
Co-authored-by: Alexander Standke <astandke@vmware.com>

internal/envoy/v2/accesslog.go

@@ -38,19 +38,14 @@ func FileAccessLogEnvoy(path string) []*accesslog.AccessLog {
 
 // FileAccessLogJSON returns a new file based access log filter
 // that will log in JSON format
-func FileAccessLogJSON(path string, keys []string) []*accesslog.AccessLog {
+func FileAccessLogJSON(path string, fields config.AccessLogFields) []*accesslog.AccessLog {
 
 	jsonformat := &_struct.Struct{
 		Fields: make(map[string]*_struct.Value),
 	}
 
-	for _, k := range keys {
-		// This will silently ignore invalid headers.
-		// TODO(youngnick): this should tell users if a header is not valid
-		// https://github.com/projectcontour/contour/issues/1507
-		if template, ok := config.JSONFields[k]; ok {
-			jsonformat.Fields[k] = sv(template)
-		}
+	for k, v := range fields.AsFieldMap() {
+		jsonformat.Fields[k] = sv(v)
 	}
 
 	return []*accesslog.AccessLog{{

internal/envoy/v2/accesslog_test.go

@@ -52,12 +52,12 @@ func TestFileAccessLog(t *testing.T) {
 func TestJSONFileAccessLog(t *testing.T) {
 	tests := map[string]struct {
 		path    string
-		headers []string
+		headers config.AccessLogFields
 		want    []*envoy_accesslog.AccessLog
 	}{
 		"only timestamp": {
 			path:    "/dev/stdout",
-			headers: []string{"@timestamp"},
+			headers: config.AccessLogFields([]string{"@timestamp"}),
 			want: []*envoy_accesslog.AccessLog{{
 				Name: wellknown.FileAccessLog,
 				ConfigType: &envoy_accesslog.AccessLog_TypedConfig{
@@ -75,13 +75,15 @@ func TestJSONFileAccessLog(t *testing.T) {
 			},
 			},
 		},
-		"invalid header should disappear": {
+		"custom fields should appear": {
 			path: "/dev/stdout",
-			headers: []string{
+			headers: config.AccessLogFields([]string{
 				"@timestamp",
-				"invalid",
 				"method",
-			},
+				"custom1=%REQ(X-CUSTOM-HEADER)%",
+				"custom2=%DURATION%.0",
+				"custom3=ST=%START_TIME(%s.%6f)%",
+			}),
 			want: []*envoy_accesslog.AccessLog{{
 				Name: wellknown.FileAccessLog,
 				ConfigType: &envoy_accesslog.AccessLog_TypedConfig{
@@ -90,8 +92,11 @@ func TestJSONFileAccessLog(t *testing.T) {
 						AccessLogFormat: &accesslog_v2.FileAccessLog_JsonFormat{
 							JsonFormat: &_struct.Struct{
 								Fields: map[string]*_struct.Value{
-									"@timestamp": sv(config.JSONFields["@timestamp"]),
-									"method":     sv(config.JSONFields["method"]),
+									"@timestamp": sv("%START_TIME%"),
+									"method":     sv("%REQ(:METHOD)%"),
+									"custom1":    sv("%REQ(X-CUSTOM-HEADER)%"),
+									"custom2":    sv("%DURATION%.0"),
+									"custom3":    sv("ST=%START_TIME(%s.%6f)%"),
 								},
 							},
 						},

internal/xdscache/v2/listener.go

@@ -96,7 +96,7 @@ type ListenerConfig struct {
 	// AccessLogFields sets the fields that should be shown in JSON logs.
 	// Valid entries are the keys from internal/envoy/accesslog.go:jsonheaders
 	// Defaults to a particular set of fields.
-	AccessLogFields []string
+	AccessLogFields config.AccessLogFields
 
 	// RequestTimeout configures the request_timeout for all Connection Managers.
 	RequestTimeout timeout.Setting
@@ -181,7 +181,7 @@ func (lvc *ListenerConfig) accesslogType() string {
 
 // accesslogFields returns the access log fields that should be configured
 // for Envoy, or a default set if not configured.
-func (lvc *ListenerConfig) accesslogFields() []string {
+func (lvc *ListenerConfig) accesslogFields() config.AccessLogFields {
 	if lvc.AccessLogFields != nil {
 		return lvc.AccessLogFields
 	}

pkg/config/accesslog.go

@@ -1,36 +1,7 @@
 package config
 
-//JSONFields is the canonical translation table for JSON fields to Envoy log template formats,
-//used for specifying fields for Envoy to log when JSON logging is enabled.
-//Only fields specified in this map may be used for JSON logging.
-var JSONFields = map[string]string{
-	"@timestamp":                "%START_TIME%",
-	"ts":                        "%START_TIME%",
-	"authority":                 "%REQ(:AUTHORITY)%",
-	"bytes_received":            "%BYTES_RECEIVED%",
-	"bytes_sent":                "%BYTES_SENT%",
-	"downstream_local_address":  "%DOWNSTREAM_LOCAL_ADDRESS%",
-	"downstream_remote_address": "%DOWNSTREAM_REMOTE_ADDRESS%",
-	"duration":                  "%DURATION%",
-	"method":                    "%REQ(:METHOD)%",
-	"path":                      "%REQ(X-ENVOY-ORIGINAL-PATH?:PATH)%",
-	"protocol":                  "%PROTOCOL%",
-	"request_id":                "%REQ(X-REQUEST-ID)%",
-	"requested_server_name":     "%REQUESTED_SERVER_NAME%",
-	"response_code":             "%RESPONSE_CODE%",
-	"response_flags":            "%RESPONSE_FLAGS%",
-	"uber_trace_id":             "%REQ(UBER-TRACE-ID)%",
-	"upstream_cluster":          "%UPSTREAM_CLUSTER%",
-	"upstream_host":             "%UPSTREAM_HOST%",
-	"upstream_local_address":    "%UPSTREAM_LOCAL_ADDRESS%",
-	"upstream_service_time":     "%RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)%",
-	"user_agent":                "%REQ(USER-AGENT)%",
-	"x_forwarded_for":           "%REQ(X-FORWARDED-FOR)%",
-	"x_trace_id":                "%REQ(X-TRACE-ID)%",
-}
-
 // DefaultFields are fields that will be included by default when JSON logging is enabled.
-var DefaultFields = []string{
+var DefaultFields = AccessLogFields([]string{
 	"@timestamp",
 	"authority",
 	"bytes_received",
@@ -52,7 +23,80 @@ var DefaultFields = []string{
 	"upstream_service_time",
 	"user_agent",
 	"x_forwarded_for",
-}
+})
 
 // DEFAULT_ACCESS_LOG_TYPE is the default access log format.
 const DEFAULT_ACCESS_LOG_TYPE = EnvoyAccessLog
+
+// jsonFields is the canonical translation table for JSON fields to Envoy log template formats,
+// used for specifying fields for Envoy to log when JSON logging is enabled.
+var jsonFields = map[string]string{
+	"@timestamp":            "%START_TIME%",
+	"ts":                    "%START_TIME%",
+	"authority":             "%REQ(:AUTHORITY)%",
+	"method":                "%REQ(:METHOD)%",
+	"path":                  "%REQ(X-ENVOY-ORIGINAL-PATH?:PATH)%",
+	"request_id":            "%REQ(X-REQUEST-ID)%",
+	"uber_trace_id":         "%REQ(UBER-TRACE-ID)%",
+	"upstream_service_time": "%RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)%",
+	"user_agent":            "%REQ(USER-AGENT)%",
+	"x_forwarded_for":       "%REQ(X-FORWARDED-FOR)%",
+	"x_trace_id":            "%REQ(X-TRACE-ID)%",
+}
+
+// envoySimpleOperators is the list of known supported Envoy log template keywords that do not
+// have arguments nor require canonical translations.
+var envoySimpleOperators = map[string]struct{}{
+	"BYTES_RECEIVED":                                {},
+	"BYTES_SENT":                                    {},
+	"CONNECTION_ID":                                 {},
+	"CONNECTION_TERMINATION_DETAILS":                {},
+	"DOWNSTREAM_DIRECT_REMOTE_ADDRESS":              {},
+	"DOWNSTREAM_DIRECT_REMOTE_ADDRESS_WITHOUT_PORT": {},
+	"DOWNSTREAM_LOCAL_ADDRESS":                      {},
+	"DOWNSTREAM_LOCAL_ADDRESS_WITHOUT_PORT":         {},
+	"DOWNSTREAM_LOCAL_PORT":                         {},
+	"DOWNSTREAM_LOCAL_SUBJECT":                      {},
+	"DOWNSTREAM_LOCAL_URI_SAN":                      {},
+	"DOWNSTREAM_PEER_CERT":                          {},
+	"DOWNSTREAM_PEER_CERT_V_END":                    {},
+	"DOWNSTREAM_PEER_CERT_V_START":                  {},
+	"DOWNSTREAM_PEER_FINGERPRINT_1":                 {},
+	"DOWNSTREAM_PEER_FINGERPRINT_256":               {},
+	"DOWNSTREAM_PEER_ISSUER":                        {},
+	"DOWNSTREAM_PEER_SERIAL":                        {},
+	"DOWNSTREAM_PEER_SUBJECT":                       {},
+	"DOWNSTREAM_PEER_URI_SAN":                       {},
+	"DOWNSTREAM_REMOTE_ADDRESS":                     {},
+	"DOWNSTREAM_REMOTE_ADDRESS_WITHOUT_PORT":        {},
+	"DOWNSTREAM_TLS_CIPHER":                         {},
+	"DOWNSTREAM_TLS_SESSION_ID":                     {},
+	"DOWNSTREAM_TLS_VERSION":                        {},
+	"DURATION":                                      {},
+	"GRPC_STATUS":                                   {},
+	"HOSTNAME":                                      {},
+	"LOCAL_REPLY_BODY":                              {},
+	"PROTOCOL":                                      {},
+	"REQUESTED_SERVER_NAME":                         {},
+	"REQUEST_DURATION":                              {},
+	"RESPONSE_CODE":                                 {},
+	"RESPONSE_CODE_DETAILS":                         {},
+	"RESPONSE_DURATION":                             {},
+	"RESPONSE_FLAGS":                                {},
+	"RESPONSE_TX_DURATION":                          {},
+	"ROUTE_NAME":                                    {},
+	"START_TIME":                                    {},
+	"UPSTREAM_CLUSTER":                              {},
+	"UPSTREAM_HOST":                                 {},
+	"UPSTREAM_LOCAL_ADDRESS":                        {},
+	"UPSTREAM_TRANSPORT_FAILURE_REASON":             {},
+}
+
+// envoyComplexOperators is the list of known Envoy log template keywords that require
+// arguments.
+var envoyComplexOperators = map[string]struct{}{
+	"REQ":        {},
+	"RESP":       {},
+	"START_TIME": {},
+	"TRAILER":    {},
+}

pkg/config/parameters.go

@@ -19,6 +19,7 @@ import (
 	"io"
 	"os"
 	"path/filepath"
+	"regexp"
 	"strings"
 	"time"
 
@@ -89,6 +90,90 @@ func (a AccessLogType) Validate() error {
 const EnvoyAccessLog AccessLogType = "envoy"
 const JSONAccessLog AccessLogType = "json"
 
+type AccessLogFields []string
+
+func (a AccessLogFields) Validate() error {
+	// Capture Groups:
+	// Given string "the start time is %START_TIME(%s):3% wow!"
+	//
+	//   0. Whole match "%START_TIME(%s):3%"
+	//   1. Full operator: "START_TIME(%s):3%"
+	//   2. Operator Name: "START_TIME"
+	//   3. Arguments: "(%s)"
+	//   4. Truncation length: ":3"
+	re := regexp.MustCompile(`%(([A-Z_]+)(\([^)]+\)(:[0-9]+)?)?%)?`)
+
+	for key, val := range a.AsFieldMap() {
+		if val == "" {
+			return fmt.Errorf("invalid JSON log field name %s", key)
+		}
+
+		if jsonFields[key] == val {
+			continue
+		}
+
+		// FindAllStringSubmatch will always return a slice with matches where every slice is a slice
+		// of submatches with length of 5 (number of capture groups + 1).
+		tokens := re.FindAllStringSubmatch(val, -1)
+		if len(tokens) == 0 {
+			continue
+		}
+
+		for _, f := range tokens {
+			op := f[2]
+			if op == "" {
+				return fmt.Errorf("invalid JSON field: %s, invalid Envoy format: %s", val, f)
+			}
+
+			_, okSimple := envoySimpleOperators[op]
+			_, okComplex := envoyComplexOperators[op]
+			if !okSimple && !okComplex {
+				return fmt.Errorf("invalid JSON field: %s, invalid Envoy format: %s, invalid Envoy operator: %s", val, f, op)
+			}
+
+			if (op == "REQ" || op == "RESP" || op == "TRAILER") && f[3] == "" {
+				return fmt.Errorf("invalid JSON field: %s, invalid Envoy format: %s, arguments required for operator: %s", val, f, op)
+			}
+
+			// START_TIME cannot not have truncation length.
+			if op == "START_TIME" && f[4] != "" {
+				return fmt.Errorf("invalid JSON field: %s, invalid Envoy format: %s, operator %s cannot have truncation length", val, f, op)
+			}
+		}
+	}
+
+	return nil
+}
+
+func (a AccessLogFields) AsFieldMap() map[string]string {
+	fieldMap := map[string]string{}
+
+	for _, val := range a {
+		parts := strings.SplitN(val, "=", 2)
+
+		if len(parts) == 1 {
+			operator, foundInFieldMapping := jsonFields[val]
+			_, isSimpleOperator := envoySimpleOperators[strings.ToUpper(val)]
+
+			if isSimpleOperator && !foundInFieldMapping {
+				// Operator name is known to be simple, upcase and wrap it in percents.
+				fieldMap[val] = fmt.Sprintf("%%%s%%", strings.ToUpper(val))
+			} else if foundInFieldMapping {
+				// Operator name has a known mapping, store the result of the mapping.
+				fieldMap[val] = operator
+			} else {
+				// Operator name not found, save as emptystring and let validation catch it later.
+				fieldMap[val] = ""
+			}
+		} else {
+			// Value is a full key:value pair, store it as is.
+			fieldMap[parts[0]] = parts[1]
+		}
+	}
+
+	return fieldMap
+}
+
 // HTTPVersionType is the name of a supported HTTP version.
 type HTTPVersionType string
 
@@ -288,7 +373,7 @@ type Parameters struct {
 
 	// AccessLogFields sets the fields that JSON logging will
 	// output when AccessLogFormat is json.
-	AccessLogFields []string `yaml:"json-fields,omitempty"`
+	AccessLogFields AccessLogFields `yaml:"json-fields,omitempty"`
 
 	// TLS contains TLS policy parameters.
 	TLS TLSParameters `yaml:"tls,omitempty"`
@@ -341,10 +426,8 @@ func (p *Parameters) Validate() error {
 		return err
 	}
 
-	for _, f := range p.AccessLogFields {
-		if _, ok := JSONFields[f]; !ok {
-			return fmt.Errorf("invalid JSON log field name %s", f)
-		}
+	if err := p.AccessLogFields.Validate(); err != nil {
+		return err
 	}
 
 	// Check TLS secret names.

pkg/config/parameters_test.go

@@ -126,6 +126,48 @@ func TestValidateAccessLogType(t *testing.T) {
 	assert.NoError(t, JSONAccessLog.Validate())
 }
 
+func TestValidateAccessLogFields(t *testing.T) {
+	errorCases := [][]string{
+		{"dog", "cat"},
+		{"req"},
+		{"resp"},
+		{"trailer"},
+		{"@timestamp", "dog"},
+		{"@timestamp", "content-id=%REQ=dog%"},
+		{"@timestamp", "content-id=%dog(%"},
+		{"@timestamp", "content-id=%REQ()%"},
+		{"@timestamp", "content-id=%DOG%"},
+		{"@timestamp", "duration=my durations % are %DURATION%.0 and %REQ(:METHOD)%"},
+		{"invalid=%REQ%"},
+		{"invalid=%TRAILER%"},
+		{"invalid=%RESP%"},
+		{"@timestamp", "invalid=%START_TIME(%s.%6f):10%"},
+	}
+
+	for _, c := range errorCases {
+		assert.Error(t, AccessLogFields(c).Validate(), c)
+	}
+
+	successCases := [][]string{
+		{"@timestamp", "method"},
+		{"start_time"},
+		{"@timestamp", "response_duration"},
+		{"@timestamp", "duration=%DURATION%.0"},
+		{"@timestamp", "duration=My duration=%DURATION%.0"},
+		{"@timestamp", "duratin=%START_TIME(%s.%6f)%"},
+		{"@timestamp", "content-id=%REQ(X-CONTENT-ID)%"},
+		{"@timestamp", "content-id=%REQ(X-CONTENT-ID):10%"},
+		{"@timestamp", "length=%RESP(CONTENT-LENGTH):10%"},
+		{"@timestamp", "trailer=%TRAILER(CONTENT-LENGTH):10%"},
+		{"@timestamp", "duration=my durations are %DURATION%.0 and method is %REQ(:METHOD)%"},
+		{"dog=pug", "cat=black"},
+	}
+
+	for _, c := range successCases {
+		assert.NoError(t, AccessLogFields(c).Validate(), c)
+	}
+}
+
 func TestValidateHTTPVersionType(t *testing.T) {
 	assert.Error(t, HTTPVersionType("").Validate())
 	assert.Error(t, HTTPVersionType("foo").Validate())