Bridge cannot find session with QOS_ONCE_AND_ONLY_ONCE

[julians37]

Hi,

I'm using JBoss Messaging 1.4.0CR2 on JBoss AS 4.2.1GA.

I have two separate clusters and a bridge forwarding messages from a topic on one cluster to another topic on the other cluster (for now, only one node per cluster). This works fine for QOS_DUPLICATES_OK but I get errors when I use QOS_ONCE_AND_ONLY_ONCE:

2007-09-21 17:42:27,654 ERROR [org.jboss.messaging.util.ExceptionUtil] ConnectionEndpoint[32-xgoxdu6f-1-k9iwdu6f-ihy4pf-u402a] sendTransaction [i2-6woxdu6f-1-k9iwdu6f-ihy4pf-u402a]
javax.jms.IllegalStateException: Cannot find session with id 71-4voxdu6f-1-tvwfdu6f-hphtrk-o05a
 at org.jboss.jms.server.endpoint.ServerConnectionEndpoint.processTransaction(ServerConnectionEndpoint.java:801)
 at org.jboss.jms.server.endpoint.ServerConnectionEndpoint.sendTransaction(ServerConnectionEndpoint.java:450)
 at org.jboss.jms.server.endpoint.advised.ConnectionAdvised.org$jboss$jms$server$endpoint$advised$ConnectionAdvised$sendTransaction$aop(ConnectionAdvised.java:101)
 at org.jboss.jms.server.endpoint.advised.ConnectionAdvised$sendTransaction_N3268650789275322226.invokeNext(ConnectionAdvised$sendTransaction_N3268650789275322226.java)
 at org.jboss.jms.server.container.SecurityAspect.handleSendTransaction(SecurityAspect.java:196)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.aop.advice.PerInstanceAdvice.invoke(PerInstanceAdvice.java:121)
 at org.jboss.jms.server.endpoint.advised.ConnectionAdvised$sendTransaction_N3268650789275322226.invokeNext(ConnectionAdvised$sendTransaction_N3268650789275322226.java)
 at org.jboss.jms.server.container.ServerLogInterceptor.invoke(ServerLogInterceptor.java:105)
 at org.jboss.jms.server.endpoint.advised.ConnectionAdvised$sendTransaction_N3268650789275322226.invokeNext(ConnectionAdvised$sendTransaction_N3268650789275322226.java)
 at org.jboss.jms.server.endpoint.advised.ConnectionAdvised.sendTransaction(ConnectionAdvised.java)
 at org.jboss.jms.wireformat.ConnectionSendTransactionRequest.serverInvoke(ConnectionSendTransactionRequest.java:82)
 at org.jboss.jms.server.remoting.JMSServerInvocationHandler.invoke(JMSServerInvocationHandler.java:144)
 at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:734)
 at org.jboss.remoting.transport.local.LocalClientInvoker.invoke(LocalClientInvoker.java:101)
 at org.jboss.remoting.Client.invoke(Client.java:1550)
 at org.jboss.remoting.Client.invoke(Client.java:530)
 at org.jboss.remoting.Client.invoke(Client.java:518)
 at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:186)
 at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:157)
 at org.jboss.jms.client.delegate.ClientConnectionDelegate.org$jboss$jms$client$delegate$ClientConnectionDelegate$sendTransaction$aop(ClientConnectionDelegate.java:221)
 at org.jboss.jms.client.delegate.ClientConnectionDelegate$sendTransaction_N3268650789275322226.invokeNext(ClientConnectionDelegate$sendTransaction_N3268650789275322226.java)
 at org.jboss.jms.client.container.FailoverValveInterceptor.invoke(FailoverValveInterceptor.java:91)
 at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
 at org.jboss.jms.client.delegate.ClientConnectionDelegate$sendTransaction_N3268650789275322226.invokeNext(ClientConnectionDelegate$sendTransaction_N3268650789275322226.java)
 at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170)
 at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
 at org.jboss.jms.client.delegate.ClientConnectionDelegate$sendTransaction_N3268650789275322226.invokeNext(ClientConnectionDelegate$sendTransaction_N3268650789275322226.java)
 at org.jboss.jms.client.delegate.ClientConnectionDelegate.sendTransaction(ClientConnectionDelegate.java)
 at org.jboss.jms.tx.ResourceManager.sendTransactionXA(ResourceManager.java:637)
 at org.jboss.jms.tx.ResourceManager.commit(ResourceManager.java:370)
 at org.jboss.jms.tx.MessagingXAResource.commit(MessagingXAResource.java:238)
 at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelOnePhaseCommit(XAResourceRecord.java:636)
 at com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2619)
 at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1779)
 at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:88)
 at com.arjuna.ats.arjuna.AtomicAction.end(AtomicAction.java:216)
 at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commit(TransactionImple.java:238)
 at org.jboss.jms.server.bridge.Bridge.sendBatch(Bridge.java:1250)
 at org.jboss.jms.server.bridge.Bridge.access$1700(Bridge.java:65)
 at org.jboss.jms.server.bridge.Bridge$SourceListener.onMessage(Bridge.java:1557)
 at org.jboss.jms.client.container.ClientConsumer.callOnMessage(ClientConsumer.java:157)
 at org.jboss.jms.client.container.ClientConsumer$ListenerRunner.run(ClientConsumer.java:941)
 at EDU.oswego.cs.dl.util.concurrent.QueuedExecutor$RunLoop.run(QueuedExecutor.java:89)
 at java.lang.Thread.run(Thread.java:595)
2007-09-21 18:10:30,646 WARN [org.jboss.jms.server.bridge.Bridge] Failed to send + acknowledge batch, closing JMS objects
javax.transaction.RollbackException: [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] Can't commit because the transaction is in aborted state
 at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commit(TransactionImple.java:253)
 at org.jboss.jms.server.bridge.Bridge.sendBatch(Bridge.java:1250)
 at org.jboss.jms.server.bridge.Bridge.access$1700(Bridge.java:65)
 at org.jboss.jms.server.bridge.Bridge$SourceListener.onMessage(Bridge.java:1557)
 at org.jboss.jms.client.container.ClientConsumer.callOnMessage(ClientConsumer.java:157)
 at org.jboss.jms.client.container.ClientConsumer$ListenerRunner.run(ClientConsumer.java:941)
 at EDU.oswego.cs.dl.util.concurrent.QueuedExecutor$RunLoop.run(QueuedExecutor.java:89)
 at java.lang.Thread.run(Thread.java:595)
2007-09-21 18:10:30,656 ERROR [org.jboss.jms.client.container.ClosedInterceptor] ClosedInterceptor.ClientSessionDelegate[c2-8voxdu6f-1-k9iwdu6f-ihy4pf-u402a]: method getXAResource() did not go through, the interceptor is CLOSED

My bridge configuration:

<?xml version="1.0" encoding="UTF-8"?>

