Repository: avenga/couper
Pull request #199 (2021-04-12 10:09:06)

Extend AC validation logging


Patch:
diff --git a/accesscontrol/ac.go b/accesscontrol/ac.go
index aa316c31..82e247bf 100644
--- a/accesscontrol/ac.go
+++ b/accesscontrol/ac.go
@@ -8,9 +8,18 @@ import (
 
 var _ AccessControl = ValidateFunc(func(_ *http.Request) error { return nil })
 
+type ListItem struct {
+	Func AccessControl
+	Name string
+}
+
+func (i ListItem) Validate(req *http.Request) error {
+	return i.Func.Validate(req)
+}
+
 type (
 	Map  map[string]AccessControl
-	List []AccessControl
+	List []ListItem
 )
 
 type ValidateFunc func(*http.Request) error
diff --git a/config/runtime/server.go b/config/runtime/server.go
index 44810deb..926b0762 100644
--- a/config/runtime/server.go
+++ b/config/runtime/server.go
@@ -556,10 +556,10 @@ func configureProtectedHandler(m ac.Map, errTpl *errors.Template, parentAC, hand
 	for _, acName := range parentAC.
 		Merge(handlerAC).List() {
 		m.MustExist(acName)
-		acList = append(acList, m[acName])
+		acList = append(acList, ac.ListItem{Func: m[acName], Name: acName})
 	}
 	if len(acList) > 0 {
-		return hac.NewAccessControl(h, errTpl, acList...)
+		return hac.NewAccessControl(h, errTpl, acList)
 	}
 	return h
 }
diff --git a/handler/ac/access_control.go b/handler/ac/access_control.go
index 2db9827d..211a820d 100644
--- a/handler/ac/access_control.go
+++ b/handler/ac/access_control.go
@@ -15,21 +15,21 @@ var (
 )
 
 type AccessControl struct {
-	ac        accesscontrol.List
+	acl       accesscontrol.List
 	errorTpl  *errors.Template
 	protected http.Handler
 }
 
-func NewAccessControl(protected http.Handler, errTpl *errors.Template, list ...accesscontrol.AccessControl) *AccessControl {
+func NewAccessControl(protected http.Handler, errTpl *errors.Template, list accesscontrol.List) *AccessControl {
 	return &AccessControl{
-		ac:        list,
+		acl:       list,
 		errorTpl:  errTpl,
 		protected: protected,
 	}
 }
 
 func (a *AccessControl) ServeHTTP(rw http.ResponseWriter, req *http.Request) {
-	for _, control := range a.ac {
+	for _, control := range a.acl {
 		if err := control.Validate(req); err != nil {
 			var code errors.Code
 			if authError, ok := err.(*accesscontrol.BasicAuthError); ok {
@@ -50,7 +50,8 @@ func (a *AccessControl) ServeHTTP(rw http.ResponseWriter, req *http.Request) {
 				}
 			}
 			if ctx, ok := req.Context().Value(request.AccessControl).(*AccessControlContext); ok {
-				ctx.errors = append(ctx.errors, err)
+				ctx.error = err
+				ctx.name = control.Name
 			}
 			a.errorTpl.ServeError(code).ServeHTTP(rw, req)
 			return
diff --git a/handler/ac/access_control_context.go b/handler/ac/access_control_context.go
index 916e9ef5..58611acd 100644
--- a/handler/ac/access_control_context.go
+++ b/handler/ac/access_control_context.go
@@ -7,7 +7,8 @@ import (
 )
 
 type AccessControlContext struct {
-	errors []error
+	error error
+	name  string
 }
 
 func NewWithContext(ctx context.Context) (context.Context, *AccessControlContext) {
@@ -15,13 +16,14 @@ func NewWithContext(ctx context.Context) (context.Context, *AccessControlContext
 	return context.WithValue(ctx, request.AccessControl, octx), octx
 }
 
-func (o *AccessControlContext) Errors() []string {
-	if len(o.errors) == 0 {
-		return nil
-	}
-	var result []string
-	for _, e := range o.errors {
-		result = append(result, e.Error())
+func (o *AccessControlContext) Name() string {
+	return o.name
+}
+
+func (o *AccessControlContext) Error() string {
+	if o.error == nil {
+		return ""
 	}
-	return result
+
+	return o.error.Error()
 }
diff --git a/logging/access_log.go b/logging/access_log.go
index 3f3edb57..1527393a 100644
--- a/logging/access_log.go
+++ b/logging/access_log.go
@@ -47,10 +47,6 @@ func (log *AccessLog) ServeHTTP(rw http.ResponseWriter, req *http.Request, nextH
 		"bytes": statusRecorder.writtenBytes,
 	}
 
-	if acErrors := acContext.Errors(); len(acErrors) > 0 {
-		fields["access_control"] = acErrors
-	}
-
 	backendName, _ := req.Context().Value(request.BackendName).(string)
 	if backendName == "" {
 		endpointName, _ := req.Context().Value(request.Endpoint).(string)
@@ -139,6 +135,10 @@ func (log *AccessLog) ServeHTTP(rw http.ResponseWriter, req *http.Request, nextH
 	entry := log.logger.WithFields(logrus.Fields(fields))
 	entry.Time = startTime
 
+	if acError := acContext.Error(); acError != "" {
+		err = fmt.Errorf("access control: %s: %s", acContext.Name(), acError)
+	}
+
 	if statusRecorder.status == http.StatusInternalServerError || err != nil {
 		if err != nil {
 			entry.Error(err)


Test patch:
diff --git a/handler/ac/access_control_test.go b/handler/ac/access_control_test.go
index d8ef0bfb..ca1cac2c 100644
--- a/handler/ac/access_control_test.go
+++ b/handler/ac/access_control_test.go
@@ -43,39 +43,42 @@ func TestAccessControl_ServeHTTP(t *testing.T) {
 			rw.WriteHeader(http.StatusNoContent)
 		})}, newReq("GET", "http://ac.test/")("", ""), http.StatusNoContent, ""},
 
-		{"with access control valid req", fields{accesscontrol.List{accesscontrol.ValidateFunc(func(r *http.Request) error {
+		{"with access control valid req", fields{accesscontrol.List{accesscontrol.ListItem{Func: accesscontrol.ValidateFunc(func(r *http.Request) error {
 			return nil // valid
-		})}, http.HandlerFunc(func(rw http.ResponseWriter, _ *http.Request) {
+		}), Name: ""}}, http.HandlerFunc(func(rw http.ResponseWriter, _ *http.Request) {
 			rw.WriteHeader(http.StatusNoContent)
 		})}, newReq("GET", "http://ac.test/")("", ""), http.StatusNoContent, ""},
 
-		{"with access control invalid req/empty token", fields{accesscontrol.List{accesscontrol.ValidateFunc(func(r *http.Request) error {
+		{"with access control invalid req/empty token", fields{accesscontrol.List{accesscontrol.ListItem{Func: accesscontrol.ValidateFunc(func(r *http.Request) error {
 			return accesscontrol.ErrorEmptyToken
-		})}, http.HandlerFunc(func(rw http.ResponseWriter, _ *http.Request) {
+		}), Name: ""}}, http.HandlerFunc(func(rw http.ResponseWriter, _ *http.Request) {
 			rw.WriteHeader(http.StatusGone)
 		})}, newReq("GET", "http://ac.test/")("", ""), http.StatusUnauthorized, ""},
 
-		{"with access control invalid req", fields{accesscontrol.List{accesscontrol.ValidateFunc(func(r *http.Request) error {
+		{"with access control invalid req", fields{accesscontrol.List{accesscontrol.ListItem{Func: accesscontrol.ValidateFunc(func(r *http.Request) error {
 			return fmt.Errorf("no! ")
-		})}, http.HandlerFunc(func(rw http.ResponseWriter, _ *http.Request) {
+		}), Name: ""}}, http.HandlerFunc(func(rw http.ResponseWriter, _ *http.Request) {
 			rw.WriteHeader(http.StatusGone)
 		})}, newReq("GET", "http://ac.test/")("", ""), http.StatusForbidden, ""},
 
-		{"basic_auth", fields{accesscontrol.List{newBasicAuth("hans", "", "")}, http.HandlerFunc(func(rw http.ResponseWriter, _ *http.Request) {
+		{"basic_auth", fields{accesscontrol.List{accesscontrol.ListItem{Func: newBasicAuth("hans", "", ""),
+			Name: ""}}, http.HandlerFunc(func(rw http.ResponseWriter, _ *http.Request) {
 			rw.WriteHeader(http.StatusNoContent)
 		})}, newReq("GET", "http://ac.test/")("Authorization", "Basic aGFuczovVnFoV3FsS1VrSVNzUC8K"), http.StatusUnauthorized, "Basic"},
 
-		{"basic_auth /wo authorization header", fields{accesscontrol.List{newBasicAuth("hans", "", "")}, http.HandlerFunc(func(rw http.ResponseWriter, _ *http.Request) {
+		{"basic_auth /wo authorization header", fields{accesscontrol.List{accesscontrol.ListItem{Func: newBasicAuth("hans", "", ""),
+			Name: ""}}, http.HandlerFunc(func(rw http.ResponseWriter, _ *http.Request) {
 			rw.WriteHeader(http.StatusNoContent)
 		})}, newReq("GET", "http://ac.test/")("Authorization", ""), http.StatusUnauthorized, "Basic"},
 
-		{"basic_auth /w realm", fields{accesscontrol.List{newBasicAuth("hans", "", "My-Realm")}, http.HandlerFunc(func(rw http.ResponseWriter, _ *http.Request) {
+		{"basic_auth /w realm", fields{accesscontrol.List{accesscontrol.ListItem{Func: newBasicAuth("hans", "", "My-Realm"),
+			Name: ""}}, http.HandlerFunc(func(rw http.ResponseWriter, _ *http.Request) {
 			rw.WriteHeader(http.StatusNoContent)
 		})}, newReq("GET", "http://ac.test/")("Authorization", "Basic aGFuczovVnFoV3FsS1VrSVNzUC8K"), http.StatusUnauthorized, "Basic realm=My-Realm"},
 	}
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
-			a := NewAccessControl(tt.fields.protected, errors.DefaultJSON, tt.fields.ac...)
+			a := NewAccessControl(tt.fields.protected, errors.DefaultJSON, tt.fields.ac)
 
 			res := httptest.NewRecorder()
 			a.ServeHTTP(res, tt.req)
diff --git a/server/http_integration_test.go b/server/http_integration_test.go
index 2a324afd..3151a4a4 100644
--- a/server/http_integration_test.go
+++ b/server/http_integration_test.go
@@ -1959,12 +1959,12 @@ func TestConfigBodyContentAccessControl(t *testing.T) {
 		//{"/v1", http.Header{"Authorization": []string{"Basic OmFzZGY="}, "Auth": []string{"ba1"}}, http.StatusOK, "application/json"},
 		//{"/v1", http.Header{"Auth": []string{}}, http.StatusUnauthorized, "application/json"},
 		{"/v2", http.Header{"Authorization": []string{"Basic OmFzZGY="}, "Auth": []string{"ba1", "ba2"}}, http.StatusOK, "application/json", ""}, // minimum ':'
-		{"/v2", http.Header{}, http.StatusUnauthorized, "application/json", "missing credentials"},
+		{"/v2", http.Header{}, http.StatusUnauthorized, "application/json", "access control: ba1: missing credentials"},
 		{"/v3", http.Header{}, http.StatusOK, "application/json", ""},
 		{"/status", http.Header{}, http.StatusOK, "application/json", ""},
 		{"/superadmin", http.Header{"Authorization": []string{"Basic OmFzZGY="}, "Auth": []string{"ba1", "ba4"}}, http.StatusOK, "application/json", ""},
-		{"/superadmin", http.Header{}, http.StatusUnauthorized, "application/json", "missing credentials"},
-		{"/v4", http.Header{}, http.StatusUnauthorized, "text/html", "missing credentials"},
+		{"/superadmin", http.Header{}, http.StatusUnauthorized, "application/json", "access control: ba1: missing credentials"},
+		{"/v4", http.Header{}, http.StatusUnauthorized, "text/html", "access control: ba1: missing credentials"},
 	} {
 		t.Run(tc.path[1:], func(subT *testing.T) {
 			helper := test.New(subT)
@@ -1980,21 +1980,14 @@ func TestConfigBodyContentAccessControl(t *testing.T) {
 			res, err := client.Do(req)
 			helper.Must(err)
 
-			acEntries := getAccessControlMessages(hook)
+			message := getAccessControlMessages(hook)
 			if tc.wantErrLog == "" {
-				if len(acEntries) > 0 {
-					t.Errorf("Expected error log: %q, actual: %#v", tc.wantErrLog, acEntries)
+				if message != "" {
+					t.Errorf("Expected error log: %q, actual: %#v", tc.wantErrLog, message)
 				}
 			} else {
-				var found bool
-				for _, valMsg := range acEntries {
-					if strings.HasPrefix(valMsg, tc.wantErrLog) {
-						found = true
-						break
-					}
-				}
-				if !found {
-					t.Errorf("Expected error log: %q, actual: %#v", tc.wantErrLog, acEntries)
+				if message != tc.wantErrLog {
+					t.Errorf("Expected error log message: %q, actual: %#v", tc.wantErrLog, message)
 				}
 			}
 
@@ -2049,8 +2042,8 @@ func TestJWTAccessControl(t *testing.T) {
 	}
 
 	for _, tc := range []testCase{
-		{"no token", "/jwt", http.Header{}, http.StatusUnauthorized, "empty token"},
-		{"expired token", "/jwt", http.Header{"Authorization": []string{"Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiIxMjM0NTY3ODkwIiwibmFtZSI6IkpvaG4gRG9lIiwiaWF0IjoxNTE2MjM5MDIyLCJleHAiOjEyMzQ1Njc4OX0.wLWj9XgBZAPoDYPXsmDrEBzR6BUWfwPqQNlR_F0naZA"}}, http.StatusForbidden, "token is expired by "},
+		{"no token", "/jwt", http.Header{}, http.StatusUnauthorized, "access control: JWTToken: empty toke"},
+		{"expired token", "/jwt", http.Header{"Authorization": []string{"Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiIxMjM0NTY3ODkwIiwibmFtZSI6IkpvaG4gRG9lIiwiaWF0IjoxNTE2MjM5MDIyLCJleHAiOjEyMzQ1Njc4OX0.wLWj9XgBZAPoDYPXsmDrEBzR6BUWfwPqQNlR_F0naZA"}}, http.StatusForbidden, "access control: JWTToken: token is expired by "},
 		{"valid token", "/jwt", http.Header{"Authorization": []string{"Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiIxMjM0NTY3ODkwIiwibmFtZSI6IkpvaG4gRG9lIiwiaWF0IjoxNTE2MjM5MDIyfQ.Qf0lkeZKZ3NJrYm3VdgiQiQ6QTrjCvISshD_q9F8GAM"}}, http.StatusOK, ""},
 	} {
 		t.Run(tc.path[1:], func(subT *testing.T) {
@@ -2072,21 +2065,14 @@ func TestJWTAccessControl(t *testing.T) {
 				return
 			}
 
-			acEntries := getAccessControlMessages(hook)
+			message := getAccessControlMessages(hook)
 			if tc.wantErrLog == "" {
-				if len(acEntries) > 0 {
-					t.Errorf("Expected error log: %q, actual: %#v", tc.wantErrLog, acEntries)
+				if message != "" {
+					t.Errorf("Expected error log: %q, actual: %#v", tc.wantErrLog, message)
 				}
 			} else {
-				var found bool
-				for _, valMsg := range acEntries {
-					if strings.HasPrefix(valMsg, tc.wantErrLog) {
-						found = true
-						break
-					}
-				}
-				if !found {
-					t.Errorf("Expected error log: %q, actual: %#v", tc.wantErrLog, acEntries)
+				if !strings.HasPrefix(message, tc.wantErrLog) {
+					t.Errorf("Expected error log message: %q, actual: %#v", tc.wantErrLog, message)
 				}
 			}
 
@@ -2101,16 +2087,14 @@ func TestJWTAccessControl(t *testing.T) {
 	}
 }
 
-func getAccessControlMessages(hook *logrustest.Hook) []string {
-	var acEntries []string
+func getAccessControlMessages(hook *logrustest.Hook) string {
 	for _, entry := range hook.Entries {
-		if valEntry, ok := entry.Data["access_control"]; ok {
-			if list, ok := valEntry.([]string); ok {
-				acEntries = append(acEntries, list...)
-			}
+		if entry.Message != "" {
+			return entry.Message
 		}
 	}
-	return acEntries
+
+	return ""
 }
 
 func TestWrapperHiJack_WebsocketUpgrade(t *testing.T) {