Hide Forgot
All MDB tests in JMS modul in Java EE TCK fails, see example of results in https://hudson.qa.jboss.com/hudson/view/EAP-MRG/job/tck5-eap51-jms-mrg/13/testReport/unknownTestSuite.0/packageTests/com.sun.ts.tests.jms.ee.mdb.mdb_sndQ/ The test consists of application client (test), session bean and MDB. Test invokes session bean that sends message to MDB. MDB then replies to different queue on which session bean listens. The problem is that session bean sends the message. Message is delivered to message broker (verified with Wireshark) but the message is not stored in the queue. The excerpt of server.log of EAP under TCK is 2011-09-12 15:58:06,034 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger:?] (WorkerThread#0[127.0.0.1:58322]) TransactionReaper::insert ( BasicAction: 7f000001:d9f1:4e6e0fcf:69 status: ActionStatus.RUNNING, 300 ) 2011-09-12 15:58:06,035 INFO [org.apache.qpid.client.AMQConnection:296] (WorkerThread#0[127.0.0.1:58322]) Connection:amqp://j2ee:********@jpechane1315835882496/test?sync_ack='true'&maxprefetch='0'&brokerlist='tcp://mrg01.mw.lab.eng.bos.redhat.com:5672'&sync_ack='true'&maxprefetch='0' 2011-09-12 15:58:06,035 INFO [org.apache.qpid.client.protocol.AMQProtocolSession:296] (WorkerThread#0[127.0.0.1:58322]) Using ProtocolVersion for Session:0-10 2011-09-12 15:58:06,035 INFO [org.apache.qpid.client.handler.ClientMethodDispatcherImpl:296] (WorkerThread#0[127.0.0.1:58322]) New Method Dispatcher:AMQProtocolSession[null] 2011-09-12 15:58:06,036 INFO [org.apache.qpid.client.AMQConnection:296] (WorkerThread#0[127.0.0.1:58322]) Connecting with ProtocolHandler Version:0-10 2011-09-12 15:58:06,340 INFO [org.apache.qpid.client.AMQSession:296] (WorkManager(3)-1) Prefetching delayed existing messages will not flow until requested via receive*() or setML(). 2011-09-12 15:58:06,607 INFO [org.apache.qpid.client.AMQSession:296] (WorkManager(3)-1) Created session:org.apache.qpid.client.XASessionImpl@6d4d63ba 2011-09-12 15:58:06,670 INFO [org.apache.qpid.client.AMQConnection:296] (WorkerThread#0[127.0.0.1:58322]) Connected with ProtocolHandler Version:0-10 2011-09-12 15:58:06,670 INFO [org.apache.qpid.client.AMQSession:296] (WorkerThread#0[127.0.0.1:58322]) Created session:org.apache.qpid.client.AMQSession_0_10@73ce8065 2011-09-12 15:58:07,133 INFO [org.apache.qpid.client.AMQSession:296] (WorkManager(3)-1) Prefetching delayed existing messages will not flow until requested via receive*() or setML(). 2011-09-12 15:58:07,332 INFO [org.apache.qpid.client.BasicMessageProducer_0_10:296] (WorkerThread#0[127.0.0.1:58322]) MessageProducer org.apache.qpid.client.BasicMessageProducer_0_10@7a4fa248 using publish mode : ASYNC_PUBLISH_ALL 2011-09-12 15:58:07,363 INFO [org.apache.qpid.client.AMQSession:296] (WorkerThread#0[127.0.0.1:58322]) Closing session: org.apache.qpid.client.AMQSession_0_10@73ce8065 2011-09-12 15:58:07,439 INFO [org.apache.qpid.client.AMQSession:296] (WorkManager(3)-1) Created session:org.apache.qpid.client.XASessionImpl@10b44b04 2011-09-12 15:58:07,993 INFO [org.apache.qpid.client.AMQSession:296] (WorkManager(3)-1) Prefetching delayed existing messages will not flow until requested via receive*() or setML(). 2011-09-12 15:58:08,054 WARN [org.apache.qpid.transport.SessionDelegate:352] (IoReceiver - mrg01.mw.lab.eng.bos.redhat.com/10.16.88.240:5672) CLOSED: [ssn:"7f195900-f2c3-442f-8e7f-69a318483b42"] 2011-09-12 15:58:08,161 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger:?] (WorkerThread#0[127.0.0.1:58322]) TransactionReaper::remove ( BasicAction: 7f000001:d9f1:4e6e0fcf:69 status: ActionStatus.COMMITTED ) On Qpid broker the logging is enabled too 2011-09-12 09:53:31 trace SENT [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {ConnectionStartBody: server-properties={qpid.federation_tag:V2:36:str16(b4540dbe-9c8f-455b-97f6-40bdb4962cb5)}; mechanisms=str16{V2:9:str16(ANONYMOUS), V2:5:str16(PLAIN)}; locales=str16{V2:5:str16(en_US)}; }] 2011-09-12 09:53:31 trace RECV [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {ConnectionStartOkBody: client-properties={clientName:V2:21:str16(jpechane1315835882496),qpid.client_pid:F4:int32(30228),qpid.client_process:V2:16:str16(Qpid Java Client),qpid.session_flow:F4:int32(1)}; mechanism=PLAIN; response=xxxxxx; }] 2011-09-12 09:53:31 trace SENT [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {ConnectionTuneBody: channel-max=32767; max-frame-size=65535; heartbeat-min=0; heartbeat-max=120; }] 2011-09-12 09:53:31 trace RECV [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {ConnectionTuneOkBody: channel-max=32767; max-frame-size=65535; heartbeat=120; }] 2011-09-12 09:53:31 trace RECV [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {ConnectionOpenBody: virtual-host=test; insist=1; }] 2011-09-12 09:53:31 trace SENT [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {ConnectionOpenOkBody: known-hosts=str16{V2:26:str16(amqp:tcp:10.16.88.240:5672)}; }] 2011-09-12 09:53:31 trace RECV [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {SessionAttachBody: name=7f195900-f2c3-442f-8e7f-69a318483b42; }] 2011-09-12 09:53:31 debug Attached channel 0 to j2ee 2011-09-12 09:53:31 trace RECV [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {SessionRequestTimeoutBody: timeout=0; }] 2011-09-12 09:53:31 trace SENT [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {SessionAttachedBody: name=7f195900-f2c3-442f-8e7f-69a318483b42; }] 2011-09-12 09:53:31 trace SENT [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {SessionCommandPointBody: command-id=0; command-offset=0; }] 2011-09-12 09:53:31 trace SENT [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {SessionTimeoutBody: timeout=0; }] 2011-09-12 09:53:31 trace RECV [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {SessionCommandPointBody: command-id=0; command-offset=0; }] 2011-09-12 09:53:31 trace RECV [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {TxSelectBody: }] 2011-09-12 09:53:31 trace RECV [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {SessionFlushBody: completed=1; }] 2011-09-12 09:53:31 trace RECV [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {ExchangeBoundBody: exchange=jms_ee_mdb_mdb_sndQ_MDB_QUEUE; queue=jms_ee_mdb_mdb_sndQ_MDB_QUEUE; }] 2011-09-12 09:53:31 trace SENT [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {SessionCompletedBody: commands={ [0,0] }; timely-reply=1; }] 2011-09-12 09:53:31 trace SENT [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {ExecutionResultBody: command-id=1; value=\x07\x02\x01\x00; }] 2011-09-12 09:53:31 trace RECV [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {SessionKnownCompletedBody: commands={ [0,0] }; }] 2011-09-12 09:53:32 trace RECV [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {SessionCompletedBody: commands={ }; timely-reply=1; }] 2011-09-12 09:53:32 trace RECV [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {QueueQueryBody: queue=jms_ee_mdb_mdb_sndQ_MDB_QUEUE; }] 2011-09-12 09:53:32 trace SENT [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {SessionKnownCompletedBody: commands={ }; }] 2011-09-12 09:53:32 trace SENT [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {ExecutionResultBody: command-id=2; value=\x08\x01\xE3\x00\x1Djms_ee_mdb_mdb_sndQ_MDB_QUEUE\x00\x00\x00\x00\x04\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x07; }] 2011-09-12 09:53:32 trace RECV [10.16.88.240:5672-10.34.3.135:44845]: Frame[Bbe; channel=0; {MessageTransferBody: destination=; accept-mode=1; acquire-mode=0; }] 2011-09-12 09:53:32 trace RECV [10.16.88.240:5672-10.34.3.135:44845]: Frame[be; channel=0; header (675 bytes); properties={{MessageProperties: content-length=0; message-id=31d250f2-9f5c-314f-95a2-6ef6c06c85a0; content-type=text/plain; content-encoding=UTF-8; user-id=j2ee; application-headers={MessageType:V2:12:str16(BytesMessage),finder:V2:3:str16(cts),harnesshost:V2:9:str16(127.0.0.1),harnesslogport:V2:4:str16(2000),harnesslogtraceflag:V2:4:str16(true),jms_timeout:V2:4:str16(5000),namingServiceHost1:V2:9:str16(localhost),namingServiceHost2:V2:9:str16(localhost),namingServicePort1:V2:4:str16(3528),namingServicePort2:V2:4:str16(3700),password:V2:4:str16(j2ee),testName:V2:19:str16(mdbSendBytesMsgTest),test_classname:V2:46:str16(com.sun.ts.tests.jms.ee.mdb.mdb_sndQ.MDBClient),user:V2:4:str16(j2ee),wsdlRepository1:V2:85:str16(/home/jpechane/workspace/mrgjob/work/work/jboss-eap-5.1/jboss-as/server/cts/data/wsdl),wsdlRepository2:V2:71:str16(/home/jpechane/workspace/mrgjob/work/work/javaeetck/tmp/wsdlRepository2)}; }{DeliveryProperties: priority=4; delivery-mode=2; timestamp=1315835887359; exchange=; routing-key=jms_ee_mdb_mdb_sndQ_MDB_QUEUE; }}] 2011-09-12 09:53:32 trace RECV [10.16.88.240:5672-10.34.3.135:44845]: Frame[Ebe; channel=0; content (28 bytes) I want you to send a message] 2011-09-12 09:53:32 trace RECV [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {ExecutionSyncBody: }] 2011-09-12 09:53:32 trace SENT [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {SessionCompletedBody: commands={ [1,4] }; }] 2011-09-12 09:53:32 trace RECV [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {SessionRequestTimeoutBody: timeout=0; }] 2011-09-12 09:53:32 trace RECV [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {SessionDetachBody: name=7f195900-f2c3-442f-8e7f-69a318483b42; }] 2011-09-12 09:53:32 trace SENT [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {SessionTimeoutBody: timeout=0; }] 2011-09-12 09:53:32 trace SENT [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {SessionDetachedBody: name=7f195900-f2c3-442f-8e7f-69a318483b42; code=0; }] 2011-09-12 09:53:32 trace RECV [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {ConnectionCloseBody: reply-code=200; }] 2011-09-12 09:53:32 trace SENT [10.16.88.240:5672-10.34.3.135:44845]: Frame[BEbe; channel=0; {ConnectionCloseOkBody: }] We tried to create a simple reproducer using 2.x session bean but the message was delivered, see the appropriate logs 2011-09-13 10:16:19,176 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkerThread#0[127.0.0.1:50096]) TransactionReaper::insert ( BasicAction: 7f000001:99c0:4e6f1143:11 status: ActionStatus.RUNNING, 300 ) 2011-09-13 10:16:19,177 INFO [org.apache.qpid.client.AMQConnection] (WorkerThread#0[127.0.0.1:50096]) Connection:amqp://guest:********@client_id/test?sync_ack='true'&maxprefetch='0'&brokerlist='tcp://mrg01.mw.lab.eng.bos.redhat.com:5673'&sync_ack='true'&maxprefetch='0' 2011-09-13 10:16:19,177 INFO [org.apache.qpid.client.protocol.AMQProtocolSession] (WorkerThread#0[127.0.0.1:50096]) Using ProtocolVersion for Session:0-10 2011-09-13 10:16:19,177 INFO [org.apache.qpid.client.handler.ClientMethodDispatcherImpl] (WorkerThread#0[127.0.0.1:50096]) New Method Dispatcher:AMQProtocolSession[null] 2011-09-13 10:16:19,177 INFO [org.apache.qpid.client.AMQConnection] (WorkerThread#0[127.0.0.1:50096]) Connecting with ProtocolHandler Version:0-10 2011-09-13 10:16:19,867 INFO [org.apache.qpid.client.AMQConnection] (WorkerThread#0[127.0.0.1:50096]) Connected with ProtocolHandler Version:0-10 2011-09-13 10:16:19,867 INFO [org.apache.qpid.client.AMQSession] (WorkerThread#0[127.0.0.1:50096]) Created session:org.apache.qpid.client.XASessionImpl@c200ff6 2011-09-13 10:16:20,634 INFO [org.apache.qpid.client.BasicMessageProducer_0_10] (WorkerThread#0[127.0.0.1:50096]) MessageProducer org.apache.qpid.client.BasicMessageProducer_0_10@3f8703c7 using publish mode : ASYNC_PUBLISH_ALL 2011-09-13 10:16:20,639 INFO [STDOUT] (WorkerThread#0[127.0.0.1:50096]) message Hello! sent to MDB_QUEUE 2011-09-13 10:16:21,092 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkerThread#0[127.0.0.1:50096]) TransactionReaper::remove ( BasicAction: 7f000001:99c0:4e6f1143:11 status: ActionStatus.COMMITTED ) 2011-09-13 10:16:21,099 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkerThread#0[127.0.0.1:50096]) TransactionReaper::insert ( BasicAction: 7f000001:99c0:4e6f1143:16 status: ActionStatus.RUNNING, 300 ) 2011-09-13 10:16:21,100 DEBUG [org.jboss.ejb.StatelessSessionContainer] (WorkerThread#0[127.0.0.1:50096]) Useless invocation of remove() for stateless session bean 2011-09-13 10:16:21,100 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkerThread#0[127.0.0.1:50096]) TransactionReaper::remove ( BasicAction: 7f000001:99c0:4e6f1143:16 status: ActionStatus.COMMITTED ) 2011-09-13 04:13:13 trace RECV [10.16.88.240:5673-10.34.3.135:34096]: Frame[BEbe; channel=1; {DtxStartBody: xid={Xid: format=131075; global-id=1-7f000001:99c0:4e6f1143:18; branch-id=7f000001:99c0:4e6f1143:1a; }; }] 2011-09-13 04:13:13 trace SENT [10.16.88.240:5673-10.34.3.135:34096]: Frame[BEbe; channel=1; {ExecutionResultBody: command-id=9; value=\x06\x01\x01\x00\x00\x00; }] 2011-09-13 04:13:13 trace RECV [10.16.88.240:5673-10.34.3.135:34096]: Frame[BEbe; channel=1; {DtxSetTimeoutBody: xid={Xid: format=131075; global-id=1-7f000001:99c0:4e6f1143:18; branch-id=7f000001:99c0:4e6f1143:1a; }; timeout=300; }] 2011-09-13 04:13:13 trace RECV [10.16.88.240:5673-10.34.3.135:34096]: Frame[BEbe; channel=1; {ExecutionSyncBody: }] 2011-09-13 04:13:13 trace SENT [10.16.88.240:5673-10.34.3.135:34096]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [1,11] }; }] 2011-09-13 04:13:13 trace RECV [10.16.88.240:5673-10.34.3.135:34096]: Frame[BEbe; channel=1; {ExchangeBoundBody: exchange=jms_ee_mdb_mdb_sndQ_MDB_QUEUE; queue=jms_ee_mdb_mdb_sndQ_MDB_QUEUE; }] 2011-09-13 04:13:13 trace SENT [10.16.88.240:5673-10.34.3.135:34096]: Frame[BEbe; channel=1; {ExecutionResultBody: command-id=12; value=\x07\x02\x01\x00; }] 2011-09-13 04:13:14 trace RECV [10.16.88.240:5673-10.34.3.135:34096]: Frame[BEbe; channel=1; {QueueQueryBody: queue=jms_ee_mdb_mdb_sndQ_MDB_QUEUE; }] 2011-09-13 04:13:14 trace SENT [10.16.88.240:5673-10.34.3.135:34096]: Frame[BEbe; channel=1; {ExecutionResultBody: command-id=13; value=\x08\x01\xE3\x00\x1Djms_ee_mdb_mdb_sndQ_MDB_QUEUE\x00\x00\x00\x00\x04\x00\x00\x00\x00\x00\x00\x00\x01\x00\x00\x00\x00; }] 2011-09-13 04:13:14 trace RECV [10.16.88.240:5673-10.34.3.135:34096]: Frame[Bbe; channel=1; {MessageTransferBody: destination=; accept-mode=1; acquire-mode=0; }] 2011-09-13 04:13:14 trace RECV [10.16.88.240:5673-10.34.3.135:34096]: Frame[be; channel=1; header (133 bytes); properties={{MessageProperties: content-length=0; message-id=44f1e51e-5192-3af8-ac18-6e2f508d3bd0; content-type=text/plain; content-encoding=UTF-8; user-id=guest; application-headers={MessageType:V2:5:str16(svine)}; }{DeliveryProperties: priority=4; delivery-mode=2; timestamp=1315901868174; exchange=; routing-key=jms_ee_mdb_mdb_sndQ_MDB_QUEUE; }}] 2011-09-13 04:13:14 trace RECV [10.16.88.240:5673-10.34.3.135:34096]: Frame[Ebe; channel=1; content (6 bytes) Hello!] 2011-09-13 04:13:14 trace RECV [10.16.88.240:5673-10.34.3.135:34096]: Frame[BEbe; channel=1; {ExecutionSyncBody: }] 2011-09-13 04:13:14 trace SENT [10.16.88.240:5673-10.34.3.135:34096]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [1,15] }; }] 2011-09-13 04:13:14 trace RECV [10.16.88.240:5673-10.34.3.135:34096]: Frame[BEbe; channel=1; {DtxEndBody: xid={Xid: format=131075; global-id=1-7f000001:99c0:4e6f1143:18; branch-id=7f000001:99c0:4e6f1143:1a; }; }] 2011-09-13 04:13:14 trace SENT [10.16.88.240:5673-10.34.3.135:34096]: Frame[BEbe; channel=1; {ExecutionResultBody: command-id=16; value=\x06\x01\x01\x00\x00\x00; }] 2011-09-13 04:13:14 trace RECV [10.16.88.240:5673-10.34.3.135:34096]: Frame[BEbe; channel=1; {DtxCommitBody: xid={Xid: format=131075; global-id=1-7f000001:99c0:4e6f1143:18; branch-id=7f000001:99c0:4e6f1143:1a; }; one-phase=1; }] 2011-09-13 04:13:14 trace SENT [10.16.88.240:5673-10.34.3.135:34096]: Frame[BEbe; channel=1; {ExecutionResultBody: command-id=17; value=\x06\x01\x01\x00\x00\x00; }] As you can see there are missing DtxStartBody calls in case of TCKs (not speaking about other differences). Full logs and parts of test source code are in the attachment. This is the configuration of connection factory <jndi-name>QueueConnectionFactory</jndi-name> <rar-name>qpid-ra-0.10.rar</rar-name> <connection-definition> org.apache.qpid.ra.QpidRAConnectionFactory </connection-definition> <xa-transaction/> <config-property name="SessionDefaultType" type="java.lang.String">javax.jms.Queue</config-property> <config-property name="ConnectionURL" type="java.lang.String">amqp://guest:guest@/test?brokerlist='tcp://mrg01.mw.lab.eng.bos.redhat.com:5673'&sync_ack='true'&maxprefetch='0'</config-property> To sum-up - the client sent the message. Middleware reported message as successfully delivered but was lost on the broker
Created attachment 522886 [details] Logs and sources
Good analysis. ConnectionFactory definition looks fine as well. Since this is on the broker side, Gordon would probably be better able to help with this. However, a few thoughts. It is strange, as you observed, that in the case of the TCK/MDB test, no transaction seems to be started, even though the ejb descriptors clearly specify that they are required. The cases that a Broker will drop messages are: 1) If the destination or exchange doesn't exist 2) If the key/subject doesn't match any binding on the exchange 3) If the queue is full The one thing we might want to do is deploy everything and then run qpid-stat -q to make sure the destinations that the test expects to be there are actually being created correctly. But again, I agree that no transaction appears to have been started. The only thing I can think of is in the first case (MDB/TCK), there is only one resource and the transaction manager is optimizing the test to use local transactions. JBossTM will do this in the case that there is only one resource enlisted in the transaction as the two phase commit protocol would be unnecessary overhead. Are you running your test in the same instance as the TCK? There is a setting in the jbossts-properties.xml file that toggles the JBossTM to use two phase commit even in the case of one resource. The property is <property name="com.arjuna.ats.arjuna.coordinator.commitOnePhase" value="YES"/> A 'YES' value will tell the JBossTM to commit the one phase resource without the 2PC protocol. A 'NO' value will disable this and force the use of 2PC even in the case that there is only one resource. If you are testing recovery and using the file from the jca-xa-recovery project you may have this value set to NO. Can you verify this for me? That's the only thing I can think of at this point.
Hi, unfortunately messages were not dropped (at least officially). I asked one guy from MRG QE for a help and we identified that any condition for dropping was not satisfied and even the drop counter displays zero Exchanges exchange type dur bind msgIn msgOut msgDrop byteIn byteOut byteDrop ============================================================================================ amq.direct direct Y 3 1.34k 1.34k 0 178k 178k 0 amq.topic topic Y 1.48k 1.48k 1.11m 151 25.9k 20.4m 3.39k qmf.default.direct direct 3 217 217 0 13.4m 13.4m 0 amq.fanout fanout Y 0 0 0 0 0 0 0 amq.match headers Y 0 0 0 0 0 0 0 qmf.default.topic topic 3 154k 70 154k 537m 15.0k 537m qpid.management topic 6 126k 0 126k 142m 0 142m direct 1.52k 53.6k 53.6k 0 1.92m 1.92m 0 Bindings [jpechane@mrg01 ~]$ qpid-config queues -b |grep jms_ee_mdb_mdb_sndQ_MDB_QUEUE -A 10 Queue 'jms_ee_mdb_mdb_sndQ_MDB_QUEUE' bind [jms_ee_mdb_mdb_sndQ_MDB_QUEUE] => '' Queue 'jms_ee_mdb_mdb_sndToQueue_MDB_QUEUE' bind [jms_ee_mdb_mdb_sndToQueue_MDB_QUEUE] => '' Queue 'jms_ee_mdb_mdb_synchrec_MDB_QUEUE' bind [jms_ee_mdb_mdb_synchrec_MDB_QUEUE] => '' Queue 'jms_ee_mdb_xa_MDB_QUEUE_BMT' bind [jms_ee_mdb_xa_MDB_QUEUE_BMT] => '' Queue 'jms_ee_mdb_xa_MDB_QUEUE_CMT' bind [jms_ee_mdb_xa_MDB_QUEUE_CMT] => '' Queue 'mrg_mrg_jca_mdb_transactions_in' bind [mrg_mrg_jca_mdb_transactions_in] => '' [jpechane@mrg01 ~]$ The com.arjuna.ats.arjuna.coordinator.commitOnePhase optimization was enabled, so I turned it off and re-run the tests. Unfortunately with the same results
Cool. Thanks for doing both. I am going to loop Gordon in as this one is on the broker side at this point.
First broker trace in the description shows a local transaction enabled (TxSelect) but no commit. Hence when the session is detached, the transaction is aborted and the message sent under it is discarded.
I believe I see the issue. In QpidRALocalTransaction, on a commit we evaluate: try { if (_mc.getSession() != null && _mc.getSession().getTransacted()) { _mc.getSession().commit(); } } catch (JMSException e) { throw new ResourceException("Could not commit LocalTransaction", e); } finally { _mc.unlock(); } Obviously, in JCA the getTransacted() flag is going to return false, more to the point, we shouldn't really be using this flag at all to evaluate whether or not we should commit. Good catch. I will file a bug and link this one to the other as a dependency.
Created attachment 523844 [details] Logs with build from Sep 19th I tried to re-run tests with build from Sep 16th. The issue is still present. The log is attached.
Ok, I finally had a chance to go through this in more detail. I believe I see the issue. If you look at the mdb_sndQ_ejb.jar.jboss.xml descriptor for the test, notice the resource-ref for the connection factory in use: <resource-ref> <res-ref-name>jms/MyQueueConnectionFactory</res-ref-name> <jndi-name>jms/QueueConnectionFactory</jndi-name> </resource-ref> This is the connection factory that is being used in the MDBTest Session Bean . We can see from the startup EAP logs the following entry: 2011-09-12 15:57:36,617 INFO [org.jboss.resource.deployment.AdminObject:296] (main) Bound admin object 'org.apache.qpid.ra.admin.QpidConnectionFactoryProxy' at 'jms/QueueConnectionFactory' Note, this is NOT a JCA connection factory but a proxy which is meant to be used outside of the application server as per the README file. 'QpidConnectionFactoryProxy The QpidConnectionFactoryProxy allows for a non-JCA ConnectionFactory to be bound into the JNDI tree. This ConnectionFactory can in turn be used outside of the application server. Typically ConnectionFactory of this sort is used by Swing clients.' Note, the JNDI names are the same. So, in the MDB test when this CF is used: cf = (ConnectionFactory)context.lookup("java:comp/env/jms/MyQueueConnectionFactory"); what you are actually using is a non-XA connection factory that is not even JCA. A quick check in the JMX Console should reveal this. This would explain the lack of transactional support in the test, and as per Gordon's comments, why messages are never being delivered as a 'commit' command is never being sent since automatic transaction enlistment is not being invoked.
Hi, thanks for spotting this. I must be completely blind missing the prefix between jms/QueueConnectionFactory when I meant QueueConnectionFactory. It seems it is working now - I tried with one sample. I am closing the bug now and re-open if it happens again next time
Thanks for checking. No worries. It's very easy to miss actually, the TCK configuration leaves a lot to be desired and it's not trivial to sport config errors due to the XSLT process to configure etc.