<server>
 <mbean code="org.jboss.jms.server.bridge.BridgeService"
 name="jboss.messaging:service=Bridge,name=TestBridge"
 xmbean-dd="xmdesc/Bridge-xmbean.xml">

 <!-- The JMS provider loader that is used to lookup the source destination -->
 <depends optional-attribute-name="SourceProviderLoader">jboss.messaging:service=JMSProviderLoader,name=HAJNDIJMSProvider</depends>

 <!-- The JMS provider loader that is used to lookup the target destination -->
 <depends optional-attribute-name="TargetProviderLoader">jboss.messaging:service=JMSProviderLoaderRemote,name=RemoteJMSProvider</depends>

 <!-- The JNDI lookup for the source destination -->
 <attribute name="SourceDestinationLookup">/topic/foo</attribute>

 <!-- The JNDI lookup for the target destination -->
 <attribute name="TargetDestinationLookup">/topic/bar</attribute>

 <!-- The username to use for the source connection -->
 <attribute name="SourceUsername">guest</attribute>

 <!-- The password to use for the source connection -->
 <attribute name="SourcePassword">guest</attribute>

 <!-- The username to use for the target connection
 <attribute name="TargetUsername">mary</attribute>
 -->

 <!-- The password to use for the target connection
 <attribute name="TargetPassword">hotdog</attribute>
 -->

 <!-- Optional: The Quality Of Service mode to use, one of:
 QOS_AT_MOST_ONCE = 0;
 QOS_DUPLICATES_OK = 1;
 QOS_ONCE_AND_ONLY_ONCE = 2; -->
 <attribute name="QualityOfServiceMode">2</attribute>

 <!-- JMS selector to use for consuming messages from the source
 <attribute name="Selector">specify jms selector here</attribute>
 -->

 <!-- The maximum number of messages to consume from the source before sending to the target -->
 <attribute name="MaxBatchSize">1</attribute>

 <!-- The maximum time to wait (in ms) before sending a batch to the target even if MaxBatchSize is not exceeded.
 -1 means wait forever -->
 <attribute name="MaxBatchTime">-1</attribute>

 <!-- If consuming from a durable subscription this is the subscription name -->
 <attribute name="SubName">cross-office-bridge-subscription</attribute>

 <!-- If consuming from a durable subscription this is the client ID to use -->
 <attribute name="ClientID">cross-office-bridge-client-id</attribute>

 <!-- The number of ms to wait between connection retrues in the event connections to source or target fail -->
 <attribute name="FailureRetryInterval">5000</attribute>

 <!-- The maximum number of connection retries to make in case of failure, before giving up
 -1 means try forever-->
 <attribute name="MaxRetries">-1</attribute>

 </mbean>

</server>

My local JMS datasource:

 <mbean code="org.jboss.jms.jndi.JMSProviderLoader"
 name="jboss.messaging:service=JMSProviderLoader,name=HAJNDIJMSProvider">
 <attribute name="ProviderName">HAJNDIJMSProvider</attribute>
 <attribute name="ProviderAdapterClass">
 org.jboss.jms.jndi.JNDIProviderAdapter
 </attribute>
 <!-- The combined connection factory -->
 <attribute name="FactoryRef">XAConnectionFactory</attribute>
 <!-- The queue connection factory -->
 <attribute name="QueueFactoryRef">XAConnectionFactory</attribute>
 <!-- The topic factory -->
 <attribute name="TopicFactoryRef">XAConnectionFactory</attribute>
 <!-- Access JMS via HAJNDI -->
 <attribute name="Properties">
 java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory
 java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces
 java.naming.provider.url=${jboss.bind.address:localhost}:1100
 jnp.disableDiscovery=false
 jnp.partitionName=${jboss.partition.name:DefaultPartition}
 jnp.discoveryGroup=${jboss.partition.udpGroup:230.0.0.4}
 jnp.discoveryPort=1102
 jnp.discoveryTTL=16
 jnp.discoveryTimeout=5000
 jnp.maxRetries=1
 </attribute>
 </mbean>

My remote JMS datasource:

<mbean code="org.jboss.jms.jndi.JMSProviderLoader"
 name="jboss.messaging:service=JMSProviderLoaderRemote,name=RemoteJMSProvider">
 <attribute name="ProviderName">RemoteJMSProvider</attribute>
 <attribute name="ProviderAdapterClass">
 org.jboss.jms.jndi.JNDIProviderAdapter
 </attribute>
 <!-- The combined connection factory -->
 <attribute name="FactoryRef">/XAConnectionFactory</attribute>
 <!-- The queue connection factory -->
 <attribute name="QueueFactoryRef">/XAConnectionFactory</attribute>
 <!-- The topic factory -->
 <attribute name="TopicFactoryRef">/XAConnectionFactory</attribute>
 <!-- Access JMS via HAJNDI -->
 <attribute name="Properties">
 java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory
 java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces
 java.naming.provider.url=remotehost:1100
 jnp.disableDiscovery=true
 jnp.partitionName=${jboss.partition.name:DefaultPartition}
 jnp.discoveryGroup=${jboss.partition.udpGroup:230.0.0.4}
 jnp.discoveryPort=1102
 jnp.discoveryTTL=16
 jnp.discoveryTimeout=5000
 jnp.maxRetries=1
 </attribute>
 </mbean>

I've also tried with JBM trunk (as of today) but that gives me the same error.

I've tried clearing out the topic using JMX and sending an fresh message, but I get the same problem.

As you can see I'm using a durable subscription for the bridge, and my messages are persistent.

It looks like my transaction manager might be configured wrongly, but it's really just the factory defaults. Here's my jbossjta-properties.xml:

