8000 Improve details for user error events in OIDC protocol endpoints by thomasdarimont · Pull Request #29167 · keycloak/keycloak · GitHub
[go: up one dir, main page]

Skip to content

Improve details for user error events in OIDC protocol endpoints - #29167

Merged
ahus1 merged 12 commits into
keycloak:mainfrom
thomasdarimont:issue/GH-29166-improve-debug-info-in-event-details
May 6, 2024
Merged

ahus1 merged 12 commits into
keycloak:mainfrom
thomasdarimont:issue/GH-29166-improve-debug-info-in-event-details

Conversation

@thomasdarimont
Copy link
Copy Markdown
Contributor

Fixes #29166

@thomasdarimont
thomasdarimont force-pushed the issue/GH-29166-improve-debug-info-in-event-details branch from 07b8566 to a900b7a Compare April 29, 2024 20:17
@thomasdarimont thomasdarimont changed the title Improve Details for protocol endpoints in User Error events (#29166) Improve details for user error events in protocol endpoints (#29166) Apr 29, 2024
@thomasdarimont
thomasdarimont force-pushed the issue/GH-29166-improve-debug-info-in-event-details branch from a900b7a to eba98f2 Compare April 29, 2024 20:20
@thomasdarimont thomasdarimont changed the title Improve details for user error events in protocol endpoints (#29166) Improve details for user error events in protocol endpoints Apr 29, 2024
@thomasdarimont
thomasdarimont force-pushed the issue/GH-29166-improve-debug-info-in-event-details branch from eba98f2 to 3fa0f84 Compare April 29, 2024 20:23
@thomasdarimont
thomasdarimont marked this pull request as ready for review April 29, 2024 20:24
@thomasdarimont
thomasdarimont requested a review from a team as a code owner April 29, 2024 20:24
@thomasdarimont thomasdarimont changed the title Improve details for user error events in protocol endpoints Improve details for user error events in OIDC protocol endpoints Apr 30, 2024
@mposolda mposolda left a comment
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@thomasdarimont Thanks, the additional details in the event are useful!

Added some minor comments inline, but I think that this also causes some test failures AccessTokenTest, OAuth2DeviceAuthorizationGrantTest, OAuthProofKeyForCodeExchangeTest, OID4VCIssuerEndpointTest (not sure about last one as it is flaky in general and it is failing in some other PRs as well...)

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same concern like above (the fact that we're returning scopes inside the CorsErrorResponseException is likely also far from ideal, so if you can change in the PR when on this, it can be nice :-)

@thomasdarimont thomasdarimont Apr 30, 2024 •
Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same as above. I'll remove the received scopes from the returned response. How about logging a warning here with the invalid scope?

We could also just sent out all allowed scopes with the response, e.g.: https://www.googlecloudcommunity.com/gc/Apigee/Invalid-Scope-Error/m-p/644418

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks. Also sounds good to me to log the warning. Sending back the valid scopes is also a good idea.

@thomasdarimont thomasdarimont Apr 30, 2024 •
Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I updated the code, the error response now looks like this:

curl -s \
  -d "grant_type=password" \
  -d "username=admin" \
  -d "password=admin" \
  -d "client_id=admin-cli" \
  -d "scope=unknown" \
  http://localhost:8081/auth/realms/master/protocol/openid-connect/token 
{
  "error":"invalid_scope",
  "error_description":"Invalid scopes. Scopes must be contained in [address, email, microprofile-jwt, offline_access, organization, phone, profile]"
}

This is a bit more telling than just invalid scopes. For now I filter the scopes to those that are also included in the token scope, but that might be not necessary. I could probably remove the filter and render out all allowed scopes. WDYT?

Without the "include in tokenscope" filter we get this:

{
  "error":"invalid_scope",
  "error_description":"Invalid scopes. Scopes must be contained in [acr, address, basic, email, microprofile-jwt, offline_access, organization, phone, profile, roles, web-origins]"
}

Note that the artifical scopes roles, web-origins, basic, acr are now also added to the response.

@mposolda mposolda self-assigned this Apr 30, 2024
@thomasdarimont
thomasdarimont force-pushed the issue/GH-29166-improve-debug-info-in-event-details branch from 3fa0f84 to 13c4955 Compare April 30, 2024 17:46
@thomasdarimont
thomasdarimont requested review from a team as code owners April 30, 2024 18:11
@thomasdarimont
Copy link
Copy Markdown
Contributor Author

@mposolda I revised the code as discussed and fixed the test failures, which were mostly checking for the errorDescription in the response. All tests pass now locally including OID4VCTest which I didn't need to adapt.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Here I used the more appropriate Errors.INVALID_REDIRECT_URI instead of Errors.INVALID_CODE

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Here I used the more appropriate Errors.INVALID_CLIENT instead of Errors.INVALID_CODE

@thomasdarimont
thomasdarimont force-pushed the issue/GH-29166-improve-debug-info-in-event-details branch 3 times, most recently from f0d00ef to 6889ad5 Compare April 30, 2024 20:46
Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Here we collect all allowed scope names that can be requested (and represented in the token).

@ahus1 ahus1 left a comment
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hi @thomasdarimont - thank you for improving the logging and the events.

Something I learned just recently: You'll need to call event.detail() before calling event.error(), as the event.error() will send out and store the event. If you do it the other way around, the details will get lost.

About the available scopes: I agree to store this information in the event, which will then be logged and depending on the configuration also stored in the database.

I then disagree to share the whole list of scopes with the caller, as I would consider this an information leak if this is shared with an unauthorized caller aka public client (CWE-200). Maybe we could have different messages for the event and returned to the caller.

I also see that you're adding log.warn() in some places. As the default setting is to log error events, this is IMHO redundant. Maybe you want to reconsider some of those log messages.

@thomasdarimont
thomasdarimont commented May 1, 2024 •
Copy link
Copy Markdown
Contributor Author

Thanks @ahus1 for taking a look and your helpful suggestions. I totally missed the subtle relationship between event.detail(..) and event.error(..).

Regarding saving the elegible scopes in the events, I just reverted this for now to the previous state.
I'm not sure if this presents an information leak as the information is already exposed via the /.well-known/openid-configuration:

...
"scopes_supported": [
"openid",
"roles",
"organization",
"profile",
"web-origins",
"microprofile-jwt",
"phone",
"address",
"acr",
"email",
"basic",
"offline_access"
],
...

Perhaps we should add a setting to the client scope configuration that allows to hide a client scope from the OIDC configuration document.

@mposolda I just tested the initial suggestion in org.keycloak.protocol.oidc.endpoints.AuthorizationEndpointChecker#checkValidScope(..)

String errorMessage = "Invalid scopes: " + request.getScope();
event.detail(Details.REASON, errorMessage);

A scope parameter like &scope=openid+unknown would show up like this in the user events view in the admin ui:
image

The current admin ui encodes the values shown in the events view, so I think we are fine with showing this in the table.

I also reverted the changed log levels in OAuth2GrantTypeBase back to their previous levels (info).

@thomasdarimont
thomasdarimont force-pushed the issue/GH-29166-improve-debug-info-in-event-details branch from d804da7 to 739ca5c Compare May 1, 2024 15:15
@thomasdarimont
thomasdarimont force-pushed the issue/GH-29166-improve-debug-info-in-event-details branch from 777320c to a3cad80 Compare May 2, 2024 18:16
@thomasdarimont
Copy link
Copy Markdown
Contributor Author

@mposolda thanks for the review! I Adapted the PkceUtils to avoid info logging in favor of relying on the error events.

There were two log messages in info in org.keycloak.protocol.oidc.utils.PkceUtils#isValidPkceCodeVerifier(..) that I changed to debug to avoid spamming logs.

@thomasdarimont
10000
Copy link
Copy Markdown
Contributor Author

I just looked at the same problem for the SAML Endpoints #29238 and noticed that the Details.REASON in the SAML error events is often a message key instead of a concrete message. Other places add a plain english error message to Details.REASON.

Unfortunately the intent of Details.REASON is not specified explicitly... can I assume that the Details.REASON should always contain a human readable message?

@keycloak-github-bot
Copy link
Copy Markdown

Unreported flaky test detected

If the flaky tests below are affected by the changes, please review and update the changes accordingly. Otherwise, a maintainer should report the flaky tests prior to merging the PR.

org.keycloak.testsuite.webauthn.AppInitiatedActionWebAuthnTest#proceedSetupWebAuthnLogoutOtherSessionsChecked

Keycloak CI - WebAuthn IT (chrome)

java.lang.RuntimeException: Could not create statement
	at org.jboss.arquillian.junit.Arquillian.methodBlock(Arquillian.java:307)
	at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
...

Report flaky test

org.keycloak.testsuite.oauth.ClientTokenExchangeTest#testExchangeWithDynamicScopesEnabled

Keycloak CI - Base IT (6)

org.keycloak.common.VerificationException: Token not set
	at org.keycloak.TokenVerifier.parse(TokenVerifier.java:401)
	at org.keycloak.testsuite.oauth.ClientTokenExchangeTest.testExchange(ClientTokenExchangeTest.java:309)
	at org.keycloak.testsuite.oauth.ClientTokenExchangeTest.testExchangeWithDynamicScopesEnabled(ClientTokenExchangeTest.java:1021)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
...

Report flaky test

org.keycloak.testsuite.oauth.ClientTokenExchangeTest#testClientExchange

Keycloak CI - Base IT (6)

java.lang.AssertionError: expected:<200> but was:<400>
	at org.junit.Assert.fail(Assert.java:89)
	at org.junit.Assert.failNotEquals(Assert.java:835)
	at org.junit.Assert.assertEquals(Assert.java:647)
	at org.junit.Assert.assertEquals(Assert.java:633)
...

Report flaky test

org.keycloak.testsuite.oauth.ClientTokenExchangeTest#testIntrospectTokenAfterImpersonation

Keycloak CI - Base IT (6)

java.lang.AssertionError: expected:<200> but was:<400>
	at org.junit.Assert.fail(Assert.java:89)
	at org.junit.Assert.failNotEquals(Assert.java:835)
	at org.junit.Assert.assertEquals(Assert.java:647)
	at org.junit.Assert.assertEquals(Assert.java:633)
...

Report flaky test

org.keycloak.testsuite.oauth.ClientTokenExchangeTest#testPublicClientNotAllowed

Keycloak CI - Base IT (6)

java.lang.AssertionError: expected:<403> but was:<400>
	at org.junit.Assert.fail(Assert.java:89)
	at org.junit.Assert.failNotEquals(Assert.java:835)
	at org.junit.Assert.assertEquals(Assert.java:647)
	at org.junit.Assert.assertEquals(Assert.java:633)
...

Report flaky test

org.keycloak.testsuite.oauth.ClientTokenExchangeTest#testExchangeUsingServiceAccount

Keycloak CI - Base IT (6)

org.keycloak.common.VerificationException: Token not set
	at org.keycloak.TokenVerifier.parse(TokenVerifier.java:401)
	at org.keycloak.testsuite.oauth.ClientTokenExchangeTest.testExchangeUsingServiceAccount(ClientTokenExchangeTest.java:347)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
...

Report flaky test

org.keycloak.testsuite.oauth.ClientTokenExchangeTest#testImpersonation

Keycloak CI - Base IT (6)

java.lang.AssertionError: expected:<200> but was:<400>
	at org.junit.Assert.fail(Assert.java:89)
	at org.junit.Assert.failNotEquals(Assert.java:835)
	at org.junit.Assert.assertEquals(Assert.java:647)
	at org.junit.Assert.assertEquals(Assert.java:633)
...

Report flaky test

org.keycloak.testsuite.oauth.ClientTokenExchangeTest#testImpersonationUsingPublicClient

Keycloak CI - Base IT (6)

java.lang.AssertionError: expected:<200> but was:<400>
	at org.junit.Assert.fail(Assert.java:89)
	at org.junit.Assert.failNotEquals(Assert.java:835)
	at org.junit.Assert.assertEquals(Assert.java:647)
	at org.junit.Assert.assertEquals(Assert.java:633)
...

Report flaky test

org.keycloak.testsuite.client.ClientTypesTest#testUpdateClientWithClientType

Keycloak CI - Base IT (4)

java.lang.AssertionError: Not expected to update client
	at org.junit.Assert.fail(Assert.java:89)
	at org.keycloak.testsuite.client.ClientTypesTest.testUpdateClientWithClientType(ClientTypesTest.java:112)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
...

Report flaky test

@keycloak-github-bot keycloak-github-bot Bot left a comment
Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Unreported flaky test detected, please review

@mposolda mposolda left a comment
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@thomasdarimont Thanks! IMO this is sufficient. We can possibly have a follow-up to adjust Details.REASON in other places if needed.

@ahus1 WDYT? Are we ok with merge this?

…#29166)

Fixes keycloak#29166

Signed-off-by: Thomas Darimont <thomas.darimont@googlemail.com>
Signed-off-by: Thomas Darimont <thomas.darimont@googlemail.com>
Signed-off-by: Thomas Darimont <thomas.darimont@googlemail.com>
- Adapted tests to reflect the change

Signed-off-by: Thomas Darimont <thomas.darimont@googlemail.com>
Signed-off-by: Thomas Darimont <thomas.darimont@googlemail.com>
Signed-off-by: Thomas Darimont <thomas.darimont@googlemail.com>
- Adapted code to call event.detail(..) before event.error(..)
- Adapted remaining OIDC endpoints
- Reverted log levels to previous values in OAuth2GrantTypeBase

Signed-off-by: Thomas Darimont <thomas.darimont@googlemail.com>
Signed-off-by: Thomas Darimont <thomas.darimont@googlemail.com>
Signed-off-by: Thomas Darimont <thomas.darimont@googlemail.com>
Signed-off-by: Thomas Darimont <thomas.darimont@googlemail.com>
- Added Details.REASON to events
- Removed info level logging in favor of event based logging
- Changed info level logging in isValidPkceCodeVerifier method to debug

The previously logged information in now contained in the error event.

Signed-off-by: Thomas Darimont <thomas.darimont@googlemail.com>
Signed-off-by: Thomas Darimont <thomas.darimont@googlemail.com>
@ahus1 ahus1 left a comment
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thank you - looks great. This will help users and admin a lot, especially when they first try out Keycloak.

@ahus1
ahus1 merged commit ba43a10 into keycloak:main May 6, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Improve details for user error events in OIDC protocol endpoints

3 participants

0