search

ivangfr / keycloak-clustered

Keycloak-Clustered extends quay.io/keycloak/keycloak official Keycloak Docker image by adding JDBC_PING discovery protocol.
162 stars 57 forks source link

Unable to delete PingData on container shutdown #6

Closed zdykstra closed 2 years ago

zdykstra commented 2 years ago

I noticed that I have a number of entries in the jgroupsping table under Postgres, even after the container has been shutdown and destroyed. Looking at the docker logs for a shutdown container, I see this:

*** JBossAS process (791) received TERM signal ***
21:38:46,043 INFO  [org.jboss.as.server] (Thread-1) WFLYSRV0272: Suspending server
21:38:46,047 INFO  [org.jboss.as.ejb3] (Thread-1) WFLYEJB0493: Jakarta Enterprise Beans subsystem suspension complete
21:38:46,053 INFO  [org.jboss.as.server] (Thread-1) WFLYSRV0220: Server shutdown has been requested via an OS signal
21:38:46,095 INFO  [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-3) WFLYJCA0010: Unbound data source [java:jboss/datasources/KeycloakDS]
21:38:46,102 INFO  [org.infinispan.manager.DefaultCacheManager] (ServerService Thread Pool -- 69) Stopping cache manager null on keycloak-dev-template-2021-09-2
21:38:46,106 INFO  [org.infinispan.CLUSTER] (ServerService Thread Pool -- 69) ISPN000080: Disconnecting JGroups channel ejb
21:38:46,110 INFO  [org.jboss.as.mail.extension] (MSC service thread 1-4) WFLYMAIL0002: Unbound mail session [java:jboss/mail/Default]
21:38:46,127 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-2) WFLYUT0008: Undertow HTTPS listener https suspending
21:38:46,118 INFO  [org.infinispan.manager.DefaultCacheManager] (ServerService Thread Pool -- 73) Stopping cache manager null on keycloak-dev-template-2021-09-2
21:38:46,131 INFO  [org.infinispan.CLUSTER] (ServerService Thread Pool -- 73) ISPN000080: Disconnecting JGroups channel ejb
21:38:46,130 INFO  [org.infinispan.manager.DefaultCacheManager] (ServerService Thread Pool -- 74) Stopping cache manager null on keycloak-dev-template-2021-09-2
21:38:46,137 INFO  [org.wildfly.extension.undertow] (ServerService Thread Pool -- 69) WFLYUT0022: Unregistered web context: '/auth' from server 'default-server'
21:38:46,140 INFO  [org.infinispan.CLUSTER] (ServerService Thread Pool -- 74) ISPN000080: Disconnecting JGroups channel ejb
21:38:46,153 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-2) WFLYUT0007: Undertow HTTPS listener https stopped, was bound to 10.128.0.44:8443
21:38:46,179 INFO  [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-2) WFLYJCA0010: Unbound data source [java:jboss/datasources/ExampleDS]
21:38:46,185 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-3) WFLYUT0019: Host default-host stopping
21:38:46,186 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-1) WFLYUT0008: Undertow AJP listener ajp suspending
21:38:46,189 INFO  [org.jboss.modcluster] (ServerService Thread Pool -- 78) MODCLUSTER000002: Initiating mod_cluster shutdown
21:38:46,187 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-1) WFLYUT0007: Undertow AJP listener ajp stopped, was bound to 10.128.0.44:8009
21:38:46,207 INFO  [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-1) WFLYJCA0019: Stopped Driver service with driver-name = h2
21:38:46,215 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 86) WFLYCLINF0003: Stopped authorization cache from keycloak container
21:38:46,218 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 69) WFLYCLINF0003: Stopped keys cache from keycloak container
21:38:46,234 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 83) WFLYCLINF0003: Stopped users cache from keycloak container
21:38:46,240 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 73) WFLYCLINF0003: Stopped work cache from keycloak container
21:38:46,244 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 74) WFLYCLINF0003: Stopped actionTokens cache from keycloak container
21:38:46,248 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 85) WFLYCLINF0003: Stopped loginFailures cache from keycloak container
21:38:46,251 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 87) WFLYCLINF0003: Stopped sessions cache from keycloak container
21:38:46,254 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 82) WFLYCLINF0003: Stopped clientSessions cache from keycloak container
21:38:46,258 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 80) WFLYCLINF0003: Stopped offlineSessions cache from keycloak container
21:38:46,260 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 84) WFLYCLINF0003: Stopped offlineClientSessions cache from keycloak container
21:38:46,263 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 76) WFLYCLINF0003: Stopped authenticationSessions cache from keycloak container
21:38:46,275 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-2) WFLYSRV0028: Stopped deployment keycloak-server.war (runtime-name: keycloak-server.war) in 214ms
21:38:46,278 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-2) WFLYUT0008: Undertow HTTP listener default suspending
21:38:46,281 INFO  [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-4) WFLYJCA0019: Stopped Driver service with driver-name = postgresql
21:38:46,284 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-2) WFLYUT0007: Undertow HTTP listener default stopped, was bound to 10.128.0.44:8080
21:38:46,298 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-3) WFLYUT0004: Undertow 2.2.5.Final stopping
21:38:46,305 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 81) WFLYCLINF0003: Stopped realms cache from keycloak container
21:38:46,307 INFO  [org.infinispan.manager.DefaultCacheManager] (ServerService Thread Pool -- 81) Stopping cache manager null on keycloak-dev-template-2021-09-2
21:38:46,315 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 83) WFLYCLINF0003: Stopped http-remoting-connector cache from ejb container
21:38:46,316 INFO  [org.infinispan.manager.DefaultCacheManager] (ServerService Thread Pool -- 75) Stopping cache manager null on keycloak-dev-template-2021-09-2
21:38:46,321 INFO  [org.infinispan.CLUSTER] (ServerService Thread Pool -- 75) ISPN000080: Disconnecting JGroups channel ejb
21:38:46,328 INFO  [org.infinispan.CLUSTER] (ServerService Thread Pool -- 81) ISPN000080: Disconnecting JGroups channel ejb
21:38:46,347 ERROR [org.jgroups.protocols.JDBC_PING] (ServerService Thread Pool -- 75) JGRP000115: Could not open connection to database: java.sql.SQLException: javax.resource.ResourceException: IJ000470: You are trying to use a connection factory that has been shut down: java:jboss
/datasources/KeycloakDS
        at org.jboss.ironjacamar.jdbcadapters@1.4.27.Final//org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:159)
        at org.jboss.as.connector@23.0.2.Final//org.jboss.as.connector.subsystems.datasources.WildFlyDataSource.getConnection(WildFlyDataSource.java:64)
        at org.jgroups@4.2.11.Final//org.jgroups.protocols.JDBC_PING.getConnection(JDBC_PING.java:302)
        at org.jgroups@4.2.11.Final//org.jgroups.protocols.JDBC_PING.delete(JDBC_PING.java:337)
        at org.jgroups@4.2.11.Final//org.jgroups.protocols.JDBC_PING.remove(JDBC_PING.java:175)
        at org.jgroups@4.2.11.Final//org.jgroups.protocols.FILE_PING.stop(FILE_PING.java:101)
        at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
        at org.jgroups@4.2.11.Final//org.jgroups.stack.ProtocolStack.stopStack(ProtocolStack.java:899)
        at org.jgroups@4.2.11.Final//org.jgroups.JChannel.stopStack(JChannel.java:1085)
        at org.jgroups@4.2.11.Final//org.jgroups.JChannel.disconnect(JChannel.java:444)
        at org.jboss.as.clustering.jgroups@23.0.2.Final//org.jboss.as.clustering.jgroups.subsystem.ChannelServiceConfigurator.accept(ChannelServiceConfigurator.java:122)
        at org.jboss.as.clustering.jgroups@23.0.2.Final//org.jboss.as.clustering.jgroups.subsystem.ChannelServiceConfigurator.accept(ChannelServiceConfigurator.java:58)
        at org.wildfly.clustering.service@23.0.2.Final//org.wildfly.clustering.service.FunctionalService.stop(FunctionalService.java:73)
        at org.wildfly.clustering.service@23.0.2.Final//org.wildfly.clustering.service.AsyncServiceConfigurator$AsyncService.lambda$stop$1(AsyncServiceConfigurator.java:142)
        at org.jboss.threads@2.4.0.Final//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
        at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1990)
        at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
        at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
        at java.base/java.lang.Thread.run(Thread.java:829)
        at org.jboss.threads@2.4.0.Final//org.jboss.threads.JBossThread.run(JBossThread.java:513)
