qpid-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Robbie Gemmell <robbie.gemm...@gmail.com>
Subject Re: Qpid JMS 0.3.0 "Holding message send until credit is available"
Date Fri, 26 Jun 2015 11:05:41 GMT
On 26 June 2015 at 02:16, acartcat <Cartwright_Andrew@cat.com> wrote:
> Robbie,
>     Yes we are seeing a failure in that the messages are not delivered.
> When talking to Azure Service Bus the process hangs on the first attempt of
> send.  From the log it looks like the send attempt happens before the
> receipt of a FLOW, is there some option I need to set to ensure this happens
> first?
> 2015-06-26 10:44:04,796 [dows.net:5671/]] - TRACE AmqpProvider
> - New Proton Event: LINK_INIT
> 2015-06-26 10:44:04,796 [dows.net:5671/]] - TRACE AmqpProvider
> - New Proton Event: LINK_LOCAL_OPEN
> 2015-06-26 10:44:04,796 [dows.net:5671/]] - TRACE AmqpProvider
> - New Proton Event: LINK_REMOTE_OPEN
> 2015-06-26 10:44:04,811 [dows.net:5671/]] - DEBUG AmqpAbstractResource
> - AmqpFixedProducer { ID:WIN81CLIENT-58486-1435279438889-0:1:1:1 } is now
> open:
> 2015-06-26 10:44:04,827 [dows.net:5671/]] - TRACE AmqpFixedProducer
> - Holding Message send until credit is available.
> 2015-06-26 10:44:05,124 [ntLoopGroup-2-1] - TRACE NettyTcpTransport
> - New data read: 35 bytes incoming: UnpooledHeapByteBuf(ridx: 0, widx: 35,
> cap: 69)
> 2015-06-26 10:44:05,124 [dows.net:5671/]] - INFO  BYTES
> - Recieved:
> 0000002302000001005313c0160b520143520170000007fe434370000003e843404240
> 2015-06-26 10:44:05,124 [dows.net:5671/]] - TRACE FRAMES
> - RECV: Flow{nextIncomingId=1, incomingWindow=0, nextOutgoingId=1,
> outgoingWindow=2046, handle=0, deliveryCount=0, linkCredit=1000,
> available=0, drain=false, echo=false, properties=null}
> 2015-06-26 10:44:05,124 [dows.net:5671/]] - TRACE AmqpProvider
> - New Proton Event: LINK_FLOW
> 2015-06-26 10:44:05,124 [dows.net:5671/]] - TRACE AmqpFixedProducer
> - Dispatching previously held send
> 2015-06-26 10:44:05,124 [dows.net:5671/]] - TRACE AmqpFixedProducer
> - Producer sending message: JmsOutboundMessageDispatch {dispatchId =
> ID:WIN81CLIENT-58486-1435279438889-0:1:1:1-1}
> 2015-06-26 10:44:57,343 [ntLoopGroup-2-1] - TRACE NettyTcpTransport
> - New data read: 8 bytes incoming: UnpooledHeapByteBuf(ridx: 0, widx: 8,
> cap: 37)
> 2015-06-26 10:44:57,343 [dows.net:5671/]] - INFO  BYTES
> - Recieved: 0000000802000000
> 2015-06-26 10:45:49,906 [ntLoopGroup-2-1] - TRACE NettyTcpTransport
> - New data read: 8 bytes incoming: UnpooledHeapByteBuf(ridx: 0, widx: 8,
> cap: 37)
> 2015-06-26 10:45:49,906 [dows.net:5671/]] - INFO  BYTES
> - Recieved: 0000000802000000
>
>
> Yet in the case of Windows Service Bus, which for our test is hosted in an
> Azure VM, we can successfully send 50 of 100 messages but then get into the
> same "no credit".  In this case the FLOW is received before the first
> attempted message send:
>
> 2015-06-26 11:06:07,387 [dapp.net:8671/]] - TRACE AmqpProvider
> - New Proton Event: LINK_INIT
> 2015-06-26 11:06:07,387 [dapp.net:8671/]] - TRACE AmqpProvider
> - New Proton Event: LINK_LOCAL_OPEN
> 2015-06-26 11:06:07,387 [dapp.net:8671/]] - TRACE AmqpProvider
> - New Proton Event: LINK_REMOTE_OPEN
> 2015-06-26 11:06:07,387 [dapp.net:8671/]] - DEBUG AmqpAbstractResource
> - AmqpFixedProducer { ID:WIN81CLIENT-58513-1435280763074-0:1:1:1 } is now
> open:
> 2015-06-26 11:06:07,387 [dapp.net:8671/]] - INFO  BYTES
> - Recieved: 0000001c02000001005313c00f0b5201435201434343523243404240
> 2015-06-26 11:06:07,387 [dapp.net:8671/]] - TRACE FRAMES
> - RECV: Flow{nextIncomingId=1, incomingWindow=0, nextOutgoingId=1,
> outgoingWindow=0, handle=0, deliveryCount=0, linkCredit=50, available=0,
> drain=false, echo=false, properties=null}
> 2015-06-26 11:06:07,387 [dapp.net:8671/]] - TRACE AmqpProvider
> - New Proton Event: LINK_FLOW
> 2015-06-26 11:06:07,402 [dapp.net:8671/]] - TRACE AmqpFixedProducer
> - Producer sending message: JmsOutboundMessageDispatch {dispatchId =
> ID:WIN81CLIENT-58513-1435280763074-0:1:1:1-1}
> 2015-06-26 11:06:07,418 [dapp.net:8671/]] - TRACE AmqpFixedProducer
> - Producer sending message: JmsOutboundMessageDispatch {dispatchId =
> ID:WIN81CLIENT-58513-1435280763074-0:1:1:1-2}
> Sent message with JMSMessageID =
> ID:WIN81CLIENT-58513-1435280763074-0:1:1:1-2
> 2015-06-26 11:06:07,527 [dapp.net:8671/]] - TRACE AmqpFixedProducer
> - Producer sending message: JmsOutboundMessageDispatch {dispatchId =
> ID:WIN81CLIENT-58513-1435280763074-0:1:1:1-3}
> Sent message with JMSMessageID =
> ID:WIN81CLIENT-58513-1435280763074-0:1:1:1-3
>
> Cheers
>
>

