Created attachment 476601 [details]
Full broker trace for this bug

When sending large (megabyte-sized) messages, the JMS client times out after the transfer of the first message. Examination of the store shows that only the first message was written. The producer appears to be stuck  in a loop which occurs after the first message is sent in which the session is being repeatedly flushed.

This was tested on mrg42 and is 100% reproducible. This problem appears to affect the durable test only.

The broker was started as follows:
./qpidd --auth no --load-module /home/kpvdr/mrg/store/lib/.libs/msgstore.so --data-dirum-jfiles 32 --jfile-size-pgs 96 --log-enable trace+ -m no >& broker.log

The client was started as follows (modified in tools/bin/perf_report.sh):

WARMUP_COUNT=1000
TINY_MSG_CNT=40
MSG_SIZE_2M=2097152

SUB_BASE_OPTS="-Damqj.tcpNoDelay=true"
PUB_BASE_OPTS="-Damqj.tcpNoDelay=true -Dwarmup_count=$WARMUP_COUNT"
DURABLE="-Ddurable=true"

...

# Test 24 2M Msg Durable
run_testcase "Msg_2M_Dura" \
             "$SUB_BASE_OPTS $DURABLE" \
             "$PUB_BASE_OPTS $DURABLE -Dmsg_count=$TINY_MSG_COUNT -Dmsg_size=$MSG_SIZE_2M"


The client waits for 60 secs, then times out with:

Error when running test Exception when sending message
javax.jms.JMSException: Exception when sending message
	at org.apache.qpid.client.BasicMessageProducer_0_10.sendMessage(BasicMessageProducer_0_10.java:230)
	at org.apache.qpid.client.BasicMessageProducer.sendImpl(BasicMessageProducer.java:501)
	at org.apache.qpid.client.BasicMessageProducer.sendImpl(BasicMessageProducer.java:456)
	at org.apache.qpid.client.BasicMessageProducer.send(BasicMessageProducer.java:283)
	at org.apache.qpid.tools.PerfProducer.warmup(PerfProducer.java:146)
	at org.apache.qpid.tools.PerfProducer.test(PerfProducer.java:228)
	at org.apache.qpid.tools.PerfProducer$1.run(PerfProducer.java:247)
	at java.lang.Thread.run(Thread.java:636)
Caused by: org.apache.qpid.transport.SessionException: timed out waiting for completion
	at org.apache.qpid.transport.Session.invoke(Session.java:646)
	at org.apache.qpid.transport.Session.invoke(Session.java:528)
	at org.apache.qpid.transport.SessionInvoker.messageTransfer(SessionInvoker.java:96)
	at org.apache.qpid.client.BasicMessageProducer_0_10.sendMessage(BasicMessageProducer_0_10.java:216)
	... 7 more


If run against a broker with tracing on, the following is seen.

Summary:
1. 08:35:23 Initialization of producer connection
2. 08:35:23 Start of message transfer from producer
3. 08:35:23 End of message transfer from producer
4. 08:35:23 Start of message transfer to consumer
5. 08:35:23 End of message transfer to consumer
6. 08:35:23 Start of SessionFlush/SessionCompleted/SessionKnownCompleted loop
7. 08:36:24 Producer session disconnects approx 60 sec later

...

2011-02-02 08:35:23 debug RECV [127.0.0.1:45377] INIT(0-10)
2011-02-02 08:35:23 debug SASL: No Authentication Performed
2011-02-02 08:35:23 trace SENT 127.0.0.1:45377 INIT(0-10)
2011-02-02 08:35:23 trace SENT [127.0.0.1:45377]: Frame[BEbe; channel=0; {ConnectionStartBody: server-properties={qpid.federation_tag:V2:36:str16(7c2e4012-c58c-4cc0-8bef-e1f14ed40914)}; mechanisms=str16{V2:9:str16(ANONYMOUS), V2:5:str16(PLAIN)}; locales=str16{V2:5:str16(en_US)}; }]
2011-02-02 08:35:23 trace RECV [127.0.0.1:45377]: Frame[BEbe; channel=0; {ConnectionStartOkBody: client-properties={clientName:V2:8:str16(clientid),qpid.client_pid:F4:int32(2423),qpid.client_process:V2:16:str16(Qpid Java Client),qpid.session_flow:F4:int32(1)}; mechanism=PLAIN; response=xxxxxx; }]
2011-02-02 08:35:23 trace SENT [127.0.0.1:45377]: Frame[BEbe; channel=0; {ConnectionTuneBody: channel-max=32767; max-frame-size=65535; heartbeat-min=0; heartbeat-max=120; }]
2011-02-02 08:35:23 trace RECV [127.0.0.1:45377]: Frame[BEbe; channel=0; {ConnectionTuneOkBody: channel-max=32767; max-frame-size=65535; heartbeat=120; }]
2011-02-02 08:35:23 trace RECV [127.0.0.1:45377]: Frame[BEbe; channel=0; {ConnectionOpenBody: virtual-host=testpath; insist=1; }]
2011-02-02 08:35:23 trace SENT [127.0.0.1:45377]: Frame[BEbe; channel=0; {ConnectionOpenOkBody: known-hosts=str16{V2:26:str16(amqp:tcp:10.16.44.247:5672)}; }]
2011-02-02 08:35:23 trace RECV [127.0.0.1:45377]: Frame[BEbe; channel=1; {SessionAttachBody: name=f810a541-1a55-409a-ad63-3e2662e84271; }]
2011-02-02 08:35:23 debug SessionState::SessionState guest: 0x7f5d40084380
2011-02-02 08:35:23 debug guest: attached on broker.
2011-02-02 08:35:23 debug Attached channel 1 to guest
2011-02-02 08:35:23 debug guest: ready to send, activating output.
2011-02-02 08:35:23 trace SENT [127.0.0.1:45377]: Frame[BEbe; channel=1; {SessionAttachedBody: name=f810a541-1a55-409a-ad63-3e2662e84271; }]