Caused by: javax.resource.ResourceException: IJ000470: You are trying to use a connection factory that has been shut down: java:jboss/datasources/KeycloakDS        at org.jboss.ironjacamar.impl@1.4.27.Final//org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:777)
        at org.jboss.ironjacamar.jdbcadapters@1.4.27.Final//org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:151)
        ... 19 more

21:38:46,351 ERROR [org.jgroups.protocols.JDBC_PING] (ServerService Thread Pool -- 75) JGRP000215: Failed to delete PingData in database
21:38:46,381 INFO  [org.jboss.as] (MSC service thread 1-1) WFLYSRV0050: Keycloak 15.0.2 (WildFly Core 15.0.1.Final) stopped in 320ms
*** JBossAS process (791) received TERM signal ***

Based on this, it looks like [java:jboss/datasources/KeycloakDS] is being shutdown before the final org.jgroups.protocols.JDBC_PING deletion takes place.

ivangfr commented 2 years ago

Hi @zdykstra , thanks for opening the issue.

I've tried to reproduce the issue on my machine following the steps described on Running a Keycloak Cluster using JDBC_PING in a local Docker network

In my experiment, I've started and shut down, several times, two keycloak-clustered instances and, at the same time, checking the records in JGROUPSPING table.

Indeed, I can see the error logs you mentioned above but, checking the records in JGROUPSPING, it kept correctly according to the number of keycloak-clustered instances at a specific time. When one was shut down, its record was deleted from JGROUPSPING table although the error message was logged anyway.

So, unfortunately, I couldn't reproduce your case.

Let me know if I can help in another way, maybe trying a different approach.

Best regards,

zdykstra commented 2 years ago

@ivangfr thank you for taking the time to look at this and attempting to replicate the problem, I appreciate it. I've also attempted to replicate this again on GCP with the keycloak-clustered 15.0.2 container and a hosted pgsql database instance. Instances are currently being removed from the jgroupsping table on shutdown. So right now, the problem is either resolved with 15.0.2 or isn't readily repeatable.