To clarify some things:
- What message delivery mode are you using, Persistent or non-persistent?
- What session acknowledgement mode are you setting?
- Can you create a JIRA and attach the full logs for runs with 1 and
100 messages to both Windows and Azure Service Bus, and the code too
if possible?
https://issues.apache.org/jira/browse/QPIDJMS

As it turns out, things are more complicated than it seemed initially.

I tried to reproduce the issue you are seeing locally (against a test
peer as I don't currently have access to Service Bus) and was
initially unable to, with the client being able to send the messages
successfully regardless whether the link credit was available before
or after the send attempt. After poking around some more I noticed a
key difference in my logs versus what your output indicated, and upon
making changes to get some finer details matching exactly I was able
to finally reproduce the issue.

If you notice in your Azure Service Bus logs they do show the client
logging "Dispatching previously held send" which indicates it is
handing the messsage off to to the underlying proton 'Sender' link
which now has link credit. However, there are then no subsequent
FRAMES or BYTES tracing emitted as would be expected if the messsage
was being sent. From the logs you can see that the arriving Flow frame
indicated a link credit of 1000 but also "incomingWindow=0". The
latter is a session-level window related to the session-level id's
given to transfer frames, with my reading of the AMQP spec [1]
suggesting that the value being 0 means that the remote session
endpoint (i.e Azure) can't currently accept any more transfer frames.
As a result, proton did not actually send any of the message (which
could be split over multiple transfer frames), since doing so would
violate what the peer session endpoint has told it. There is then no
activity until Azure sends a couple of empty heartbeat frames to
narrowly satisfy the 0.3.0 clients 60 second idle-timeout.

In the case of the Windows Service Bus logs, you can see that the Flow
frame arriving for the producer indicated credit of 50 and again said
"incomingWindow=0". The main difference in behaviour between the two
arose because with Windows Service Bus the Flow arrived before the
first send() call occurred. In that case, the client saw the sending
link currently had credit and so didn't wait for any to arrive, and as
the send call was being done asynchronously (likely due to the
delivery and acknowledgement modes, which I enquired about at the top)
it returned and you were able to similarly 'send' the next messages.
In each case the message was actually buffered by proton because the
remote session endpoint had said it was unable to accept any transfer
frames. Only once you 'sent' the 50th message did you exhaust the link
credit at which point the send() call was again 'held for credit',
which isn't replenished by Service Bus as it hasn't actually received
any messages (seeminly because Proton didn't send it any, because
Service Bus said it couldn't accept any) to let it know credit is
being used.

I'd like to see the full logs to get a better handle on everything
that gets sent back and forth, as I'm aware of proton-c being used
against Service Bus through several previous conversations on the
lists over the past couple years, so I think there must be some
'interesting' difference somewhere when using proton-j.

Robbie

[1] http://docs.oasis-open.org/amqp/core/v1.0/os/amqp-core-transport-v1.0-os.html#doc-session-flow-control

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org


Mime
View raw message