ServiceBus over AMQP looses redelivered messages

Question

We have on-premise installation of ServiceBus. I noticed strange behavior when dealing with redelivery. I created sample application, see bellow. This application will post 5 messages to topic with persistent queue and than tries to read all the messages. For each message it will create new session and start/stop message delivery (the timeouts are needed for graceful start/stop of qpid background thread). I suppose that prefetch will make note read messages peek locked. I expect to eventually get all messages, but some messages are being lost. Max delivery count is set to 10. The queue was examined by Serviuce Bus Explorer, it is empty after the test and the missing messages are not in Dealetter queue.

The test used to manifest the behavior, this is not the way one should consume messages:

private static final long RECEIVE_TIMEOUT_MS = 5000;
private static final long SLEEP_BETWEEN_SESSIONS_MS = 1000;
private static final long SLEEP_PEEK_TIMEOUT_MS = 70000;
private static final int MAX_SUBSEQUENT_FAILURES = 3;
private static final int MESSAGES_TO_TEST = 5;

        // send some messages to empty queue
        for (int i = 0; i < MESSAGES_TO_TEST; i++) {
            testSendToTopic(connection, context, Integer.toString(i));
            Thread.sleep(SLEEP_BETWEEN_SESSIONS_MS);
        }

        // wait for message
        OUTER:
        for (int i = 0; i < MESSAGES_TO_TEST; i++) {
            Thread.sleep(SLEEP_BETWEEN_SESSIONS_MS);
            int subsequentFailures = 0;

            while (!testReceiveFromQueue(connection, context)) {
                log.info("Waiting for peek lock timeout");

                Thread.sleep(SLEEP_PEEK_TIMEOUT_MS);

                subsequentFailures++;
                if (subsequentFailures > MAX_SUBSEQUENT_FAILURES) {
                    log.info("Giving up");
                    break OUTER;
                }
            }
        }

This is log, message 1, 2 and 4 were lost:

    19:05:51,012 [      main] INFO  [Qpid] Message sent, id: 0
    19:05:52,039 [      main] INFO  [Qpid] Message sent, id: 1
    19:05:53,055 [      main] INFO  [Qpid] Message sent, id: 2
    19:05:54,074 [      main] INFO  [Qpid] Message sent, id: 3
    19:05:55,088 [      main] INFO  [Qpid] Message sent, id: 4
    19:05:57,131 [      main] INFO  [Qpid] Received message, id: 0, redelivered: false
    19:05:57,133 [      main] INFO  [Qpid] Message acknowledged
    19:06:03,342 [      main] INFO  [Qpid] Queue is empty
    19:06:03,345 [      main] INFO  [Qpid] Waiting for peek lock timeout
    19:07:13,358 [      main] INFO  [Qpid] Received message, id: 4, redelivered: true
    19:07:13,359 [      main] INFO  [Qpid] Message acknowledged
    19:07:19,367 [      main] INFO  [Qpid] Queue is empty
    19:07:19,370 [      main] INFO  [Qpid] Waiting for peek lock timeout
    19:08:34,379 [      main] INFO  [Qpid] Queue is empty
    19:08:34,381 [      main] INFO  [Qpid] Waiting for peek lock timeout
    19:09:49,400 [      main] INFO  [Qpid] Queue is empty
    19:09:49,402 [      main] INFO  [Qpid] Waiting for peek lock timeout
    19:11:04,417 [      main] INFO  [Qpid] Queue is empty
    19:11:04,419 [      main] INFO  [Qpid] Waiting for peek lock timeout
    19:12:14,423 [      main] INFO  [Qpid] Giving up

Missing methods (EDITED, simplified code):

static void testSendToTopic(Connection connection, Context context) throws JMSException,
        NamingException {
    Session session = null;
    MessageProducer messageProducer = null;
    try {
        session = connection.createSession(false/*transacted*/, Session.AUTO_ACKNOWLEDGE);

        Topic topic = (Topic) context.lookup("ORDER_HISTORY_TOPIC");
        messageProducer = session.createProducer(topic);
        TextMessage message = session.createTextMessage("Hello MS SB");
        message.setJMSDeliveryMode(DeliveryMode.PERSISTENT);
        messageProducer.send(message);
        log.info("Message sent");
    } finally {
        if (null != messageProducer)
            messageProducer.close();
        if (null != session)
            session.close();
    }
}

