3:08 p.m.
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
3:29 p.m.
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(a)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(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/keycloak-user
5:09 p.m.
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(a)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(a)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(a)lists.jboss.org
>> https://lists.jboss.org/mailman/listinfo/keycloak-user
>
>
--
Rafael Weingärtner
2:39 a.m.
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(a)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(a)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(a)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(a)lists.jboss.org
>> https://lists.jboss.org/mailman/listinfo/keycloak-user
>
>
--
Rafael Weingärtner
--
Rafael Weingärtner
8:46 p.m.
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(a)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(a)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(a)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(a)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(a)lists.jboss.org
>>> https://lists.jboss.org/mailman/listinfo/keycloak-user
>>
>>
>
> --
> Rafael Weingärtner
>
--
Rafael Weingärtner
--
Rafael Weingärtner
2:01 p.m.
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(a)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(a)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(a)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(a)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(a)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(a)lists.jboss.org
>>>> https://lists.jboss.org/mailman/listinfo/keycloak-user
>>>
>>>
>>
>> --
>> Rafael Weingärtner
>>
>
>
> --
> Rafael Weingärtner
>
--
Rafael Weingärtner
2:07 p.m.
That is what we will do for now.
Thanks for the help!
On Fri, Oct 26, 2018 at 9:02 AM Sebastian Laskawiec <slaskawi(a)redhat.com>
wrote:
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(a)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(a)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(a)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(a)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(a)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(a)lists.jboss.org
>>>>> https://lists.jboss.org/mailman/listinfo/keycloak-user
>>>>
>>>>
>>>
>>> --
>>> Rafael Weingärtner
>>>
>>
>>
>> --
>> Rafael Weingärtner
>>
>
>
> --
> Rafael Weingärtner
>
--
Rafael Weingärtner
2276
days inactive
2278
days old
6 comments
2 participants
participants (2)
-
Rafael Weingärtner -
Sebastian Laskawiec