keycloak 19 (new data store ) does not work well with external infinispan (data grid) #14984

kkcmadhu · 2022-10-18T16:54:19Z

kkcmadhu
Oct 18, 2022

hi i used infinispan operator to create an infinispan cluster
pointed my keycloak 19 to this cluster, things worked perfectly fine.

Now, i tweaked my infispan cluster and increased the nodes in cluser (replicas >1), and things started failing..

My keycloak uses points to the kubernetes service (and not to specific infinispan pod).

Any suggestions wrt to configuring keycloak to work with infinispan data grid ?

this is what i use to create my infinispan cluser

apiVersion: infinispan.org/v1
kind: Infinispan
metadata:
  name: infinispan
spec:
  replicas: 2
  service:
    type: DataGrid

My logs looks like this

keycloak logs:

2022-10-18 13:21:11,433 WARN  [org.keycloak.events] (executor-thread-19) type=LOGIN_ERROR, realmId=b51745eb-1f08-424d-aebe-27628eee037d, clientId=security-admin-console, userId=null, ipAddress=10.1.3.112, error=invalid_user_credentials, auth_method=openid-connect, auth_type=code, response_type=code, redirect_uri=http://prospectfarm1-aw-us.kubernetes.docker.internal/auth/admin/scimaster/console/#/realms/scimaster/identity-provider-settings, code_id=c7a844db-af33-418c-bf11-08baca492f06, response_mode=fragment, authSessionParentId=c7a844db-af33-418c-bf11-08baca492f06, authSessionTabId=OEFv6XU3hL0
2022-10-18 13:38:30,315 INFO  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-2) ISPN004006: Server sent new topology view (id=38, age=0) containing 1 addresses: [10.1.3.124/<unresolved>:11222]
2022-10-18 13:38:30,315 INFO  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-2) ISPN004016: Server not in cluster anymore(10.1.3.140/<unresolved>:11222), removing from the pool.
2022-10-18 13:38:30,315 INFO  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-2) ISPN004016: Server not in cluster anymore(10.1.3.141/<unresolved>:11222), removing from the pool.
2022-10-18 13:38:30,315 INFO  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-2) ISPN004016: Server not in cluster anymore(10.1.3.137/<unresolved>:11222), removing from the pool.
2022-10-18 13:38:30,315 INFO  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-2) ISPN004016: Server not in cluster anymore(10.1.3.138/<unresolved>:11222), removing from the pool.
2022-10-18 13:38:35,012 INFO  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-2) ISPN004006: Server sent new topology view (id=30, age=0) containing 1 addresses: [10.1.3.124/<unresolved>:11222]
2022-10-18 13:38:35,013 INFO  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-2) ISPN004016: Server not in cluster anymore(10.1.3.140/<unresolved>:11222), removing from the pool.
2022-10-18 13:38:35,013 INFO  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-2) ISPN004016: Server not in cluster anymore(10.1.3.141/<unresolved>:11222), removing from the pool.
2022-10-18 13:38:35,013 INFO  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-2) ISPN004016: Server not in cluster anymore(10.1.3.137/<unresolved>:11222), removing from the pool.
2022-10-18 13:38:35,013 INFO  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-2) ISPN004016: Server not in cluster anymore(10.1.3.138/<unresolved>:11222), removing from the pool.
2022-10-18 13:59:09,927 INFO  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-2) ISPN004006: Server sent new topology view (id=46, age=0) containing 3 addresses: [10.1.3.142/<unresolved>:11222, 10.1.3.124/<unresolved>:11222, 10.1.3.143/<unresolved>:11222]
2022-10-18 13:59:09,927 INFO  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-2) ISPN004014: New server added(10.1.3.142/<unresolved>:11222), adding to the pool.
2022-10-18 13:59:09,928 INFO  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-2) ISPN004014: New server added(10.1.3.143/<unresolved>:11222), adding to the pool.
2022-10-18 13:59:10,154 INFO  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-2) ISPN004006: Server sent new topology view (id=38, age=0) containing 3 addresses: [10.1.3.142/<unresolved>:11222, 10.1.3.124/<unresolved>:11222, 10.1.3.143/<unresolved>:11222]
2022-10-18 13:59:10,155 INFO  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-2) ISPN004014: New server added(10.1.3.142/<unresolved>:11222), adding to the pool.
2022-10-18 13:59:10,155 INFO  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-2) ISPN004014: New server added(10.1.3.143/<unresolved>:11222), adding to the pool.
2022-10-18 13:59:10,165 WARN  [org.keycloak.events] (executor-thread-17) type=LOGIN_ERROR, realmId=b51745eb-1f08-424d-aebe-27628eee037d, clientId=null, userId=null, ipAddress=10.1.3.112, error=expired_code, restart_after_timeout=true, authSessionParentId=c7a844db-af33-418c-bf11-08baca492f06, authSessionTabId=yOgIw6yO5xI
2022-10-18 13:59:15,362 INFO  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-2) ISPN004006: Server sent new topology view (id=46, age=0) containing 3 addresses: [10.1.3.142/<unresolved>:11222, 10.1.3.124/<unresolved>:11222, 10.1.3.143/<unresolved>:11222]
2022-10-18 13:59:15,362 INFO  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-2) ISPN004014: New server added(10.1.3.142/<unresolved>:11222), adding to the pool.
2022-10-18 13:59:15,362 INFO  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-2) ISPN004014: New server added(10.1.3.143/<unresolved>:11222), adding to the pool.
2022-10-18 13:59:15,382 WARN  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-8) ISPN004005: Error received from the server: org.infinispan.commons.CacheException: Initial state transfer timed out for cache user-sessions on keycloak-cache-2-24806
2022-10-18 13:59:19,266 WARN  [org.keycloak.events] (executor-thread-28) type=LOGIN_ERROR, realmId=b51745eb-1f08-424d-aebe-27628eee037d, clientId=null, userId=null, ipAddress=10.1.3.112, error=expired_code, restart_after_timeout=true, authSessionParentId=d78443b8-1e79-46cc-a2bb-fe09936822c6, authSessionTabId=1To58Jgh09U