...

2011-02-02 08:35:23 trace RECV [127.0.0.1:45377]: Frame[Bbe; channel=1; {MessageTransferBody: destination=amq.direct; accept-mode=1; acquire-mode=0; }]
2011-02-02 08:35:23 trace guest: recv cmd 15: {MessageTransferBody: destination=amq.direct; accept-mode=1; acquire-mode=0; }
2011-02-02 08:35:23 trace RECV [127.0.0.1:45377]: Frame[be; channel=1; header (104 bytes); properties={{MessageProperties: content-length=0; message-id=2fefbb92-b857-3372-90aa-644cd8852def; content-type=application/octet-stream; user-id=guest; }{DeliveryProperties: priority=4; delivery-mode=2; timestamp=1296653723639; exchange=amq.direct; routing-key=testQueueD; }}]
2011-02-02 08:35:23 trace guest: recv cmd 15: header (104 bytes); properties={{MessageProperties: content-length=0; message-id=2fefbb92-b857-3372-90aa-644cd8852def; content-type=application/octet-stream; user-id=guest; }{DeliveryProperties: priority=4; delivery-mode=2; timestamp=1296653723639; exchange=amq.direct; routing-key=testQueueD; }}
2011-02-02 08:35:23 trace RECV [127.0.0.1:45377]: Frame[Eb; channel=1; content (65523 bytes) Qpid Test MessageQpid Test Messa...]
2011-02-02 08:35:23 trace guest: recv cmd 15: content (65523 bytes) Qpid Test MessageQpid Test Messa...
2011-02-02 08:35:23 trace RECV [127.0.0.1:45377]: Frame[E; channel=1; content (65523 bytes) Test MessageQpid Test MessageQpi...]
2011-02-02 08:35:23 trace guest: recv cmd 15: content (65523 bytes) Test MessageQpid Test MessageQpi...

... (transfer of message from producer to broker takes place) ...

2011-02-02 08:35:23 trace RECV [127.0.0.1:45377]: Frame[E; channel=1; content (65523 bytes) id Test MessageQpid Test Message...]
2011-02-02 08:35:23 trace guest: recv cmd 15: content (65523 bytes) id Test MessageQpid Test Message...
2011-02-02 08:35:23 trace RECV [127.0.0.1:45377]: Frame[Ee; channel=1; content (416 bytes) st MessageQpid Test MessageQpid ...]
2011-02-02 08:35:23 trace guest: recv cmd 15: content (416 bytes) st MessageQpid Test MessageQpid ...
2011-02-02 08:35:23 debug Message 0x7f5d40085a90 enqueued on testQueueD
2011-02-02 08:35:23 trace RECV [127.0.0.1:45377]: Frame[BEbe; channel=1; {SessionFlushBody: completed=1; }]
2011-02-02 08:35:23 debug Sufficient credit for 1 on guest, have bytes: 4294967295 msgs: 500, need 2097256 bytes
2011-02-02 08:35:23 trace SENT [127.0.0.1:45377]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [1,14] }; timely-reply=1; }]
2011-02-02 08:35:23 debug Credit allocated for 1 on guest, was  bytes: 4294967295 msgs: 500 now bytes: 4294967295 msgs: 499

...

