On 26 June 2015 at 02:16, acartcat <[email protected]> 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: [email protected] For additional commands, e-mail: [email protected]
