Local development environment fails to start

[thomasdarimont]

Keycloak fails to start when running the local Keycloak development environment for the terraform-provider-keycloak,
due to a NullPointerException.

Steps to reproduce:

Run in terminal 1

1. make user-federation-example
2. make local
   Run in terminal 2
3. docker-compose logs -f

Output:

keycloak_1  | 10:24:01,618 INFO  [org.keycloak.services] (ServerService Thread Pool -- 69) KC-SERVICES0001: Loading config from standalone.xml or domain.xml
####
keycloak_1  | 10:24:01,624 FATAL [org.keycloak.services] (ServerService Thread Pool -- 69) java.lang.RuntimeException: java.lang.NullPointerException
####
keycloak_1  | 10:24:01,626 INFO  [org.jboss.resteasy.resteasy_jaxrs.i18n] (ServerService Thread Pool -- 69) RESTEASY002225: Deploying javax.ws.rs.core.Application: class org.keycloak.services.resources.KeycloakApplication
keycloak_1  | 10:24:01,627 INFO  [org.jboss.as.server] (Thread-1) WFLYSRV0220: Server shutdown has been requested via an OS signal
keycloak_1  | 10:24:01,628 INFO  [org.wildfly.extension.undertow] (ServerService Thread Pool -- 69) WFLYUT0021: Registered web context: '/auth' for server 'default-server'
keycloak_1  | 10:24:01,634 INFO  [org.wildfly.extension.undertow] (ServerService Thread Pool -- 69) WFLYUT0022: Unregistered web context: '/auth' from server 'default-server'
keycloak_1  | 10:24:01,638 INFO  [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-5) WFLYJCA0010: Unbound data source [java:jboss/datasources/KeycloakDS]
keycloak_1  | 10:24:01,641 INFO  [org.jboss.as.mail.extension] (MSC service thread 1-1) WFLYMAIL0002: Unbound mail session [java:jboss/mail/Default]
keycloak_1  | 10:24:01,642 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-7) WFLYUT0008: Undertow HTTPS listener https suspending
keycloak_1  | 10:24:01,645 INFO  [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-8) ISPN000080: Disconnecting JGroups channel ejb
keycloak_1  | 10:24:01,644 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-7) WFLYUT0007: Undertow HTTPS listener https stopped, was bound to 0.0.0.0:8443
keycloak_1  | 10:24:01,645 INFO  [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-4) ISPN000080: Disconnecting JGroups channel ejb
keycloak_1  | 10:24:01,647 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-7) WFLYUT0008: Undertow AJP listener ajp suspending
keycloak_1  | 10:24:01,648 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-7) WFLYUT0007: Undertow AJP listener ajp stopped, was bound to 0.0.0.0:8009
keycloak_1  | 10:24:01,648 INFO  [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-2) ISPN000080: Disconnecting JGroups channel ejb
keycloak_1  | 10:24:01,650 INFO  [org.jboss.modcluster] (ServerService Thread Pool -- 69) MODCLUSTER000002: Initiating mod_cluster shutdown
keycloak_1  | 10:24:01,651 INFO  [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-5) WFLYJCA0019: Stopped Driver service with driver-name = postgresql
keycloak_1  | 10:24:01,652 INFO  [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-6) WFLYJCA0010: Unbound data source [java:jboss/datasources/ExampleDS]
keycloak_1  | 10:24:01,654 INFO  [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-2) WFLYJCA0019: Stopped Driver service with driver-name = h2
keycloak_1  | 10:24:01,657 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-3) WFLYUT0019: Host default-host stopping
keycloak_1  | 10:24:01,661 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-7) WFLYUT0008: Undertow HTTP listener default suspending
keycloak_1  | 10:24:01,665 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-7) WFLYUT0007: Undertow HTTP listener default stopped, was bound to 0.0.0.0:8080
keycloak_1  | 10:24:01,665 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 62) WFLYCLINF0003: Stopped authorization cache from keycloak container
keycloak_1  | 10:24:01,665 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 67) WFLYCLINF0003: Stopped realms cache from keycloak container
keycloak_1  | 10:24:01,666 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-3) WFLYUT0004: Undertow 2.1.0.Final stopping
keycloak_1  | 10:24:01,669 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 63) WFLYCLINF0003: Stopped keys cache from keycloak container
keycloak_1  | 10:24:01,670 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-7) WFLYSRV0028: Stopped deployment keycloak-server.war (runtime-name: keycloak-server.war) in 40ms
keycloak_1  | 10:24:01,672 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 65) WFLYCLINF0003: Stopped users cache from keycloak container
keycloak_1  | 10:24:01,677 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 70) WFLYCLINF0003: Stopped work cache from keycloak container
keycloak_1  | 10:24:01,679 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 61) WFLYCLINF0003: Stopped offlineSessions cache from keycloak container
keycloak_1  | 10:24:01,679 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 68) WFLYCLINF0003: Stopped authenticationSessions cache from keycloak container
keycloak_1  | 10:24:01,679 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 66) WFLYCLINF0003: Stopped offlineClientSessions cache from keycloak container
keycloak_1  | 10:24:01,679 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 72) WFLYCLINF0003: Stopped loginFailures cache from keycloak container
keycloak_1  | 10:24:01,679 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 60) WFLYCLINF0003: Stopped clientSessions cache from keycloak container
keycloak_1  | 10:24:01,677 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 71) WFLYCLINF0003: Stopped actionTokens cache from keycloak container
keycloak_1  | 10:24:01,681 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 64) WFLYCLINF0003: Stopped client-mappings cache from ejb container
keycloak_1  | 10:24:01,681 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 73) WFLYCLINF0003: Stopped sessions cache from keycloak container
keycloak_1  | 10:24:01,682 INFO  [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-5) ISPN000080: Disconnecting JGroups channel ejb
keycloak_1  | 10:24:01,682 INFO  [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-2) ISPN000080: Disconnecting JGroups channel ejb
keycloak_1  | 10:24:01,692 ERROR [org.jboss.as.controller.management-operation] (Controller Boot Thread) WFLYCTL0013: Operation ("add") failed - address: ([("subsystem" => "microprofile-metrics-smallrye")]): java.lang.NullPointerException
keycloak_1  | 	at org.wildfly.extension.microprofile.metrics-smallrye@19.1.0.Final//org.wildfly.extension.microprofile.metrics.MicroProfileMetricsSubsystemAdd$2.execute(MicroProfileMetricsSubsystemAdd.java:86)
keycloak_1  | 	at org.jboss.as.controller@11.1.1.Final//org.jboss.as.controller.AbstractOperationContext.executeStep(AbstractOperationContext.java:999)
keycloak_1  | 	at org.jboss.as.controller@11.1.1.Final//org.jboss.as.controller.AbstractOperationContext.processStages(AbstractOperationContext.java:743)
keycloak_1  | 	at org.jboss.as.controller@11.1.1.Final//org.jboss.as.controller.AbstractOperationContext.executeOperation(AbstractOperationContext.java:467)
keycloak_1  | 	at org.jboss.as.controller@11.1.1.Final//org.jboss.as.controller.OperationContextImpl.executeOperation(OperationContextImpl.java:1413)
keycloak_1  | 	at org.jboss.as.controller@11.1.1.Final//org.jboss.as.controller.ModelControllerImpl.boot(ModelControllerImpl.java:527)
keycloak_1  | 	at org.jboss.as.controller@11.1.1.Final//org.jboss.as.controller.AbstractControllerService.boot(AbstractControllerService.java:515)
keycloak_1  | 	at org.jboss.as.controller@11.1.1.Final//org.jboss.as.controller.AbstractControllerService.boot(AbstractControllerService.java:477)
keycloak_1  | 	at org.jboss.as.server@11.1.1.Final//org.jboss.as.server.ServerService.boot(ServerService.java:448)
keycloak_1  | 	at org.jboss.as.server@11.1.1.Final//org.jboss.as.server.ServerService.boot(ServerService.java:401)
keycloak_1  | 	at org.jboss.as.controller@11.1.1.Final//org.jboss.as.controller.AbstractControllerService$1.run(AbstractControllerService.java:416)
...
keycloak_1  | }]: java.lang.RuntimeException: WFLYCTL0195: Interrupted awaiting transaction commit or rollback
keycloak_1  | 	at org.jboss.as.controller@11.1.1.Final//org.jboss.as.controller.ParallelBootOperationStepHandler$ParallelBootTransactionControl.operationPrepared(ParallelBootOperationStepHandler.java:458)
keycloak_1  | 	at org.jboss.as.controller@11.1.1.Final//org.jboss.as.controller.ModelController$OperationTransactionControl.operationPrepared(ModelController.java:131)
keycloak_1  | 	at org.jboss.as.controller@11.1.1.Final//org.jboss.as.controller.AbstractOperationContext.executeDoneStage(AbstractOperationContext.java:838)
keycloak_1  | 	at org.jboss.as.controller@11.1.1.Final//org.jboss.as.controller.AbstractOperationContext.processStages(AbstractOperationContext.java:769)
keycloak_1  | 	at org.jboss.as.controller@11.1.1.Final//org.jboss.as.controller.AbstractOperationContext.executeOperation(AbstractOperationContext.java:467)
keycloak_1  | 	at org.jboss.as.controller@11.1.1.Final//org.jboss.as.controller.ParallelBootOperationStepHandler$ParallelBootTask.run(ParallelBootOperationStepHandler.java:384)
keycloak_1  | 	at org.jboss.threads@2.3.3.Final//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
keycloak_1  | 	at org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982)
keycloak_1  | 	at org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
keycloak_1  | 	at org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
keycloak_1  | 	at java.base/java.lang.Thread.run(Thread.java:834)
keycloak_1  | 	at org.jboss.threads@2.3.3.Final//org.jboss.threads.JBossThread.run(JBossThread.java:485)
keycloak_1  | terraform-provider-keycloak_keycloak_1 exited with code 1

