Script-based Authenticator is not working properly in 7.0.1

Extending the server
1

Hi there, recently we upgrade Keycloak to 7.0.1 and found out that our previously custom Authenticator is gone – the new version disabled the Upload Scripts feature. We then changed the way to provide the JS files and put them into a JAR file and deployed it. However, we found out that the script is getting called, but when the logic calls

    context.failure(AuthenticationFlowError.INVALID_USER);

The system is not making the user invalid, rather lets the login process go through and redirects to the URL wrongly. Please help looking into it and see whether it’s potentially a bug. Thanks!

function authenticate(context) {
var username = user ? user.username : “anonymous”;
LOG.info(script.name + " trace auth for: " + username);

var authShouldFail = !user.hasRole(realm.getRole("fhir_admin"));

if (authShouldFail) {
    LOG.info(script.name + " trace auth for: " + username + " -- it should fail!");
    context.failure(AuthenticationFlowError.INVALID_USER);
} else {
    LOG.info(script.name + " trace auth for: " + username + " -- it should succeed!");
    context.success();
}

}

The Log snippets:

  1. test user doesn’t have the required realmRole, it should fail. But we only have a warning and the login process went through.

e[0me[31m21:18:15,728 ERROR [stderr] (default task-8) Warning: Nashorn engine is planned to be removed from a future JDK release
e[0me[0m21:18:17,019 INFO [org.keycloak.authentication.authenticators.browser.ScriptBasedAuthenticator] (default task-8) PDD-Registry Authenticator trace auth for: test
e[0me[0m21:18:18,697 INFO [org.keycloak.authentication.authenticators.browser.ScriptBasedAuthenticator] (default task-8) PDD-Registry Authenticator trace auth for: test – it should fail!
e[0me[33m21:18:18,737 WARN [org.keycloak.services] (Brute Force Protector) KC-SERVICES0053: login failure for user 83c361ce-3d54-49b3-a039-47861c3d269b from ip 10.1.0.12
e[0me[0m21:18:19,786 INFO [org.keycloak.events] (default task-8) type=LOGIN, realmId=nhf, clientId=pdd-registry-local-server, userId=83c361ce-3d54-49b3-a039-47861c3d269b, ipAddress=10.1.0.12, auth_method=openid-connect, response_type=code, redirect_uri=http://localhost:4444/pdd-registry/, remember_me=false, consent=no_consent_required, code_id=420276a6-7f91-435a-ad29-37eaa5ea4649, response_mode=fragment, username=test, authSessionParentId=420276a6-7f91-435a-ad29-37eaa5ea4649, authSessionTabId=WETjUsEP4zY
e[0me[0m21:18:24,708 INFO [org.keycloak.events] (default task-8) type=CODE_TO_TOKEN, realmId=nhf, clientId=pdd-registry-local-server, userId=83c361ce-3d54-49b3-a039-47861c3d269b, ipAddress=10.1.0.12, token_id=ec68475b-b5cf-4adb-a4e0-e829bce1f01a, grant_type=authorization_code, refresh_token_type=Refresh, scope=‘openid email profile’, refresh_token_id=953c59eb-28c9-42f1-a629-abc6aeed5056, code_id=420276a6-7f91-435a-ad29-37eaa5ea4649, client_auth_method=client-secret
e[0me[0m21:18:25,393 INFO [org.keycloak.events] (default task-8) type=USER_INFO_REQUEST, realmId=nhf, clientId=pdd-registry-local-server, userId=83c361ce-3d54-49b3-a039-47861c3d269b, ipAddress=10.1.0.12, auth_method=validate_access_token, signature_required=false, username=test

  1. pddadmin user has the required realmRole, hence login process should go through.

e[0me[31m21:20:42,227 ERROR [stderr] (default task-8) Warning: Nashorn engine is planned to be removed from a future JDK release
e[0me[0m21:20:42,308 INFO [org.keycloak.authentication.authenticators.browser.ScriptBasedAuthenticator] (default task-8) PDD-Registry Authenticator trace auth for: pddadmin
e[0me[0m21:20:43,016 INFO [org.keycloak.authentication.authenticators.browser.ScriptBasedAuthenticator] (default task-8) PDD-Registry Authenticator trace auth for: pddadmin – it should succeed!
e[0me[0m21:20:43,968 INFO [org.keycloak.events] (default task-8) type=LOGIN, realmId=nhf, clientId=pdd-registry-local-server, userId=9f620737-6ffe-49fa-ae2a-4ae55da029ad, ipAddress=10.1.0.12, auth_method=openid-connect, response_type=code, redirect_uri=http://localhost:4444/pdd-registry/, remember_me=false, consent=no_consent_required, code_id=2dec2664-1ec4-4bc5-a563-9e328b7b2bcc, response_mode=fragment, username=pddadmin, authSessionParentId=2dec2664-1ec4-4bc5-a563-9e328b7b2bcc, authSessionTabId=3yzNp9OAzMw
e[0me[0m21:20:46,960 INFO [org.keycloak.events] (default task-8) type=CODE_TO_TOKEN, realmId=nhf, clientId=pdd-registry-local-server, userId=9f620737-6ffe-49fa-ae2a-4ae55da029ad, ipAddress=10.1.0.12, token_id=85ae1db5-fcac-4b62-81bf-3045ae0dd0cf, grant_type=authorization_code, refresh_token_type=Refresh, scope=‘openid email profile’, refresh_token_id=26fb7dd7-2aac-4d00-83fe-a9f741b9bac2, code_id=2dec2664-1ec4-4bc5-a563-9e328b7b2bcc, client_auth_method=client-secret
e[0me[0m21:20:47,327 INFO [org.keycloak.events] (default task-8) type=USER_INFO_REQUEST, realmId=nhf, clientId=pdd-registry-local-server, userId=9f620737-6ffe-49fa-ae2a-4ae55da029ad, ipAddress=10.1.0.12, auth_method=validate_access_token, signature_required=false, username=pddadmin

2

We figured this out. Details to follow.

3

Background:

  • we made a copy of Browser Flow and added a script-based Authentication.

Issues:

  • The new code treats the Alternative as a whole as Optional, even some Flows are marked as Required
  • The default Browser Flow is Alternative
    • Under the new logic, if the Login fails, the exception was IGNORED and allow the Login process to proceed

Solving the Issue — the process:

  • First of all, the logs (Default to INFO level) don’t reveal much about what happen.
  • When browsing the code base around the ScriptedBaseAuthenticator, it seems there are many DEBUG level logging.
  • Then decided to change the logging level to DEBUG to see what we are getting
    • Tried to follow instructions in this link: Docker
      • However, both the terminal commands and the environment variables did not work
    • Then, found this link: KEYCLOAK_LOGLEVEL is not used · Issue #93 · codecentric/helm-charts · GitHub
      • KEYCLOAK_LOGLEVEL is not used; Use WILDFLY_LOGLEVEL instead.
    • After setting WILDFLY_LOGLEVEL to DEBUG in helmfile.yaml in Idp project and re-applying the helmfile, we are getting tons of DEBUG logs.
    • those DEBUG logs really helped me pin-point the issue and related code, especially this line:
      • [0m[32m16:31:19,002 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-8) Thrown exception in alternative Subflow. Ignoring Subflow
        • The message is: “Thrown exception in alternative Subflow. Ignoring Subflow”
    • The Keycloak 7.0.1 code:
      • In DefaultAuthenticationFlow.java Line 162~164: ignoring the exception and continue
    • This alerts me that maybe the Authentication Flow was set to Alternative
    • After trying to change the setting to Required in Dev, we are getting the desired result.
    • Hence the below two pics describe the problem and the solution:

07%20PM
07%20PM2172×806 125 KB

4

The 2nd pic is here: (the system only allow one pic for a post)

25%20PM
25%20PM2172×806 155 KB

5

Link to the code DefaultAuthenticationFlow.java: https://github.com/keycloak/keycloak/blob/d593ac3e6fa28f98c3ea99ada29564791d467731/services/src/main/java/org/keycloak/authentication/DefaultAuthenticationFlow.java

We believe this is potentially a bug. Or at least there is a mismatch between the new code and the UI component. Could someone from the development team take a look at this?Thanks!

6

This is not done yet. After we changed the Browser Forms to REQUIRED, every time we refresh the window, the system is redirecting us to the login screen. It looks like it really needs us to log in again (as Required).

Can someone in Development team come in and give any suggestion? Thanks

7

I’m having a similar problem with all the script-based custom authenticator with keycloak 8.0.1.
I enabled the feature.scripts in a profile.properties file and I created a Window service with this command:

.\service.bat install /startup /name Keycloak /properties D:\keycloak\standalone\configuration\profile.properties

When I check the server.log I see that the property is retrieved correctly:

2020-01-28 11:20:06,710 DEBUG [org.jboss.as.config] (MSC service thread 1-3) Configured system properties:
	awt.toolkit = sun.awt.windows.WToolkit
	feature.scripts = enabled
	file.encoding = Cp1252
	file.encoding.pkg = sun.io
	file.separator = \
	java.awt.graphicsenv = sun.awt.Win32GraphicsEnvironment
	java.awt.printerjob = sun.awt.windows.WPrinterJob
...

But when I navigate to the custom authenticator this error appear:

2020-01-28 11:36:52,082 WARN  [org.keycloak.services] (default task-9) KC-SERVICES0013: Failed authentication: java.lang.RuntimeException: Unable to find factory for AuthenticatorFactory: auth-script-based did you forget to declare it in a META-INF/services file?
	at org.keycloak.authentication.DefaultAuthenticationFlow.getAuthenticatorFactory(DefaultAuthenticationFlow.java:366)
	at org.keycloak.authentication.DefaultAuthenticationFlow.isConditionalAuthenticator(DefaultAuthenticationFlow.java:360)
	at org.keycloak.authentication.DefaultAuthenticationFlow.processFlow(DefaultAuthenticationFlow.java:286)
	at org.keycloak.authentication.DefaultAuthenticationFlow.processSingleFlowExecutionModel(DefaultAuthenticationFlow.java:394)
	at org.keycloak.authentication.DefaultAuthenticationFlow.processFlow(DefaultAuthenticationFlow.java:305)
	at org.keycloak.authentication.AuthenticationProcessor.authenticateOnly(AuthenticationProcessor.java:998)
	at org.keycloak.authentication.AuthenticationProcessor.authenticate(AuthenticationProcessor.java:860)
	at org.keycloak.protocol.AuthorizationEndpointBase.handleBrowserAuthenticationRequest(AuthorizationEndpointBase.java:150)
	at org.keycloak.protocol.oidc.endpoints.AuthorizationEndpoint.buildAuthorizationCodeAuthorizationResponse(AuthorizationEndpoint.java:458)
	at org.keycloak.protocol.oidc.endpoints.AuthorizationEndpoint.process(AuthorizationEndpoint.java:154)
	at org.keycloak.protocol.oidc.endpoints.AuthorizationEndpoint.buildGet(AuthorizationEndpoint.java:110)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.lang.reflect.Method.invoke(Unknown Source)

Also when I try to configure a new one the Script value does not appear in the avaialble list o an authentication execution.

I know that this feature is preview but I can’t understand what is happening.
I rollback to the previous version 7.0.0