Infinispan pod 2(new pod)

at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: org.hibernate.search.util.common.SearchException: HSEARCH600067: Unable to delete all entries matching query '+*:* #(__HSEARCH_routing_key:150 __HSEARCH_routing_key:151 __HSEARCH_routing_key:152 __HSEARCH_routing_key:153 __HSEARCH_routing_key:154 __HSEARCH_routing_key:155 __HSEARCH_routing_key:156 __HSEARCH_routing_key:157 __HSEARCH_routing_key:158 __HSEARCH_routing_key:159 __HSEARCH_routing_key:238 __HSEARCH_routing_key:239 __HSEARCH_routing_key:10 __HSEARCH_routing_key:11 __HSEARCH_routing_key:12 __HSEARCH_routing_key:160 __HSEARCH_routing_key:161 __HSEARCH_routing_key:162 __HSEARCH_routing_key:163 __HSEARCH_routing_key:240 __HSEARCH_routing_key:164 __HSEARCH_routing_key:241 __HSEARCH_routing_key:0 __HSEARCH_routing_key:165 __HSEARCH_routing_key:242 __HSEARCH_routing_key:1 __HSEARCH_routing_key:166 __HSEARCH_routing_key:243 __HSEARCH_routing_key:2 __HSEARCH_routing_key:167 __HSEARCH_routing_key:244 __HSEARCH_routing_key:3 __HSEARCH_routing_key:168 __HSEARCH_routing_key:245 __HSEARCH_routing_key:4 __HSEARCH_routing_key:169 __HSEARCH_routing_key:246 __HSEARCH_routing_key:5 __HSEARCH_routing_key:247 __HSEARCH_routing_key:6 __HSEARCH_routing_key:248 __HSEARCH_routing_key:7 __HSEARCH_routing_key:249 __HSEARCH_routing_key:8 __HSEARCH_routing_key:9 __HSEARCH_routing_key:20 __HSEARCH_routing_key:21 __HSEARCH_routing_key:22 __HSEARCH_routing_key:23 __HSEARCH_routing_key:24 __HSEARCH_routing_key:25 __HSEARCH_routing_key:26 __HSEARCH_routing_key:27 __HSEARCH_routing_key:28 __HSEARCH_routing_key:29 __HSEARCH_routing_key:170 __HSEARCH_routing_key:171 __HSEARCH_routing_key:172 __HSEARCH_routing_key:173 __HSEARCH_routing_key:250 __HSEARCH_routing_key:174 __HSEARCH_routing_key:251 __HSEARCH_routing_key:175 __HSEARCH_routing_key:252 __HSEARCH_routing_key:176 __HSEARCH_routing_key:253 __HSEARCH_routing_key:177 __HSEARCH_routing_key:254 __HSEARCH_routing_key:178 __HSEARCH_routing_key:255 __HSEARCH_routing_key:179 __HSEARCH_routing_key:30 __HSEARCH_routing_key:31 __HSEARCH_routing_key:32 __HSEARCH_routing_key:33 __HSEARCH_routing_key:34 __HSEARCH_routing_key:35 __HSEARCH_routing_key:36 __HSEARCH_routing_key:37 __HSEARCH_routing_key:38 __HSEARCH_routing_key:39 __HSEARCH_routing_key:180 __HSEARCH_routing_key:181 __HSEARCH_routing_key:182 __HSEARCH_routing_key:146 __HSEARCH_routing_key:147 __HSEARCH_routing_key:148 __HSEARCH_routing_key:225 __HSEARCH_routing_key:149 __HSEARCH_routing_key:40)': Lock held by this virtual machine: /opt/infinispan/server/data/kc.HotRodStringPair/write.lock
Context: index 'kc.HotRodStringPair'
	at org.hibernate.search.backend.lucene.work.impl.DeleteEntriesByQueryWork.execute(DeleteEntriesByQueryWork.java:44)
	at org.hibernate.search.backend.lucene.work.impl.DeleteEntriesByQueryWork.execute(DeleteEntriesByQueryWork.java:18)
	at org.hibernate.search.backend.lucene.orchestration.impl.LuceneParallelWorkOrchestratorImpl$WorkExecution.run(LuceneParallelWorkOrchestratorImpl.java:93)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	... 1 more
