I've been doing some work on the multipoint failover/clustering code. In the
process I've done some major improvements to the client using an event pattern
which has been proving to be a major help in logging and testing.
It's basically a trimmed version of CDI @Observes/fireEvent. Something I've
been wanting to add to the server for a while, more so now seeing how well it
works in the client. Something to hack on after a final release :)
Will post more details once it's ready to commit, in the meantime "head's up"
and here's a small preview of the client log output below.
-David
Mar 21, 2012 3:38:51 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Starting red server
Mar 21, 2012 3:38:53 PM org.apache.openejb.client.EventLogger log
CONFIG: ClientVersion{version='4.0.0-beta-3-SNAPSHOT', date='20120320',
time='09:34'}
Mar 21, 2012 3:38:53 PM org.apache.openejb.client.EventLogger log
INFO: RemoteInitialContextCreated{providerUri=ejbd://localhost:50397/red}
Mar 21, 2012 3:38:53 PM org.apache.openejb.client.EventLogger log
CONFIG: ConnectionFactoryAdded{scheme='default',
factory=org.apache.openejb.client.SocketConnectionFactory}
Mar 21, 2012 3:38:53 PM org.apache.openejb.client.EventLogger log
CONFIG: ConnectionFactoryAdded{scheme='ejbd',
factory=org.apache.openejb.client.SocketConnectionFactory}
Mar 21, 2012 3:38:53 PM org.apache.openejb.client.EventLogger log
CONFIG: ConnectionFactoryAdded{scheme='ejbds',
factory=org.apache.openejb.client.SocketConnectionFactory}
Mar 21, 2012 3:38:53 PM org.apache.openejb.client.EventLogger log
CONFIG: ConnectionFactoryAdded{scheme='http',
factory=org.apache.openejb.client.HttpConnectionFactory}
Mar 21, 2012 3:38:53 PM org.apache.openejb.client.EventLogger log
CONFIG: ConnectionFactoryAdded{scheme='https',
factory=org.apache.openejb.client.HttpConnectionFactory}
Mar 21, 2012 3:38:53 PM org.apache.openejb.client.EventLogger log
CONFIG: ConnectionFactoryAdded{scheme='multicast',
factory=org.apache.openejb.client.MulticastConnectionFactory}
Mar 21, 2012 3:38:53 PM org.apache.openejb.client.EventLogger log
CONFIG: ConnectionFactoryAdded{scheme='failover',
factory=org.apache.openejb.client.FailoverConnectionFactory}
Mar 21, 2012 3:38:53 PM org.apache.openejb.client.EventLogger log
CONFIG: ConnectionStrategyAdded{scheme='sticky',
strategy=org.apache.openejb.client.StickyConnectionStrategy}
Mar 21, 2012 3:38:53 PM org.apache.openejb.client.EventLogger log
CONFIG: ConnectionStrategyAdded{scheme='random',
strategy=org.apache.openejb.client.RandomConnectionStrategy}
Mar 21, 2012 3:38:53 PM org.apache.openejb.client.EventLogger log
CONFIG: ConnectionStrategyAdded{scheme='roundrobin',
strategy=org.apache.openejb.client.RoundRobinConnectionStrategy}
Mar 21, 2012 3:38:53 PM org.apache.openejb.client.EventLogger log
CONFIG: ConnectionStrategyAdded{scheme='round-robin',
strategy=org.apache.openejb.client.RoundRobinConnectionStrategy}
Mar 21, 2012 3:38:53 PM org.apache.openejb.client.EventLogger log
CONFIG: ConnectionStrategyAdded{scheme='default',
strategy=org.apache.openejb.client.StickyConnectionStrategy}
Mar 21, 2012 3:38:53 PM org.apache.openejb.client.EventLogger log
INFO: ConnectionOpened{uri=ejbd://localhost:50397/red}
Mar 21, 2012 3:38:53 PM org.apache.openejb.client.EventLogger log
FINE: ClusterMetaDataUpdated{provider=ejbd://localhost:50397/red,
version=1332369533612, uris=1}
Mar 21, 2012 3:38:53 PM org.apache.openejb.client.EventLogger log
FINER: ClusterMetaDataUpdated{provider=ejbd://localhost:50397/red,
version=1332369533612, uris=1} #1 ejbd://localhost:50397/red
Mar 21, 2012 3:38:54 PM
org.apache.openejb.server.discovery.MultipointServer$Session info
INFO: root:50393 < 50398 GREETING Session{uri=conn://127.0.0.1:50398/red,
state=GREETING, owner=50393, s=50393, c=50402, server}@852713311 DISCOVERED
Mar 21, 2012 3:38:54 PM org.apache.openejb.server.discovery.Tracker
fireServiceAddedEvent
INFO: Added Service{uri=ejb:ejbd://localhost:50397/red}
Mar 21, 2012 3:38:58 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Starting green server
Mar 21, 2012 3:39:00 PM org.apache.openejb.client.EventLogger log
INFO: RemoteInitialContextCreated{providerUri=ejbd://localhost:50403/green}
Mar 21, 2012 3:39:00 PM org.apache.openejb.client.EventLogger log
INFO: ConnectionOpened{uri=ejbd://localhost:50403/green}
Mar 21, 2012 3:39:00 PM org.apache.openejb.client.EventLogger log
FINE: ClusterMetaDataUpdated{provider=ejbd://localhost:50403/green,
version=1332369540572, uris=1}
Mar 21, 2012 3:39:00 PM org.apache.openejb.client.EventLogger log
FINER: ClusterMetaDataUpdated{provider=ejbd://localhost:50403/green,
version=1332369540572, uris=1} #1 ejbd://localhost:50403/green
Mar 21, 2012 3:39:01 PM
org.apache.openejb.server.discovery.MultipointServer$Session info
INFO: root:50393 < 50404 GREETING Session{uri=conn://127.0.0.1:50404/green,
state=GREETING, owner=50393, s=50393, c=50408, server}@141479621 DISCOVERED
Mar 21, 2012 3:39:01 PM org.apache.openejb.server.discovery.Tracker
fireServiceAddedEvent
INFO: Added Service{uri=ejb:ejbd://localhost:50403/green}
Mar 21, 2012 3:39:04 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Starting blue server
Mar 21, 2012 3:39:06 PM org.apache.openejb.client.EventLogger log
INFO: RemoteInitialContextCreated{providerUri=ejbd://localhost:50410/blue}
Mar 21, 2012 3:39:06 PM org.apache.openejb.client.EventLogger log
INFO: ConnectionOpened{uri=ejbd://localhost:50410/blue}
Mar 21, 2012 3:39:07 PM org.apache.openejb.client.EventLogger log
FINE: ClusterMetaDataUpdated{provider=ejbd://localhost:50410/blue,
version=1332369546976, uris=1}
Mar 21, 2012 3:39:07 PM org.apache.openejb.client.EventLogger log
FINER: ClusterMetaDataUpdated{provider=ejbd://localhost:50410/blue,
version=1332369546976, uris=1} #1 ejbd://localhost:50410/blue
Mar 21, 2012 3:39:07 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Beginning Test
Mar 21, 2012 3:39:07 PM org.apache.openejb.client.EventLogger log
INFO: RemoteInitialContextCreated{providerUri=ejbd://localhost:50397/provider}
Mar 21, 2012 3:39:07 PM org.apache.openejb.client.EventLogger log
INFO: ConnectionOpened{uri=ejbd://localhost:50397/provider}
Mar 21, 2012 3:39:07 PM org.apache.openejb.client.EventLogger log
FINE: ClusterMetaDataUpdated{provider=ejbd://localhost:50397/provider,
version=1332369541083, uris=2}
Mar 21, 2012 3:39:07 PM org.apache.openejb.client.EventLogger log
FINER: ClusterMetaDataUpdated{provider=ejbd://localhost:50397/provider,
version=1332369541083, uris=2} #1 ejbd://localhost:50397/red
Mar 21, 2012 3:39:07 PM org.apache.openejb.client.EventLogger log
FINER: ClusterMetaDataUpdated{provider=ejbd://localhost:50397/provider,
version=1332369541083, uris=2} #2 ejbd://localhost:50403/green
Mar 21, 2012 3:39:07 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Looping
Mar 21, 2012 3:39:07 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Sticky request to red
Mar 21, 2012 3:39:07 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Performing 1000 invocations, expecting red to be used for each invocation.
Mar 21, 2012 3:39:07 PM
org.apache.openejb.server.discovery.MultipointServer$Session info
INFO: root:50393 < 50411 GREETING Session{uri=conn://127.0.0.1:50411/blue,
state=GREETING, owner=50393, s=50393, c=50416, server}@888356977 DISCOVERED
Mar 21, 2012 3:39:07 PM org.apache.openejb.server.discovery.Tracker
fireServiceAddedEvent
INFO: Added Service{uri=ejb:ejbd://localhost:50410/blue}
Mar 21, 2012 3:39:07 PM org.apache.openejb.client.EventLogger log
FINE: ClusterMetaDataUpdated{provider=ejbd://localhost:50397/provider,
version=1332369547482, uris=3}
Mar 21, 2012 3:39:07 PM org.apache.openejb.client.EventLogger log
FINER: ClusterMetaDataUpdated{provider=ejbd://localhost:50397/provider,
version=1332369547482, uris=3} #1 ejbd://localhost:50397/red
Mar 21, 2012 3:39:07 PM org.apache.openejb.client.EventLogger log
FINER: ClusterMetaDataUpdated{provider=ejbd://localhost:50397/provider,
version=1332369547482, uris=3} #2 ejbd://localhost:50403/green
Mar 21, 2012 3:39:07 PM org.apache.openejb.client.EventLogger log
FINER: ClusterMetaDataUpdated{provider=ejbd://localhost:50397/provider,
version=1332369547482, uris=3} #3 ejbd://localhost:50410/blue
Mar 21, 2012 3:39:07 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Shutting down red
Mar 21, 2012 3:39:08 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Looping
Mar 21, 2012 3:39:08 PM org.apache.openejb.client.EventLogger log
SEVERE: RequestFailed{server=ejbd://localhost:50397/red}
EJBRequest{deploymentId='CalculatorBean', type=EJB_OBJECT_BUSINESS_METHOD,
method='name', primaryKey='null'}
Mar 21, 2012 3:39:08 PM org.apache.openejb.client.EventLogger log
INFO: RetryingRequest{server=ejbd://localhost:50397/provider}
EJBRequest{deploymentId='CalculatorBean', type=EJB_OBJECT_BUSINESS_METHOD,
method='name', primaryKey='null'}
Mar 21, 2012 3:39:08 PM org.apache.openejb.client.EventLogger log
WARNING: StickyFailover{remaining=1, failed=1,
server=ejbd://localhost:50403/green}
Mar 21, 2012 3:39:08 PM org.apache.openejb.client.EventLogger log
FINE: ClusterMetaDataUpdated{provider=ejbd://localhost:50397/provider,
version=1332369547485, uris=3}
Mar 21, 2012 3:39:08 PM org.apache.openejb.client.EventLogger log
FINER: ClusterMetaDataUpdated{provider=ejbd://localhost:50397/provider,
version=1332369547485, uris=3} #1 ejbd://localhost:50403/green
Mar 21, 2012 3:39:08 PM org.apache.openejb.client.EventLogger log
FINER: ClusterMetaDataUpdated{provider=ejbd://localhost:50397/provider,
version=1332369547485, uris=3} #2 ejbd://localhost:50397/red
Mar 21, 2012 3:39:08 PM org.apache.openejb.client.EventLogger log
FINER: ClusterMetaDataUpdated{provider=ejbd://localhost:50397/provider,
version=1332369547485, uris=3} #3 ejbd://localhost:50410/blue
Mar 21, 2012 3:39:08 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Sticky request to green
Mar 21, 2012 3:39:08 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Performing 1000 invocations, expecting green to be used for each
invocation.
Mar 21, 2012 3:39:09 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Shutting down green
Mar 21, 2012 3:39:09 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Looping
Mar 21, 2012 3:39:09 PM org.apache.openejb.client.EventLogger log
SEVERE: RequestFailed{server=ejbd://localhost:50403/green}
EJBRequest{deploymentId='CalculatorBean', type=EJB_OBJECT_BUSINESS_METHOD,
method='name', primaryKey='null'}
Mar 21, 2012 3:39:09 PM org.apache.openejb.client.EventLogger log
INFO: RetryingRequest{server=ejbd://localhost:50397/provider}
EJBRequest{deploymentId='CalculatorBean', type=EJB_OBJECT_BUSINESS_METHOD,
method='name', primaryKey='null'}
Mar 21, 2012 3:39:09 PM org.apache.openejb.client.EventLogger log
WARNING: StickyFailover{remaining=1, failed=1,
server=ejbd://localhost:50397/red}
Mar 21, 2012 3:39:10 PM org.apache.openejb.client.EventLogger log
SEVERE: ConnectionFailed{uri=ejbd://localhost:50397/red}
Mar 21, 2012 3:39:10 PM org.apache.openejb.client.EventLogger log
WARNING: StickyFailover{remaining=0, failed=2,
server=ejbd://localhost:50410/blue}
Mar 21, 2012 3:39:10 PM org.apache.openejb.client.EventLogger log
FINE: ClusterMetaDataUpdated{provider=ejbd://localhost:50397/provider,
version=1332369547486, uris=3}
Mar 21, 2012 3:39:10 PM org.apache.openejb.client.EventLogger log
FINER: ClusterMetaDataUpdated{provider=ejbd://localhost:50397/provider,
version=1332369547486, uris=3} #1 ejbd://localhost:50410/blue
Mar 21, 2012 3:39:10 PM org.apache.openejb.client.EventLogger log
FINER: ClusterMetaDataUpdated{provider=ejbd://localhost:50397/provider,
version=1332369547486, uris=3} #2 ejbd://localhost:50397/red
Mar 21, 2012 3:39:10 PM org.apache.openejb.client.EventLogger log
FINER: ClusterMetaDataUpdated{provider=ejbd://localhost:50397/provider,
version=1332369547486, uris=3} #3 ejbd://localhost:50403/green
Mar 21, 2012 3:39:10 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Sticky request to blue
Mar 21, 2012 3:39:10 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Performing 1000 invocations, expecting blue to be used for each
invocation.
Mar 21, 2012 3:39:10 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Shutting down blue
Mar 21, 2012 3:39:11 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: All Servers Shutdown
Mar 21, 2012 3:39:11 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Making one last request, expecting complete failover
Mar 21, 2012 3:39:11 PM org.apache.openejb.client.EventLogger log
SEVERE: RequestFailed{server=ejbd://localhost:50410/blue}
EJBRequest{deploymentId='CalculatorBean', type=EJB_OBJECT_BUSINESS_METHOD,
method='name', primaryKey='null'}
Mar 21, 2012 3:39:11 PM org.apache.openejb.client.EventLogger log
INFO: RetryingRequest{server=ejbd://localhost:50397/provider}
EJBRequest{deploymentId='CalculatorBean', type=EJB_OBJECT_BUSINESS_METHOD,
method='name', primaryKey='null'}
Mar 21, 2012 3:39:11 PM org.apache.openejb.client.EventLogger log
WARNING: StickyFailover{remaining=1, failed=1,
server=ejbd://localhost:50397/red}
Mar 21, 2012 3:39:11 PM org.apache.openejb.client.EventLogger log
SEVERE: ConnectionFailed{uri=ejbd://localhost:50397/red}
Mar 21, 2012 3:39:11 PM org.apache.openejb.client.EventLogger log
WARNING: StickyFailover{remaining=0, failed=2,
server=ejbd://localhost:50403/green}
Mar 21, 2012 3:39:11 PM org.apache.openejb.client.EventLogger log
SEVERE: ConnectionFailed{uri=ejbd://localhost:50403/green}
Mar 21, 2012 3:39:11 PM org.apache.openejb.client.EventLogger log
WARNING: BootstrappingConnection{provider=ejbd://localhost:50397/provider}
Mar 21, 2012 3:39:11 PM org.apache.openejb.client.EventLogger log
SEVERE: RequestFailed{server=ejbd://localhost:50397/provider}
EJBRequest{deploymentId='CalculatorBean', type=EJB_OBJECT_BUSINESS_METHOD,
method='name', primaryKey='null'}
Mar 21, 2012 3:39:11 PM org.apache.openejb.client.EventLogger log
INFO: RetryingRequest{server=ejbd://localhost:50397/provider}
EJBRequest{deploymentId='CalculatorBean', type=EJB_OBJECT_BUSINESS_METHOD,
method='name', primaryKey='null'}
Mar 21, 2012 3:39:11 PM org.apache.openejb.client.EventLogger log
SEVERE: ConnectionStrategyFailed{strategy=StickyConnectionStrategy,
cluster=org.apache.openejb.client.ClusterMetaData@53797795,
server=ejbd://localhost:50397/provider}
Mar 21, 2012 3:39:11 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Pass. Request resulted in IOException: Unknown Container Exception:
org.apache.openejb.client.RemoteFailoverException: Cannot complete request.
Retry attempted on 4 servers; nested exception is:
java.io.IOException: Cannot write the request to the server:
Mar 21, 2012 3:39:11 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Starting blue server
Mar 21, 2012 3:39:12 PM org.apache.openejb.server.discovery.Tracker
fireServiceRemovedEvent
INFO: Removed Service{uri=ejb:ejbd://localhost:50397/red}
Mar 21, 2012 3:39:13 PM
org.apache.openejb.itest.failover.DedicatedRootServerTest test
INFO: Performing one more invocation
Mar 21, 2012 3:39:13 PM org.apache.openejb.client.EventLogger log
SEVERE: ConnectionFailed{uri=ejbd://localhost:50397/provider}
Mar 21, 2012 3:39:13 PM org.apache.openejb.client.EventLogger log
WARNING: StickyFailover{remaining=2, failed=0,
server=ejbd://localhost:50410/blue}
Mar 21, 2012 3:39:13 PM org.apache.openejb.client.EventLogger log
INFO: ConnectionOpened{uri=ejbd://localhost:50410/blue}
Mar 21, 2012 3:39:13 PM org.apache.openejb.client.EventLogger log
FINE: ClusterMetaDataUpdated{provider=ejbd://localhost:50397/provider,
version=1332369553559, uris=1}
Mar 21, 2012 3:39:13 PM org.apache.openejb.client.EventLogger log
FINER: ClusterMetaDataUpdated{provider=ejbd://localhost:50397/provider,
version=1332369553559, uris=1} #1 ejbd://localhost:50410/blue