<?xml version="1.0" encoding="UTF-8"?>
<transaction-service>
 <properties depends="common" name="arjuna">
 <!--
 Transaction Reaper Timeout (default is 120000 microseconds).
 -->
 <property
 name="com.arjuna.ats.arjuna.coordinator.txReaperTimeout" value="120000"/>
 <!--
 Transaction Reaper Mode, can be: NORMAL or DYNAMIC (default is NORMAL).
 -->
 <property name="com.arjuna.ats.arjuna.coordinator.txReaperMode" value="NORMAL"/>
 <!--
 (default is NO)
 -->
 <property name="com.arjuna.ats.arjuna.coordinator.asyncCommit" value="NO"/>
 <!--
 (default is NO)
 -->
 <property name="com.arjuna.ats.arjuna.coordinator.asyncPrepare" value="NO"/>
 <!--
 (default is YES)
 -->
 <property
 name="com.arjuna.ats.arjuna.coordinator.commitOnePhase" value="YES"/>
 <!--
 (default is defaultStore)
 -->
 <property name="com.arjuna.ats.arjuna.objectstore.localOSRoot" value="defaultStore"/>
 <!--
 default is under user.home - must be writeable!)
 -->
 <property
 name="com.arjuna.ats.arjuna.objectstore.objectStoreDir" value="PutObjectStoreDirHere"/>
 <!--
 (default is ON)
 -->
 <property
 name="com.arjuna.ats.arjuna.objectstore.objectStoreSync" value="ON"/>
 <!--
 (default is ShadowNoFileLockStore)
 -->
 <property
 name="com.arjuna.ats.arjuna.objectstore.objectStoreType" value="ShadowNoFileLockStore"/>
 <!--
 (default is 255)
 -->
 <property
 name="com.arjuna.ats.arjuna.objectstore.hashedDirectories" value="255"/>
 <!--
 (default is ON)
 -->
 <property
 name="com.arjuna.ats.arjuna.objectstore.transactionSync" value="ON"/>
 <!--
 (Must be unique across all Arjuna instances.)
 -->
 <property name="com.arjuna.ats.arjuna.xa.nodeIdentifier" value="1"/>
 <!-- property
 name="com.arjuna.ats.arjuna.coordinator.actionStore"
 value="HashedActionStore"
 value="JDBCActionStore"
 -->
 <!-- property
 name="com.arjuna.ats.arjuna.objectstore.jdbcTxDbAccess"
 value="JDBCAccess"
 -->
 <!-- property
 name="com.arjuna.ats.arjuna.objectstore.objectStoreType"
 value="ShadowNoFileLockStore"
 value="JDBCStore"
 -->
 <!-- property
 name="com.arjuna.ats.arjuna.objectstore.jdbcUserDbAccess"
 value="JDBCAccess"
 -->
 <!-- property
 name="com.arjuna.ats.arjuna.objectstore.jdbcPoolSizeInitial"
 value="1"
 -->
 <!-- property
 name="com.arjuna.ats.arjuna.objectstore.jdbcPoolSizeMaximum"
 value="1"
 -->
 <!-- property
 name="com.arjuna.ats.arjuna.objectstore.jdbcPoolPutConnections"
 value="false"
 -->
 <!-- property
 name="com.arjuna.ats.arjuna.internal.arjuna.objectstore.cacheStore.size"
 value=""
 -->
 <!-- property
 name="com.arjuna.ats.arjuna.internal.arjuna.objectstore.cacheStore.period"
 value=""
 -->
 <!--
 The location for creating temporary files, e.g., Uids.
 Default is under user.home.
 IMPORTANT: make sure the directory is lockable, e.g., /tmp on Unix
 may not be!
 -->
 <!--
 <property
 name="com.arjuna.ats.arjuna.common.varDir"
 value="var"/>
 -->
 </properties>
 <properties name="common">
 <!-- CLF 2.0 properties -->
 <property name="com.arjuna.common.util.logging.DebugLevel"
 type="System" value="0x00000000"/>
 <property name="com.arjuna.common.util.logging.FacilityLevel"
 type="System" value="0xffffffff"/>
 <property name="com.arjuna.common.util.logging.VisibilityLevel"
 type="System" value="0xffffffff"/>
 <property name="com.arjuna.common.util.logger" type="System" value="log4j"/>
 </properties>
 <properties depends="arjuna" name="txoj">
 <!--
 (default is LockStore of installation - must be writeable!)
 -->
 <!--
 <property
 name="com.arjuna.ats.txoj.lockstore.lockStoreDir"
 value="LockStore"/>
 -->
 <!--
 (default is BasicLockStore)
 -->
 <property name="com.arjuna.ats.txoj.lockstore.lockStoreType" value="BasicLockStore"/>
 <!--
 (default is NO)
 -->
 <property name="com.arjuna.ats.txoj.lockstore.multipleLockStore" value="NO"/>
 <!--
 (default is YES)
 -->
 <property name="com.arjuna.ats.txoj.lockstore.singleLockStore" value="YES"/>
 <!--
 (default is YES)
 -->
 <property
 name="com.arjuna.ats.txoj.lockstore.allowNestedLocking" value="YES"/>
 </properties>
 <properties depends="arjuna" name="jta">
 <!--
 Support subtransactions in the JTA layer?
 Default is NO.
 -->
 <property name="com.arjuna.ats.jta.supportSubtransactions" value="NO"/>
 <property name="com.arjuna.ats.jta.jtaTMImplementation" value="com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionManagerImple"/>
 <!--
 com.arjuna.ats.internal.jta.transaction.jts.TransactionManagerImple
 -->
 <property name="com.arjuna.ats.jta.jtaUTImplementation" value="com.arjuna.ats.internal.jta.transaction.arjunacore.UserTransactionImple"/>
 <!--
 com.arjuna.ats.internal.jta.transaction.jts.UserTransactionImple
 -->
 <property name="com.arjuna.ats.jta.recovery.XAResourceRecovery.JBMESSAGING1" value="org.jboss.jms.server.recovery.MessagingXAResourceRecovery;java:/HAJNDIJMSProvider"/>
 </properties>
 <properties depends="arjuna,txoj,jta" name="recoverymanager">
 <!--
 Properties used only by the RecoveryManager.
 -->
 <!--
 Periodic recovery settings.
 Time values in this section are in seconds.
 -->
 <!--
 Interval in seconds between initiating the periodic recovery modules.
 Default is 120 seconds.
 -->
 <property
 name="com.arjuna.ats.arjuna.recovery.periodicRecoveryPeriod" value="120"/>
 <!--
 Interval in seconds between first and second pass of periodic recovery.
 Default is 10 seconds.
 -->
 <property
 name="com.arjuna.ats.arjuna.recovery.recoveryBackoffPeriod" value="10"/>
 <!--
 Periodic recovery modules to use. Invoked in sort-order of names.
 -->
 <property
 name="com.arjuna.ats.arjuna.recovery.recoveryExtension1" value="com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule"/>
 <property
 name="com.arjuna.ats.arjuna.recovery.recoveryExtension2" value="com.arjuna.ats.internal.txoj.recovery.TORecoveryModule"/>
 <property
 name="com.arjuna.ats.arjuna.recovery.recoveryExtension3" value="com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule"/>
 <!--
 Expired entry removal
 -->
 <!--
 Expiry scanners to use (order of invocation is random).
 Names must begin with "com.arjuna.ats.arjuna.recovery.expiryScanner"
 -->
 <property
 name="com.arjuna.ats.arjuna.recovery.expiryScannerTransactionStatusManager" value="com.arjuna.ats.internal.arjuna.recovery.ExpiredTransactionStatusManagerScanner"/>
 <!--
 Interval, in hours, between running the expiry scanners.
 This can be quite long. The absolute value determines the interval -
 if the value is negative, the scan will NOT be run until after one
 interval has elapsed. If positive the first scan will be immediately
 after startup. Zero will prevent any scanning.
 Default = 12 = run immediately, then every 12 hours.
 -->
 <property
 name="com.arjuna.ats.arjuna.recovery.expiryScanInterval" value="12"/>
 <!--
 Age, in hours, for removal of transaction status manager item.
 This should be longer than any ts-using process will remain running.
 Zero = Never removed. Default is 12.
 -->
 <property
 name="com.arjuna.ats.arjuna.recovery.transactionStatusManagerExpiryTime" value="12"/>
 <!--
 Use this to fix the port on which the TransactionStatusManager listens,
 The default behaviour is to use any free port.
 -->
 <property
 name="com.arjuna.ats.arjuna.recovery.transactionStatusManagerPort" value="0"/>
 </properties>
 <properties depends="jta" name="jdbc">
 <!--
 property name="com.arjuna.ats.jdbc.isolationLevel" value="TRANSACTION_SERIALIZABLE"/>
 -->
 </properties>
</transaction-service>

And in my jboss-service.xml I have:

<!-- JBoss Transactions JTA -->
 <mbean code="com.arjuna.ats.jbossatx.jta.TransactionManagerService"
 name="jboss:service=TransactionManager">
 <attribute name="TransactionTimeout">300</attribute>
 <attribute name="ObjectStoreDir">${jboss.server.data.dir}/tx-object-store</attribute>
 </mbean>

Does anyone have a hint where I could start looking?

Thanks in advance,

Julian

The full excerpt from the log file:

2007-09-21 17:42:25,438 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery - second pass <Fri, 21 Sep 2007 17:42:25>
2007-09-21 17:42:25,438 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AtomicActionRecoveryModule: Second pass
2007-09-21 17:42:25,438 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N] [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second pass
2007-09-21 17:42:25,438 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second pass
2007-09-21 17:42:25,438 DEBUG [org.jboss.jms.server.recovery.MessagingXAResourceWrapper] Recover java:/HAJNDIJMSProvider
2007-09-21 17:42:25,441 DEBUG [org.jboss.remoting.Client] starting callback Connector: InvokerLocator [bisocket://10.2.0.174:1819511268/callback?
serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper&isCallbackServer=true&callbackServerProtocol=bisocket&datatype=jms&guid=a204u-fp4yhi-f6udwi9k-1-f6udxn6n-1k
&callbackServerHost=10.2.0.174&callbackServerPort=1819511268&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper]
2007-09-21 17:42:25,445 DEBUG [org.jboss.remoting.ServerInvoker] SocketServerInvoker[UNINITIALIZED] did not find server socket factory configuration as mbean service or classname. Creating default server socket factory.
2007-09-21 17:42:25,445 DEBUG [org.jboss.remoting.ServerInvoker] SocketServerInvoker[UNINITIALIZED] created server socket factory javax.net.DefaultServerSocketFactory@1552b76
2007-09-21 17:42:25,445 DEBUG [org.jboss.remoting.transport.Connector] org.jboss.remoting.transport.Connector@1181c24 started
2007-09-21 17:42:25,446 DEBUG [org.jboss.remoting.ServerInvoker] ServerInvoker (SocketServerInvoker[UNINITIALIZED]) added client callback handler CallbackManager[1712492] with session id of a204u-fp4yhi-f6udwi9k-1-f6udxn6n-1j+a204u-fp4yhi-f6udwi9k-1-f6udxn6t-1l and callback handle object of null.
2007-09-21 17:42:25,446 DEBUG [org.jboss.remoting.InvokerRegistry] removed org.jboss.remoting.transport.local.LocalClientInvoker@1dfb148 from registry
2007-09-21 17:42:25,446 DEBUG [org.jboss.remoting.callback.DefaultCallbackErrorHandler] DefaultCallbackErrorHandler[UNITIALIZED] setting server invoker to SocketServerInvoker[10.2.0.174:4457]
2007-09-21 17:42:25,446 DEBUG [org.jboss.remoting.callback.DefaultCallbackErrorHandler] DefaultCallbackErrorHandler[SocketServerInvoker[10.2.0.174:4457]] setting callback handler to ServerInvokerCallbackHandler[a204u-fp4yhi-f6udwi9k-1-f6udxn6n-1j+a204u-fp4yhi-f6udwi9k-1-f6udxn6t-1l]
2007-09-21 17:42:25,446 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] Session id for callback handler is a204u-fp4yhi-f6udwi9k-1-f6udxn6n-1j+a204u-fp4yhi-f6udwi9k-1-f6udxn6t-1l
2007-09-21 17:42:25,446 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] adding callback handler ServerInvokerCallbackHandler[a204u-fp4yhi-f6udwi9k-1-f6udxn6n-1j+a204u-fp4yhi-f6udwi9k-1-f6udxn6t-1l]
2007-09-21 17:42:25,446 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] found calllback handler for remoting session ...-f6udxn6n-1j
2007-09-21 17:42:25,452 DEBUG [org.jboss.security.auth.spi.UsersRolesLoginModule] Loaded properties, users=[guest]
2007-09-21 17:42:25,457 DEBUG [org.jboss.security.auth.spi.UsersRolesLoginModule] Loaded properties, users=[guest]
2007-09-21 17:42:25,457 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] registered connection ConnectionEndpoint[o1-57nxdu6f-1-k9iwdu6f-ihy4pf-u402a] as ...-f6udxn6n-1j
2007-09-21 17:42:25,462 DEBUG [org.jboss.jms.server.recovery.MessagingXAResourceWrapper] Recover java:/HAJNDIJMSProvider
2007-09-21 17:42:27,082 DEBUG [org.codehaus.stomp.jms.ProtocolConverter] >>>> CONNECT headers: {}
2007-09-21 17:42:27,086 DEBUG [org.jboss.remoting.Client] starting callback Connector: InvokerLocator [bisocket://10.2.0.174:1893095046/callback?serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper
&isCallbackServer=true&callbackServerProtocol=bisocket&datatype=jms&guid=a204u-fp4yhi-f6udwi9k-1-f6udxogd-1s&callbackServerHost=10.2.0.174&callbackServerPort=1893095046
&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper]
2007-09-21 17:42:27,090 DEBUG [org.jboss.remoting.ServerInvoker] SocketServerInvoker[UNINITIALIZED] did not find server socket factory configuration as mbean service or classname. Creating default server socket factory.
2007-09-21 17:42:27,090 DEBUG [org.jboss.remoting.ServerInvoker] SocketServerInvoker[UNINITIALIZED] created server socket factory javax.net.DefaultServerSocketFactory@1552b76
2007-09-21 17:42:27,090 DEBUG [org.jboss.remoting.transport.Connector] org.jboss.remoting.transport.Connector@64eff0 started
2007-09-21 17:42:27,090 DEBUG [org.jboss.remoting.ServerInvoker] ServerInvoker (SocketServerInvoker[UNINITIALIZED]) added client callback handler CallbackManager[1a65a18] with session id of a204u-fp4yhi-f6udwi9k-1-f6udxogd-1r+a204u-fp4yhi-f6udwi9k-1-f6udxogi-1t and callback handle object of null.
2007-09-21 17:42:27,090 DEBUG [org.jboss.remoting.InvokerRegistry] removed org.jboss.remoting.transport.local.LocalClientInvoker@c4b664 from registry
2007-09-21 17:42:27,090 DEBUG [org.jboss.remoting.callback.DefaultCallbackErrorHandler] DefaultCallbackErrorHandler[UNITIALIZED] setting server invoker to SocketServerInvoker[10.2.0.174:4457]
2007-09-21 17:42:27,090 DEBUG [org.jboss.remoting.callback.DefaultCallbackErrorHandler] DefaultCallbackErrorHandler[SocketServerInvoker[10.2.0.174:4457]] setting callback handler to ServerInvokerCallbackHandler[a204u-fp4yhi-f6udwi9k-1-f6udxogd-1r+a204u-fp4yhi-f6udwi9k-1-f6udxogi-1t]
2007-09-21 17:42:27,090 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] Session id for callback handler is a204u-fp4yhi-f6udwi9k-1-f6udxogd-1r+a204u-fp4yhi-f6udwi9k-1-f6udxogi-1t
2007-09-21 17:42:27,090 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] adding callback handler ServerInvokerCallbackHandler[a204u-fp4yhi-f6udwi9k-1-f6udxogd-1r+a204u-fp4yhi-f6udwi9k-1-f6udxogi-1t]
2007-09-21 17:42:27,091 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] found calllback handler for remoting session ...-f6udxogd-1r
2007-09-21 17:42:27,091 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] registered connection ConnectionEndpoint[w1-jgoxdu6f-1-k9iwdu6f-ihy4pf-u402a] as ...-f6udxogd-1r
2007-09-21 17:42:27,092 DEBUG [org.codehaus.stomp.jms.ProtocolConverter] <<<< CONNECTED headers: {session=null}
2007-09-21 17:42:27,094 DEBUG [org.codehaus.stomp.jms.ProtocolConverter] >>>> SUBSCRIBE headers: {destination=/topic/foo}
2007-09-21 17:42:27,095 DEBUG [org.codehaus.stomp.jms.ProtocolConverter] Created session with ack mode: 1
2007-09-21 17:42:27,100 DEBUG [org.jboss.remoting.Client] starting callback Connector: InvokerLocator [bisocket://10.2.0.174:1893482336/callback?serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper
&isCallbackServer=true&callbackServerProtocol=bisocket&datatype=jms&guid=a204u-fp4yhi-f6udwi9k-1-f6udxogq-1z&callbackServerHost=10.2.0.174&callbackServerPort=1893482336
&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper]
2007-09-21 17:42:27,102 DEBUG [org.jboss.remoting.ServerInvoker] SocketServerInvoker[UNINITIALIZED] did not find server socket factory configuration as mbean service or classname. Creating default server socket factory.
2007-09-21 17:42:27,102 DEBUG [org.jboss.remoting.ServerInvoker] SocketServerInvoker[UNINITIALIZED] created server socket factory javax.net.DefaultServerSocketFactory@1552b76
2007-09-21 17:42:27,103 DEBUG [org.jboss.remoting.transport.Connector] org.jboss.remoting.transport.Connector@1ffb7d4 started
2007-09-21 17:42:27,103 DEBUG [org.jboss.remoting.ServerInvoker] ServerInvoker (SocketServerInvoker[UNINITIALIZED]) added client callback handler CallbackManager[123cf50] with session id of a204u-fp4yhi-f6udwi9k-1-f6udxogq-1y+a204u-fp4yhi-f6udwi9k-1-f6udxogv-20 and callback handle object of null.
2007-09-21 17:42:27,103 DEBUG [org.jboss.remoting.InvokerRegistry] removed org.jboss.remoting.transport.local.LocalClientInvoker@17dea61 from registry
2007-09-21 17:42:27,103 DEBUG [org.jboss.remoting.callback.DefaultCallbackErrorHandler] DefaultCallbackErrorHandler[UNITIALIZED] setting server invoker to SocketServerInvoker[10.2.0.174:4457]
2007-09-21 17:42:27,103 DEBUG [org.jboss.remoting.callback.DefaultCallbackErrorHandler] DefaultCallbackErrorHandler[SocketServerInvoker[10.2.0.174:4457]] setting callback handler to ServerInvokerCallbackHandler[a204u-fp4yhi-f6udwi9k-1-f6udxogq-1y+a204u-fp4yhi-f6udwi9k-1-f6udxogv-20]
2007-09-21 17:42:27,103 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] Session id for callback handler is a204u-fp4yhi-f6udwi9k-1-f6udxogq-1y+a204u-fp4yhi-f6udwi9k-1-f6udxogv-20
2007-09-21 17:42:27,103 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] adding callback handler ServerInvokerCallbackHandler[a204u-fp4yhi-f6udwi9k-1-f6udxogq-1y+a204u-fp4yhi-f6udwi9k-1-f6udxogv-20]
2007-09-21 17:42:27,103 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] found calllback handler for remoting session ...-f6udxogq-1y
2007-09-21 17:42:27,105 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] registered connection ConnectionEndpoint[32-xgoxdu6f-1-k9iwdu6f-ihy4pf-u402a] as ...-f6udxogq-1y
2007-09-21 17:42:27,108 DEBUG [org.jboss.jms.server.connectionfactory.ConnectionFactoryJNDIMapper] Server[0].ConnFactoryJNDIMapper received notification from node 0
2007-09-21 17:42:27,243 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[67ed13, bisocket://10.5.0.24:4457] setting maxPoolSize to 50
2007-09-21 17:42:27,243 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[67ed13, bisocket://10.5.0.24:4457] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper
2007-09-21 17:42:27,244 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[67ed13, bisocket://10.5.0.24:4457] setting shouldCheckConnection to false
2007-09-21 17:42:27,244 DEBUG [org.jboss.remoting.transport.socket.SocketClientInvoker] SocketClientInvoker[67ed13, bisocket://10.5.0.24:4457] setting timeout to 0
2007-09-21 17:42:27,244 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[67ed13, bisocket://10.5.0.24:4457] constructed
2007-09-21 17:42:27,244 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[67ed13, bisocket://10.5.0.24:4457] setting maxPoolSize to 50
2007-09-21 17:42:27,244 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[67ed13, bisocket://10.5.0.24:4457] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper
2007-09-21 17:42:27,244 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[67ed13, bisocket://10.5.0.24:4457] setting shouldCheckConnection to false
2007-09-21 17:42:27,244 DEBUG [org.jboss.remoting.transport.socket.SocketClientInvoker] SocketClientInvoker[67ed13, bisocket://10.5.0.24:4457] setting timeout to 0
2007-09-21 17:42:27,244 DEBUG [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[67ed13, bisocket://10.5.0.24:4457] connecting
2007-09-21 17:42:27,244 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[67ed13, bisocket://10.5.0.24:4457] added new pool ([]) as ServerAddress[10.5.0.24:4457, NO enableTcpNoDelay timeout 0 ms]
2007-09-21 17:42:27,244 DEBUG [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[67ed13, bisocket://10.5.0.24:4457] connected
2007-09-21 17:42:27,462 DEBUG [org.jboss.remoting.Client] starting callback Connector: InvokerLocator [bisocket://10.2.0.174:1902806884/callback?serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper
&isCallbackServer=true&callbackServerProtocol=bisocket&datatype=jms&guid=a204u-fp4yhi-f6udwi9k-1-f6udxoqt-28&callbackServerHost=10.2.0.174&callbackServerPort=1902806884
&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper]
2007-09-21 17:42:27,465 DEBUG [org.jboss.remoting.ServerInvoker] SocketServerInvoker[UNINITIALIZED] did not find server socket factory configuration as mbean service or classname. Creating default server socket factory.
2007-09-21 17:42:27,465 DEBUG [org.jboss.remoting.ServerInvoker] SocketServerInvoker[UNINITIALIZED] created server socket factory javax.net.DefaultServerSocketFactory@1552b76
2007-09-21 17:42:27,465 DEBUG [org.jboss.remoting.transport.Connector] org.jboss.remoting.transport.Connector@1c3d029 started
2007-09-21 17:42:27,465 DEBUG [org.jboss.remoting.ServerInvoker] ServerInvoker (SocketServerInvoker[UNINITIALIZED]) added client callback handler CallbackManager[1b2601c] with session id of a204u-fp4yhi-f6udwi9k-1-f6udxokq-26+a204u-fp4yhi-f6udwi9k-1-f6udxoqx-29 and callback handle object of null.
2007-09-21 17:42:27,465 DEBUG [org.jboss.remoting.InvokerRegistry] removed org.jboss.remoting.transport.local.LocalClientInvoker@974e4b from registry
2007-09-21 17:42:27,465 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] getting secondary locator
2007-09-21 17:42:27,499 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] secondary locator: InvokerLocator [null://10.5.0.24:3041/null]
2007-09-21 17:42:27,499 DEBUG [org.jboss.remoting.transport.bisocket.BisocketServerInvoker] creating control connection: InvokerLocator [null://10.5.0.24:3041/null]
2007-09-21 17:42:27,528 DEBUG [org.jboss.remoting.transport.bisocket.BisocketServerInvoker] created control connection: Socket[addr=/10.5.0.24,port=3041,localport=48993]
2007-09-21 17:42:27,617 DEBUG [org.jboss.remoting.ConnectionValidator] ConnectionValidator[null, pingPeriod=2000 ms] created
2007-09-21 17:42:27,619 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1745e95, bisocket://10.5.0.24:4457] setting maxPoolSize to 50
2007-09-21 17:42:27,619 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1745e95, bisocket://10.5.0.24:4457] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper
2007-09-21 17:42:27,619 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1745e95, bisocket://10.5.0.24:4457] setting shouldCheckConnection to false
2007-09-21 17:42:27,619 DEBUG [org.jboss.remoting.transport.socket.SocketClientInvoker] SocketClientInvoker[1745e95, bisocket://10.5.0.24:4457] setting timeout to 0
2007-09-21 17:42:27,619 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1745e95, bisocket://10.5.0.24:4457] constructed
2007-09-21 17:42:27,619 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1745e95, bisocket://10.5.0.24:4457] setting maxPoolSize to 50
2007-09-21 17:42:27,619 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1745e95, bisocket://10.5.0.24:4457] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper
2007-09-21 17:42:27,619 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1745e95, bisocket://10.5.0.24:4457] setting shouldCheckConnection to false
2007-09-21 17:42:27,619 DEBUG [org.jboss.remoting.transport.socket.SocketClientInvoker] SocketClientInvoker[1745e95, bisocket://10.5.0.24:4457] setting timeout to 0
2007-09-21 17:42:27,620 DEBUG [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[1745e95, bisocket://10.5.0.24:4457] connecting
2007-09-21 17:42:27,620 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1745e95, bisocket://10.5.0.24:4457] using pool ([ClientSocketWrapper[Socket[addr=/10.5.0.24,port=4457,localport=59618].edc88b]]) already defined for ServerAddress[10.5.0.24:4457, NO enableTcpNoDelay timeout 0 ms]
2007-09-21 17:42:27,620 DEBUG [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[1745e95, bisocket://10.5.0.24:4457] connected
2007-09-21 17:42:27,620 DEBUG [org.jboss.remoting.ConnectionValidator] ConnectionValidator[SocketClientInvoker[1745e95, bisocket://10.5.0.24:4457], pingPeriod=2000 ms] started
2007-09-21 17:42:27,621 DEBUG [org.jboss.messaging.core.impl.postoffice.MessagingPostOffice] org.jboss.messaging.core.impl.postoffice.MessagingPostOffice@1546c85 puts replicant locally: cross-office-bridge-client-id.cross-office-bridge-subscription->C
2007-09-21 17:42:27,621 DEBUG [org.jboss.jms.server.connectionfactory.ConnectionFactoryJNDIMapper] Server[0].ConnFactoryJNDIMapper received notification from node 0
2007-09-21 17:42:27,653 DEBUG [org.jboss.jms.server.bridge.Bridge] Succeeded in reconnecting to servers
2007-09-21 17:42:27,653 DEBUG [org.jboss.remoting.ServerInvoker] Thread pool class supplied is not an object name.
2007-09-21 17:42:27,654 DEBUG [org.jboss.jms.server.security.SecurityMetadataStore] No SecurityMetadadata was available for bar, using default security config
2007-09-21 17:42:27,654 ERROR [org.jboss.messaging.util.ExceptionUtil] ConnectionEndpoint[32-xgoxdu6f-1-k9iwdu6f-ihy4pf-u402a] sendTransaction [i2-6woxdu6f-1-k9iwdu6f-ihy4pf-u402a]
javax.jms.IllegalStateException: Cannot find session with id 71-4voxdu6f-1-tvwfdu6f-hphtrk-o05a
 at org.jboss.jms.server.endpoint.ServerConnectionEndpoint.processTransaction(ServerConnectionEndpoint.java:801)
 at org.jboss.jms.server.endpoint.ServerConnectionEndpoint.sendTransaction(ServerConnectionEndpoint.java:450)
 at org.jboss.jms.server.endpoint.advised.ConnectionAdvised.org$jboss$jms$server$endpoint$advised$ConnectionAdvised$sendTransaction$aop(ConnectionAdvised.java:101)
 at org.jboss.jms.server.endpoint.advised.ConnectionAdvised$sendTransaction_N3268650789275322226.invokeNext(ConnectionAdvised$sendTransaction_N3268650789275322226.java)
 at org.jboss.jms.server.container.SecurityAspect.handleSendTransaction(SecurityAspect.java:196)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.aop.advice.PerInstanceAdvice.invoke(PerInstanceAdvice.java:121)
 at org.jboss.jms.server.endpoint.advised.ConnectionAdvised$sendTransaction_N3268650789275322226.invokeNext(ConnectionAdvised$sendTransaction_N3268650789275322226.java)
 at org.jboss.jms.server.container.ServerLogInterceptor.invoke(ServerLogInterceptor.java:105)
 at org.jboss.jms.server.endpoint.advised.ConnectionAdvised$sendTransaction_N3268650789275322226.invokeNext(ConnectionAdvised$sendTransaction_N3268650789275322226.java)
 at org.jboss.jms.server.endpoint.advised.ConnectionAdvised.sendTransaction(ConnectionAdvised.java)
 at org.jboss.jms.wireformat.ConnectionSendTransactionRequest.serverInvoke(ConnectionSendTransactionRequest.java:82)
 at org.jboss.jms.server.remoting.JMSServerInvocationHandler.invoke(JMSServerInvocationHandler.java:144)
 at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:734)
 at org.jboss.remoting.transport.local.LocalClientInvoker.invoke(LocalClientInvoker.java:101)
 at org.jboss.remoting.Client.invoke(Client.java:1550)
 at org.jboss.remoting.Client.invoke(Client.java:530)
 at org.jboss.remoting.Client.invoke(Client.java:518)
 at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:186)
 at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:157)
 at org.jboss.jms.client.delegate.ClientConnectionDelegate.org$jboss$jms$client$delegate$ClientConnectionDelegate$sendTransaction$aop(ClientConnectionDelegate.java:221)
 at org.jboss.jms.client.delegate.ClientConnectionDelegate$sendTransaction_N3268650789275322226.invokeNext(ClientConnectionDelegate$sendTransaction_N3268650789275322226.java)
 at org.jboss.jms.client.container.FailoverValveInterceptor.invoke(FailoverValveInterceptor.java:91)
 at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
 at org.jboss.jms.client.delegate.ClientConnectionDelegate$sendTransaction_N3268650789275322226.invokeNext(ClientConnectionDelegate$sendTransaction_N3268650789275322226.java)
 at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170)
 at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
 at org.jboss.jms.client.delegate.ClientConnectionDelegate$sendTransaction_N3268650789275322226.invokeNext(ClientConnectionDelegate$sendTransaction_N3268650789275322226.java)
 at org.jboss.jms.client.delegate.ClientConnectionDelegate.sendTransaction(ClientConnectionDelegate.java)
 at org.jboss.jms.tx.ResourceManager.sendTransactionXA(ResourceManager.java:637)
 at org.jboss.jms.tx.ResourceManager.commit(ResourceManager.java:370)
 at org.jboss.jms.tx.MessagingXAResource.commit(MessagingXAResource.java:238)
 at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelOnePhaseCommit(XAResourceRecord.java:636)
 at com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2619)
 at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1779)
 at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:88)
 at com.arjuna.ats.arjuna.AtomicAction.end(AtomicAction.java:216)
 at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commit(TransactionImple.java:238)
 at org.jboss.jms.server.bridge.Bridge.sendBatch(Bridge.java:1250)
 at org.jboss.jms.server.bridge.Bridge.access$1700(Bridge.java:65)
 at org.jboss.jms.server.bridge.Bridge$SourceListener.onMessage(Bridge.java:1557)
 at org.jboss.jms.client.container.ClientConsumer.callOnMessage(ClientConsumer.java:157)
 at org.jboss.jms.client.container.ClientConsumer$ListenerRunner.run(ClientConsumer.java:941)
 at EDU.oswego.cs.dl.util.concurrent.QueuedExecutor$RunLoop.run(QueuedExecutor.java:89)
 at java.lang.Thread.run(Thread.java:595)
2007-09-21 17:49:29,606 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] run: IdleRemover notifying pools, interval: 450000
2007-09-21 18:10:30,646 WARN [org.jboss.jms.server.bridge.Bridge] Failed to send + acknowledge batch, closing JMS objects
javax.transaction.RollbackException: [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] Can't commit because the transaction is in aborted state
 at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commit(TransactionImple.java:253)
 at org.jboss.jms.server.bridge.Bridge.sendBatch(Bridge.java:1250)
 at org.jboss.jms.server.bridge.Bridge.access$1700(Bridge.java:65)
 at org.jboss.jms.server.bridge.Bridge$SourceListener.onMessage(Bridge.java:1557)
 at org.jboss.jms.client.container.ClientConsumer.callOnMessage(ClientConsumer.java:157)
 at org.jboss.jms.client.container.ClientConsumer$ListenerRunner.run(ClientConsumer.java:941)
 at EDU.oswego.cs.dl.util.concurrent.QueuedExecutor$RunLoop.run(QueuedExecutor.java:89)
 at java.lang.Thread.run(Thread.java:595)
2007-09-21 17:49:06,582 DEBUG [org.jboss.deployment.MainDeployer] Undeploying file:/home/julians/dev/jboss-test/jboss-4.2.1.GA/server/sark/deploy/remote-jms-ds.xml, isShutdown=false
2007-09-21 17:45:04,541 DEBUG [org.jboss.remoting.ServerInvoker] SocketServerInvoker[UNINITIALIZED] stopped
2007-09-21 18:10:30,647 DEBUG [org.jboss.deployment.SARDeployer] undeploying document file:/home/julians/dev/jboss-test/jboss-4.2.1.GA/server/sark/deploy/remote-jms-ds.xml
2007-09-21 18:10:30,647 DEBUG [org.jboss.deployment.SARDeployer] stopping mbean jboss.messaging:service=JMSProviderLoaderRemote,name=RemoteJMSProvider
2007-09-21 18:10:30,647 DEBUG [org.jboss.system.ServiceController] stopping service: jboss.messaging:service=JMSProviderLoaderRemote,name=RemoteJMSProvider
2007-09-21 18:10:30,647 DEBUG [org.jboss.system.ServiceController] stopping dependent services for: jboss.messaging:service=JMSProviderLoaderRemote,name=RemoteJMSProvider dependent services are: [ObjectName: jboss.messaging:service=Bridge,name=TestBridge
 State: RUNNING
 I Depend On:
 jboss.messaging:service=JMSProviderLoader,name=HAJNDIJMSProvider
 jboss.messaging:service=JMSProviderLoaderRemote,name=RemoteJMSProvider
]
2007-09-21 18:10:30,647 DEBUG [org.jboss.system.ServiceController] stopping service: jboss.messaging:service=Bridge,name=TestBridge
2007-09-21 18:10:30,647 DEBUG [org.jboss.system.ServiceController] stopping dependent services for: jboss.messaging:service=Bridge,name=TestBridge dependent services are: []
2007-09-21 18:10:30,647 DEBUG [org.jboss.jms.server.bridge.BridgeService] Stopping jboss.messaging:service=Bridge,name=TestBridge
2007-09-21 18:10:30,648 DEBUG [org.jboss.jms.server.connectionfactory.ConnectionFactoryJNDIMapper] Server[0].ConnFactoryJNDIMapper received notification from node 0
2007-09-21 17:44:25,465 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery - first pass <Fri, 21 Sep 2007 17:44:25>
2007-09-21 18:10:30,655 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule: first pass
2007-09-21 18:10:30,656 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] unregistered connection ConnectionEndpoint[32-xgoxdu6f-1-k9iwdu6f-ihy4pf-u402a] with remoting session ID ...-f6udxogq-1y
2007-09-21 18:10:30,656 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] removing callback handler ServerInvokerCallbackHandler[a204u-fp4yhi-f6udwi9k-1-f6udxogq-1y+a204u-fp4yhi-f6udwi9k-1-f6udxogv-20]
2007-09-21 18:10:30,656 DEBUG [org.jboss.remoting.InvokerRegistry] removed org.jboss.remoting.transport.local.LocalClientInvoker@5797c0 from registry
2007-09-21 18:10:30,656 DEBUG [org.jboss.remoting.ServerInvoker] ServerInvoker (SocketServerInvoker[UNINITIALIZED]) removing client callback handler with session id of a204u-fp4yhi-f6udwi9k-1-f6udxogq-1y+a204u-fp4yhi-f6udwi9k-1-f6udxogv-20.
2007-09-21 18:10:30,656 DEBUG [org.jboss.remoting.transport.bisocket.BisocketServerInvoker] unrecognized listener ID: a204u-fp4yhi-f6udwi9k-1-f6udxogv-20
2007-09-21 18:10:30,656 DEBUG [org.jboss.remoting.InvokerRegistry] removed org.jboss.remoting.transport.local.LocalClientInvoker@abd604 from registry
2007-09-21 18:10:30,656 DEBUG [org.jboss.remoting.ServerInvoker] SocketServerInvoker[UNINITIALIZED] stopped
2007-09-21 18:10:30,656 DEBUG [org.jboss.remoting.InvokerRegistry] decremented org.jboss.remoting.transport.local.LocalClientInvoker@2f5dda's count, current count 3
2007-09-21 18:10:30,656 ERROR [org.jboss.jms.client.container.ClosedInterceptor] ClosedInterceptor.ClientSessionDelegate[c2-8voxdu6f-1-k9iwdu6f-ihy4pf-u402a]: method getXAResource() did not go through, the interceptor is CLOSED

[timfox]

Does the bridge example (in the distro) work for you?

If so, I would suggest starting from that working baseline and changing the example step by step until it resembles you're desired setup.

At some step you should figure what's going wrong.

[julians37]

Hi Tim,

thanks for your quick reply!

OK, so I've started off with the default destinations and the test bridge.

That works (queue/A to queue/B)

But as soon as I crank QOS up to 2, I get the same error...

So it seems to be unrelated to durable subscriptions etc.

Any advice on what I could try next?

Thanks for your help,

Julian

[timfox]

I just tested with the current TRUNK against AS 4.2.1.GA.

I ran the bridge example after setting the QOS mode to 2 and it works ok:

sleep:
 [echo] Sleeping for 5 seconds ...

run:
 [java] Queue JBossQueue[A] exists
 [java] Queue JBossQueue[B] exists
 [java] The message was successfully sent to the A queue
 [java] The message was successfully sent to the A queue
 [java] The message was successfully sent to the A queue
 [java] The message was successfully sent to the A queue
 [java] The message was successfully sent to the A queue
 [java] The message was successfully sent to the A queue
 [java] The message was successfully sent to the A queue
 [java] The message was successfully sent to the A queue
 [java] The message was successfully sent to the A queue
 [java] The message was successfully sent to the A queue
 [java] The message was received successfully from the B queue
 [java] The message was received successfully from the B queue
 [java] The message was received successfully from the B queue
 [java] The message was received successfully from the B queue
 [java] The message was received successfully from the B queue
 [java] The message was received successfully from the B queue
 [java] The message was received successfully from the B queue
 [java] The message was received successfully from the B queue
 [java] The message was received successfully from the B queue
 [java] The message was received successfully from the B queue
 [java] The example connected to JBoss Messaging version 1.4.0.CR2 (1.4)

 [java] #####################
 [java] ### SUCCESS! ###
 [java] #####################

undeploy:
 [delete] Deleting: /home/tim/dev/jboss-4.2.1.GA/server/messaging/deploy/test-bridge-service.xml

My guess is you have something wrong in your AS 4.2 config. Is it a fresh install of 4.2.1.GA?

Can you try re-installing AS?

Then just set JBOSS_HOME, and run:

ant -f release-admin.xml from the util directory from the JBM source.

Then go to docs/examples/bridge

edit the etc/test-bridge-service.xml file (change Qos from 0 to 2)

then run the bridge example

[julians37]

Hi Tim,

thanks again for sticking with me on this one.

I've started off with a new AS installation and ran the example as per your instructions, and it works fine.

However, it fails as soon as more than one server is involved.

Here are the steps to reproduce:

Start with a fresh JBoss AS 4.2.1 installation and create two messaging configurations:

cd util
ant -f release-admin.xml
ant -f release-admin.xml -Dmessaging.config.name=messaging2

In $JBOSS_HOME/server/messaging2/conf/jboss-service.xml, uncomment the ServiceBindingManager so that the messaging2 config uses a different set of ports:

--- messaging/conf/jboss-service.xml 2007-09-22 10:48:53.000000000 +1000
+++ messaging2/conf/jboss-service.xml 2007-09-22 14:12:27.000000000 +1000
@@ -187,6 +187,7 @@
 | during initialization that specifies how to connect to the bindings store.
 | StoreFactory: The org.jboss.services.binding.ServicesStoreFactory interface
 | implementation to create to obtain the ServicesStore instance.
+ -->

 <mbean code="org.jboss.services.binding.ServiceBindingManager"
 name="jboss.system:service=ServiceBindingManager">
@@ -196,7 +197,6 @@
 org.jboss.services.binding.XMLServicesStoreFactory
 </attribute>
 </mbean>
- -->

 <!-- ==================================================================== -->
 <!-- Class Loading -->

Modify docs/examples/bridge/etc/test-bridge-service.xml as follows:

1. 
   
2. Add a new JMSProvider connecting to jnp://localhost:1199 (which is messaging2's JNDI port)
   
3. Change the TargetProviderLoader to use the remote provider
   
4. Set QOS to 2
   
   

   Index: test-bridge-service.xml
   ===================================================================
   --- test-bridge-service.xml (revision 3139)
   +++ test-bridge-service.xml (working copy)
   @@ -8,6 +8,27 @@
   
    <server>
   
   + <!-- The JMS provider loader -->
   + <mbean code="org.jboss.jms.jndi.JMSProviderLoader"
   + name="jboss.messaging:service=JMSProviderLoader,name=RemoteJMSProvider">
   + <attribute name="ProviderName">RemoteJMSProvider</attribute>
   + <attribute name="ProviderAdapterClass">
   + org.jboss.jms.jndi.JNDIProviderAdapter
   + </attribute>
   + <!-- The combined connection factory -->
   + <attribute name="FactoryRef">/XAConnectionFactory</attribute>
   + <!-- The queue connection factory -->
   + <attribute name="QueueFactoryRef">/XAConnectionFactory</attribute>
   + <!-- The topic factory -->
   + <attribute name="TopicFactoryRef">/XAConnectionFactory</attribute>
   + <!-- Access JMS via HAJNDI -->
   + <attribute name="Properties">
   + java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory
   + java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces
   + java.naming.provider.url=localhost:1199
   + jnp.disableDiscovery=true
   + </attribute>
   + </mbean>
   
    <mbean code="org.jboss.jms.server.bridge.BridgeService"
    name="jboss.messaging:service=Bridge,name=TestBridge"
   @@ -17,7 +38,7 @@
    <depends optional-attribute-name="SourceProviderLoader">jboss.messaging:service=JMSProviderLoader,name=JMSProvider</depends>
   
    <!-- The JMS provider loader that is used to lookup the target destination -->
   - <depends optional-attribute-name="TargetProviderLoader">jboss.messaging:service=JMSProviderLoader,name=JMSProvider</depends>
   + <depends optional-attribute-name="TargetProviderLoader">jboss.messaging:service=JMSProviderLoader,name=RemoteJMSProvider</depends>
   
    <!-- The JNDI lookup for the source destination -->
    <attribute name="SourceDestinationLookup">/queue/A</attribute>
   @@ -45,7 +66,7 @@
    QOS_AT_MOST_ONCE = 0;
    QOS_DUPLICATES_OK = 1;
    QOS_ONCE_AND_ONLY_ONCE = 2; -->
   - <attribute name="QualityOfServiceMode">0</attribute>
   + <attribute name="QualityOfServiceMode">2</attribute>
   
    <!-- JMS selector to use for consuming messages from the source
    <attribute name="Selector">specify jms selector here</attribute>
   

   
   
   Now bring up the two AS instances and run the bridge example. This should give you the "session id not found" error messages in messaging's log.
   
   Can you reproduce this? If so, is this a bug or is my RemoteJMSProvider configuration wrong? Or is there anything else I need to configure in my second AS instance?
   
   (Note that in my previous test setup, the two servers were running on different machines in different subnets between which there's no multicast routing, so I doubt that there's some problem with the ports or with the fact that both servers are running on the same host in this example. Also, my previous test setup was on Linux while this example was tested on Darwin, so it doesn't seem to be some kind of network quirk or OS hickup either)
   
   Thanks again,
   
   Julian
   
   

[julians37]

I've investigated a little bit and it appears as if the session that it complains about is created on the other end. That is, the SessionDelegate is registered with ServerPeer on the "messaging2" end but the lookup happens on the "messaging" end where the session is not known, causing the IllegalStateException to be thrown.

Is it possible that there's a bug in the way sessions are created in Bridge.java in the case (qualityOfServiceMode == QOS_ONCE_AND_ONLY_ONCE && !sourceAndTargetSameServer) ? Could lines 930-932 / 1013-1015 in Bridge.java in TRUNK be the culprit?

I can't really wrap my head around sessions and transaction handling in the bridge, but is it possible that the sourceSession has to be (counter-intuitively) created from the targetConnection in this case?

[timfox]

If I follow your instructions exactly I can replicate the issue.

However it looks like you skipped a stage in the installation of messaging2 - you need to give it a unique server id.

http://labs.jboss.com/file-access/default/members/jbossmessaging/freezone/docs/userguide-1.4.0.CR3/html/configuration.html#conf.serverpeer.attributes.serverpeerid

Since both servers have got the same server id the client side resource manager thinks there is only one server and sends all the work to be processed on one - hence the issue.

After giving messaging2 a unique server id it works for me:

run:
 [java] Queue JBossQueue[A] exists
 [java] Queue JBossQueue[B] exists
 [java] The message was successfully sent to the A queue
 [java] The message was successfully sent to the A queue
 [java] The message was successfully sent to the A queue
 [java] The message was successfully sent to the A queue
 [java] The message was successfully sent to the A queue
 [java] The message was successfully sent to the A queue
 [java] The message was successfully sent to the A queue
 [java] The message was successfully sent to the A queue
 [java] The message was successfully sent to the A queue
 [java] The message was successfully sent to the A queue
 [java] The message was received successfully from the B queue
 [java] The message was received successfully from the B queue
 [java] The message was received successfully from the B queue
 [java] The message was received successfully from the B queue
 [java] The message was received successfully from the B queue
 [java] The message was received successfully from the B queue
 [java] The message was received successfully from the B queue
 [java] The message was received successfully from the B queue
 [java] The message was received successfully from the B queue
 [java] The message was received successfully from the B queue
 [java] The example connected to JBoss Messaging version 1.4.0.CR3 (1.4)

 [java] #####################
 [java] ### SUCCESS! ###
 [java] #####################

undeploy:
 [delete] Deleting: /home/tim/dev/jboss-4.2.1.GA/server/messaging/deploy/test-bridge-service.xml

[julians37]

Ah! Fair enough, but the bit of documentation you're linking to says:

6.1.1.1. ServerPeerID

The unique id of the server peer. Each node in the cluster must have a unique name.

Note that it says "each node in the cluster". But in this scenario, the two nodes are not in the same cluster. So I wouldn't have expected that they need to have different IDs.

From this point of view I'd suggest that either the documentation be updated or - and I think that would be the better solution - the code would have to take not only the ServerPeerID into account, but also some kind of "cluster id" when determining whether two nodes are the same in this context.

Does that make sense?

At any rate, thanks once more for your help Tim. That's definitely a workaround I can live with.

[julians37]

To elaborate, it feels wrong that if you set up a bridge to send messages "somewhere", to some remote JMS provider, that you have to know details about the way that remote provider is configured.

It feels to me like you shouldn't have to worry about which ServerPeerIDs that remote provider is using internally. As far as I can see, it should be just a "black box" remote JMS system. Ideally, you shouldn't even have to think about whether it's JBM or some other JMS implementation.

That's why I think the right solution would be not to tell people "whenever you have two JBM instances talking to each other, whether it be clustering or bridging, make sure every node involved has a unique ID".

I think JBM code should distinguish between the distributed case and the bridged case when it comes to clusters and node IDs.

But again, pointing out the fact that this is required would obviously already be a step forward from the current situation.

I guess it would also be good to mention somewhere in the documentation that JBM bridging uses a "special case" when it talks to another JBM instance. (At least that's how I understand the situation.)

That's just my $0.02 though...

Cheers,

Julian

[julians37]

Thinking about it a bit longer, shouldn't the ServerPeerID always be combined with the partition name when determining node equal-ness? Why would the client side resource manager think that there's only one server when two nodes have the same ServerPeerID but different partition names?

[julians37]

Sorry, this is the fourth post in a row... but one more point: I'm surprised the example worked for you since it only listens to "messaging" - but if the bridge was working correctly, shouldn't the messages only be available on "messaging2" - or have you modified the bridge example code to listen on "messaging2" for queueB?

[timfox]

"julians37" wrote:
Ah! Fair enough, but the bit of documentation you're linking to says:

6.1.1.1. ServerPeerID

The unique id of the server peer. Each node in the cluster must have a unique name.

Note that it says "each node in the cluster".

It should read "each node (period) must have a unique id". This documentation was written before the bridge was written, hence it doesn't mention the bridge. I'll update it.

[timfox]

"julians37" wrote:
To elaborate, it feels wrong that if you set up a bridge to send messages "somewhere", to some remote JMS provider, that you have to know details about the way that remote provider is configured.

I don't follow, what details do you have to know?

It feels to me like you shouldn't have to worry about which ServerPeerIDs that remote provider is using internally. As far as I can see, it should be just a "black box" remote JMS system. Ideally, you shouldn't even have to think about whether it's JBM or some other JMS implementation.

Not sure what you are referring to. You don't have to think about whether it's JBM or some other JMS implementation. There's nothing in the bridge config that makes you configure JBM servers different from any other.

I guess it would also be good to mention somewhere in the documentation that JBM bridging uses a "special case" when it talks to another JBM instance. (At least that's how I understand the situation.)

What special case is that?

[timfox]

"julians37" wrote:
That's definitely a workaround I can live with.

Well, it's not really a workaround, that's the way JBM servers are configured. Each one must have a unique id.

[julians37]

I don't follow, what details do you have to know?

Suppose you'd set up a bridge to a JMS provider operated by a third party.

If I'm not missing anything, you'd have to ask them whether they run a JBM instance and if so, which ServerPeerIDs their nodes are using, and you'd have to configure your nodes to make sure they use different IDs. That means you have to know internal implementation details about the remote setup.

And that's also the special case I was mentioning - as far as I understand, as soon as it's not JBM on the remote side I assume you wouldn't have to pay attention to potential ServerPeerID conflicts?

I can understand, to some extent, why JBM users are required to manually coordinate nodes within a cluster and make sure they have unique IDs. But having to coordinate all nodes participating in some wider communication network appears very cumbersome and error-prone to me.

Anyway, why wouldn't you want to take the partition name into account when determining node equality - and/or use different measures to make sure remote nodes are not mistaken for a node in the local cluster?