You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@qpid.apache.org by popalka <po...@ya.ru> on 2018/05/28 08:23:43 UTC
Apache Qpid and Azure Service bus: Is there internal buffer of Qpid
driver that can lead to duplicates/unordered messages processing under
load?
We use qpid-jms-client version 0.27.0 to work with Azure SB.
What the cause of processing messages out of order under load?
Currently we have next situation:
1) read message from SB by driver with JMSXDeliveryCount=1
2) SB place lock and increase deliveryCounter
3) after 5 minutes lock expires
4) read message from SB by driver with JMSXDeliveryCount=2
5) start processing of message with JMSXDeliveryCount=2 by business code of
our application
7) message with with JMSXDeliveryCount=2 successfully processed and
acknowledged
8) message removed from SB queue
*9) start processing of message with JMSXDeliveryCount=1 by business code
of our application* (!!!!!!)
10) try to acknowledge message with JMSXDeliveryCount=1 that gives user
error on SB metrics
Why the 9) is possible? Where message is stored inside driver? We disabled
prefetch by driver. Why it holds inside driver so long (over 5 minutes)?
We work in multi threaded environment and may be our CPU cores are under
load, but anyway why priority of processing is broken?
Connection parameters for SB are
amqp.idleTimeout=120000
jms.prefetchPolicy.all=0
amqp.drainTimeout=0
Also receiveLocalOnly=true on org.apache.qpid.jms.JmsConnectionFactory
Acknowledge mode is client.
Additional info:
================1==================
Spring config for message-driven-channel-adapter:
<int-jms:message-driven-channel-adapter id="reseller-orders-jms-in"
destination-name="${serviceBus.reseller-orders.destination-name}"
connection-factory="jmsConnectionFactory"
acknowledge="client"
channel="reseller-orders-in"
error-channel="reseller-orders-errors"
concurrent-consumers="${jms.concurrent-consumers:10}"
max-concurrent-consumers="${jms.max-concurrent-consumers:40}"
task-executor="resOrdExecutor"
message-converter="gzipMessageConverter"
auto-startup="${reseller-orders-flow.enabled:true}"/>
<task:executor id="resOrdExecutor"
queue-capacity="${jms.max-concurrent-consumers:40}"
pool-size="${jms.concurrent-consumers:10}-${jms.max-concurrent-consumers:40}"/>
============2================
Trace logs from our app:
HeadersLogger is our app class
grep "3e4861c4-359c-4d7b-82b3-01d3d0fc62ec:10:2:1-270"
erpc-messaging.log.jms_consumer2.log
2018-05-25 08:14:18.988 TRACE 9844 --- [resOrdExecutor-9]
org.apache.qpid.jms.JmsMessageConsumer :
ID:03d307b2-ba5c-4b86-b430-64c3ac46e2dd:2:6:1 received message:
JmsInboundMessageDispatch { sequence = 41, messageId =
ID:3e4861c4-359c-4d7b-82b3-01d3d0fc62ec:10:2:1-270, consumerId =
ID:03d307b2-ba5c-4b86-b430-64c3ac46e2dd:2:6:1 }
2018-05-25 08:14:18.988 DEBUG 9844 --- [resOrdExecutor-9]
c.o.e.messaging.log.HeadersLogger : Process message with headers
{jms_redelivered=true, JMSXDeliveryCount=2,
jms_destination=reseller-orders-topic,
id=28971091-996e-7a34-1e0d-a43d713c2ac2, priority=4,
jms_timestamp=1527235569311,
jms_messageId=ID:3e4861c4-359c-4d7b-82b3-01d3d0fc62ec:10:2:1-270,
SOURCE_SYSTEM=EXPORT_ENGINE, timestamp=1527236058988}
2018-05-25 08:14:19.003 WARN 9844 --- [resOrdExecutor-9]
c.o.e.messaging.log.HeadersLogger : More than one attempt to process
jms message. Details : {jms_redelivered=true, JMSXDeliveryCount=2,
jms_destination=reseller-orders-topic,
id=28971091-996e-7a34-1e0d-a43d713c2ac2, priority=4,
jms_timestamp=1527235569311,
jms_messageId=ID:3e4861c4-359c-4d7b-82b3-01d3d0fc62ec:10:2:1-270,
SOURCE_SYSTEM=EXPORT_ENGINE, timestamp=1527236058988}
2018-05-25 08:15:31.993 TRACE 9844 --- [resOrdExecutor-5]
org.apache.qpid.jms.JmsMessageConsumer :
ID:03d307b2-ba5c-4b86-b430-64c3ac46e2dd:2:3:1 received message:
JmsInboundMessageDispatch { sequence = 45, messageId =
ID:3e4861c4-359c-4d7b-82b3-01d3d0fc62ec:10:2:1-270, consumerId =
ID:03d307b2-ba5c-4b86-b430-64c3ac46e2dd:2:3:1 }
2018-05-25 08:15:31.993 DEBUG 9844 --- [resOrdExecutor-5]
c.o.e.messaging.log.HeadersLogger : Process message with headers
{jms_redelivered=false, JMSXDeliveryCount=1,
jms_destination=reseller-orders-topic,
id=6b5c1284-c206-0aca-290d-444e3a112e6d, priority=4,
jms_timestamp=1527235569311,
jms_messageId=ID:3e4861c4-359c-4d7b-82b3-01d3d0fc62ec:10:2:1-270,
SOURCE_SYSTEM=EXPORT_ENGINE, timestamp=1527236131993}
=============3===========
Sample driver trace log that cause increasing deliveryCount on SB side.
2018-05-27 22:33:18.317 TRACE --- [windows.net:-1]]
o.a.qpid.jms.provider.amqp.AmqpConsumer : Consumer
ID:67e44b2f-d492-4ee3-8ed0-6fb0f3345136:1:1:1 granting 1 additional credit
for pull.
2018-05-27 22:33:18.318 TRACE --- [windows.net:-1]]
o.apache.qpid.jms.provider.amqp.FRAMES : SENT: Flow{nextIncomingId=1,
incomingWindow=2047, nextOutgoingId=1, outgoingWindow=2147483647, handle=0,
deliveryCount=0, linkCredit=1, available=null, drain=false, echo=false,
properties=null}
2018-05-27 22:33:18.318 INFO --- [windows.net:-1]]
org.apache.qpid.jms.provider.amqp.BYTES : Sending:
0000002002000001005313c01307520170000007ff5201707fffffff43435201
2018-05-27 22:33:45.922 TRACE --- [windows.net:-1]]
o.a.q.j.t.netty.NettyTcpTransport : Attempted write of: 32 bytes
--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under load?
Posted by Robbie Gemmell <ro...@gmail.com>.
On 29 May 2018 at 15:33, popalka <po...@ya.ru> wrote:
> Robbie, thanks a lot for answer.
>
> I'm trying to investigate issue more deeply and reproduce it locally (this
> is issue from PROD).
>
> Yes, receiveLocalOnly=true is redudant in our config since prefetch is
> disabled, I read the source code and documentation.
> Also we increase number of CPU cores on PROD. so CPU load less than 40%. It
> didn't help.
>
> Maybe we are victim of
> http://qpid.2158936.n2.nabble.com/JMS-message-consumer-behavior-td7666936.html
I dont believe this is applicable. Since you have prefetch set to 0,
it will only only issue credit when receive() has been called on a
consumer that is started.
> or
> https://issues.apache.org/jira/browse/QPIDJMS-297 (but is should not
> affect, we use relatively fresh version 0.27.0)
>
That is an open JIRA, however I dont believe it is applicable here
either since again the prefetch is 0, and if the connection was
re-stopped you wouldnt be receiving any messages, which you are.
> My current hypothesis that instances of JmsMessageConsumer recreated by
> recovery mechanism of Spring's DefaultMessageListenerContainer it can lead
> to prefetching messages by Qpid driver with delayed processing by business
> code.
>
> Another hypothesis that JmsMessageConsumer badly cleaned by Spring's
> DefaultMessageListenerContainer
>
>
> Robbie Gemmell wrote
>> The below doesnt really give enough information to reason about what
>> happened, however some notes/observations:
>>
>> - The logs show two different consumers processing the message within
>> a minute of each other. Probably due to the server handing it to a
>> different consumer after the lock expired earlier, but its not
>> possible to say much else with the details available.
>> - Snippet 3 just shows the consumer granting the server a credit to
>> send a message after receive was called. This is expected in general
>> and necessary here in particular since prefetch is disabled.
>> - The consumer has an intermediate buffer it puts arriving messages,
>> but by disabling prefetch it should see only 1 message at a time go in
>> it and then get removed directly by the recieving application thread.
>> - The receiveLocalOnly=true probably shouldnt be used since its not
>> possible for the client to work entirely on its local buffer when
>> prefetch is disabled; it must go remote to ask the server for a
>> message when receive is called, because it has not previously given
>> credit for any messge to be sent yet.
>>
>> Robbie
>
> Regards,
> Anton Reshetnikov
>
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
> For additional commands, e-mail: users-help@qpid.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under
load?
Posted by popalka <po...@ya.ru>.
Thanks for your comments.
I'll try to collect more trace logs and will return with my findings.
2 problems here:
1) I cannot reliably reproduce this issue locally
2) Log rotation on PROD is too fast, so It's hard to get logs in moment of
issue is reproducing.
--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under load?
Posted by Robbie Gemmell <ro...@gmail.com>.
That is actually the behaviour I would typically expect given what you
did. The client recieved a message, which it processed and accepted in
the manner it should. That you deleted the message remotely during
that time doesn't really change that, and it would in many ways be
unfair to consider the application in error. From a protocol
perspective the server also has no way to indicate an error in
acceptance of that specific message to the client at that point and
would need to escalate to killing the consumer or more.
On 30 May 2018 at 19:27, popalka <po...@ya.ru> wrote:
>
>
>>Are these logs from such an experiment, as they seem valid from a
>>protocol perspective (delivery with id 0 arrives, then is accepted)?
>
> Yes these logs are from the experiment.
> 1) Start debug session of my java program. I send `Flow` frame with 1 credit
> limit, then receive 'Transfer' then pause program execution.
> 2) Open utility to browse and manipulate Azure SB queues, completely delete
> message from queue (receive with delete).
> 3) Unpause java program. It sends 'Disposition' frame. No error after it
> reported in logs.
>
> Some times after I see `user error` counter increasing in Azure SB metrics
> available via Azure portal.
> No more details like error codes available.
>
>
>
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
> For additional commands, e-mail: users-help@qpid.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under
load?
Posted by popalka <po...@ya.ru>.
>Are these logs from such an experiment, as they seem valid from a
>protocol perspective (delivery with id 0 arrives, then is accepted)?
Yes these logs are from the experiment.
1) Start debug session of my java program. I send `Flow` frame with 1 credit
limit, then receive 'Transfer' then pause program execution.
2) Open utility to browse and manipulate Azure SB queues, completely delete
message from queue (receive with delete).
3) Unpause java program. It sends 'Disposition' frame. No error after it
reported in logs.
Some times after I see `user error` counter increasing in Azure SB metrics
available via Azure portal.
No more details like error codes available.
--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under load?
Posted by Robbie Gemmell <ro...@gmail.com>.
On 30 May 2018 at 11:13, popalka <po...@ya.ru> wrote:
> I have 3 observation:
>
>
> 1.) Azure Service Bus place lock on message when receive Flow frame with
> non-zero link credit
> --------------------------------------------------------------------------------------------
>
> The clock for the expiration of the lock on the message inside the
> `queue/topic subscription` starts when the message is taken from the entity,
> not when the message is put on the wire.
>
>
> So, when Flow Frame with linkCredit=1 send to Azure SB it lead to place lock
> on message
> ```
> 2018-05-30 10:14:33.867 TRACE --- [windows.net:-1]]
> o.a.qpid.jms.provider.amqp.AmqpConsumer : Consumer
> ID:a6d1d214-eb32-4917-8e27-5a7ed0edca2a:1:1:1 granting additional credit: 1
> 2018-05-30 10:14:50.138 TRACE --- [windows.net:-1]]
> o.apache.qpid.jms.provider.amqp.FRAMES : SENT: Flow{nextIncomingId=1,
> incomingWindow=2047, nextOutgoingId=1, outgoingWindow=2147483647, handle=0,
> deliveryCount=0, linkCredit=1, available=null, drain=false, echo=false,
> properties=null}```
> 2018-05-30 10:14:50.138 TRACE --- [windows.net:-1]]
> o.a.q.j.t.netty.NettyTcpTransport : Attempted write of: 32 bytes
> ```
>
This is to be expected. You disabled prefetch, meaning the consumer
doesnt flow any credit for the server to send it messages until you
ask for a message by calling recieve. The Flow results and grants the
sender (Service Bus) 1 credit to send a message. When it sends the
message, it uses the credit, and the message becomes locked as it has
been sent to a consumer and is awaiting consumption/release/etc.
> 2.) Azure Service Bus ignores non-valid Disposition frames
> ---------------------------------------------------------
>
>
> We receive message in `Transfer` frame, confirm read by `Disposition` frame.
> But Azure SB ignores `Disposition` frames.
> For example I made experiment with sending `Disposition` frame on
> non-existing message. Azure SB silently accept it.
>
> ```
> 2018-05-30 10:16:00.710 TRACE --- [windows.net:-1]]
> o.apache.qpid.jms.provider.amqp.FRAMES : RECV: Transfer{handle=0,
> deliveryId=0,
> deliveryTag=\x1e\x86\xa8'\xa4\x07qA\xb3\x8b\xf4\xa4\x9d\xa9\x00\xc8,
> messageFormat=0, settled=null, more=false, rcvSettleMode=null, state=null,
> resume=false, aborted=false, batchable=true}
> 2018-05-30 10:16:07.141 TRACE --- [windows.net:-1]]
> o.apache.qpid.jms.provider.amqp.FRAMES : SENT: Disposition{role=RECEIVER,
> first=0, last=0, settled=true, state=Accepted{}, batchable=false}
> ```
>
Are these logs from such an experiment, as they seem valid from a
protocol perspective (delivery with id 0 arrives, then is accepted)?
>
> The 1) and 2) is really confusing. I expected, that message's lock placed
> when client confirm successful read in terms of AMQP.
It is locked when sent to a consumer, so it isnt sent to other
consumers as well (while locked).
> But Azure SB has own semantics on it.
>
It does have its own semantics with regards to timing out the lock, yes.
>
> 3.) Possibly slow Runnable's queue inside ThreadPoolExecutor used by Apache
> Qpid driver.
> ---------------------------------------------------------------------------------------
>
> Frames processed by Apache Qpid driver by single thread in internal queue of
> Runnables inside ThreadPoolExecutor
>
> class org.apache.qpid.jms.provider.amqp.AmqpProvider
>
> has field `ScheduledThreadPoolExecutor serializer`
> It created inside constructor as
>
> ```
> serializer = new ScheduledThreadPoolExecutor(1, new QpidJMSThreadFactory(
> "AmqpProvider :(" + PROVIDER_SEQUENCE.incrementAndGet() + "):["
> +
> remoteURI.getScheme() + "://" + remoteURI.getHost() + ":" +
> remoteURI.getPort() + "]", true));
> ```
>
> Invoking of any methods like
>
> Provider::pull
> Provider::acknowledge
> Provider::send
> Provider::start
> Provider::stop
>
> or
> TransportListener:onData
>
> leads to creating of Runnable that placed to internal queue of Runnables of
> ScheduledThreadPoolExecutor `serializer`.
>
> Result of this queue consumed by several threads.
>
>
> Current hypothesis
> ------------------
>
> The Runnable's queue acts like a slow buffer, that lead to "strange"
> behavior like unordered message processing.
>
> For example:
>
> 1. Runnable with processing of `Flow` trace is placed to Runnable's queue.
> (first attempt to read the message)
> 2. Azure SB place lock on message
> 3. Runnable's queue is filled by other tasks.
> 4. Lock on message expires.
Whilst not impossible with a server that remotely-expires locking on
unsettled messages this still seems unlikely, as you are effectively
doing synchronous gets against the remote server, which in many ways
will reduce the rate of tasks being processed by that thread compared
to typical cases.
> 5. Runnable with processing of `Flow` trace is placed to Runnable's queue.
> (second attempt to read the message)
> 6. Runnable with processing of `Transfer` trace with second attempt is
> placed to Runnable's queue.
The content on the wire is serialized, as is the thread processing it,
so its not possible for the first transfer to arrive after the second
if they are on the same connection, unless they were sent that way,
which doesnt seem likely. You seem to have the necessary frame tracing
enabled to see them arrive (though enabling Protons direct tracing
with PN_TRACE_FRM=true might be nicer in some ways)
> 7. Runnable with processing of `Transfer` trace with first attempt is
> placed to Runnable's queue.
>
>
> Also my current hypothesis that Runnable's queue is filled by garbage or
> slow tasks.
> Investigation is in progress.
>
>
I think it more likely something else is going on, especially as some
of the earlier bits dont hold. The logging you pasted previously
showed the points the application threads got hold of messages. Thats
not necessarily the same as when they arrived though.
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under load?
Posted by Robbie Gemmell <ro...@gmail.com>.
You are setting that as the JMS ClientID. Given the usage suggested
from the logs, I dont expect that should make any difference here. You
could simply stop setting a ClientID and let the client auto-generate
its container-id to confirm that though.
On 31 May 2018 at 10:58, popalka <po...@ya.ru> wrote:
> I notice that containerId with value 'xxx' is hardcoded in our app. May this
> is issue?
>
>
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
> For additional commands, e-mail: users-help@qpid.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under
load?
Posted by popalka <po...@ya.ru>.
I notice that containerId with value 'xxx' is hardcoded in our app. May this
is issue?
--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under load?
Posted by Robbie Gemmell <ro...@gmail.com>.
On 1 June 2018 at 08:00, popalka <po...@ya.ru> wrote:
> HI Robbie.
>
> Looks like we found root cause.
> This is network problem.
> Our java app run in Azure Cloud in VM. The was network issues - socket
> Connections were exhausted.
>
> So, we have next situation:
>
> 1) SB queue is empty
> 2) Java app constantly says that it ready to accept 10 messages (we have 10
> threads and JmsConsumers that sends 'Flow' frame with link credit 1 and
> drain it every second)
> 3) new messages arrives
> 4) lock is placed on 10 messages by Azure SB
> 5) network is busy, messages are arrived with delay
> 6) lock expire, messages appears in queue again
>
>
> Regarding ordering issues from initial message in mail thread - yes, it's
> behavior of Spring's DefaultMessageListenerContainer. Ordering guarantees
> are lost once multiple consumers are registered.
>
> Thanks a lot for your help and discussion
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
Glad you found your problems, thanks for letting us know.
Robbie
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under
load?
Posted by popalka <po...@ya.ru>.
HI Robbie.
Looks like we found root cause.
This is network problem.
Our java app run in Azure Cloud in VM. The was network issues - socket
Connections were exhausted.
So, we have next situation:
1) SB queue is empty
2) Java app constantly says that it ready to accept 10 messages (we have 10
threads and JmsConsumers that sends 'Flow' frame with link credit 1 and
drain it every second)
3) new messages arrives
4) lock is placed on 10 messages by Azure SB
5) network is busy, messages are arrived with delay
6) lock expire, messages appears in queue again
Regarding ordering issues from initial message in mail thread - yes, it's
behavior of Spring's DefaultMessageListenerContainer. Ordering guarantees
are lost once multiple consumers are registered.
Thanks a lot for your help and discussion
--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under load?
Posted by Robbie Gemmell <ro...@gmail.com>.
Those seem to show the same thing essentially. Everything seems fine
with the traces, the consumer flows credit, waits for a message,
drains the credit when the timeout expires, ServiceBus actually
responds to those drain attempts (with the way it does indicating
there are no messages available to send), the consumer issues more
credit for the next receive call, repeat.
The only issue seemingly present is the server didnt send the consumer
a message when you think it should have. I can't really assist there
any more than I have, you'll have to ask Microsoft to assist there.
I did actually notice the second connection earlier however as it
opens and closes immediately and never creates any producers or
consumers, it should have no bearing on this which is why I didnt
mention it.
On 31 May 2018 at 10:54, popalka <po...@ya.ru> wrote:
>> Do you have logs from that run?
> Yes I have logs from run on clean freshly created queue in Azure SB:
>
> output: https://gist.github.com/qwazer/88380c98325f24ffcf55549300f4b409
> jms_trace: https://gist.github.com/qwazer/3a4524b52dcdb39040d2b122f8820b99
>
>
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
> For additional commands, e-mail: users-help@qpid.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under
load?
Posted by popalka <po...@ya.ru>.
> Do you have logs from that run?
Yes I have logs from run on clean freshly created queue in Azure SB:
output: https://gist.github.com/qwazer/88380c98325f24ffcf55549300f4b409
jms_trace: https://gist.github.com/qwazer/3a4524b52dcdb39040d2b122f8820b99
--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under load?
Posted by Robbie Gemmell <ro...@gmail.com>.
Do you have logs from that run? As a note, it might actually be useful
to enable both frame tracing methods in future tests, since the logger
based output is timestamped according to your config, while protons
direct stdout tracing has access to some detail the logger based
output cant get at.
On 31 May 2018 at 08:57, popalka <po...@ya.ru> wrote:
> Seems experiment was not clean.
>
> If I use freshly created queue in Azure SB I see that only 1 message in SB
> has increased delivery count (although it was not consumed by app, but this
> is expected).
>
> Looking for leaking AMQP links, etc
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
> For additional commands, e-mail: users-help@qpid.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under
load?
Posted by popalka <po...@ya.ru>.
Seems experiment was not clean.
If I use freshly created queue in Azure SB I see that only 1 message in SB
has increased delivery count (although it was not consumed by app, but this
is expected).
Looking for leaking AMQP links, etc
--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under
load?
Posted by popalka <po...@ya.ru>.
jms.connection.parameters still the same
amqp.idleTimeout=120000
jms.prefetchPolicy.all=0
amqp.drainTimeout=0
amqp.traceFrames=true
jms.connectTimeout=120000
--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under
load?
Posted by popalka <po...@ya.ru>.
The second connection open is specific to my IDE environment.
I run my java Spring Boot App with IDEA.
IDEA has integration with Spring Boot and perform call to /health HTTP
endpoint which is checks that connection is created.
Stack trace for 'normal' start:
https://gist.github.com/qwazer/cc347f953cf35a95a3a1c344211c2a70
Stack trace for health check
https://gist.github.com/qwazer/75d1350312b0d835189ac8fb19824fc3
In some way this like production system behave, because monitoring scripts
checks /health endpoint periodically
--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under
load?
Posted by popalka <po...@ya.ru>.
>The only odd thing was that there was no message transfer to
>the first consumer, which your subsequent re-test being 'successful'
>suggests is because the test enviornment wasnt clean to start with and
>perhaps you had other consumers running.
Yes, it is strange. I run in clean environment and have the same behavior.
I'll see why 2 consumers for single is creating.
--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under load?
Posted by Robbie Gemmell <ro...@gmail.com>.
The logs below actually appear to show what I described and would
expect. The only odd thing was that there was no message transfer to
the first consumer, which your subsequent re-test being 'successful'
suggests is because the test enviornment wasnt clean to start with and
perhaps you had other consumers running.
Curiously, the logs also seem to show ServiceBus responding to the
link drain requests exactly as it should, suggesting it perhaps does
now support link credit draining. Did you set the drainTimeout to 0
from the start, or do that out of need when running into an issue?
Robbie
On 31 May 2018 at 08:05, popalka <po...@ya.ru> wrote:
>>Once the message
>>arrives, the credit has been used and as only 1 was outstanding, any
>>drain attempt that occurred can be considered complete. The behaviour
>>should be visible in your logs.
>
> Seems it is not true. See results of my experiment:
>
>
> Experiment with Azure SB and AMQP flow control frames
> -----------------------------------------------------
>
>
> Prepare queue 'reseller-queue' in Azure SB with next parameters:
> * lock duration - 10 seconds
> * Max Delivery Count - 2
>
>
> Prepare Java application with Spring's DefaultMessageListenerContainer and
> Apache QPID driver.
>
> * use 1 thread for DefaultMessageListenerContainer
> * acknowledge="client"
> * receive-timeout="10000" (ms), so it is 10 sec
>
>
> Steps:
>
> 1) Queue 'reseller-queue' is empty
> 2) Run application with PN_TRACE_FRM=true to collect AMQP frames log.
> 3) Pause/kill application after 1 minute of work. (Don't stop)
> 4) Send 4 messages to 'reseller-queue'. I use .Net utility Azure SB
> explorer.
> 5) Wait approximately 1 minute
> 6) All 4 messages moved to Dead-letter queue with reason
> MaxDeliveryCountExceeded.
>
> Why? There was not activity from client side.
> Is there buffer of `Flow` frames on Azure SB side? How to control, for
> example, clean it?
>
>
>
> Frames:
>
> ```[1807720011:0] -> Open{ containerId='xxx',
> hostname='erp-connector-dev-02.servicebus.windows.net',
> maxFrameSize=1048576, channelMax=32767, idleTimeOut=60000,
> outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
> desiredCapabilities=[sole-connection-for-container, DELAYED_DELIVERY,
> ANONYMOUS-RELAY, SHARED-SUBS], properties={product=QpidJMS, version=0.27.0,
> platform=JVM: 1.8.0_171, 25.171-b11, Oracle Corporation, OS: Linux,
> 4.9.0-6-amd64, amd64}}
> [1807720011:0] <- Open{
> containerId='65512918e04446458a023aca4e765352_G20', hostname='null',
> maxFrameSize=65536, channelMax=4999, idleTimeOut=240000,
> outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
> desiredCapabilities=null, properties=null}
> [1807720011:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
> incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [1807720011:0] <- Begin{remoteChannel=0, nextOutgoingId=1,
> incomingWindow=5000, outgoingWindow=2047, handleMax=255,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [1807720011:1] -> Begin{remoteChannel=null, nextOutgoingId=1,
> incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [1807720011:1] <- Begin{remoteChannel=1, nextOutgoingId=1,
> incomingWindow=5000, outgoingWindow=2047, handleMax=255,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [1807720011:1] ->
> Attach{name='qpid-jms:receiver:ID:a6e7f6e5-1e05-4a36-b586-06befb5dfe9b:1:1:1:reseller-orders-queue',
> handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
> source=Source{address='reseller-orders-queue', durable=NONE,
> expiryPolicy=LINK_DETACH, timeout=0, dynamic=false,
> dynamicNodeProperties=null, distributionMode=null, filter=null,
> defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=null,
> messageAnnotations=null}, outcomes=[amqp:accepted:list, amqp:rejected:list,
> amqp:released:list, amqp:modified:list], capabilities=[queue]},
> target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END,
> timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
> unsettled=null, incompleteUnsettled=false, initialDeliveryCount=null,
> maxMessageSize=null, offeredCapabilities=null, desiredCapabilities=null,
> properties=null}
> [1807720011:1] <-
> Attach{name='qpid-jms:receiver:ID:a6e7f6e5-1e05-4a36-b586-06befb5dfe9b:1:1:1:reseller-orders-queue',
> handle=0, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
> source=Source{address='reseller-orders-queue', durable=NONE,
> expiryPolicy=LINK_DETACH, timeout=0, dynamic=false,
> dynamicNodeProperties=null, distributionMode=null, filter=null,
> defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=null,
> messageAnnotations=null}, outcomes=[amqp:accepted:list, amqp:rejected:list,
> amqp:released:list, amqp:modified:list], capabilities=[queue]},
> target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END,
> timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
> unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0,
> maxMessageSize=266240, offeredCapabilities=null, desiredCapabilities=null,
> properties={com.microsoft:tracking-id=65512918e04446458a023aca4e765352_G20}}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=0,
> linkCredit=1, available=null, drain=false, echo=false, properties=null}
> [612608661:0] -> Open{ containerId='xxx',
> hostname='erp-connector-dev-02.servicebus.windows.net',
> maxFrameSize=1048576, channelMax=32767, idleTimeOut=60000,
> outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
> desiredCapabilities=[sole-connection-for-container, DELAYED_DELIVERY,
> ANONYMOUS-RELAY, SHARED-SUBS], properties={product=QpidJMS, version=0.27.0,
> platform=JVM: 1.8.0_171, 25.171-b11, Oracle Corporation, OS: Linux,
> 4.9.0-6-amd64, amd64}}
> [612608661:0] <- Open{
> containerId='16f4923d27b149898d4e3afd3ff3c878_G15', hostname='null',
> maxFrameSize=65536, channelMax=4999, idleTimeOut=240000,
> outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
> desiredCapabilities=null, properties=null}
> [612608661:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
> incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [612608661:0] <- Begin{remoteChannel=0, nextOutgoingId=1,
> incomingWindow=5000, outgoingWindow=2047, handleMax=255,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [612608661:0] -> Close{error=null}
> [612608661:0] <- Close{error=null}
> [23516751:0] -> Open{ containerId='xxx',
> hostname='erp-connector-dev-02.servicebus.windows.net',
> maxFrameSize=1048576, channelMax=32767, idleTimeOut=60000,
> outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
> desiredCapabilities=[sole-connection-for-container, DELAYED_DELIVERY,
> ANONYMOUS-RELAY, SHARED-SUBS], properties={product=QpidJMS, version=0.27.0,
> platform=JVM: 1.8.0_171, 25.171-b11, Oracle Corporation, OS: Linux,
> 4.9.0-6-amd64, amd64}}
> [23516751:0] <- Open{ containerId='43fb9da3bfac43efa8b20da7c19bbb37_G22',
> hostname='null', maxFrameSize=65536, channelMax=4999, idleTimeOut=240000,
> outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
> desiredCapabilities=null, properties=null}
> [23516751:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
> incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [23516751:0] <- Begin{remoteChannel=0, nextOutgoingId=1,
> incomingWindow=5000, outgoingWindow=2047, handleMax=255,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=0,
> linkCredit=1, available=null, drain=true, echo=false, properties=null}
> [1807720011:1] <- Flow{nextIncomingId=1, incomingWindow=5000,
> nextOutgoingId=1, outgoingWindow=2047, handle=0, deliveryCount=1,
> linkCredit=0, available=0, drain=true, echo=false, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=1,
> linkCredit=1, available=null, drain=false, echo=false, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=1,
> linkCredit=1, available=null, drain=true, echo=false, properties=null}
> [1807720011:1] <- Flow{nextIncomingId=1, incomingWindow=5000,
> nextOutgoingId=1, outgoingWindow=2047, handle=0, deliveryCount=2,
> linkCredit=0, available=0, drain=true, echo=false, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=2,
> linkCredit=1, available=null, drain=false, echo=false, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=2,
> linkCredit=1, available=null, drain=true, echo=false, properties=null}
> [1807720011:1] <- Flow{nextIncomingId=1, incomingWindow=5000,
> nextOutgoingId=1, outgoingWindow=2047, handle=0, deliveryCount=3,
> linkCredit=0, available=0, drain=true, echo=false, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=3,
> linkCredit=1, available=null, drain=false, echo=false, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=3,
> linkCredit=1, available=null, drain=true, echo=false, properties=null}
> [1807720011:1] <- Flow{nextIncomingId=1, incomingWindow=5000,
> nextOutgoingId=1, outgoingWindow=2047, handle=0, deliveryCount=4,
> linkCredit=0, available=0, drain=true, echo=false, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=4,
> linkCredit=1, available=null, drain=false, echo=false, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=4,
> linkCredit=1, available=null, drain=true, echo=false, properties=null}
> [1807720011:1] <- Flow{nextIncomingId=1, incomingWindow=5000,
> nextOutgoingId=1, outgoingWindow=2047, handle=0, deliveryCount=5,
> linkCredit=0, available=0, drain=true, echo=false, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=5,
> linkCredit=1, available=null, drain=false, echo=false, properties=null}
>
> ```
>
> I asked Azure support questions above
>
>
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
> For additional commands, e-mail: users-help@qpid.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under load?
Posted by Robbie Gemmell <ro...@gmail.com>.
Missed some reply comments, see inline.
On 31 May 2018 at 08:05, popalka <po...@ya.ru> wrote:
>>Once the message
>>arrives, the credit has been used and as only 1 was outstanding, any
>>drain attempt that occurred can be considered complete. The behaviour
>>should be visible in your logs.
>
> Seems it is not true. See results of my experiment:
>
>
> Experiment with Azure SB and AMQP flow control frames
> -----------------------------------------------------
>
>
> Prepare queue 'reseller-queue' in Azure SB with next parameters:
> * lock duration - 10 seconds
> * Max Delivery Count - 2
>
>
> Prepare Java application with Spring's DefaultMessageListenerContainer and
> Apache QPID driver.
>
> * use 1 thread for DefaultMessageListenerContainer
> * acknowledge="client"
> * receive-timeout="10000" (ms), so it is 10 sec
>
>
> Steps:
>
> 1) Queue 'reseller-queue' is empty
> 2) Run application with PN_TRACE_FRM=true to collect AMQP frames log.
> 3) Pause/kill application after 1 minute of work. (Don't stop)
> 4) Send 4 messages to 'reseller-queue'. I use .Net utility Azure SB
> explorer.
> 5) Wait approximately 1 minute
> 6) All 4 messages moved to Dead-letter queue with reason
> MaxDeliveryCountExceeded.
>
> Why? There was not activity from client side.
> Is there buffer of `Flow` frames on Azure SB side? How to control, for
> example, clean it?
>
I actually misread this the first time, and thought you sent the
messages before pausing/killing the first application. If you didnt
send them until after, then it seems like you definitely had something
else running on the queue that caused them to be locked (or ran into a
bug in Service Bus) in order for there to be no message transfers to
the consumers, since the frame tracing shows the two consumers
behaving as expected (and to be fair, given what actually happened
they also seem to show Service Bus doing the same).
You can see the first consumer granted 1 credit, so it only has
ability to influence 1 message. Assuming you just suspend its JVM,
ServiceBus would rightly see it as still active and allocate+send it
the message, explaining it being locked then later expired in your
second test. You dont indicate whether the other messages were
successfully received in the second test, but I assume they were.
>
>
> Frames:
>
> ```[1807720011:0] -> Open{ containerId='xxx',
> hostname='erp-connector-dev-02.servicebus.windows.net',
> maxFrameSize=1048576, channelMax=32767, idleTimeOut=60000,
> outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
> desiredCapabilities=[sole-connection-for-container, DELAYED_DELIVERY,
> ANONYMOUS-RELAY, SHARED-SUBS], properties={product=QpidJMS, version=0.27.0,
> platform=JVM: 1.8.0_171, 25.171-b11, Oracle Corporation, OS: Linux,
> 4.9.0-6-amd64, amd64}}
> [1807720011:0] <- Open{
> containerId='65512918e04446458a023aca4e765352_G20', hostname='null',
> maxFrameSize=65536, channelMax=4999, idleTimeOut=240000,
> outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
> desiredCapabilities=null, properties=null}
> [1807720011:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
> incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [1807720011:0] <- Begin{remoteChannel=0, nextOutgoingId=1,
> incomingWindow=5000, outgoingWindow=2047, handleMax=255,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [1807720011:1] -> Begin{remoteChannel=null, nextOutgoingId=1,
> incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [1807720011:1] <- Begin{remoteChannel=1, nextOutgoingId=1,
> incomingWindow=5000, outgoingWindow=2047, handleMax=255,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [1807720011:1] ->
> Attach{name='qpid-jms:receiver:ID:a6e7f6e5-1e05-4a36-b586-06befb5dfe9b:1:1:1:reseller-orders-queue',
> handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
> source=Source{address='reseller-orders-queue', durable=NONE,
> expiryPolicy=LINK_DETACH, timeout=0, dynamic=false,
> dynamicNodeProperties=null, distributionMode=null, filter=null,
> defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=null,
> messageAnnotations=null}, outcomes=[amqp:accepted:list, amqp:rejected:list,
> amqp:released:list, amqp:modified:list], capabilities=[queue]},
> target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END,
> timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
> unsettled=null, incompleteUnsettled=false, initialDeliveryCount=null,
> maxMessageSize=null, offeredCapabilities=null, desiredCapabilities=null,
> properties=null}
> [1807720011:1] <-
> Attach{name='qpid-jms:receiver:ID:a6e7f6e5-1e05-4a36-b586-06befb5dfe9b:1:1:1:reseller-orders-queue',
> handle=0, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
> source=Source{address='reseller-orders-queue', durable=NONE,
> expiryPolicy=LINK_DETACH, timeout=0, dynamic=false,
> dynamicNodeProperties=null, distributionMode=null, filter=null,
> defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=null,
> messageAnnotations=null}, outcomes=[amqp:accepted:list, amqp:rejected:list,
> amqp:released:list, amqp:modified:list], capabilities=[queue]},
> target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END,
> timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
> unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0,
> maxMessageSize=266240, offeredCapabilities=null, desiredCapabilities=null,
> properties={com.microsoft:tracking-id=65512918e04446458a023aca4e765352_G20}}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=0,
> linkCredit=1, available=null, drain=false, echo=false, properties=null}
> [612608661:0] -> Open{ containerId='xxx',
> hostname='erp-connector-dev-02.servicebus.windows.net',
> maxFrameSize=1048576, channelMax=32767, idleTimeOut=60000,
> outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
> desiredCapabilities=[sole-connection-for-container, DELAYED_DELIVERY,
> ANONYMOUS-RELAY, SHARED-SUBS], properties={product=QpidJMS, version=0.27.0,
> platform=JVM: 1.8.0_171, 25.171-b11, Oracle Corporation, OS: Linux,
> 4.9.0-6-amd64, amd64}}
> [612608661:0] <- Open{
> containerId='16f4923d27b149898d4e3afd3ff3c878_G15', hostname='null',
> maxFrameSize=65536, channelMax=4999, idleTimeOut=240000,
> outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
> desiredCapabilities=null, properties=null}
> [612608661:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
> incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [612608661:0] <- Begin{remoteChannel=0, nextOutgoingId=1,
> incomingWindow=5000, outgoingWindow=2047, handleMax=255,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [612608661:0] -> Close{error=null}
> [612608661:0] <- Close{error=null}
> [23516751:0] -> Open{ containerId='xxx',
> hostname='erp-connector-dev-02.servicebus.windows.net',
> maxFrameSize=1048576, channelMax=32767, idleTimeOut=60000,
> outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
> desiredCapabilities=[sole-connection-for-container, DELAYED_DELIVERY,
> ANONYMOUS-RELAY, SHARED-SUBS], properties={product=QpidJMS, version=0.27.0,
> platform=JVM: 1.8.0_171, 25.171-b11, Oracle Corporation, OS: Linux,
> 4.9.0-6-amd64, amd64}}
> [23516751:0] <- Open{ containerId='43fb9da3bfac43efa8b20da7c19bbb37_G22',
> hostname='null', maxFrameSize=65536, channelMax=4999, idleTimeOut=240000,
> outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
> desiredCapabilities=null, properties=null}
> [23516751:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
> incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [23516751:0] <- Begin{remoteChannel=0, nextOutgoingId=1,
> incomingWindow=5000, outgoingWindow=2047, handleMax=255,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=0,
> linkCredit=1, available=null, drain=true, echo=false, properties=null}
> [1807720011:1] <- Flow{nextIncomingId=1, incomingWindow=5000,
> nextOutgoingId=1, outgoingWindow=2047, handle=0, deliveryCount=1,
> linkCredit=0, available=0, drain=true, echo=false, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=1,
> linkCredit=1, available=null, drain=false, echo=false, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=1,
> linkCredit=1, available=null, drain=true, echo=false, properties=null}
> [1807720011:1] <- Flow{nextIncomingId=1, incomingWindow=5000,
> nextOutgoingId=1, outgoingWindow=2047, handle=0, deliveryCount=2,
> linkCredit=0, available=0, drain=true, echo=false, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=2,
> linkCredit=1, available=null, drain=false, echo=false, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=2,
> linkCredit=1, available=null, drain=true, echo=false, properties=null}
> [1807720011:1] <- Flow{nextIncomingId=1, incomingWindow=5000,
> nextOutgoingId=1, outgoingWindow=2047, handle=0, deliveryCount=3,
> linkCredit=0, available=0, drain=true, echo=false, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=3,
> linkCredit=1, available=null, drain=false, echo=false, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=3,
> linkCredit=1, available=null, drain=true, echo=false, properties=null}
> [1807720011:1] <- Flow{nextIncomingId=1, incomingWindow=5000,
> nextOutgoingId=1, outgoingWindow=2047, handle=0, deliveryCount=4,
> linkCredit=0, available=0, drain=true, echo=false, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=4,
> linkCredit=1, available=null, drain=false, echo=false, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=4,
> linkCredit=1, available=null, drain=true, echo=false, properties=null}
> [1807720011:1] <- Flow{nextIncomingId=1, incomingWindow=5000,
> nextOutgoingId=1, outgoingWindow=2047, handle=0, deliveryCount=5,
> linkCredit=0, available=0, drain=true, echo=false, properties=null}
> [1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=5,
> linkCredit=1, available=null, drain=false, echo=false, properties=null}
>
> ```
>
> I asked Azure support questions above
>
>
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
> For additional commands, e-mail: users-help@qpid.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under
load?
Posted by popalka <po...@ya.ru>.
>Once the message
>arrives, the credit has been used and as only 1 was outstanding, any
>drain attempt that occurred can be considered complete. The behaviour
>should be visible in your logs.
Seems it is not true. See results of my experiment:
Experiment with Azure SB and AMQP flow control frames
-----------------------------------------------------
Prepare queue 'reseller-queue' in Azure SB with next parameters:
* lock duration - 10 seconds
* Max Delivery Count - 2
Prepare Java application with Spring's DefaultMessageListenerContainer and
Apache QPID driver.
* use 1 thread for DefaultMessageListenerContainer
* acknowledge="client"
* receive-timeout="10000" (ms), so it is 10 sec
Steps:
1) Queue 'reseller-queue' is empty
2) Run application with PN_TRACE_FRM=true to collect AMQP frames log.
3) Pause/kill application after 1 minute of work. (Don't stop)
4) Send 4 messages to 'reseller-queue'. I use .Net utility Azure SB
explorer.
5) Wait approximately 1 minute
6) All 4 messages moved to Dead-letter queue with reason
MaxDeliveryCountExceeded.
Why? There was not activity from client side.
Is there buffer of `Flow` frames on Azure SB side? How to control, for
example, clean it?
Frames:
```[1807720011:0] -> Open{ containerId='xxx',
hostname='erp-connector-dev-02.servicebus.windows.net',
maxFrameSize=1048576, channelMax=32767, idleTimeOut=60000,
outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
desiredCapabilities=[sole-connection-for-container, DELAYED_DELIVERY,
ANONYMOUS-RELAY, SHARED-SUBS], properties={product=QpidJMS, version=0.27.0,
platform=JVM: 1.8.0_171, 25.171-b11, Oracle Corporation, OS: Linux,
4.9.0-6-amd64, amd64}}
[1807720011:0] <- Open{
containerId='65512918e04446458a023aca4e765352_G20', hostname='null',
maxFrameSize=65536, channelMax=4999, idleTimeOut=240000,
outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
[1807720011:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[1807720011:0] <- Begin{remoteChannel=0, nextOutgoingId=1,
incomingWindow=5000, outgoingWindow=2047, handleMax=255,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[1807720011:1] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[1807720011:1] <- Begin{remoteChannel=1, nextOutgoingId=1,
incomingWindow=5000, outgoingWindow=2047, handleMax=255,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[1807720011:1] ->
Attach{name='qpid-jms:receiver:ID:a6e7f6e5-1e05-4a36-b586-06befb5dfe9b:1:1:1:reseller-orders-queue',
handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='reseller-orders-queue', durable=NONE,
expiryPolicy=LINK_DETACH, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=null,
messageAnnotations=null}, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=[queue]},
target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
unsettled=null, incompleteUnsettled=false, initialDeliveryCount=null,
maxMessageSize=null, offeredCapabilities=null, desiredCapabilities=null,
properties=null}
[1807720011:1] <-
Attach{name='qpid-jms:receiver:ID:a6e7f6e5-1e05-4a36-b586-06befb5dfe9b:1:1:1:reseller-orders-queue',
handle=0, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='reseller-orders-queue', durable=NONE,
expiryPolicy=LINK_DETACH, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=null,
messageAnnotations=null}, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=[queue]},
target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0,
maxMessageSize=266240, offeredCapabilities=null, desiredCapabilities=null,
properties={com.microsoft:tracking-id=65512918e04446458a023aca4e765352_G20}}
[1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=0,
linkCredit=1, available=null, drain=false, echo=false, properties=null}
[612608661:0] -> Open{ containerId='xxx',
hostname='erp-connector-dev-02.servicebus.windows.net',
maxFrameSize=1048576, channelMax=32767, idleTimeOut=60000,
outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
desiredCapabilities=[sole-connection-for-container, DELAYED_DELIVERY,
ANONYMOUS-RELAY, SHARED-SUBS], properties={product=QpidJMS, version=0.27.0,
platform=JVM: 1.8.0_171, 25.171-b11, Oracle Corporation, OS: Linux,
4.9.0-6-amd64, amd64}}
[612608661:0] <- Open{
containerId='16f4923d27b149898d4e3afd3ff3c878_G15', hostname='null',
maxFrameSize=65536, channelMax=4999, idleTimeOut=240000,
outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
[612608661:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[612608661:0] <- Begin{remoteChannel=0, nextOutgoingId=1,
incomingWindow=5000, outgoingWindow=2047, handleMax=255,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[612608661:0] -> Close{error=null}
[612608661:0] <- Close{error=null}
[23516751:0] -> Open{ containerId='xxx',
hostname='erp-connector-dev-02.servicebus.windows.net',
maxFrameSize=1048576, channelMax=32767, idleTimeOut=60000,
outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
desiredCapabilities=[sole-connection-for-container, DELAYED_DELIVERY,
ANONYMOUS-RELAY, SHARED-SUBS], properties={product=QpidJMS, version=0.27.0,
platform=JVM: 1.8.0_171, 25.171-b11, Oracle Corporation, OS: Linux,
4.9.0-6-amd64, amd64}}
[23516751:0] <- Open{ containerId='43fb9da3bfac43efa8b20da7c19bbb37_G22',
hostname='null', maxFrameSize=65536, channelMax=4999, idleTimeOut=240000,
outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
[23516751:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[23516751:0] <- Begin{remoteChannel=0, nextOutgoingId=1,
incomingWindow=5000, outgoingWindow=2047, handleMax=255,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=0,
linkCredit=1, available=null, drain=true, echo=false, properties=null}
[1807720011:1] <- Flow{nextIncomingId=1, incomingWindow=5000,
nextOutgoingId=1, outgoingWindow=2047, handle=0, deliveryCount=1,
linkCredit=0, available=0, drain=true, echo=false, properties=null}
[1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=1,
linkCredit=1, available=null, drain=false, echo=false, properties=null}
[1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=1,
linkCredit=1, available=null, drain=true, echo=false, properties=null}
[1807720011:1] <- Flow{nextIncomingId=1, incomingWindow=5000,
nextOutgoingId=1, outgoingWindow=2047, handle=0, deliveryCount=2,
linkCredit=0, available=0, drain=true, echo=false, properties=null}
[1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=2,
linkCredit=1, available=null, drain=false, echo=false, properties=null}
[1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=2,
linkCredit=1, available=null, drain=true, echo=false, properties=null}
[1807720011:1] <- Flow{nextIncomingId=1, incomingWindow=5000,
nextOutgoingId=1, outgoingWindow=2047, handle=0, deliveryCount=3,
linkCredit=0, available=0, drain=true, echo=false, properties=null}
[1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=3,
linkCredit=1, available=null, drain=false, echo=false, properties=null}
[1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=3,
linkCredit=1, available=null, drain=true, echo=false, properties=null}
[1807720011:1] <- Flow{nextIncomingId=1, incomingWindow=5000,
nextOutgoingId=1, outgoingWindow=2047, handle=0, deliveryCount=4,
linkCredit=0, available=0, drain=true, echo=false, properties=null}
[1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=4,
linkCredit=1, available=null, drain=false, echo=false, properties=null}
[1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=4,
linkCredit=1, available=null, drain=true, echo=false, properties=null}
[1807720011:1] <- Flow{nextIncomingId=1, incomingWindow=5000,
nextOutgoingId=1, outgoingWindow=2047, handle=0, deliveryCount=5,
linkCredit=0, available=0, drain=true, echo=false, properties=null}
[1807720011:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=5,
linkCredit=1, available=null, drain=false, echo=false, properties=null}
```
I asked Azure support questions above
--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under load?
Posted by Robbie Gemmell <ro...@gmail.com>.
One thing to be clear on is that the credit given by a Flow frame can
endure for a time until used. Credit granted must either be used by
sending a message, or removed by further Flows so that there is no
outstanding credit if no messages are desired. The clients consumers
'drain' the link credit (request the sender uses the credit they have
to send messages and then burn any remaining credit and indaicte so,
leaving them with none) if the receive timeout expires without a
message becoming available in its local buffer, or its a 0-prefetch
consumer and no message has yet arrived, in order to ensure it either
gets a message and returns if if there is one, or returns null if
there isnt (and remove outstanding credit for 0-prefetch consumers, to
avoid buffering messages without associated recieve call waiting).
Service Bus has not historically supported draining link credit, so
that process would time out at the client, hence why I believe you
configured the drain timeout to 0 so that it does not. As a result, it
should effectively wait for a message to arrive. Once the message
arrives, the credit has been used and as only 1 was outstanding, any
drain attempt that occurred can be considered complete. The behaviour
should be visible in your logs.
On 30 May 2018 at 17:54, popalka <po...@ya.ru> wrote:
> Hi Robbie
>
>
> Indeed we have some different cases on PROD.
>
> 1) Some messages processed by our app several times. Frequent use case.
>
> 2) Sometimes we got message with JMXDeliveryCount=2 with no log entries with
> JMXDeliveryCount=1 on the same message before or after.
>
> 3) We processed message with JMXDeliveryCount=2 before message with
> JMXDeliveryCount=1 (asked in start of the mail thread). Rare case.
>
> Most likely there are lock expiration issues.
>
> We have lock timeout 5 minutes, business code of our app process message in
> several seconds. In some extreme cases it works 2 minutes at maximum.
>
>
> So I was looking for interal queue/buffer inside Qpid Driver.
> After investigation and discussion with you I think it's less probable than
> I had think before.
>
> Currently I think It is a queue or a buffer of Flow Frames on the Azure SB
> side.
>
> Behaviour is next:
>
> 1) Every thread of Spring's JmsDefaultListenerContainer produce pull
> requests with timeout 1 second. This is default configuration.
> 2) Every pull request produce AMQP Flow Frame
> 3) If no messages in Azure SB queue, this Flow Frames buffered on Azure SB
> side while we have connection/sessions open. The number of send Flow Frames
> increases every 1 second at number of threads.
> 4) New messages arrives to Azure SB queue.
> 5) Azure SB buffered Flow Frames start processing
> 6) For first N messages lock is placed and those put on wire.
> 7) For next M messages , only lock is placed, because SB cannot put it on
> wire - connection is busy.
> 8) On some messages lock expires, attribute DeliveryCount increases
> 9) Some messages processed by our app, but client acknowledging doesn't take
> no effect, because lock expires, so we process such messages twice or more
> times.
>
>
> I'm going to ask Azure support about AMQP Flow Frames buffers on SB side and
> possibility to control it.
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
> For additional commands, e-mail: users-help@qpid.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under
load?
Posted by popalka <po...@ya.ru>.
Hi Robbie
Indeed we have some different cases on PROD.
1) Some messages processed by our app several times. Frequent use case.
2) Sometimes we got message with JMXDeliveryCount=2 with no log entries with
JMXDeliveryCount=1 on the same message before or after.
3) We processed message with JMXDeliveryCount=2 before message with
JMXDeliveryCount=1 (asked in start of the mail thread). Rare case.
Most likely there are lock expiration issues.
We have lock timeout 5 minutes, business code of our app process message in
several seconds. In some extreme cases it works 2 minutes at maximum.
So I was looking for interal queue/buffer inside Qpid Driver.
After investigation and discussion with you I think it's less probable than
I had think before.
Currently I think It is a queue or a buffer of Flow Frames on the Azure SB
side.
Behaviour is next:
1) Every thread of Spring's JmsDefaultListenerContainer produce pull
requests with timeout 1 second. This is default configuration.
2) Every pull request produce AMQP Flow Frame
3) If no messages in Azure SB queue, this Flow Frames buffered on Azure SB
side while we have connection/sessions open. The number of send Flow Frames
increases every 1 second at number of threads.
4) New messages arrives to Azure SB queue.
5) Azure SB buffered Flow Frames start processing
6) For first N messages lock is placed and those put on wire.
7) For next M messages , only lock is placed, because SB cannot put it on
wire - connection is busy.
8) On some messages lock expires, attribute DeliveryCount increases
9) Some messages processed by our app, but client acknowledging doesn't take
no effect, because lock expires, so we process such messages twice or more
times.
I'm going to ask Azure support about AMQP Flow Frames buffers on SB side and
possibility to control it.
--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under
load?
Posted by popalka <po...@ya.ru>.
I have 3 observation:
1.) Azure Service Bus place lock on message when receive Flow frame with
non-zero link credit
--------------------------------------------------------------------------------------------
The clock for the expiration of the lock on the message inside the
`queue/topic subscription` starts when the message is taken from the entity,
not when the message is put on the wire.
So, when Flow Frame with linkCredit=1 send to Azure SB it lead to place lock
on message
```
2018-05-30 10:14:33.867 TRACE --- [windows.net:-1]]
o.a.qpid.jms.provider.amqp.AmqpConsumer : Consumer
ID:a6d1d214-eb32-4917-8e27-5a7ed0edca2a:1:1:1 granting additional credit: 1
2018-05-30 10:14:50.138 TRACE --- [windows.net:-1]]
o.apache.qpid.jms.provider.amqp.FRAMES : SENT: Flow{nextIncomingId=1,
incomingWindow=2047, nextOutgoingId=1, outgoingWindow=2147483647, handle=0,
deliveryCount=0, linkCredit=1, available=null, drain=false, echo=false,
properties=null}```
2018-05-30 10:14:50.138 TRACE --- [windows.net:-1]]
o.a.q.j.t.netty.NettyTcpTransport : Attempted write of: 32 bytes
```
2.) Azure Service Bus ignores non-valid Disposition frames
---------------------------------------------------------
We receive message in `Transfer` frame, confirm read by `Disposition` frame.
But Azure SB ignores `Disposition` frames.
For example I made experiment with sending `Disposition` frame on
non-existing message. Azure SB silently accept it.
```
2018-05-30 10:16:00.710 TRACE --- [windows.net:-1]]
o.apache.qpid.jms.provider.amqp.FRAMES : RECV: Transfer{handle=0,
deliveryId=0,
deliveryTag=\x1e\x86\xa8'\xa4\x07qA\xb3\x8b\xf4\xa4\x9d\xa9\x00\xc8,
messageFormat=0, settled=null, more=false, rcvSettleMode=null, state=null,
resume=false, aborted=false, batchable=true}
2018-05-30 10:16:07.141 TRACE --- [windows.net:-1]]
o.apache.qpid.jms.provider.amqp.FRAMES : SENT: Disposition{role=RECEIVER,
first=0, last=0, settled=true, state=Accepted{}, batchable=false}
```
The 1) and 2) is really confusing. I expected, that message's lock placed
when client confirm successful read in terms of AMQP.
But Azure SB has own semantics on it.
3.) Possibly slow Runnable's queue inside ThreadPoolExecutor used by Apache
Qpid driver.
---------------------------------------------------------------------------------------
Frames processed by Apache Qpid driver by single thread in internal queue of
Runnables inside ThreadPoolExecutor
class org.apache.qpid.jms.provider.amqp.AmqpProvider
has field `ScheduledThreadPoolExecutor serializer`
It created inside constructor as
```
serializer = new ScheduledThreadPoolExecutor(1, new QpidJMSThreadFactory(
"AmqpProvider :(" + PROVIDER_SEQUENCE.incrementAndGet() + "):["
+
remoteURI.getScheme() + "://" + remoteURI.getHost() + ":" +
remoteURI.getPort() + "]", true));
```
Invoking of any methods like
Provider::pull
Provider::acknowledge
Provider::send
Provider::start
Provider::stop
or
TransportListener:onData
leads to creating of Runnable that placed to internal queue of Runnables of
ScheduledThreadPoolExecutor `serializer`.
Result of this queue consumed by several threads.
Current hypothesis
------------------
The Runnable's queue acts like a slow buffer, that lead to "strange"
behavior like unordered message processing.
For example:
1. Runnable with processing of `Flow` trace is placed to Runnable's queue.
(first attempt to read the message)
2. Azure SB place lock on message
3. Runnable's queue is filled by other tasks.
4. Lock on message expires.
5. Runnable with processing of `Flow` trace is placed to Runnable's queue.
(second attempt to read the message)
6. Runnable with processing of `Transfer` trace with second attempt is
placed to Runnable's queue.
7. Runnable with processing of `Transfer` trace with first attempt is
placed to Runnable's queue.
Also my current hypothesis that Runnable's queue is filled by garbage or
slow tasks.
Investigation is in progress.
--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under load?
Posted by Robbie Gemmell <ro...@gmail.com>.
I dont think youll find much useful in it without something to look for first.
On 29 May 2018 at 15:47, popalka <po...@ya.ru> wrote:
> I'll try to take heapdump when the issue will be reproduced on PROD
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
> For additional commands, e-mail: users-help@qpid.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under
load?
Posted by popalka <po...@ya.ru>.
I'll try to take heapdump when the issue will be reproduced on PROD
--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under
load?
Posted by popalka <po...@ya.ru>.
Robbie, thanks a lot for answer.
I'm trying to investigate issue more deeply and reproduce it locally (this
is issue from PROD).
Yes, receiveLocalOnly=true is redudant in our config since prefetch is
disabled, I read the source code and documentation.
Also we increase number of CPU cores on PROD. so CPU load less than 40%. It
didn't help.
Maybe we are victim of
http://qpid.2158936.n2.nabble.com/JMS-message-consumer-behavior-td7666936.html
or
https://issues.apache.org/jira/browse/QPIDJMS-297 (but is should not
affect, we use relatively fresh version 0.27.0)
My current hypothesis that instances of JmsMessageConsumer recreated by
recovery mechanism of Spring's DefaultMessageListenerContainer it can lead
to prefetching messages by Qpid driver with delayed processing by business
code.
Another hypothesis that JmsMessageConsumer badly cleaned by Spring's
DefaultMessageListenerContainer
Robbie Gemmell wrote
> The below doesnt really give enough information to reason about what
> happened, however some notes/observations:
>
> - The logs show two different consumers processing the message within
> a minute of each other. Probably due to the server handing it to a
> different consumer after the lock expired earlier, but its not
> possible to say much else with the details available.
> - Snippet 3 just shows the consumer granting the server a credit to
> send a message after receive was called. This is expected in general
> and necessary here in particular since prefetch is disabled.
> - The consumer has an intermediate buffer it puts arriving messages,
> but by disabling prefetch it should see only 1 message at a time go in
> it and then get removed directly by the recieving application thread.
> - The receiveLocalOnly=true probably shouldnt be used since its not
> possible for the client to work entirely on its local buffer when
> prefetch is disabled; it must go remote to ask the server for a
> message when receive is called, because it has not previously given
> credit for any messge to be sent yet.
>
> Robbie
Regards,
Anton Reshetnikov
--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: Apache Qpid and Azure Service bus: Is there internal buffer of
Qpid driver that can lead to duplicates/unordered messages processing under load?
Posted by Robbie Gemmell <ro...@gmail.com>.
The below doesnt really give enough information to reason about what
happened, however some notes/observations:
- The logs show two different consumers processing the message within
a minute of each other. Probably due to the server handing it to a
different consumer after the lock expired earlier, but its not
possible to say much else with the details available.
- Snippet 3 just shows the consumer granting the server a credit to
send a message after receive was called. This is expected in general
and necessary here in particular since prefetch is disabled.
- The consumer has an intermediate buffer it puts arriving messages,
but by disabling prefetch it should see only 1 message at a time go in
it and then get removed directly by the recieving application thread.
- The receiveLocalOnly=true probably shouldnt be used since its not
possible for the client to work entirely on its local buffer when
prefetch is disabled; it must go remote to ask the server for a
message when receive is called, because it has not previously given
credit for any messge to be sent yet.
Robbie
On 28 May 2018 at 09:23, popalka <po...@ya.ru> wrote:
> We use qpid-jms-client version 0.27.0 to work with Azure SB.
>
> What the cause of processing messages out of order under load?
>
> Currently we have next situation:
> 1) read message from SB by driver with JMSXDeliveryCount=1
> 2) SB place lock and increase deliveryCounter
> 3) after 5 minutes lock expires
> 4) read message from SB by driver with JMSXDeliveryCount=2
> 5) start processing of message with JMSXDeliveryCount=2 by business code of
> our application
> 7) message with with JMSXDeliveryCount=2 successfully processed and
> acknowledged
> 8) message removed from SB queue
> *9) start processing of message with JMSXDeliveryCount=1 by business code
> of our application* (!!!!!!)
> 10) try to acknowledge message with JMSXDeliveryCount=1 that gives user
> error on SB metrics
>
> Why the 9) is possible? Where message is stored inside driver? We disabled
> prefetch by driver. Why it holds inside driver so long (over 5 minutes)?
> We work in multi threaded environment and may be our CPU cores are under
> load, but anyway why priority of processing is broken?
>
> Connection parameters for SB are
> amqp.idleTimeout=120000
> jms.prefetchPolicy.all=0
> amqp.drainTimeout=0
>
> Also receiveLocalOnly=true on org.apache.qpid.jms.JmsConnectionFactory
>
> Acknowledge mode is client.
>
>
> Additional info:
> ================1==================
> Spring config for message-driven-channel-adapter:
>
> <int-jms:message-driven-channel-adapter id="reseller-orders-jms-in"
>
> destination-name="${serviceBus.reseller-orders.destination-name}"
>
> connection-factory="jmsConnectionFactory"
> acknowledge="client"
> channel="reseller-orders-in"
>
> error-channel="reseller-orders-errors"
>
> concurrent-consumers="${jms.concurrent-consumers:10}"
>
> max-concurrent-consumers="${jms.max-concurrent-consumers:40}"
> task-executor="resOrdExecutor"
>
> message-converter="gzipMessageConverter"
>
> auto-startup="${reseller-orders-flow.enabled:true}"/>
>
> <task:executor id="resOrdExecutor"
> queue-capacity="${jms.max-concurrent-consumers:40}"
> pool-size="${jms.concurrent-consumers:10}-${jms.max-concurrent-consumers:40}"/>
>
>
> ============2================
> Trace logs from our app:
> HeadersLogger is our app class
>
> grep "3e4861c4-359c-4d7b-82b3-01d3d0fc62ec:10:2:1-270"
> erpc-messaging.log.jms_consumer2.log
>
> 2018-05-25 08:14:18.988 TRACE 9844 --- [resOrdExecutor-9]
> org.apache.qpid.jms.JmsMessageConsumer :
> ID:03d307b2-ba5c-4b86-b430-64c3ac46e2dd:2:6:1 received message:
> JmsInboundMessageDispatch { sequence = 41, messageId =
> ID:3e4861c4-359c-4d7b-82b3-01d3d0fc62ec:10:2:1-270, consumerId =
> ID:03d307b2-ba5c-4b86-b430-64c3ac46e2dd:2:6:1 }
> 2018-05-25 08:14:18.988 DEBUG 9844 --- [resOrdExecutor-9]
> c.o.e.messaging.log.HeadersLogger : Process message with headers
> {jms_redelivered=true, JMSXDeliveryCount=2,
> jms_destination=reseller-orders-topic,
> id=28971091-996e-7a34-1e0d-a43d713c2ac2, priority=4,
> jms_timestamp=1527235569311,
> jms_messageId=ID:3e4861c4-359c-4d7b-82b3-01d3d0fc62ec:10:2:1-270,
> SOURCE_SYSTEM=EXPORT_ENGINE, timestamp=1527236058988}
> 2018-05-25 08:14:19.003 WARN 9844 --- [resOrdExecutor-9]
> c.o.e.messaging.log.HeadersLogger : More than one attempt to process
> jms message. Details : {jms_redelivered=true, JMSXDeliveryCount=2,
> jms_destination=reseller-orders-topic,
> id=28971091-996e-7a34-1e0d-a43d713c2ac2, priority=4,
> jms_timestamp=1527235569311,
> jms_messageId=ID:3e4861c4-359c-4d7b-82b3-01d3d0fc62ec:10:2:1-270,
> SOURCE_SYSTEM=EXPORT_ENGINE, timestamp=1527236058988}
>
> 2018-05-25 08:15:31.993 TRACE 9844 --- [resOrdExecutor-5]
> org.apache.qpid.jms.JmsMessageConsumer :
> ID:03d307b2-ba5c-4b86-b430-64c3ac46e2dd:2:3:1 received message:
> JmsInboundMessageDispatch { sequence = 45, messageId =
> ID:3e4861c4-359c-4d7b-82b3-01d3d0fc62ec:10:2:1-270, consumerId =
> ID:03d307b2-ba5c-4b86-b430-64c3ac46e2dd:2:3:1 }
> 2018-05-25 08:15:31.993 DEBUG 9844 --- [resOrdExecutor-5]
> c.o.e.messaging.log.HeadersLogger : Process message with headers
> {jms_redelivered=false, JMSXDeliveryCount=1,
> jms_destination=reseller-orders-topic,
> id=6b5c1284-c206-0aca-290d-444e3a112e6d, priority=4,
> jms_timestamp=1527235569311,
> jms_messageId=ID:3e4861c4-359c-4d7b-82b3-01d3d0fc62ec:10:2:1-270,
> SOURCE_SYSTEM=EXPORT_ENGINE, timestamp=1527236131993}
>
>
> =============3===========
>
> Sample driver trace log that cause increasing deliveryCount on SB side.
>
> 2018-05-27 22:33:18.317 TRACE --- [windows.net:-1]]
> o.a.qpid.jms.provider.amqp.AmqpConsumer : Consumer
> ID:67e44b2f-d492-4ee3-8ed0-6fb0f3345136:1:1:1 granting 1 additional credit
> for pull.
> 2018-05-27 22:33:18.318 TRACE --- [windows.net:-1]]
> o.apache.qpid.jms.provider.amqp.FRAMES : SENT: Flow{nextIncomingId=1,
> incomingWindow=2047, nextOutgoingId=1, outgoingWindow=2147483647, handle=0,
> deliveryCount=0, linkCredit=1, available=null, drain=false, echo=false,
> properties=null}
> 2018-05-27 22:33:18.318 INFO --- [windows.net:-1]]
> org.apache.qpid.jms.provider.amqp.BYTES : Sending:
> 0000002002000001005313c01307520170000007ff5201707fffffff43435201
> 2018-05-27 22:33:45.922 TRACE --- [windows.net:-1]]
> o.a.q.j.t.netty.NettyTcpTransport : Attempted write of: 32 bytes
>
>
>
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
> For additional commands, e-mail: users-help@qpid.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org