[keycloak-user] Standalone-ha Keycloak and ISPN000476: Timed out waiting for responses for request
Sebastian Laskawiec
slaskawi at redhat.com
Fri Oct 26 08:01:53 EDT 2018
It's absolutely fine to stick with TCP. For small clusters (a finger in the
air guesstimate - < 10 nodes) you should see no performance difference.
For some reason UDP is very sensitive to underlying OS configuration. So I
would advice just sticking with TCP.
On Thu, Oct 25, 2018 at 8:47 PM Rafael Weingärtner <
rafaelweingartner at gmail.com> wrote:
> Another discovery.
> I changed the configuration:
>
>> <subsystem xmlns="urn:jboss:domain:jgroups:6.0">
>> <channels default="ee">
>> <channel name="ee" stack="udp" cluster="ejb"/>
>> </channels>
>>
>
> to:
>
>> <subsystem xmlns="urn:jboss:domain:jgroups:6.0">
>> <channels default="ee">
>> <channel name="ee" stack="tcp" cluster="ejb"/>
>> </channels>
>>
>
> This change has fixed the problem. It seems that there is a networking
> problem that is affecting UDP. However, I still have not figured out the
> root cause of the problem though.
>
> On Wed, Oct 24, 2018 at 9:39 PM Rafael Weingärtner <
> rafaelweingartner at gmail.com> wrote:
>
>> Just an update.
>>
>> It is interesting, at least to me, but version 4.0.0.Final of Keycloak
>> works just fine in the same set up. It seems that there is something that
>> was changed in Keycloak 4.5.0, which is somehow sensitive to something in
>> this environment. I have not being able to pin point it though.
>>
>> On Wed, Oct 24, 2018 at 12:09 PM Rafael Weingärtner <
>> rafaelweingartner at gmail.com> wrote:
>>
>>> Thanks for the prompt reply. To answer you:
>>>
>>>> - Very short timeout on FD_* protocols
>>>>
>>> It is the standard configuration, so, this should not be a problem.
>>>
>>> - Faulty NIC or incorrect network level configuration in the datacenter
>>>> - Network packets are cut when in transport. I've seen it with one of
>>>> the hardware firewalls (don't remember which one though). Due to faulty
>>>> configuration it was cutting packets to certain length causing other layers
>>>> to fail miserably.
>>>>
>>>
>>> Maybe? Well, both VMs are in the same broadcast domain, and there is no
>>> firewall in-between them.
>>>
>>> Here go some log entries. There are some things that I do not understand
>>> here. Why am I seing multiple “keycloak-1: installing view”? Shouldn't it
>>> only happen once? The same situation is happening with “created cluster
>>> (first member). My view is [keycloak-1|0]”
>>>
>>>
>>>
>>>> 2018-10-24 14:45:25,130 DEBUG [org.jgroups.protocols.UDP]
>>>> (ServerService Thread Pool -- 50) socket information:
>>>> mcast_addr=230.0.0.4:45688, bind_addr=/<<IP-address-Keycloak1>>, ttl=2
>>>> sock: bound to <<IP-address-Keycloak1>>:55200, receive buffer
>>>> size=212992, send buffer size=212992
>>>> mcast_sock: bound to <<IP-address-Keycloak1>>:45688, send buffer
>>>> size=212992, receive buffer size=212992
>>>> 2018-10-24 14:45:25,130 DEBUG [org.jgroups.protocols.UDP]
>>>> (ServerService Thread Pool -- 50) socket information:
>>>> mcast_addr=230.0.0.4:45688, bind_addr=/<<IP-address-Keycloak1>>, ttl=2
>>>> sock: bound to <<IP-address-Keycloak1>>:55200, receive buffer
>>>> size=212992, send buffer size=212992
>>>> mcast_sock: bound to <<IP-address-Keycloak1>>:45688, send buffer
>>>> size=212992, receive buffer size=212992
>>>> 2018-10-24 14:45:25,139 DEBUG [org.jgroups.protocols.pbcast.GMS]
>>>> (ServerService Thread Pool -- 50) address=keycloak-1, cluster=ejb, physical
>>>> address=<<IP-address-Keycloak1>>:55200
>>>> 2018-10-24 14:45:25,139 DEBUG [org.jgroups.protocols.pbcast.GMS]
>>>> (ServerService Thread Pool -- 50) address=keycloak-1, cluster=ejb, physical
>>>> address=<<IP-address-Keycloak1>>:55200
>>>> 2018-10-24 14:45:28,148 DEBUG [org.jgroups.protocols.pbcast.NAKACK2]
>>>> (ServerService Thread Pool -- 50)
>>>> [keycloak-1 setDigest()]
>>>> existing digest: []
>>>> new digest: keycloak-1: [0 (0)]
>>>> resulting digest: keycloak-1: [0 (0)]
>>>> 2018-10-24 14:45:28,148 DEBUG [org.jgroups.protocols.pbcast.NAKACK2]
>>>> (ServerService Thread Pool -- 50)
>>>> [keycloak-1 setDigest()]
>>>> existing digest: []
>>>> new digest: keycloak-1: [0 (0)]
>>>> resulting digest: keycloak-1: [0 (0)]
>>>> 2018-10-24 14:45:28,148 DEBUG [org.jgroups.protocols.pbcast.GMS]
>>>> (ServerService Thread Pool -- 50) keycloak-1: installing view
>>>> [keycloak-1|0] (1) [keycloak-1]
>>>> 2018-10-24 14:45:28,148 DEBUG [org.jgroups.protocols.pbcast.GMS]
>>>> (ServerService Thread Pool -- 50) keycloak-1: installing view
>>>> [keycloak-1|0] (1) [keycloak-1]
>>>> 2018-10-24 14:45:28,150 DEBUG [org.jgroups.protocols.pbcast.STABLE]
>>>> (ServerService Thread Pool -- 50) resuming message garbage collection
>>>> 2018-10-24 14:45:28,150 DEBUG [org.jgroups.protocols.pbcast.STABLE]
>>>> (ServerService Thread Pool -- 50) resuming message garbage collection
>>>> 2018-10-24 14:45:28,161 DEBUG [org.jgroups.protocols.pbcast.STABLE]
>>>> (ServerService Thread Pool -- 50) resuming message garbage collection
>>>> 2018-10-24 14:45:28,161 DEBUG [org.jgroups.protocols.pbcast.STABLE]
>>>> (ServerService Thread Pool -- 50) resuming message garbage collection
>>>> 2018-10-24 14:45:28,161 DEBUG [org.jgroups.protocols.pbcast.GMS]
>>>> (ServerService Thread Pool -- 50) keycloak-1: created cluster (first
>>>> member). My view is [keycloak-1|0], impl is
>>>> org.jgroups.protocols.pbcast.CoordGmsImpl
>>>> 2018-10-24 14:45:28,161 DEBUG [org.jgroups.protocols.pbcast.GMS]
>>>> (ServerService Thread Pool -- 50) keycloak-1: created cluster (first
>>>> member). My view is [keycloak-1|0], impl is
>>>> org.jgroups.protocols.pbcast.CoordGmsImpl
>>>> 2018-10-24 14:45:28,621 INFO
>>>> [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service
>>>> thread 1-3) ISPN000078: Starting JGroups channel ejb
>>>> 2018-10-24 14:45:28,620 INFO
>>>> [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service
>>>> thread 1-1) ISPN000078: Starting JGroups channel ejb
>>>> 2018-10-24 14:45:28,620 INFO
>>>> [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service
>>>> thread 1-5) ISPN000078: Starting JGroups channel ejb
>>>> 2018-10-24 14:45:28,625 INFO [org.infinispan.CLUSTER] (MSC service
>>>> thread 1-3) ISPN000094: Received new cluster view for channel ejb:
>>>> [keycloak-1|0] (1) [keycloak-1]
>>>>
>>>
>>>
>>> 2018-10-24 14:48:02,138 DEBUG [org.jgroups.protocols.pbcast.STABLE]
>>>> (thread-9,ejb,keycloak-1) suspending message garbage collection
>>>> 2018-10-24 14:48:02,138 DEBUG [org.jgroups.protocols.pbcast.STABLE]
>>>> (thread-9,ejb,keycloak-1) suspending message garbage collection
>>>> 2018-10-24 14:48:02,139 DEBUG [org.jgroups.protocols.pbcast.STABLE]
>>>> (thread-9,ejb,keycloak-1) keycloak-1: resume task started,
>>>> max_suspend_time=33000
>>>> 2018-10-24 14:48:02,139 DEBUG [org.jgroups.protocols.pbcast.STABLE]
>>>> (thread-9,ejb,keycloak-1) keycloak-1: resume task started,
>>>> max_suspend_time=33000
>>>> 2018-10-24 14:48:02,140 DEBUG [org.jgroups.protocols.pbcast.GMS]
>>>> (thread-9,ejb,keycloak-1) keycloak-1: installing view [keycloak-1|1] (2)
>>>> [keycloak-1, keycloak-2]
>>>> 2018-10-24 14:48:02,140 DEBUG [org.jgroups.protocols.pbcast.GMS]
>>>> (thread-9,ejb,keycloak-1) keycloak-1: installing view [keycloak-1|1] (2)
>>>> [keycloak-1, keycloak-2]
>>>> 2018-10-24 14:48:02,142 INFO [org.infinispan.CLUSTER]
>>>> (thread-9,ejb,keycloak-1) ISPN000094: Received new cluster view for channel
>>>> ejb: [keycloak-1|1] (2) [keycloak-1, keycloak-2]
>>>> 2018-10-24 14:48:02,143 DEBUG [org.jgroups.protocols.FD_SOCK] (FD_SOCK
>>>> pinger-10,ejb,keycloak-1) keycloak-1: pingable_mbrs=[keycloak-1,
>>>> keycloak-2], ping_dest=keycloak-2
>>>> 2018-10-24 14:48:02,143 DEBUG [org.jgroups.protocols.FD_SOCK] (FD_SOCK
>>>> pinger-10,ejb,keycloak-1) keycloak-1: pingable_mbrs=[keycloak-1,
>>>> keycloak-2], ping_dest=keycloak-2
>>>> 2018-10-24 14:48:02,148 INFO [org.infinispan.CLUSTER]
>>>> (thread-9,ejb,keycloak-1) ISPN100000: Node keycloak-2 joined the cluster
>>>> 2018-10-24 14:48:02,149 INFO [org.infinispan.CLUSTER]
>>>> (thread-9,ejb,keycloak-1) ISPN000094: Received new cluster view for channel
>>>> ejb: [keycloak-1|1] (2) [keycloak-1, keycloak-2]
>>>> 2018-10-24 14:48:02,151 INFO [org.infinispan.CLUSTER]
>>>> (thread-9,ejb,keycloak-1) ISPN100000: Node keycloak-2 joined the cluster
>>>> 2018-10-24 14:48:02,153 INFO [org.infinispan.CLUSTER]
>>>> (thread-9,ejb,keycloak-1) ISPN000094: Received new cluster view for channel
>>>> ejb: [keycloak-1|1] (2) [keycloak-1, keycloak-2]
>>>> 2018-10-24 14:48:02,154 INFO [org.infinispan.CLUSTER]
>>>> (thread-9,ejb,keycloak-1) ISPN100000: Node keycloak-2 joined the cluster
>>>> 2018-10-24 14:48:02,154 INFO [org.infinispan.CLUSTER]
>>>> (thread-9,ejb,keycloak-1) ISPN000094: Received new cluster view for channel
>>>> ejb: [keycloak-1|1] (2) [keycloak-1, keycloak-2]
>>>> 2018-10-24 14:48:02,155 INFO [org.infinispan.CLUSTER]
>>>> (thread-9,ejb,keycloak-1) ISPN100000: Node keycloak-2 joined the cluster
>>>>
>>>
>>> 2018-10-24 14:48:02,155 INFO [org.infinispan.CLUSTER]
>>>> (thread-9,ejb,keycloak-1) ISPN100000: Node keycloak-2 joined the cluster
>>>> 2018-10-24 14:48:02,156 INFO [org.infinispan.CLUSTER]
>>>> (thread-9,ejb,keycloak-1) ISPN000094: Received new cluster view for channel
>>>> ejb: [keycloak-1|1] (2) [keycloak-1, keycloak-2]
>>>> 2018-10-24 14:48:02,156 INFO [org.infinispan.CLUSTER]
>>>> (thread-9,ejb,keycloak-1) ISPN100000: Node keycloak-2 joined the cluster
>>>> 2018-10-24 14:48:02,194 DEBUG [org.jgroups.protocols.pbcast.STABLE]
>>>> (thread-9,ejb,keycloak-1) resuming message garbage collection
>>>> 2018-10-24 14:48:02,194 DEBUG [org.jgroups.protocols.pbcast.STABLE]
>>>> (thread-9,ejb,keycloak-1) resuming message garbage collection
>>>> 2018-10-24 14:48:03,229 INFO [org.infinispan.CLUSTER]
>>>> (remote-thread--p16-t2) ISPN000310: Starting cluster-wide rebalance for
>>>> cache offlineSessions, topology CacheTopology{id=2,
>>>> phase=READ_OLD_WRITE_ALL, rebalanceId=2,
>>>> currentCH=DefaultConsistentHash{ns=256, owners = (1)[keycloak-1: 256+0]},
>>>> pendingCH=DefaultConsistentHash{ns=256, owners = (2)[keycloak-1: 134+122,
>>>> keycloak-2: 122+134]}, unionCH=null, actualMembers=[keycloak-1,
>>>> keycloak-2], persistentUUIDs=[ac5d9ae6-7720-4fd7-8df0-b0727acaed48,
>>>> 378015dd-8c56-44a7-ab7e-a93d706dd623]}
>>>> 2018-10-24 14:48:03,231 INFO [org.infinispan.CLUSTER]
>>>> (remote-thread--p16-t2)
>>>> [Context=offlineSessions][Scope=keycloak-1]ISPN100002: Started rebalance
>>>> with topology id 2
>>>> 2018-10-24 14:48:03,238 INFO [org.infinispan.CLUSTER]
>>>> (remote-thread--p16-t4) ISPN000310: Starting cluster-wide rebalance for
>>>> cache sessions, topology CacheTopology{id=2, phase=READ_OLD_WRITE_ALL,
>>>> rebalanceId=2, currentCH=DefaultConsistentHash{ns=256, owners =
>>>> (1)[keycloak-1: 256+0]}, pendingCH=DefaultConsistentHash{ns=256, owners =
>>>> (2)[keycloak-1: 134+122, keycloak-2: 122+134]}, unionCH=null,
>>>> actualMembers=[keycloak-1, keycloak-2],
>>>> persistentUUIDs=[ac5d9ae6-7720-4fd7-8df0-b0727acaed48,
>>>> 378015dd-8c56-44a7-ab7e-a93d706dd623]}
>>>> 2018-10-24 14:48:03,238 INFO [org.infinispan.CLUSTER]
>>>> (remote-thread--p16-t4) [Context=sessions][Scope=keycloak-1]ISPN100002:
>>>> Started rebalance with topology id 2
>>>> 2018-10-24 14:48:03,242 INFO [org.infinispan.CLUSTER]
>>>> (remote-thread--p12-t2) ISPN000310: Starting cluster-wide rebalance for
>>>> cache client-mappings, topology CacheTopology{id=2,
>>>> phase=READ_OLD_WRITE_ALL, rebalanceId=2,
>>>> currentCH=ReplicatedConsistentHash{ns = 256, owners = (1)[keycloak-1:
>>>> 256]}, pendingCH=ReplicatedConsistentHash{ns = 256, owners =
>>>> (2)[keycloak-1: 134, keycloak-2: 122]}, unionCH=null,
>>>> actualMembers=[keycloak-1, keycloak-2],
>>>> persistentUUIDs=[f239ad45-df8a-4f17-a08b-6962b47ef073,
>>>> 33572709-8cca-4daa-a2fd-eee2e3fd4c17]}
>>>> 2018-10-24 14:48:03,243 INFO [org.infinispan.CLUSTER]
>>>> (remote-thread--p12-t2)
>>>> [Context=client-mappings][Scope=keycloak-1]ISPN100002: Started rebalance
>>>> with topology id 2
>>>> 2018-10-24 14:48:03,247 INFO [org.infinispan.CLUSTER]
>>>> (remote-thread--p16-t7) ISPN000310: Starting cluster-wide rebalance for
>>>> cache actionTokens, topology CacheTopology{id=2, phase=READ_OLD_WRITE_ALL,
>>>> rebalanceId=2, currentCH=DefaultConsistentHash{ns=256, owners =
>>>> (1)[keycloak-1: 256+0]}, pendingCH=DefaultConsistentHash{ns=256, owners =
>>>> (2)[keycloak-1: 134+122, keycloak-2: 122+134]}, unionCH=null,
>>>> actualMembers=[keycloak-1, keycloak-2],
>>>> persistentUUIDs=[ac5d9ae6-7720-4fd7-8df0-b0727acaed48,
>>>> 378015dd-8c56-44a7-ab7e-a93d706dd623]}
>>>> 2018-10-24 14:48:03,247 INFO [org.infinispan.CLUSTER]
>>>> (remote-thread--p16-t7) [Context=actionTokens][Scope=keycloak-1]ISPN100002:
>>>> Started rebalance with topology id 2
>>>> 2018-10-24 14:48:03,242 INFO [org.infinispan.CLUSTER]
>>>> (remote-thread--p16-t3) ISPN000310: Starting cluster-wide rebalance for
>>>> cache loginFailures, topology CacheTopology{id=2, phase=READ_OLD_WRITE_ALL,
>>>> rebalanceId=2, currentCH=DefaultConsistentHash{ns=256, owners =
>>>> (1)[keycloak-1: 256+0]}, pendingCH=DefaultConsistentHash{ns=256, owners =
>>>> (2)[keycloak-1: 134+122, keycloak-2: 122+134]}, unionCH=null,
>>>> actualMembers=[keycloak-1, keycloak-2],
>>>> persistentUUIDs=[ac5d9ae6-7720-4fd7-8df0-b0727acaed48,
>>>> 378015dd-8c56-44a7-ab7e-a93d706dd623]}
>>>>
>>>
>>> 2018-10-24 14:48:03,271 INFO [org.infinispan.CLUSTER]
>>>> (transport-thread--p18-t2)
>>>> [Context=offlineSessions][Scope=keycloak-1]ISPN100003: Node keycloak-1
>>>> finished rebalance phase with topology id 2
>>>> 2018-10-24 14:48:03,273 INFO [org.infinispan.CLUSTER]
>>>> (remote-thread--p16-t6) ISPN000310: Starting cluster-wide rebalance for
>>>> cache offlineClientSessions, topology CacheTopology{id=2,
>>>> phase=READ_OLD_WRITE_ALL, rebalanceId=2,
>>>> currentCH=DefaultConsistentHash{ns=256, owners = (1)[keycloak-1: 256+0]},
>>>> pendingCH=DefaultConsistentHash{ns=256, owners = (2)[keycloak-1: 134+122,
>>>> keycloak-2: 122+134]}, unionCH=null, actualMembers=[keycloak-1,
>>>> keycloak-2], persistentUUIDs=[ac5d9ae6-7720-4fd7-8df0-b0727acaed48,
>>>> 378015dd-8c56-44a7-ab7e-a93d706dd623]}
>>>> 2018-10-24 14:48:03,273 INFO [org.infinispan.CLUSTER]
>>>> (remote-thread--p16-t6)
>>>> [Context=offlineClientSessions][Scope=keycloak-1]ISPN100002: Started
>>>> rebalance with topology id 2
>>>> 2018-10-24 14:48:03,278 INFO [org.infinispan.CLUSTER]
>>>> (transport-thread--p18-t3) [Context=sessions][Scope=keycloak-1]ISPN100003:
>>>> Node keycloak-1 finished rebalance phase with topology id 2
>>>> 2018-10-24 14:48:03,293 INFO [org.infinispan.CLUSTER]
>>>> (transport-thread--p18-t8)
>>>> [Context=actionTokens][Scope=keycloak-1]ISPN100003: Node keycloak-1
>>>> finished rebalance phase with topology id 2
>>>> 2018-10-24 14:48:03,294 INFO [org.infinispan.CLUSTER]
>>>> (transport-thread--p18-t4)
>>>> [Context=clientSessions][Scope=keycloak-1]ISPN100003: Node keycloak-1
>>>> finished rebalance phase with topology id 2
>>>> 2018-10-24 14:48:03,294 INFO [org.infinispan.CLUSTER]
>>>> (transport-thread--p18-t9)
>>>> [Context=loginFailures][Scope=keycloak-1]ISPN100003: Node keycloak-1
>>>> finished rebalance phase with topology id 2
>>>> 2018-10-24 14:48:03,297 INFO [org.infinispan.CLUSTER]
>>>> (transport-thread--p18-t18)
>>>> [Context=authenticationSessions][Scope=keycloak-1]ISPN100003: Node
>>>> keycloak-1 finished rebalance phase with topology id 2
>>>> 2018-10-24 14:48:03,297 INFO [org.infinispan.CLUSTER]
>>>> (transport-thread--p18-t18) [Context=work][Scope=keycloak-1]ISPN100003:
>>>> Node keycloak-1 finished rebalance phase with topology id 2
>>>> 2018-10-24 14:48:03,299 INFO [org.infinispan.CLUSTER]
>>>> (transport-thread--p18-t23)
>>>> [Context=offlineClientSessions][Scope=keycloak-1]ISPN100003: Node
>>>> keycloak-1 finished rebalance phase with topology id 2
>>>> 2018-10-24 14:48:03,299 INFO [org.infinispan.CLUSTER]
>>>> (transport-thread--p20-t8)
>>>> [Context=client-mappings][Scope=keycloak-1]ISPN100003: Node keycloak-1
>>>> finished rebalance phase with topology id 2
>>>> 2018-10-24 14:49:02,158 WARN
>>>> [org.infinispan.topology.ClusterTopologyManagerImpl]
>>>> (transport-thread--p19-t2) ISPN000197: Error updating cluster member list:
>>>> org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out
>>>> waiting for responses for request 1 from keycloak-2
>>>> at
>>>> org.infinispan.remoting.transport.impl.MultiTargetRequest.onTimeout(MultiTargetRequest.java:167)
>>>> at
>>>> org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:87)
>>>> at
>>>> org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:22)
>>>> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
>>>> at
>>>> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
>>>> at
>>>> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
>>>> at
>>>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
>>>> at
>>>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
>>>> at
>>>>
>>>
>>>
>>>
>>> On Wed, Oct 24, 2018 at 10:29 AM Sebastian Laskawiec <
>>> slaskawi at redhat.com> wrote:
>>>
>>>> The new view log messages look a bit weird. It seems that JGroups
>>>> installed new view every 1 ms, which is very unusual. There are three
>>>> scenarios where this may happen (at least that I can think from the top of
>>>> my head):
>>>> - Very short timeout on FD_* protocols
>>>> - Faulty NIC or incorrect network level configuration in the datacenter
>>>> - Network packets are cut when in transport. I've seen it with one of
>>>> the hardware firewalls (don't remember which one though). Due to faulty
>>>> configuration it was cutting packets to certain length causing other layers
>>>> to fail miserably.
>>>>
>>>> Perhaps you could set the logging level to DEBUG on org.jgroups package
>>>> and check if there's anything interesting there?
>>>>
>>>> On Wed, Oct 24, 2018 at 3:11 PM Rafael Weingärtner <
>>>> rafaelweingartner at gmail.com> wrote:
>>>>
>>>>> Hello Keycloakers,
>>>>> I am having some problems with Keycloak 4.5.0. I basically have set up
>>>>> two
>>>>> nodes, and they see each other. I am using MPING (the default
>>>>> configuration). The nodes are called “Keycloak-1” and “Keycloak-2”. In
>>>>> front of these Keycloak nodes I have an HTTPD, which is using AJP to
>>>>> connect and load balance them.
>>>>>
>>>>> When the second server starts I can see:
>>>>>
>>>>> > 2018-10-24 12:35:02,277 INFO [org.infinispan.CLUSTER] (MSC service
>>>>> thread
>>>>> > 1-5) ISPN000094: Received new cluster view for channel ejb:
>>>>> [keycloak-1|1]
>>>>> > (2) [keycloak-1, keycloak-2]
>>>>> > 2018-10-24 12:35:02,277 INFO [org.infinispan.CLUSTER] (MSC service
>>>>> thread
>>>>> > 1-2) ISPN000094: Received new cluster view for channel ejb:
>>>>> [keycloak-1|1]
>>>>> > (2) [keycloak-1, keycloak-2]
>>>>> > 2018-10-24 12:35:02,278 INFO [org.infinispan.CLUSTER] (MSC service
>>>>> thread
>>>>> > 1-3) ISPN000094: Received new cluster view for channel ejb:
>>>>> [keycloak-1|1]
>>>>> > (2) [keycloak-1, keycloak-2]
>>>>> > 2018-10-24 12:35:02,279 INFO [org.infinispan.CLUSTER] (MSC service
>>>>> thread
>>>>> > 1-8) ISPN000094: Received new cluster view for channel ejb:
>>>>> [keycloak-1|1]
>>>>> > (2) [keycloak-1, keycloak-2]
>>>>> > 2018-10-24 12:35:02,280 INFO [org.infinispan.CLUSTER] (MSC service
>>>>> thread
>>>>> > 1-7) ISPN000094: Received new cluster view for channel ejb:
>>>>> [keycloak-1|1]
>>>>> > (2) [keycloak-1, keycloak-2]
>>>>> >
>>>>>
>>>>> So, they are seeing/reaching each other. The problem happens when I
>>>>> try to
>>>>> login. I then get the following:
>>>>>
>>>>> > MSC000001: Failed to start service
>>>>> > org.wildfly.clustering.infinispan.cache.keycloak.loginFailures:
>>>>> > org.jboss.msc.service.StartException in service
>>>>> > org.wildfly.clustering.infinispan.cache.keycloak.loginFailures:
>>>>> > org.infinispan.commons.CacheException: Unable to invoke method
>>>>> public void
>>>>> >
>>>>> org.infinispan.statetransfer.StateTransferManagerImpl.waitForInitialStateTransferToComplete()
>>>>> > throws java.lang.Exception on object of type StateTransferManagerImpl
>>>>> >
>>>>>
>>>>> And errors like:
>>>>>
>>>>> > Suppressed: java.util.concurrent.ExecutionException:
>>>>> > org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed
>>>>> out
>>>>> > waiting for responses for request 2 from keycloak-2
>>>>> >
>>>>>
>>>>> 018-10-24 12:55:48,990 ERROR
>>>>> [org.jboss.as.controller.management-operation]
>>>>> > (Controller Boot Thread) WFLYCTL0013: Operation ("add") failed -
>>>>> address: ([
>>>>> > ("subsystem" => "infinispan"),
>>>>> > ("cache-container" => "ejb"),
>>>>> > ("thread-pool" => "transport")
>>>>> > ]) - failure description: {
>>>>> > "WFLYCTL0080: Failed services" =>
>>>>> > {"org.wildfly.clustering.infinispan.cache.ejb.client-mappings" =>
>>>>> > "org.infinispan.commons.CacheException: Unable to invoke method
>>>>> public void
>>>>> >
>>>>> org.infinispan.statetransfer.StateTransferManagerImpl.waitForInitialStateTransferToComplete()
>>>>> > throws java.lang.Exception on object of type StateTransferManagerImpl
>>>>> > Caused by: org.infinispan.commons.CacheException: Unable to
>>>>> invoke
>>>>> > method public void
>>>>> >
>>>>> org.infinispan.statetransfer.StateTransferManagerImpl.waitForInitialStateTransferToComplete()
>>>>> > throws java.lang.Exception on object of type StateTransferManagerImpl
>>>>> > Caused by: org.infinispan.commons.CacheException: Initial state
>>>>> > transfer timed out for cache client-mappings on keycloak-2"},
>>>>> > "WFLYCTL0288: One or more services were unable to start due to
>>>>> one or
>>>>> > more indirect dependencies not being available." => {
>>>>> > "Services that were unable to start:" =>
>>>>> > ["org.wildfly.clustering.cache.group.ejb.client-mappings"],
>>>>> > "Services that may be the cause:" => [
>>>>> > "jboss.clustering.web.route.default-server",
>>>>> > "jboss.deployment.discovery.\"keycloak-server.war\"",
>>>>> > "jboss.ejb.association",
>>>>> > "jboss.ejb.remoting.connector.client-mappings",
>>>>> > "jboss.iiop-openjdk.poa-service.rootpoa",
>>>>> >
>>>>>
>>>>>
>>>>> I am quite puzzled, there is not ports being blocked, and the system
>>>>> has no
>>>>> load at all. Why would this timeout happen?
>>>>>
>>>>> --
>>>>> Rafael Weingärtner
>>>>> _______________________________________________
>>>>> keycloak-user mailing list
>>>>> keycloak-user at lists.jboss.org
>>>>> https://lists.jboss.org/mailman/listinfo/keycloak-user
>>>>
>>>>
>>>
>>> --
>>> Rafael Weingärtner
>>>
>>
>>
>> --
>> Rafael Weingärtner
>>
>
>
> --
> Rafael Weingärtner
>
More information about the keycloak-user
mailing list