log token request error (#755)

* log token request error

* test case: AS responding with error

* changelog entry

---------

Co-authored-by: Alex Schneider <alex.schneider@avenga.com>

CHANGELOG.md

@@ -9,6 +9,9 @@ Unreleased changes are available as `avenga/couper:edge` container.
   * `bearer = true` attribute for [`jwt` block](https://docs.couper.io/configuration/block/jwt#attributes) to indicate retrieving token from `Authorization: Bearer ...`. This is the new default token source indicator. `header = "Authorization"` is now _deprecated_ in favour of this new attribute. ([#724](https://github.com/avenga/couper/pull/724))
   * If Couper starts with `-watch` CLI flag, watch referenced files, too ([#747](https://github.com/avenga/couper/pull/747))
 
+* **Changed**
+  * More specific error log messages for [`oauth2`](https://docs.couper.io/configuration/block/oauth2) and [`beta_token_request`](https://docs.couper.io/configuration/block/token_request) token request errors ([#755](https://github.com/avenga/couper/pull/755))
+
 * **Fixed**
   * Erroneously sending an empty [`Server-Timing` header](https://docs.couper.io/configuration/command-line#oberservation-options) ([#700](https://github.com/avenga/couper/pull/700))
   * `WWW-Authenticate` header `realm` param value for [`basic_auth`](https://docs.couper.io/configuration/block/basic_auth) ([#715](https://github.com/avenga/couper/pull/715))

handler/transport/oauth2_req_auth.go

@@ -223,7 +223,7 @@ func (oa *OAuth2ReqAuth) GetToken(req *http.Request) error {
 
 	tokenResponseData, token, err := oa.oauth2Client.GetTokenResponse(req.Context(), formParams)
 	if err != nil {
-		return requestError.Message("token request failed") // don't propagate token request roundtrip error
+		return requestError.Message("token request failed").With(err)
 	}
 
 	oa.updateAccessToken(token, tokenResponseData)

handler/transport/token_request.go

@@ -59,7 +59,7 @@ func (t *TokenRequest) GetToken(req *http.Request) error {
 	)
 	token, ttl, err = t.requestToken(req)
 	if err != nil {
-		return errors.Request.Label(t.config.Name).With(err)
+		return errors.Request.Label(t.config.Name).Message("token request failed").With(err)
 	}
 
 	t.memStore.Set(t.storageKey, token, ttl)
@@ -85,7 +85,7 @@ func (t *TokenRequest) requestToken(req *http.Request) (string, int64, error) {
 	outreq, _ := http.NewRequestWithContext(ctx, req.Method, "", nil)
 	result := t.reqProducer.Produce(outreq)
 	if result.Err != nil {
-		return "", 0, fmt.Errorf("token request failed") // don't propagate token request roundtrip error
+		return "", 0, result.Err
 	}
 
 	// obtain synced and already read beresp value; map to context variables

server/http_oauth2_test.go

@@ -1067,20 +1067,35 @@ func TestOAuth2_Runtime_Errors(t *testing.T) {
 			helper.Must(werr)
 			return
 		}
+		if req.URL.Path == "/token/error" {
+			rw.Header().Set("Content-Type", "application/json")
+			rw.WriteHeader(http.StatusBadRequest)
+
+			body := []byte(`{
+				"error": "the_error",
+				"error_description": "the error description",
+				"error_uri": "https://as/error/uri"
+			}`)
+			_, werr := rw.Write(body)
+			helper.Must(werr)
+			return
+		}
 		rw.WriteHeader(http.StatusBadRequest)
 	}))
 	defer asOrigin.Close()
 
 	type testCase struct {
 		name       string
 		filename   string
+		path       string
 		wantErrLog string
 	}
 
 	for _, tc := range []testCase{
-		{"null assertion", "17_couper.hcl", "backend error: be: request error: oauth2: assertion expression evaluates to null"},
-		{"non-string assertion", "18_couper.hcl", "backend error: be: request error: oauth2: assertion expression must evaluate to a string"},
-		{"token request error", "19_couper.hcl", "backend error: be: request error: oauth2: token request failed"},
+		{"null assertion", "17_couper.hcl", "/resource", "backend error: be: request error: oauth2: assertion expression evaluates to null"},
+		{"non-string assertion", "18_couper.hcl", "/resource", "backend error: be: request error: oauth2: assertion expression must evaluate to a string"},
+		{"token request error: connect error", "19_couper.hcl", "/resource", "backend error: be: request error: oauth2: token request failed: backend error: as_down: proxyconnect tcp: connecting to as_down '1.2.3.4:80' failed: dial tcp 127.0.0.1:9999: connect: connection refused"},
+		{"token request error: AS responding with error", "19_couper.hcl", "/other/resource", "backend error: be2: request error: oauth2: token request failed: error=the_error, error_description=the error description, error_uri=https://as/error/uri"},
 	} {
 		t.Run(tc.name, func(subT *testing.T) {
 			h := test.New(subT)
@@ -1089,7 +1104,7 @@ func TestOAuth2_Runtime_Errors(t *testing.T) {
 			h.Must(err)
 			defer shutdown()
 
-			req, err := http.NewRequest(http.MethodGet, "http://anyserver:8080/resource", nil)
+			req, err := http.NewRequest(http.MethodGet, "http://anyserver:8080"+tc.path, nil)
 			h.Must(err)
 
 			hook.Reset()
@@ -2169,14 +2184,14 @@ func TestTokenRequest_Runtime_Errors(t *testing.T) {
 	}
 
 	for _, tc := range []testCase{
-		{"token request error, handled by error handler", "01_token_request_error.hcl", http.StatusNoContent, "backend error: be: request error: tr: token request failed"},
+		{"token request error, handled by error handler", "01_token_request_error.hcl", http.StatusNoContent, "backend error: be: request error: tr: token request failed: backend error: down: proxyconnect tcp: connecting to down '1.2.3.4:80' failed: dial tcp 127.0.0.1:9999: connect: connection refused"},
 		{"token expression evaluation error", "02_token_request_error.hcl", http.StatusBadGateway, "couper-bytes.hcl:23,15-31: Call to unknown function; There is no function named \"evaluation_error\"."},
-		{"null token", "03_token_request_error.hcl", http.StatusBadGateway, "backend error: be: request error: tr: token expression evaluates to null"},
-		{"non-string token", "04_token_request_error.hcl", http.StatusBadGateway, "backend error: be: request error: tr: token expression must evaluate to a string"},
+		{"null token", "03_token_request_error.hcl", http.StatusBadGateway, "backend error: be: request error: tr: token request failed: token expression evaluates to null"},
+		{"non-string token", "04_token_request_error.hcl", http.StatusBadGateway, "backend error: be: request error: tr: token request failed: token expression must evaluate to a string"},
 		{"ttl expression evaluation error", "05_token_request_error.hcl", http.StatusBadGateway, "couper-bytes.hcl:24,13-29: Call to unknown function; There is no function named \"evaluation_error\"."},
-		{"null ttl", "06_token_request_error.hcl", http.StatusBadGateway, "backend error: be: request error: tr: ttl expression evaluates to null"},
-		{"non-string ttl", "07_token_request_error.hcl", http.StatusBadGateway, "backend error: be: request error: tr: ttl expression must evaluate to a string"},
-		{"non-duration ttl", "08_token_request_error.hcl", http.StatusBadGateway, "backend error: be: request error: tr: ttl: time: invalid duration \"no duration\""},
+		{"null ttl", "06_token_request_error.hcl", http.StatusBadGateway, "backend error: be: request error: tr: token request failed: ttl expression evaluates to null"},
+		{"non-string ttl", "07_token_request_error.hcl", http.StatusBadGateway, "backend error: be: request error: tr: token request failed: ttl expression must evaluate to a string"},
+		{"non-duration ttl", "08_token_request_error.hcl", http.StatusBadGateway, "backend error: be: request error: tr: token request failed: ttl: time: invalid duration \"no duration\""},
 	} {
 		t.Run(tc.name, func(subT *testing.T) {
 			h := test.New(subT)

server/testdata/oauth2/19_couper.hcl

@@ -5,6 +5,11 @@ server {
         backend = "be"
       }
     }
+    endpoint "/other/resource" {
+      proxy {
+        backend = "be2"
+      }
+    }
   }
 }
 
@@ -21,6 +26,17 @@ definitions {
     }
   }
 
+  backend "be2" {
+    origin = "http://does.not.matter"
+
+    oauth2 {
+      token_endpoint = "{{.asOrigin}}/token/error"
+      client_id = "my_clid"
+      client_secret = "my_cls"
+      grant_type = "client_credentials"
+    }
+  }
+
   backend "as_down" {
     origin = "http://1.2.3.4"
   }