Bug 737880 - JMS/MDB TCK does not pass due to issues with sending test messages
Summary: JMS/MDB TCK does not pass due to issues with sending test messages
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Red Hat Enterprise MRG
Classification: Red Hat
Component: qpid-jca
Version: 2.0
Hardware: Unspecified
OS: Unspecified
unspecified
urgent
Target Milestone: 2.0.4
: ---
Assignee: Weston M. Price
QA Contact: MRG Quality Engineering
URL:
Whiteboard:
Depends On: 738316
Blocks:
TreeView+ depends on / blocked
 
Reported: 2011-09-13 10:25 UTC by Jiri Pechanec
Modified: 2016-02-22 00:59 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2011-09-22 12:45:25 UTC


Attachments (Terms of Use)
Logs and sources (785.57 KB, application/x-gzip)
2011-09-13 10:26 UTC, Jiri Pechanec
no flags Details
Logs with build from Sep 19th (22.54 KB, application/x-gzip)
2011-09-19 14:11 UTC, Jiri Pechanec
no flags Details

Description Jiri Pechanec 2011-09-13 10:25:44 UTC
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@QPID.7f195900-f2c3-442f-8e7f-69a318483b42
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'&amp;sync_ack='true'&amp;maxprefetch='0'</config-property>


To sum-up - the client sent the message. Middleware reported message as successfully delivered but was lost on the broker

Comment 1 Jiri Pechanec 2011-09-13 10:26:42 UTC
Created attachment 522886 [details]
Logs and sources

Comment 2 Weston M. Price 2011-09-13 19:49:35 UTC
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.

Comment 3 Jiri Pechanec 2011-09-14 06:26:56 UTC
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

Comment 4 Weston M. Price 2011-09-14 12:13:40 UTC
Cool. Thanks for doing both. I am going to loop Gordon in as this one is on the broker side at this point.

Comment 5 Gordon Sim 2011-09-14 12:22:40 UTC
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.

Comment 6 Weston M. Price 2011-09-14 13:10:06 UTC
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.

Comment 7 Jiri Pechanec 2011-09-19 14:11:32 UTC
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.

Comment 8 Weston M. Price 2011-09-21 23:18:56 UTC
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.

Comment 9 Jiri Pechanec 2011-09-22 12:45:25 UTC
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

Comment 10 Weston M. Price 2011-09-22 12:51:14 UTC
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.


Note You need to log in before you can comment on or make changes to this bug.