Currently Keycloak is configured with this volume mapping to expose the custom-user-federation for testing:

- ./custom-user-federation-example/build/libs:/opt/jboss/keycloak/providers/

With remote debugging I found out, that the NPE is triggered because dir.listFiles(...) returns null here:
https://github.com/keycloak/keycloak/blob/master/services/src/main/java/org/keycloak/provider/FileSystemProviderLoaderFactory.java#L53

Also /opt/jboss/keycloak/providers/ is not supported by Keycloak since many moons.

A better way would be to expose the extension via the supported /opt/jboss/keycloak/standalone/deployments folder:

- ./custom-user-federation-example/build/libs/custom-user-federation-example.jar:/opt/jboss/keycloak/standalone/deployments/custom-user-federation-example.jar:z

once this is fixed, the example still fails, because of classloading issues:

The extension jar is missing a META-INF/jboss-deployment-structure.xml file which makes the required Keycloak modules available to the extension classpath.

<?xml version="1.0" encoding="UTF-8"?>
<jboss-deployment-structure>
    <deployment>
        <dependencies>
            <module name="org.keycloak.keycloak-core" export="true" />
            <module name="org.keycloak.keycloak-server-spi" export="true" />
            <module name="org.keycloak.keycloak-server-spi-private" export="true" />
            <module name="org.keycloak.keycloak-services" export="true" />
            <module name="org.bouncycastle" export="true" />
            <module name="com.google.guava" export="true" />
            <module name="org.jboss.logging" export="true" />
            <module name="org.apache.commons.io" export="true" />
        </dependencies>
    </deployment>