static boolean testReceiveFromQueue(Connection connection, Context context)
        throws JMSException,
        NamingException {
    Session session = null;
    MessageConsumer consumer = null;
    try {
        session = connection.createSession(false/*transacted*/, Session.CLIENT_ACKNOWLEDGE);

        Queue queue = (Queue) context.lookup("ORDER_HISTORY_QUEUE");
        consumer = session.createConsumer(queue);

        // start delivery of incoming messages, otherwise receiveXXX will not get any
        connection.start();

        // even when there are messages, receiveNoWait may return null
        Message message = consumer.receive(RECEIVE_TIMEOUT_MS);
        if (null == message) {
            log.info("Nothing to receive");

            return false;
        }

        log.info("Received message");

        // must be acknowledged before peek lock expires (see Lock Duration)
        // Until peek lock timeout the message is will not be delivered to other receivers
        // on the same subscription
        message.acknowledge();
        log.info("Acknowledged");

        return true;
    } finally {
        connection.stop();
        if (consumer != null)
            consumer.close();
        if (null != session)
            session.close();
    }
}

Answer 1

I tried your code. It seems that the Qpid client could ack multiple messages even if the app is only calling message.acknowledge() once. In the traces you can find the the following line which shows the client is accepting 3 messages:

SEND Disposition{role=receiver,first=0,last=2,settled=true,state=Accepted{}}

Complete traces:

