Great, i like this feature! regarding logs couldn't "org.apache.openejb.client.EventLogger" be replaced by the source of the event?
is it easy to register an observer? couldn't we use cdi? - Romain 2012/3/22 David Blevins <[email protected]> > 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}@852713311DISCOVERED > 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}@141479621DISCOVERED > 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}@888356977DISCOVERED > 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 > >
