Backport: no response-body reflection in API errors (#4421)

auth/api/iam/openid4vci.go

@@ -30,6 +30,7 @@ import (
 	"github.com/lestrrat-go/jwx/v3/jwt"
 	"github.com/nuts-foundation/go-did/did"
 	"github.com/nuts-foundation/go-did/vc"
+	"github.com/nuts-foundation/nuts-node/auth/log"
 	"github.com/nuts-foundation/nuts-node/auth/oauth"
 	"github.com/nuts-foundation/nuts-node/core"
 	"github.com/nuts-foundation/nuts-node/crypto"
@@ -144,27 +145,30 @@ func (r Wrapper) handleOpenID4VCICallback(ctx context.Context, authorizationCode
 	// use code to request access token from remote token endpoint
 	response, err := r.auth.IAMClient().AccessToken(ctx, authorizationCode, oauthSession.TokenEndpoint, checkURL.String(), *oauthSession.OwnSubject, clientID, oauthSession.PKCEParams.Verifier, false)
 	if err != nil {
-		return nil, withCallbackURI(oauthError(oauth.AccessDenied, fmt.Sprintf("error while fetching the access_token from endpoint: %s, error: %s", oauthSession.TokenEndpoint, err.Error())), appCallbackURI)
+		return nil, withCallbackURI(oauthError(oauth.AccessDenied, fmt.Sprintf("failed to retrieve access token from %s", oauthSession.TokenEndpoint), err), appCallbackURI)
 	}
 
 	// make proof and collect credential
 	proofJWT, err := r.openid4vciProof(ctx, *oauthSession.OwnDID, oauthSession.IssuerURL, response.Get(oauth.CNonceParam))
 	if err != nil {
-		return nil, withCallbackURI(oauthError(oauth.ServerError, fmt.Sprintf("error building proof to fetch the credential from endpoint %s, error: %s", oauthSession.IssuerCredentialEndpoint, err.Error())), appCallbackURI)
+		return nil, withCallbackURI(oauthError(oauth.ServerError, fmt.Sprintf("failed to build proof for the credential request to %s", oauthSession.IssuerCredentialEndpoint), err), appCallbackURI)
 	}
 	credentials, err := r.auth.IAMClient().VerifiableCredentials(ctx, oauthSession.IssuerCredentialEndpoint, response.AccessToken, proofJWT)
 	if err != nil {
-		return nil, withCallbackURI(oauthError(oauth.ServerError, fmt.Sprintf("error while fetching the credential from endpoint %s, error: %s", oauthSession.IssuerCredentialEndpoint, err.Error())), appCallbackURI)
+		return nil, withCallbackURI(oauthError(oauth.ServerError, fmt.Sprintf("failed to retrieve the credential from %s", oauthSession.IssuerCredentialEndpoint), err), appCallbackURI)
 	}
 	// validate credential
 	// TODO: check that issued credential is bound to DID that requested it (OwnDID)???
 	credential, err := vc.ParseVerifiableCredential(credentials.Credential)
 	if err != nil {
-		return nil, withCallbackURI(oauthError(oauth.ServerError, fmt.Sprintf("error while parsing the credential: %s, error: %s", credentials.Credential, err.Error())), appCallbackURI)
+		// Debug-log the (truncated) credential for diagnostics, but never reflect it: it is
+		// fetched from the issuer's (attacker-influenceable) credential endpoint.
+		log.Logger().Debugf("credential returned by %s could not be parsed (credential: %q)", oauthSession.IssuerCredentialEndpoint, core.TruncateHTTPBody([]byte(credentials.Credential)))
+		return nil, withCallbackURI(oauthError(oauth.ServerError, fmt.Sprintf("failed to parse the credential returned by %s", oauthSession.IssuerCredentialEndpoint), err), appCallbackURI)
 	}
 	err = r.vcr.Verifier().Verify(*credential, true, true, nil)
 	if err != nil {
-		return nil, withCallbackURI(oauthError(oauth.ServerError, fmt.Sprintf("error while verifying the credential from issuer: %s, error: %s", credential.Issuer.String(), err.Error())), appCallbackURI)
+		return nil, withCallbackURI(oauthError(oauth.ServerError, fmt.Sprintf("the credential returned by issuer %s failed verification", credential.Issuer.String()), err), appCallbackURI)
 	}
 	// store credential in wallet
 	err = r.vcr.Wallet().Put(ctx, *credential)

auth/api/iam/openid4vci_test.go

@@ -246,7 +246,8 @@ func TestWrapper_handleOpenID4VCICallback(t *testing.T) {
 
 		assert.Error(t, err)
 		assert.Nil(t, callback)
-		assert.Equal(t, "access_denied - error while fetching the access_token from endpoint: https://auth.server/token, error: FAIL", err.Error())
+		assert.ErrorContains(t, err, "failed to retrieve access token from https://auth.server/token")
+		assert.ErrorContains(t, err, "FAIL")
 	})
 	t.Run("fail_credential_response", func(t *testing.T) {
 		ctx := newTestClient(t)
@@ -258,21 +259,34 @@ func TestWrapper_handleOpenID4VCICallback(t *testing.T) {
 		callback, err := ctx.client.handleOpenID4VCICallback(nil, code, &session)
 
 		assert.Nil(t, callback)
-		assert.EqualError(t, err, "server_error - error while fetching the credential from endpoint https://auth.server/credz, error: FAIL")
+		assert.ErrorContains(t, err, "failed to retrieve the credential from https://auth.server/credz")
+		assert.ErrorContains(t, err, "FAIL")
 	})
 	t.Run("err - invalid credential", func(t *testing.T) {
 		ctx := newTestClient(t)
 		ctx.iamClient.EXPECT().AccessToken(nil, code, tokenEndpoint, redirectURI, holderSubjectID, holderClientID, pkceParams.Verifier, false).Return(tokenResponse, nil)
 		ctx.keyResolver.EXPECT().ResolveKey(holderDID, nil, resolver.NutsSigningKeyType).Return("kid", nil, nil)
 		ctx.jwtSigner.EXPECT().SignJWT(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any()).Return("signed-proof", nil)
 		ctx.iamClient.EXPECT().VerifiableCredentials(nil, credEndpoint, accessToken, "signed-proof").Return(&iam.CredentialResponse{
-			Credential: "super invalid",
+			Credential: "SENTINEL-CREDENTIAL-BODY",
 		}, nil)
 
 		callback, err := ctx.client.handleOpenID4VCICallback(nil, code, &session)
 
 		assert.Nil(t, callback)
-		assert.EqualError(t, err, "server_error - error while parsing the credential: super invalid, error: jwt.Parse: failed to parse token: unknown payload type (payload is not JWT?)")
+		require.Error(t, err)
+		var oauthErr oauth.OAuth2Error
+		require.ErrorAs(t, err, &oauthErr)
+		// It failed specifically because the returned credential could not be parsed:
+		// the static description identifies that branch, so the test can't pass on an
+		// unrelated earlier error.
+		assert.Equal(t, oauth.ServerError, oauthErr.Code)
+		assert.Contains(t, oauthErr.Description, "failed to parse the credential")
+		// The parse failure detail is still available for diagnostics ...
+		require.NotNil(t, oauthErr.InternalError)
+		assert.ErrorContains(t, err, "failed to parse token")
+		// ... but the raw credential body is never reflected into the response.
+		assert.NotContains(t, oauthErr.Description, "SENTINEL-CREDENTIAL-BODY")
 	})
 	t.Run("fail_verify", func(t *testing.T) {
 		ctx := newTestClient(t)
@@ -285,7 +299,8 @@ func TestWrapper_handleOpenID4VCICallback(t *testing.T) {
 		callback, err := ctx.client.handleOpenID4VCICallback(nil, code, &session)
 
 		assert.Nil(t, callback)
-		assert.EqualError(t, err, "server_error - error while verifying the credential from issuer: did:web:example.com:iam:issuer, error: FAIL")
+		assert.ErrorContains(t, err, "the credential returned by issuer did:web:example.com:iam:issuer failed verification")
+		assert.ErrorContains(t, err, "FAIL")
 	})
 	t.Run("error - key not found", func(t *testing.T) {
 		ctx := newTestClient(t)

auth/api/iam/openid4vp.go

@@ -737,12 +737,12 @@ func (r Wrapper) handleCallback(ctx context.Context, authorizationCode string, o
 	// use code to request access token from remote token endpoint
 	tokenResponse, err := r.auth.IAMClient().AccessToken(ctx, authorizationCode, oauthSession.TokenEndpoint, checkURL.String(), *oauthSession.OwnSubject, clientID, oauthSession.PKCEParams.Verifier, oauthSession.UseDPoP)
 	if err != nil {
-		return nil, withCallbackURI(oauthError(oauth.ServerError, fmt.Sprintf("failed to retrieve access token: %s", err.Error())), appCallbackURI)
+		return nil, withCallbackURI(oauthError(oauth.ServerError, fmt.Sprintf("failed to retrieve access token from %s", oauthSession.TokenEndpoint), err), appCallbackURI)
 	}
 	// update TokenResponse using session.SessionID
 	tokenResponse = tokenResponse.With("status", oauth.AccessTokenRequestStatusActive)
 	if err = r.accessTokenClientStore().Put(oauthSession.SessionID, tokenResponse); err != nil {
-		return nil, withCallbackURI(oauthError(oauth.ServerError, fmt.Sprintf("failed to store access token: %s", err.Error())), appCallbackURI)
+		return nil, withCallbackURI(oauthError(oauth.ServerError, "failed to store access token", err), appCallbackURI)
 	}
 	return Callback302Response{
 		Headers: Callback302ResponseHeaders{Location: appCallbackURI.String()},

auth/api/iam/openid4vp_test.go

@@ -757,7 +757,8 @@ func Test_handleCallback(t *testing.T) {
 
 		_, err := ctx.client.handleCallback(nil, code, &session)
 
-		requireOAuthError(t, err, oauth.ServerError, "failed to retrieve access token: assert.AnError general error for testing")
+		// The remote error must not be reflected into the description; only static context (the endpoint) is kept.
+		requireOAuthError(t, err, oauth.ServerError, "failed to retrieve access token from https://example.com/token")
 	})
 }
 

auth/client/iam/client.go

@@ -211,12 +211,11 @@ func (hb HTTPClient) AccessToken(ctx context.Context, tokenEndpoint string, data
 		return token, fmt.Errorf("unable to read response: %w", err)
 	}
 	if err = json.Unmarshal(responseData, &token); err != nil {
-		// Cut off the response body to 100 characters max to prevent logging of large responses
-		responseBodyString := string(responseData)
-		if len(responseBodyString) > core.HttpResponseBodyLogClipAt {
-			responseBodyString = responseBodyString[:core.HttpResponseBodyLogClipAt] + "...(clipped)"
-		}
-		return token, fmt.Errorf("unable to unmarshal response: %w, %s", err, responseBodyString)
+		// Debug-log the (truncated) body for diagnostics, but never return it: the token
+		// endpoint may have been redirected to an attacker-influenced target, and the body
+		// must not be reflected back to the caller.
+		log.Logger().Debugf("token endpoint returned an unparseable response (body: %q)", core.TruncateHTTPBody(responseData))
+		return token, fmt.Errorf("unable to unmarshal response: %w", err)
 	}
 	return token, nil
 }

auth/client/iam/client_test.go

@@ -31,9 +31,12 @@ import (
 	nutsCrypto "github.com/nuts-foundation/nuts-node/crypto"
 	test2 "github.com/nuts-foundation/nuts-node/crypto/test"
 	"github.com/nuts-foundation/nuts-node/vdr/resolver"
+	"github.com/sirupsen/logrus"
+	logrustest "github.com/sirupsen/logrus/hooks/test"
 	"net/http"
 	"net/http/httptest"
 	"net/url"
+	"strings"
 	"testing"
 	"time"
 
@@ -188,13 +191,29 @@ func TestHTTPClient_AccessToken(t *testing.T) {
 		assert.Equal(t, "offline", string(httpError.ResponseBody))
 	})
 	t.Run("error - invalid response", func(t *testing.T) {
-		handler := http2.Handler{StatusCode: http.StatusOK, ResponseData: "}"}
+		hook := logrustest.NewGlobal()
+		oldLevel := logrus.GetLevel()
+		logrus.SetLevel(logrus.DebugLevel)
+		t.Cleanup(func() { logrus.SetLevel(oldLevel) })
+
+		handler := http2.Handler{StatusCode: http.StatusOK, ResponseData: "SECRET-RESPONSE-BODY"}
 		tlsServer, client := testServerAndClient(t, &handler)
 
 		_, err := client.AccessToken(ctx, tlsServer.URL, data, dpopHeader)
 
 		require.Error(t, err)
-		assert.EqualError(t, err, "unable to unmarshal response: invalid character '}' looking for beginning of value, }")
+		assert.ErrorContains(t, err, "unable to unmarshal response")
+		// The raw response body must not be reflected in the returned error, since it can
+		// carry content fetched from an attacker-influenced endpoint.
+		assert.NotContains(t, err.Error(), "SECRET-RESPONSE-BODY")
+		// It is debug-logged (truncated) for diagnostics instead.
+		var logged bool
+		for _, entry := range hook.AllEntries() {
+			if strings.Contains(entry.Message, "SECRET-RESPONSE-BODY") {
+				logged = true
+			}
+		}
+		assert.True(t, logged, "response body should be debug-logged")
 	})
 
 }

core/http_client.go

@@ -33,9 +33,22 @@ import (
 // This callback pattern avoids circular imports between core and tracing packages.
 var TracingHTTPTransport func(http.RoundTripper) http.RoundTripper
 
-// HttpResponseBodyLogClipAt is the maximum length of a response body to log.
+// HttpResponseBodyLogTruncateAt is the maximum length of a response body to log.
 // If the response body is longer than this, it will be truncated.
-const HttpResponseBodyLogClipAt = 200
+const HttpResponseBodyLogTruncateAt = 200
+
+// TruncateHTTPBody returns the response body truncated to at most HttpResponseBodyLogTruncateAt bytes,
+// safe to write to a (debug) log. It exists so an unexpected response can be logged for
+// diagnostics without ever placing the full, possibly attacker-influenced, body into an
+// error message that could be reflected back to a caller.
+func TruncateHTTPBody(body []byte) string {
+	if len(body) <= HttpResponseBodyLogTruncateAt {
+		return string(body)
+	}
+	// The cut may split a multi-byte UTF-8 character; that is fine for logging,
+	// callers log the result with %q which escapes any invalid bytes.
+	return string(body[:HttpResponseBodyLogTruncateAt]) + "...(truncated)"
+}
 
 // HttpError describes an error returned when invoking a remote server.
 type HttpError struct {
@@ -56,13 +69,8 @@ func TestResponseCodeWithLog(expectedStatusCode int, response *http.Response, lo
 	if response.StatusCode != expectedStatusCode {
 		responseData, _ := io.ReadAll(response.Body)
 		if log != nil {
-			// Cut off the response body to 100 characters max to prevent logging of large responses
-			responseBodyString := string(responseData)
-			if len(responseBodyString) > HttpResponseBodyLogClipAt {
-				responseBodyString = responseBodyString[:HttpResponseBodyLogClipAt] + "...(clipped)"
-			}
 			log.WithField("http_request_path", response.Request.URL.Path).
-				Infof("Unexpected HTTP response (len=%d): %s", len(responseData), responseBodyString)
+				Infof("Unexpected HTTP response (len=%d): %q", len(responseData), TruncateHTTPBody(responseData))
 		}
 		return HttpError{
 			error:        fmt.Errorf("server returned HTTP %d (expected: %d)", response.StatusCode, expectedStatusCode),

core/http_client_test.go

@@ -106,6 +106,20 @@ func TestTestResponseCode(t *testing.T) {
 	})
 }
 
+func TestTruncateHTTPBody(t *testing.T) {
+	t.Run("short body is returned as-is", func(t *testing.T) {
+		assert.Equal(t, "hello", TruncateHTTPBody([]byte("hello")))
+	})
+	t.Run("body at the limit is returned as-is", func(t *testing.T) {
+		body := strings.Repeat("a", HttpResponseBodyLogTruncateAt)
+		assert.Equal(t, body, TruncateHTTPBody([]byte(body)))
+	})
+	t.Run("longer body is truncated", func(t *testing.T) {
+		body := strings.Repeat("a", HttpResponseBodyLogTruncateAt+1)
+		assert.Equal(t, strings.Repeat("a", HttpResponseBodyLogTruncateAt)+"...(truncated)", TruncateHTTPBody([]byte(body)))
+	})
+}
+
 func TestTestResponseCodeWithLog(t *testing.T) {
 	t.Run("ok", func(t *testing.T) {
 		logger := logrus.New()
@@ -130,9 +144,9 @@ func TestTestResponseCodeWithLog(t *testing.T) {
 
 		assert.Len(t, hook.Entries, 1)
 		assert.Equal(t, logrus.InfoLevel, hook.LastEntry().Level)
-		assert.Equal(t, "Unexpected HTTP response (len=13): hello, world!", hook.LastEntry().Message)
+		assert.Equal(t, `Unexpected HTTP response (len=13): "hello, world!"`, hook.LastEntry().Message)
 	})
-	t.Run("large response body (>200), clipped", func(t *testing.T) {
+	t.Run("large response body (>200), truncated", func(t *testing.T) {
 		data := strings.Repeat("a", 201)
 		status := stdHttp.StatusUnauthorized
 		logger := logrus.New()
@@ -142,7 +156,7 @@ func TestTestResponseCodeWithLog(t *testing.T) {
 
 		_ = TestResponseCodeWithLog(stdHttp.StatusOK, &stdHttp.Response{StatusCode: status, Body: readCloser(data), Request: request}, logger.WithFields(nil))
 
-		assert.Equal(t, "Unexpected HTTP response (len=201): "+strings.Repeat("a", HttpResponseBodyLogClipAt)+"...(clipped)", hook.LastEntry().Message)
+		assert.Equal(t, `Unexpected HTTP response (len=201): "`+strings.Repeat("a", HttpResponseBodyLogTruncateAt)+`...(truncated)"`, hook.LastEntry().Message)
 	})
 }
 

discovery/api/server/client/http.go

@@ -64,8 +64,9 @@ func (h DefaultHTTPClient) Register(ctx context.Context, serviceEndpointURL stri
 	}
 	defer httpResponse.Body.Close()
 	if err := core.TestResponseCodeWithLog(201, httpResponse, log.Logger()); err != nil {
-		httpErr := err.(core.HttpError) // TestResponseCodeWithLog always returns an HttpError
-		return fmt.Errorf("non-OK response from remote Discovery Service (url=%s): %s", serviceEndpointURL, problemResponseToError(httpErr))
+		// The response body is not part of the returned error: it comes from a remote server
+		// and must not be reflected in our own API responses. TestResponseCodeWithLog logs it (truncated).
+		return fmt.Errorf("non-OK response from remote Discovery Service (url=%s): %w", serviceEndpointURL, err)
 	}
 	return nil
 }
@@ -82,9 +83,10 @@ func (h DefaultHTTPClient) Get(ctx context.Context, serviceEndpointURL string, t
 		return nil, "", 0, fmt.Errorf("failed to invoke remote Discovery Service (url=%s): %w", serviceEndpointURL, err)
 	}
 	defer httpResponse.Body.Close()
-	if err := core.TestResponseCode(200, httpResponse); err != nil {
-		httpErr := err.(core.HttpError) // TestResponseCodeWithLog always returns an HttpError
-		return nil, "", 0, fmt.Errorf("non-OK response from remote Discovery Service (url=%s): %s", serviceEndpointURL, problemResponseToError(httpErr))
+	if err := core.TestResponseCodeWithLog(200, httpResponse, log.Logger()); err != nil {
+		// The response body is not part of the returned error: it comes from a remote server
+		// and must not be reflected in our own API responses. TestResponseCodeWithLog logs it (truncated).
+		return nil, "", 0, fmt.Errorf("non-OK response from remote Discovery Service (url=%s): %w", serviceEndpointURL, err)
 	}
 	responseData, err := io.ReadAll(httpResponse.Body)
 	if err != nil {
@@ -96,17 +98,3 @@ func (h DefaultHTTPClient) Get(ctx context.Context, serviceEndpointURL string, t
 	}
 	return result.Entries, result.Seed, result.Timestamp, nil
 }
-
-// problemResponseToError converts a Problem Details response to an error.
-// It creates an error with the given string concatenated with the title and detail fields of the problem details.
-func problemResponseToError(httpErr core.HttpError) string {
-	var problemDetails struct {
-		Title       string `json:"title"`
-		Description string `json:"detail"`
-		Status      int    `json:"status"`
-	}
-	if err := json.Unmarshal(httpErr.ResponseBody, &problemDetails); err != nil {
-		return fmt.Sprintf("%s: %s", httpErr.Error(), httpErr.ResponseBody)
-	}
-	return fmt.Sprintf("server returned HTTP status code %d: %s: %s", problemDetails.Status, problemDetails.Title, problemDetails.Description)
-}