SEND Begin{nextOutgoingId=0,incomingWindow=2048,outgoingWindow=2048,handleMax=4294967295}
SEND Attach{name=contoso/q1<-053e99d4-7581-46ef-bb8b-0988e408673d,handle=0,role=sender,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=053e99d4-7581-46ef-bb8b-0988e408673d,defaultOutcome=Accepted{},outcomes=[Lorg.apache.qpid.amqp_1_0.type.Symbol;@16374f1},target=Target{address=contoso/q1},initialDeliveryCount=0}
RECV Begin{remoteChannel=0,nextOutgoingId=1,incomingWindow=2048,outgoingWindow=2048,handleMax=7}
RECV Attach{name=contoso/q1<-053e99d4-7581-46ef-bb8b-0988e408673d,handle=0,role=receiver,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=053e99d4-7581-46ef-bb8b-0988e408673d,defaultOutcome=Accepted{},outcomes=[Lorg.apache.qpid.amqp_1_0.type.Symbol;@d91c60},target=Target{address=contoso/q1},maxMessageSize=262144,properties={com.microsoft:tracking-id=fd3059fb3fae4d34ab876a58e30bf88a_Gxctest1_Bxctest1;172:114:115}}
RECV Flow{nextIncomingId=0,incomingWindow=2048,nextOutgoingId=1,outgoingWindow=2048,handle=0,deliveryCount=0,linkCredit=50,available=0,echo=false}
SEND Transfer{handle=0,deliveryId=0,deliveryTag=0,messageFormat=0,settled=false}
RECV Disposition{role=receiver,first=0,settled=true,state=Accepted{}}
SEND Detach{handle=0}
RECV Detach{handle=0,closed=true}
SEND End{}
RECV End{}
SEND Begin{nextOutgoingId=0,incomingWindow=2048,outgoingWindow=2048,handleMax=4294967295}
SEND Attach{name=contoso/q1<-61cc0707-fa2b-449a-b23e-c10f94a07ea8,handle=0,role=sender,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=61cc0707-fa2b-449a-b23e-c10f94a07ea8,defaultOutcome=Accepted{},outcomes=[Lorg.apache.qpid.amqp_1_0.type.Symbol;@f75c3b},target=Target{address=contoso/q1},initialDeliveryCount=0}
RECV Begin{remoteChannel=0,nextOutgoingId=1,incomingWindow=2048,outgoingWindow=2048,handleMax=7}
RECV Attach{name=contoso/q1<-61cc0707-fa2b-449a-b23e-c10f94a07ea8,handle=0,role=receiver,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=61cc0707-fa2b-449a-b23e-c10f94a07ea8,defaultOutcome=Accepted{},outcomes=[Lorg.apache.qpid.amqp_1_0.type.Symbol;@1c85632},target=Target{address=contoso/q1},maxMessageSize=262144,properties={com.microsoft:tracking-id=fd3059fb3fae4d34ab876a58e30bf88a_Gxctest1_Bxctest1;172:116:117}}
RECV Flow{nextIncomingId=0,incomingWindow=2048,nextOutgoingId=1,outgoingWindow=2048,handle=0,deliveryCount=0,linkCredit=50,available=0,echo=false}
SEND Transfer{handle=0,deliveryId=0,deliveryTag=0,messageFormat=0,settled=false}
RECV Disposition{role=receiver,first=0,settled=true,state=Accepted{}}
SEND Detach{handle=0}
RECV Detach{handle=0,closed=true}
SEND End{}
RECV End{}
SEND Begin{nextOutgoingId=0,incomingWindow=2048,outgoingWindow=2048,handleMax=4294967295}
SEND Attach{name=contoso/q1<-a351fac2-9837-42b4-88ac-7da4f8edd4f3,handle=0,role=sender,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=a351fac2-9837-42b4-88ac-7da4f8edd4f3,defaultOutcome=Accepted{},outcomes=[Lorg.apache.qpid.amqp_1_0.type.Symbol;@2d4e47},target=Target{address=contoso/q1},initialDeliveryCount=0}
RECV Begin{remoteChannel=0,nextOutgoingId=1,incomingWindow=2048,outgoingWindow=2048,handleMax=7}
RECV Attach{name=contoso/q1<-a351fac2-9837-42b4-88ac-7da4f8edd4f3,handle=0,role=receiver,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=a351fac2-9837-42b4-88ac-7da4f8edd4f3,defaultOutcome=Accepted{},outcomes=[Lorg.apache.qpid.amqp_1_0.type.Symbol;@6e4ecd},target=Target{address=contoso/q1},maxMessageSize=262144,properties={com.microsoft:tracking-id=fd3059fb3fae4d34ab876a58e30bf88a_Gxctest1_Bxctest1;172:118:119}}
RECV Flow{nextIncomingId=0,incomingWindow=2048,nextOutgoingId=1,outgoingWindow=2048,handle=0,deliveryCount=0,linkCredit=50,available=0,echo=false}
SEND Transfer{handle=0,deliveryId=0,deliveryTag=0,messageFormat=0,settled=false}
RECV Disposition{role=receiver,first=0,settled=true,state=Accepted{}}
SEND Detach{handle=0}
RECV Detach{handle=0,closed=true}
SEND End{}
RECV End{}
SEND Begin{nextOutgoingId=0,incomingWindow=2048,outgoingWindow=2048,handleMax=4294967295}
SEND Attach{name=contoso/q1<-1ad6b487-dac9-4042-9ff7-b334c52a2220,handle=0,role=sender,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=1ad6b487-dac9-4042-9ff7-b334c52a2220,defaultOutcome=Accepted{},outcomes=[Lorg.apache.qpid.amqp_1_0.type.Symbol;@eab576},target=Target{address=contoso/q1},initialDeliveryCount=0}
RECV Begin{remoteChannel=0,nextOutgoingId=1,incomingWindow=2048,outgoingWindow=2048,handleMax=7}
RECV Attach{name=contoso/q1<-1ad6b487-dac9-4042-9ff7-b334c52a2220,handle=0,role=receiver,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=1ad6b487-dac9-4042-9ff7-b334c52a2220,defaultOutcome=Accepted{},outcomes=[Lorg.apache.qpid.amqp_1_0.type.Symbol;@12f9712},target=Target{address=contoso/q1},maxMessageSize=262144,properties={com.microsoft:tracking-id=fd3059fb3fae4d34ab876a58e30bf88a_Gxctest1_Bxctest1;172:120:121}}
RECV Flow{nextIncomingId=0,incomingWindow=2048,nextOutgoingId=1,outgoingWindow=2048,handle=0,deliveryCount=0,linkCredit=50,available=0,echo=false}
SEND Transfer{handle=0,deliveryId=0,deliveryTag=0,messageFormat=0,settled=false}
RECV Disposition{role=receiver,first=0,settled=true,state=Accepted{}}
SEND Detach{handle=0}
RECV Detach{handle=0,closed=true}
SEND End{}
RECV End{}
SEND Begin{nextOutgoingId=0,incomingWindow=2048,outgoingWindow=2048,handleMax=4294967295}
SEND Attach{name=contoso/q1<-d36e273d-c72e-4639-8e03-88640b9dbc40,handle=0,role=sender,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=d36e273d-c72e-4639-8e03-88640b9dbc40,defaultOutcome=Accepted{},outcomes=[Lorg.apache.qpid.amqp_1_0.type.Symbol;@1a72b8a},target=Target{address=contoso/q1},initialDeliveryCount=0}
RECV Begin{remoteChannel=0,nextOutgoingId=1,incomingWindow=2048,outgoingWindow=2048,handleMax=7}
RECV Attach{name=contoso/q1<-d36e273d-c72e-4639-8e03-88640b9dbc40,handle=0,role=receiver,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=d36e273d-c72e-4639-8e03-88640b9dbc40,defaultOutcome=Accepted{},outcomes=[Lorg.apache.qpid.amqp_1_0.type.Symbol;@1b7c21},target=Target{address=contoso/q1},maxMessageSize=262144,properties={com.microsoft:tracking-id=fd3059fb3fae4d34ab876a58e30bf88a_Gxctest1_Bxctest1;172:122:123}}
RECV Flow{nextIncomingId=0,incomingWindow=2048,nextOutgoingId=1,outgoingWindow=2048,handle=0,deliveryCount=0,linkCredit=50,available=0,echo=false}
SEND Transfer{handle=0,deliveryId=0,deliveryTag=0,messageFormat=0,settled=false}
RECV Disposition{role=receiver,first=0,settled=true,state=Accepted{}}
SEND Detach{handle=0}
RECV Detach{handle=0,closed=true}
SEND End{}
RECV End{}
SEND Begin{nextOutgoingId=0,incomingWindow=2048,outgoingWindow=2048,handleMax=4294967295}
SEND Attach{name=contoso/q1-> (e488fc54-63a4-40ba-b3c4-e73788900a3e),handle=0,role=receiver,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=contoso/q1,durable=none,expiryPolicy=link-detach},target=Target{}}
RECV Begin{remoteChannel=0,nextOutgoingId=1,incomingWindow=2048,outgoingWindow=2048,handleMax=7}
RECV Attach{name=contoso/q1-> (e488fc54-63a4-40ba-b3c4-e73788900a3e),handle=0,role=sender,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=contoso/q1,durable=none,expiryPolicy=link-detach},target=Target{},initialDeliveryCount=0,maxMessageSize=262144,properties={com.microsoft:tracking-id=fd3059fb3fae4d34ab876a58e30bf88a_Gxctest1_Bxctest1;172:124:125}}
SEND Flow{nextIncomingId=1,incomingWindow=2048,nextOutgoingId=0,outgoingWindow=2048,handle=0,deliveryCount=0,linkCredit=100,drain=false,echo=false}
RECV Transfer{handle=0,deliveryId=0,deliveryTag=\xc7h\xf5C\xe2\x8d\xedM\xba+6\xf1\x12?\x07\x1f,messageFormat=0,more=false,batchable=true}
Received message
RECV Transfer{handle=0,deliveryId=1,deliveryTag=*\xaaK\xba\xbf\x8fjD\xb2\xca,\xf8e/\x97H,messageFormat=0,more=false,batchable=true}
Acknowledged
SEND Disposition{role=receiver,first=0,last=0,settled=true,state=Accepted{}}
SEND Detach{handle=0,closed=true}
SEND Disposition{role=receiver,first=1,last=1,settled=true,state=Released{}}
RECV Transfer{handle=0,deliveryId=2,deliveryTag=gz\x10e\xb2\xff\x9fJ\xb9c+ig\xcf\x1eq,messageFormat=0,more=false,batchable=true}
RECV Transfer{handle=0,deliveryId=3,deliveryTag=\x92\x80\xb3\x96R*\x0eI\x8cE$\xb8#\x9eY@,messageFormat=0,more=false,batchable=true}
RECV Transfer{handle=0,deliveryId=4,deliveryTag=-\xc6p\xf7^\x0f5K\x844yF\x13\x1eGg,messageFormat=0,more=false,batchable=true}
RECV Detach{handle=0,closed=true}
SEND Disposition{role=receiver,first=2,last=2,settled=true,state=Released{}}
SEND Disposition{role=receiver,first=3,last=3,settled=true,state=Released{}}
SEND Disposition{role=receiver,first=4,last=4,settled=true,state=Released{}}
SEND End{}
RECV End{}
SEND Begin{nextOutgoingId=0,incomingWindow=2048,outgoingWindow=2048,handleMax=4294967295}
SEND Attach{name=contoso/q1-> (e70c21b2-4c26-4a81-ad58-6b1c6c8d03b8),handle=0,role=receiver,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=contoso/q1,durable=none,expiryPolicy=link-detach},target=Target{}}
RECV Begin{remoteChannel=0,nextOutgoingId=1,incomingWindow=2048,outgoingWindow=2048,handleMax=7}
RECV Attach{name=contoso/q1-> (e70c21b2-4c26-4a81-ad58-6b1c6c8d03b8),handle=0,role=sender,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=contoso/q1,durable=none,expiryPolicy=link-detach},target=Target{},initialDeliveryCount=0,maxMessageSize=262144,properties={com.microsoft:tracking-id=fd3059fb3fae4d34ab876a58e30bf88a_Gxctest1_Bxctest1;172:126:127}}
SEND Flow{nextIncomingId=1,incomingWindow=2048,nextOutgoingId=0,outgoingWindow=2048,handle=0,deliveryCount=0,linkCredit=100,drain=false,echo=false}
Nothing to receive
SEND Detach{handle=0,closed=true}
RECV Detach{handle=0,closed=true}
Waiting for peek lock timeout
SEND End{}
RECV End{}
SEND Begin{nextOutgoingId=0,incomingWindow=2048,outgoingWindow=2048,handleMax=4294967295}
SEND Attach{name=contoso/q1-> (6e67a1ae-d956-4c7e-b4e8-f021e6109d95),handle=0,role=receiver,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=contoso/q1,durable=none,expiryPolicy=link-detach},target=Target{}}
RECV Begin{remoteChannel=0,nextOutgoingId=1,incomingWindow=2048,outgoingWindow=2048,handleMax=7}
RECV Attach{name=contoso/q1-> (6e67a1ae-d956-4c7e-b4e8-f021e6109d95),handle=0,role=sender,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=contoso/q1,durable=none,expiryPolicy=link-detach},target=Target{},initialDeliveryCount=0,maxMessageSize=262144,properties={com.microsoft:tracking-id=fd3059fb3fae4d34ab876a58e30bf88a_Gxctest1_Bxctest1;172:128:129}}
SEND Flow{nextIncomingId=1,incomingWindow=2048,nextOutgoingId=0,outgoingWindow=2048,handle=0,deliveryCount=0,linkCredit=100,drain=false,echo=false}
RECV Transfer{handle=0,deliveryId=0,deliveryTag=\xc4\xa02\xd4k\x1e\xf6N\x82\xd4dFA\xc5\xb4\xe8,messageFormat=0,more=false,batchable=true}
Received message
Acknowledged
SEND Disposition{role=receiver,first=0,last=0,settled=true,state=Accepted{}}
RECV Transfer{handle=0,deliveryId=1,deliveryTag=\x1d\xfd\xff\xa9\xae\xb0\xf5N\xa9\xa9n\xd9\x84\xd8\xf2\x05,messageFormat=0,more=false,batchable=true}
SEND Detach{handle=0,closed=true}
SEND Disposition{role=receiver,first=1,last=1,settled=true,state=Released{}}
RECV Transfer{handle=0,deliveryId=2,deliveryTag=?1r\x0aY\x84\xf5H\x8b^\x0fp\x9b\x9a\xe2h,messageFormat=0,more=false,batchable=true}
SEND Disposition{role=receiver,first=2,last=2,settled=true,state=Released{}}
RECV Transfer{handle=0,deliveryId=3,deliveryTag=\xf9^\x84\x95\xbd;\x1aJ\x91\xf1H\xaeL\x080\xef,messageFormat=0,more=false,batchable=true}
SEND Disposition{role=receiver,first=3,last=3,settled=true,state=Released{}}
RECV Detach{handle=0,closed=true}
SEND End{}
RECV End{}
SEND Begin{nextOutgoingId=0,incomingWindow=2048,outgoingWindow=2048,handleMax=4294967295}
SEND Attach{name=contoso/q1-> (32d1f566-c055-4955-9c13-634f02e9f6eb),handle=0,role=receiver,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=contoso/q1,durable=none,expiryPolicy=link-detach},target=Target{}}
RECV Begin{remoteChannel=0,nextOutgoingId=1,incomingWindow=2048,outgoingWindow=2048,handleMax=7}
RECV Attach{name=contoso/q1-> (32d1f566-c055-4955-9c13-634f02e9f6eb),handle=0,role=sender,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=contoso/q1,durable=none,expiryPolicy=link-detach},target=Target{},initialDeliveryCount=0,maxMessageSize=262144,properties={com.microsoft:tracking-id=fd3059fb3fae4d34ab876a58e30bf88a_Gxctest1_Bxctest1;172:130:131}}
SEND Flow{nextIncomingId=1,incomingWindow=2048,nextOutgoingId=0,outgoingWindow=2048,handle=0,deliveryCount=0,linkCredit=100,drain=false,echo=false}
Nothing to receive
SEND Detach{handle=0,closed=true}
RECV Detach{handle=0,closed=true}
Waiting for peek lock timeout
SEND End{}
RECV End{}
SEND Begin{nextOutgoingId=0,incomingWindow=2048,outgoingWindow=2048,handleMax=4294967295}
SEND Attach{name=contoso/q1-> (46e009c6-0365-4249-be01-9a90d0c6f4cc),handle=0,role=receiver,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=contoso/q1,durable=none,expiryPolicy=link-detach},target=Target{}}
RECV Begin{remoteChannel=0,nextOutgoingId=1,incomingWindow=2048,outgoingWindow=2048,handleMax=7}
RECV Attach{name=contoso/q1-> (46e009c6-0365-4249-be01-9a90d0c6f4cc),handle=0,role=sender,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=contoso/q1,durable=none,expiryPolicy=link-detach},target=Target{},initialDeliveryCount=0,maxMessageSize=262144,properties={com.microsoft:tracking-id=fd3059fb3fae4d34ab876a58e30bf88a_Gxctest1_Bxctest1;172:132:133}}
SEND Flow{nextIncomingId=1,incomingWindow=2048,nextOutgoingId=0,outgoingWindow=2048,handle=0,deliveryCount=0,linkCredit=100,drain=false,echo=false}
RECV Transfer{handle=0,deliveryId=0,deliveryTag=..:\xe5\x94{\xadA\xa5\xa5\x12\xb10K\x94D,messageFormat=0,more=false,batchable=true}
RECV Transfer{handle=0,deliveryId=1,deliveryTag={\x9c\xc5\xba@\xeaqD\x9f\xc6y\xa4\x04\xa0\xb0d,messageFormat=0,more=false,batchable=true}
RECV Transfer{handle=0,deliveryId=2,deliveryTag=\xe1\xa7\xf4-K\xb36K\xbf\xec\xbc\x1f\xb6\xf9h\x9b,messageFormat=0,more=false,batchable=true}
Received message
Acknowledged
SEND Disposition{role=receiver,first=0,last=2,settled=true,state=Accepted{}}
SEND Detach{handle=0,closed=true}
RECV Detach{handle=0,closed=true}
SEND End{}
RECV End{}
SEND Begin{nextOutgoingId=0,incomingWindow=2048,outgoingWindow=2048,handleMax=4294967295}
SEND Attach{name=contoso/q1-> (3893f561-682f-48e4-9416-dc452668e6df),handle=0,role=receiver,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=contoso/q1,durable=none,expiryPolicy=link-detach},target=Target{}}
RECV Begin{remoteChannel=0,nextOutgoingId=1,incomingWindow=2048,outgoingWindow=2048,handleMax=7}
RECV Attach{name=contoso/q1-> (3893f561-682f-48e4-9416-dc452668e6df),handle=0,role=sender,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=contoso/q1,durable=none,expiryPolicy=link-detach},target=Target{},initialDeliveryCount=0,maxMessageSize=262144,properties={com.microsoft:tracking-id=fd3059fb3fae4d34ab876a58e30bf88a_Gxctest1_Bxctest1;172:134:135}}
SEND Flow{nextIncomingId=1,incomingWindow=2048,nextOutgoingId=0,outgoingWindow=2048,handle=0,deliveryCount=0,linkCredit=100,drain=false,echo=false}
Nothing to receive
SEND Detach{handle=0,closed=true}
RECV Detach{handle=0,closed=true}
Waiting for peek lock timeout
SEND End{}
RECV End{}
SEND Begin{nextOutgoingId=0,incomingWindow=2048,outgoingWindow=2048,handleMax=4294967295}
SEND Attach{name=contoso/q1-> (7b99ef20-95c8-4320-af84-1d1389472eb5),handle=0,role=receiver,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=contoso/q1,durable=none,expiryPolicy=link-detach},target=Target{}}
RECV Begin{remoteChannel=0,nextOutgoingId=1,incomingWindow=2048,outgoingWindow=2048,handleMax=7}
RECV Attach{name=contoso/q1-> (7b99ef20-95c8-4320-af84-1d1389472eb5),handle=0,role=sender,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=contoso/q1,durable=none,expiryPolicy=link-detach},target=Target{},initialDeliveryCount=0,maxMessageSize=262144,properties={com.microsoft:tracking-id=fd3059fb3fae4d34ab876a58e30bf88a_Gxctest1_Bxctest1;172:136:137}}
SEND Flow{nextIncomingId=1,incomingWindow=2048,nextOutgoingId=0,outgoingWindow=2048,handle=0,deliveryCount=0,linkCredit=100,drain=false,echo=false}
Nothing to receive
SEND Detach{handle=0,closed=true}
RECV Detach{handle=0,closed=true}
Waiting for peek lock timeout
SEND End{}
RECV End{}
SEND Begin{nextOutgoingId=0,incomingWindow=2048,outgoingWindow=2048,handleMax=4294967295}
SEND Attach{name=contoso/q1-> (3c8b90d9-438e-4b32-bc54-5c90e4b9ef87),handle=0,role=receiver,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=contoso/q1,durable=none,expiryPolicy=link-detach},target=Target{}}
RECV Begin{remoteChannel=0,nextOutgoingId=1,incomingWindow=2048,outgoingWindow=2048,handleMax=7}
RECV Attach{name=contoso/q1-> (3c8b90d9-438e-4b32-bc54-5c90e4b9ef87),handle=0,role=sender,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=contoso/q1,durable=none,expiryPolicy=link-detach},target=Target{},initialDeliveryCount=0,maxMessageSize=262144,properties={com.microsoft:tracking-id=fd3059fb3fae4d34ab876a58e30bf88a_Gxctest1_Bxctest1;172:138:139}}
SEND Flow{nextIncomingId=1,incomingWindow=2048,nextOutgoingId=0,outgoingWindow=2048,handle=0,deliveryCount=0,linkCredit=100,drain=false,echo=false}
Nothing to receive
SEND Detach{handle=0,closed=true}
RECV Detach{handle=0,closed=true}
Waiting for peek lock timeout
SEND End{}
RECV End{}
SEND Begin{nextOutgoingId=0,incomingWindow=2048,outgoingWindow=2048,handleMax=4294967295}
SEND Attach{name=contoso/q1-> (e8bbbbee-8727-448b-a753-cc43d43870ac),handle=0,role=receiver,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=contoso/q1,durable=none,expiryPolicy=link-detach},target=Target{}}
RECV Begin{remoteChannel=0,nextOutgoingId=1,incomingWindow=2048,outgoingWindow=2048,handleMax=7}
RECV Attach{name=contoso/q1-> (e8bbbbee-8727-448b-a753-cc43d43870ac),handle=0,role=sender,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=contoso/q1,durable=none,expiryPolicy=link-detach},target=Target{},initialDeliveryCount=0,maxMessageSize=262144,properties={com.microsoft:tracking-id=fd3059fb3fae4d34ab876a58e30bf88a_Gxctest1_Bxctest1;172:140:141}}
SEND Flow{nextIncomingId=1,incomingWindow=2048,nextOutgoingId=0,outgoingWindow=2048,handle=0,deliveryCount=0,linkCredit=100,drain=false,echo=false}
Nothing to receive
SEND Detach{handle=0,closed=true}
RECV Detach{handle=0,closed=true}
Waiting for peek lock timeout
SEND End{}
RECV End{}
Giving up

Thanks, Xin

Answer 2

Fixed in QPID trunk, thanks Rob, https://issues.apache.org/jira/browse/QPID-5570