</jboss-deployment-structure>

[thomasdarimont]

In addition to the provided fix, I could also upgrade the local Keycloak version to 11.0.2.

This requires to add an additional method createConfig in the CustomIdentityProviderFactory class and upgrading the version to Keycloak 11.0.2.

I'll send a separate PR for this once this gets merged.

[mrparkers]

Hey @thomasdarimont, thanks for issue. The information you're providing here is very helpful.

For some context, I originally wrote the example custom user federation provider back when I was running Keycloak 4.8.3.Final in order to test the keycloak_custom_user_federation resource. I haven't really kept it up to date since then, as the current Keycloak environment that I maintain doesn't use custom user federation. So I appreciate another set of 👀 on this!

Anyways, I did a fresh clone of this repository and followed the steps you outlined and I wasn't able to reproduce the NPE that you seem to be running in to. For me, Keycloak started just fine, and I was able to use the custom user federation provider.

I also tested the contents of #425 locally, and everything seems to be working just fine with the changes you suggested as well. So I'm perfectly happy to defer to your Keycloak expertise and accept those changes. Although I am curious if you have any thoughts about why the code that's currently in master is working for me as-is. Perhaps you're building the custom user federation example with a different version of the JDK? If you use jabba, could you try running jabba use within the custom-user-federation-example directory to switch to zulu@1.8.172 and see if anything changes?

Thanks!