Caused by: org.apache.lucene.store.LockObtainFailedException: Lock held by this virtual machine: /opt/infinispan/server/data/kc.HotRodStringPair/write.lock
	at org.apache.lucene.store.NativeFSLockFactory.obtainFSLock(NativeFSLockFactory.java:139)
	at org.apache.lucene.store.FSLockFactory.obtainLock(FSLockFactory.java:41)
	at org.apache.lucene.store.BaseDirectory.obtainLock(BaseDirectory.java:45)
	at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:923)
	at org.hibernate.search.backend.lucene.lowlevel.writer.impl.IndexWriterProvider.createNewIndexWriter(IndexWriterProvider.java:139)
	at org.hibernate.search.backend.lucene.lowlevel.writer.impl.IndexWriterProvider.getOrCreate(IndexWriterProvider.java:117)
	at org.hibernate.search
8000
.backend.lucene.lowlevel.index.impl.IndexAccessorImpl.getIndexWriterDelegator(IndexAccessorImpl.java:164)
	at org.hibernate.search.backend.lucene.work.impl.DeleteEntriesByQueryWork.execute(DeleteEntriesByQueryWork.java:40)
	... 8 more
2022-10-18T13:48:27.927823442Z

Infinispan pod 3 (new pod)

13:59:15,380 ERROR (non-blocking-thread--p2-t1) [org.infinispan.server.hotrod.BaseRequestProcessor] ISPN005003: Exception reported org.infinispan.commons.CacheException: Initial state transfer timed out for cache user-sessions on keycloak-cache-2-24806
	at org.infinispan.statetransfer.StateTransferManagerImpl.waitForInitialStateTransferToComplete(StateTransferManagerImpl.java:248)
	at org.infinispan.cache.impl.CacheImpl.start(CacheImpl.java:1017)
	at org.infinispan.cache.impl.AbstractDelegatingCache.start(AbstractDelegatingCache.java:512)
	at org.infinispan.manager.DefaultCacheManager.wireAndStartCache(DefaultCacheManager.java:714)
	at org.infinispan.manager.DefaultCacheManager.createCache(DefaultCacheManager.java:660)

kkcmadhu · 2022-10-18T17:20:09Z

kkcmadhu
Oct 18, 2022
Author

i think where there is more than one node in infinispan cluster (replica >1), keycloak auth calls times out while doing a hotrod call


2022-10-18 17:16:15,620 WARN  [org.infinispan.HOTROD] (HotRod-client-async-pool-1-25) ISPN004005: Error received from the server: org.infinispan.util.concurrent.TimeoutException: ISPN000638: Timeout waiting for topology 12 transaction data

2022-10-18 17:16:15,621 WARN  [org.keycloak.services] (executor-thread-56) KC-SERVICES0013: Failed authentication: org.infinispan.client.hotrod.exceptions.HotRodClientException:Request for messageId=1182 returned server error (status=0x86): org.infinispan.util.concurrent.TimeoutException: ISPN000638: Timeout waiting for topology 12 transaction data
	at org.infinispan.client.hotrod.impl.protocol.Codec20.checkForErrorsInResponseStatus(Codec20.java:323)
	at org.infinispan.client.hotrod.impl.protocol.Codec20.readHeader(Codec20.java:168)
	at org.infinispan.client.hotrod.impl.transport.netty.HeaderDecoder.decode(HeaderDecoder.java:139)
	at org.infinispan.client.hotrod.impl.transport.netty.HintedReplayingDecoder.callDecode(HintedReplayingDecoder.java:94)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:279)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:279)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:795)
	at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:480)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:378)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:833)

2022-10-18 17:16:15,628 WARN  [org.keycloak.events] (executor-thread-56) type=LOGIN_ERROR, realmId=b51745eb-1f08-424d-aebe-27628eee037d, clientId=security-admin-console

0 replies

Navigation Menu

Repository navigation

keycloak 19 (new data store ) does not work well with external infinispan (data grid) #14984

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Replies: 1 comment

Uh oh!

{{title}}

Uh oh!

Select a reply

Uh oh!

keycloak 19 (new data store ) does not work well with external infinispan (data grid) #14984

Uh oh!

Uh oh!

kkcmadhu Oct 18, 2022

keycloak logs:

Infinispan pod 2(new pod)

Infinispan pod 3 (new pod)

Replies: 1 comment

Uh oh!

kkcmadhu Oct 18, 2022 Author

kkcmadhu
Oct 18, 2022

kkcmadhu
Oct 18, 2022
Author