2011-02-02 08:35:23 trace SENT [127.0.0.1:45375]: Frame[Bbe; channel=1; {MessageTransferBody: destination=1; accept-mode=0; acquire-mode=0; }]
2011-02-02 08:35:23 trace SENT [127.0.0.1:45375]: Frame[be; channel=1; header (104 bytes); properties={{MessageProperties: content-length=0; message-id=2fefbb92-b857-3372-90aa-644cd8852def; content-type=application/octet-stream; user-id=guest; }{DeliveryProperties: priority=4; delivery-mode=2; timestamp=1296653723639; exchange=amq.direct; routing-key=testQueueD; }}]
2011-02-02 08:35:23 debug No messages to dispatch on queue 'testQueueD'
2011-02-02 08:35:23 trace SENT [127.0.0.1:45375]: Frame[Eb; channel=1; content (65523 bytes) Qpid Test MessageQpid Test Messa...]
2011-02-02 08:35:23 trace SENT [127.0.0.1:45375]: Frame[E; channel=1; content (65523 bytes) Test MessageQpid Test MessageQpi...]
2011-02-02 08:35:23 trace RECV [127.0.0.1:45375]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ }; }]
2011-02-02 08:35:23 trace SENT [127.0.0.1:45375]: Frame[E; channel=1; content (65523 bytes) MessageQpid Test MessageQpid Tes...]
2011-02-02 08:35:23 trace SENT [127.0.0.1:45375]: Frame[E; channel=1; content (65523 bytes) geQpid Test MessageQpid Test Mes...]

... (transfer of message to consumer takes place) ...

2011-02-02 08:35:23 trace SENT [127.0.0.1:45375]: Frame[E; channel=1; content (65523 bytes) id Test MessageQpid Test Message...]
2011-02-02 08:35:23 trace SENT [127.0.0.1:45375]: Frame[Ee; channel=1; content (416 bytes) st MessageQpid Test MessageQpid ...]
2011-02-02 08:35:23 trace RECV [127.0.0.1:45377]: Frame[BEbe; channel=1; {SessionFlushBody: completed=1; }]
2011-02-02 08:35:23 trace SENT [127.0.0.1:45377]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [1,14] }; timely-reply=1; }]
2011-02-02 08:35:23 trace RECV [127.0.0.1:45377]: Frame[BEbe; channel=1; {SessionKnownCompletedBody: commands={ }; }]
2011-02-02 08:35:23 debug guest: receiver known completed: { } unknown: { [1,14] }
2011-02-02 08:35:23 trace RECV [127.0.0.1:45375]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ }; timely-reply=1; }]
2011-02-02 08:35:23 trace SENT [127.0.0.1:45375]: Frame[BEbe; channel=1; {SessionKnownCompletedBody: commands={ }; }]
2011-02-02 08:35:23 trace RECV [127.0.0.1:45377]: Frame[BEbe; channel=1; {SessionFlushBody: completed=1; }]
2011-02-02 08:35:23 trace SENT [127.0.0.1:45377]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [1,14] }; timely-reply=1; }]
2011-02-02 08:35:23 trace RECV [127.0.0.1:45377]: Frame[BEbe; channel=1; {SessionKnownCompletedBody: commands={ }; }]
2011-02-02 08:35:23 debug guest: receiver known completed: { } unknown: { [1,14] }
2011-02-02 08:35:23 trace RECV [127.0.0.1:45377]: Frame[BEbe; channel=1; {SessionFlushBody: completed=1; }]
2011-02-02 08:35:23 trace SENT [127.0.0.1:45377]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [1,14] }; timely-reply=1; }]
2011-02-02 08:35:23 trace RECV [127.0.0.1:45377]: Frame[BEbe; channel=1; {SessionKnownCompletedBody: commands={ }; }]

... (60 seconds of sending the same sequence) ...

2011-02-02 08:36:23 debug guest: receiver known completed: { } unknown: { [1,14] }
2011-02-02 08:36:23 trace RECV [127.0.0.1:45377]: Frame[BEbe; channel=1; {SessionFlushBody: completed=1; }]
2011-02-02 08:36:23 trace SENT [127.0.0.1:45377]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [1,14] }; timely-reply=1; }]
2011-02-02 08:36:23 trace RECV [127.0.0.1:45377]: Frame[BEbe; channel=1; {SessionKnownCompletedBody: commands={ }; }]
2011-02-02 08:36:23 debug guest: receiver known completed: { } unknown: { [1,14] }
2011-02-02 08:36:23 trace RECV [127.0.0.1:45377]: Frame[BEbe; channel=1; {SessionFlushBody: completed=1; }]
2011-02-02 08:36:23 trace SENT [127.0.0.1:45377]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [1,14] }; timely-reply=1; }]
2011-02-02 08:36:23 trace RECV [127.0.0.1:45377]: Frame[BEbe; channel=1; {SessionKnownCompletedBody: commands={ }; }]
2011-02-02 08:36:23 debug guest: receiver known completed: { } unknown: { [1,14] }
2011-02-02 08:36:24 debug DISCONNECTED [127.0.0.1:45377]
2011-02-02 08:36:24 debug guest: detached on broker.
2011-02-02 08:36:24 debug Unbind key [TempQueuef1826c23-d86a-431c-a273-8c1c4de26e99] from queue TempQueuef1826c23-d86a-431c-a273-8c1c4de26e99
2011-02-02 08:36:24 debug Unbind key [TempQueuef1826c23-d86a-431c-a273-8c1c4de26e99] from queue TempQueuef1826c23-d86a-431c-a273-8c1c4de26e99