From fc8d73cc393b409fafaa083647b82596ae296b4d Mon Sep 17 00:00:00 2001 From: Johannes Koch Date: Thu, 6 Apr 2023 13:47:06 +0200 Subject: [PATCH 1/3] log token request error --- handler/transport/oauth2_req_auth.go | 2 +- handler/transport/token_request.go | 4 ++-- server/http_oauth2_test.go | 14 +++++++------- 3 files changed, 10 insertions(+), 10 deletions(-) diff --git a/handler/transport/oauth2_req_auth.go b/handler/transport/oauth2_req_auth.go index 5d272fdb9..15eb15778 100644 --- a/handler/transport/oauth2_req_auth.go +++ b/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) diff --git a/handler/transport/token_request.go b/handler/transport/token_request.go index f102b704e..58473b05b 100644 --- a/handler/transport/token_request.go +++ b/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 diff --git a/server/http_oauth2_test.go b/server/http_oauth2_test.go index 7bc9de395..a54c5a673 100644 --- a/server/http_oauth2_test.go +++ b/server/http_oauth2_test.go @@ -1080,7 +1080,7 @@ func TestOAuth2_Runtime_Errors(t *testing.T) { 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"}, + {"token request error", "19_couper.hcl", "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"}, } { t.Run(tc.name, func(subT *testing.T) { h := test.New(subT) @@ -2169,14 +2169,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) From 72e832ebc6ffc5415a169b7fa9bc408cf7a7146e Mon Sep 17 00:00:00 2001 From: Johannes Koch Date: Thu, 6 Apr 2023 14:04:59 +0200 Subject: [PATCH 2/3] test case: AS responding with error --- server/http_oauth2_test.go | 23 +++++++++++++++++++---- server/testdata/oauth2/19_couper.hcl | 16 ++++++++++++++++ 2 files changed, 35 insertions(+), 4 deletions(-) diff --git a/server/http_oauth2_test.go b/server/http_oauth2_test.go index a54c5a673..788b126bc 100644 --- a/server/http_oauth2_test.go +++ b/server/http_oauth2_test.go @@ -1067,6 +1067,19 @@ 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() @@ -1074,13 +1087,15 @@ func TestOAuth2_Runtime_Errors(t *testing.T) { 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: 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"}, + {"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() diff --git a/server/testdata/oauth2/19_couper.hcl b/server/testdata/oauth2/19_couper.hcl index dea809204..23a41fbcc 100644 --- a/server/testdata/oauth2/19_couper.hcl +++ b/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" } From e55ab3e92fdb17dd57ac2e1588e9c40642a17378 Mon Sep 17 00:00:00 2001 From: Johannes Koch Date: Thu, 6 Apr 2023 14:11:11 +0200 Subject: [PATCH 3/3] changelog entry --- CHANGELOG.md | 3 +++ 1 file changed, 3 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 85bda12bb..99505dce6 100644 --- a/CHANGELOG.md +++ b/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))