[
https://issues.apache.org/jira/browse/AMQ-7343?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Dominic Gagne updated AMQ-7343:
-------------------------------
Description:
h3. Problem Overview
We recently encountered an issue where a significant delay (often up to 20
seconds) occurs between the time a message is acknowledged by a consumer and
the time the next message is received from the broker. This issue only
manifests itself until fairly specific conditions, but we do have a
reproducible case. The problem occurs when the broker transport `nio+ssl` is
used and clients are running in Docker containers. ActiveMQ versions tested are
5.15.9 and 5.15.10. Default ActiveMQ broker configuration can be used (with the
exception of the nio+ssl transport). Disabling either nio or ssl in the broker
configuration prevents this issue from occurring. Producing messages to the
broker is not impacted whatsoever, this is strictly an issue for consumers.
Using Wireshark, we analyzed all ingress and egress traffic from the Docker
network while the consumer was running. This analysis revealed that there are
in fact long periods of no activity on the network, despite the fact that the
client immediately acknowledges the message and is ready to receive a new one.
In addition to a long delay between a message being acknowledged and the next
message being received, the initial connection to the broker takes upwards of
15 seconds. This is not the case if either nio or ssl is disabled (e.g.
transport is just 'nio' or just 'ssl' works fine). Enabling verbose logging on
the broker has not yet yielded any useful information, but we are continuing
our investigation.
h3.
h3. Expected results (can be achieved by disabling nio transport):
Sending 500 messages to the broker and then consuming them all is completed in
~2.5 seconds
h4. Receive timestamps (see currentTime):
Received Queue 1 0 - *currentTime*: 972 msgId:
67ddfe5f-023c-4090-9d1c-ac60160947cc, msgTimeStamp: 11/14/2019 20:10:29
Received Queue 1 1 - *currentTime*: 981 msgId:
803fdea7-546f-4a80-ad3b-ad6c89669fbc, msgTimeStamp: 11/14/2019 20:10:29
Received Queue 1 2 - *currentTime*: 983 msgId:
dbccb3c6-4f3f-4ce5-97d8-d77a41e46561, msgTimeStamp: 11/14/2019 20:10:29
Received Queue 1 3 - *currentTime*: 984 msgId:
65c550aa-1260-4e3f-9d7c-d51a62f4a3d0, msgTimeStamp: 11/14/2019 20:10:29
Received Queue 1 4 - *currentTime*: 986 msgId:
725064b8-c796-429c-bd98-a48a15913d81, msgTimeStamp: 11/14/2019 20:10:29
Received Queue 1 5 - *currentTime*: 988 msgId:
a7335557-c564-4bb0-984e-7d87fde6646e, msgTimeStamp: 11/14/2019 20:10:29
h3. Actual results:
Connection takes ~15 seconds
Producing 500 messages takes < 1 second, as expected
Consumption of messages is delayed, alternates back and forth between ~10
seconds and ~20 seconds between ack time and next message being received.
h4. Receive timestamps (see currentTime):
Received Queue 1 0 - *currentTime*: 60961 msgId:
370d03c9-8f00-4e49-b38d-3fa1ec4a0b3e, msgTimeStamp: 11/14/2019 20:13:06
Received Queue 1 1 - *currentTime*: 80741 msgId:
93f1f217-7be4-4a8e-a7a6-7edde541d260, msgTimeStamp: 11/14/2019 20:13:26
Received Queue 1 2 - *currentTime*: 90886 msgId:
23919310-a1f3-4891-98c3-886e64639eb4, msgTimeStamp: 11/14/2019 20:13:36
Received Queue 1 3 - *currentTime*: 110731 msgId:
cb2bdc40-a146-4f47-8ad9-efd15e411ce5, msgTimeStamp: 11/14/2019 20:13:56
Received Queue 1 4 - *currentTime*: 120933 msgId:
b241ac14-3573-40ef-a611-5dac34ea0ab4, msgTimeStamp: 11/14/2019 20:14:06
Received Queue 1 5 - *currentTime*: 140734 msgId:
0f7eda18-8998-41c2-aa8b-5cacfc791597, msgTimeStamp: 11/14/2019 20:14:25
h2. To reproduce using the attached example:
{{docker build -f ActiveMqTest/Dockerfile-ActiveMqTest -t 'activemqtest'
ActiveMqTest/}}
{{docker run activemqtest}}
was:
h3. Problem Overview
We recently encountered an issue where a significant delay (often up to 20
seconds) occurs between the time a message is acknowledged by a consumer and
the time the next message is received from the broker. This issue only
manifests itself until fairly specific conditions, but we do have a
reproducible case. The problem occurs when the broker transport `nio+ssl` is
used and clients are running in Docker containers. ActiveMQ versions tested are
5.15.9 and 5.15.10. Default ActiveMQ broker configuration can be used (with the
exception of the nio+ssl transport). Disabling either nio or ssl in the broker
configuration prevents this issue from occurring. Producing messages to the
broker is not impacted whatsoever, this is strictly an issue for consumers.
Using Wireshark, we analyzed all ingress and egress traffic from the Docker
network while the consumer was running. This analysis revealed that there are
in fact long periods of no activity on the network, despite the fact that the
client immediately acknowledges the message and is ready to receive a new one.
In addition to a long delay between a message being acknowledged and the next
message being received, the initial connection to the broker takes upwards of
15 seconds. This is not the case if either nio or ssl is disabled (e.g.
transport is just 'nio' or just 'ssl' works fine). Enabling verbose logging on
the broker has not yet yielded any useful information, but we are continuing
our investigation.
h3. Expected results (can be achieved by disabling nio transport):
Sending 500 messages to the broker and then consuming them all is completed in
~2.5 seconds
h4. Receive timestamps (see currentTime):
Received Queue 1 0 - *currentTime*: 972 msgId:
67ddfe5f-023c-4090-9d1c-ac60160947cc, msgTimeStamp: 11/14/2019 20:10:29
Received Queue 1 1 - *currentTime*: 981 msgId:
803fdea7-546f-4a80-ad3b-ad6c89669fbc, msgTimeStamp: 11/14/2019 20:10:29
Received Queue 1 2 - *currentTime*: 983 msgId:
dbccb3c6-4f3f-4ce5-97d8-d77a41e46561, msgTimeStamp: 11/14/2019 20:10:29
Received Queue 1 3 - *currentTime*: 984 msgId:
65c550aa-1260-4e3f-9d7c-d51a62f4a3d0, msgTimeStamp: 11/14/2019 20:10:29
Received Queue 1 4 - *currentTime*: 986 msgId:
725064b8-c796-429c-bd98-a48a15913d81, msgTimeStamp: 11/14/2019 20:10:29
Received Queue 1 5 - *currentTime*: 988 msgId:
a7335557-c564-4bb0-984e-7d87fde6646e, msgTimeStamp: 11/14/2019 20:10:29
h3. Actual results:
Connection takes ~15 seconds
Producing 500 messages takes < 1 second, as expected
Consumption of messages is delayed, alternates back and forth between ~10
seconds and ~20 seconds between ack time and next message being received.
h4. Receive timestamps (see currentTime):
Received Queue 1 0 - *currentTime*: 60961 msgId:
370d03c9-8f00-4e49-b38d-3fa1ec4a0b3e, msgTimeStamp: 11/14/2019 20:13:06
Received Queue 1 1 - *currentTime*: 80741 msgId:
93f1f217-7be4-4a8e-a7a6-7edde541d260, msgTimeStamp: 11/14/2019 20:13:26
Received Queue 1 2 - *currentTime*: 90886 msgId:
23919310-a1f3-4891-98c3-886e64639eb4, msgTimeStamp: 11/14/2019 20:13:36
Received Queue 1 3 - *currentTime*: 110731 msgId:
cb2bdc40-a146-4f47-8ad9-efd15e411ce5, msgTimeStamp: 11/14/2019 20:13:56
Received Queue 1 4 - *currentTime*: 120933 msgId:
b241ac14-3573-40ef-a611-5dac34ea0ab4, msgTimeStamp: 11/14/2019 20:14:06
Received Queue 1 5 - *currentTime*: 140734 msgId:
0f7eda18-8998-41c2-aa8b-5cacfc791597, msgTimeStamp: 11/14/2019 20:14:25
h2. To reproduce using the attached example:
{{docker build -f ActiveMqTest/Dockerfile-ActiveMqTest -t 'activemqtest'
ActiveMqTest/}}
{{docker run activemqtest}}
> Delayed Consumption of Messages with nio+ssl Transport
> ------------------------------------------------------
>
> Key: AMQ-7343
> URL: https://issues.apache.org/jira/browse/AMQ-7343
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker
> Affects Versions: 5.15.9, 5.15.10
> Environment: ActiveMQ version: 5.15.10 or 5.15.9
> ActiveMQ configuration: default
> Client: C# running in Docker container
> Transport: nio+ssl
>
>
> Reporter: Dominic Gagne
> Priority: Critical
> Attachments: ActiveMqTest_Consumption.zip
>
>
> h3. Problem Overview
> We recently encountered an issue where a significant delay (often up to 20
> seconds) occurs between the time a message is acknowledged by a consumer and
> the time the next message is received from the broker. This issue only
> manifests itself until fairly specific conditions, but we do have a
> reproducible case. The problem occurs when the broker transport `nio+ssl` is
> used and clients are running in Docker containers. ActiveMQ versions tested
> are 5.15.9 and 5.15.10. Default ActiveMQ broker configuration can be used
> (with the exception of the nio+ssl transport). Disabling either nio or ssl in
> the broker configuration prevents this issue from occurring. Producing
> messages to the broker is not impacted whatsoever, this is strictly an issue
> for consumers.
> Using Wireshark, we analyzed all ingress and egress traffic from the Docker
> network while the consumer was running. This analysis revealed that there are
> in fact long periods of no activity on the network, despite the fact that the
> client immediately acknowledges the message and is ready to receive a new one.
> In addition to a long delay between a message being acknowledged and the next
> message being received, the initial connection to the broker takes upwards of
> 15 seconds. This is not the case if either nio or ssl is disabled (e.g.
> transport is just 'nio' or just 'ssl' works fine). Enabling verbose logging
> on the broker has not yet yielded any useful information, but we are
> continuing our investigation.
> h3.
> h3. Expected results (can be achieved by disabling nio transport):
> Sending 500 messages to the broker and then consuming them all is completed
> in ~2.5 seconds
> h4. Receive timestamps (see currentTime):
> Received Queue 1 0 - *currentTime*: 972 msgId:
> 67ddfe5f-023c-4090-9d1c-ac60160947cc, msgTimeStamp: 11/14/2019 20:10:29
> Received Queue 1 1 - *currentTime*: 981 msgId:
> 803fdea7-546f-4a80-ad3b-ad6c89669fbc, msgTimeStamp: 11/14/2019 20:10:29
> Received Queue 1 2 - *currentTime*: 983 msgId:
> dbccb3c6-4f3f-4ce5-97d8-d77a41e46561, msgTimeStamp: 11/14/2019 20:10:29
> Received Queue 1 3 - *currentTime*: 984 msgId:
> 65c550aa-1260-4e3f-9d7c-d51a62f4a3d0, msgTimeStamp: 11/14/2019 20:10:29
> Received Queue 1 4 - *currentTime*: 986 msgId:
> 725064b8-c796-429c-bd98-a48a15913d81, msgTimeStamp: 11/14/2019 20:10:29
> Received Queue 1 5 - *currentTime*: 988 msgId:
> a7335557-c564-4bb0-984e-7d87fde6646e, msgTimeStamp: 11/14/2019 20:10:29
> h3. Actual results:
> Connection takes ~15 seconds
> Producing 500 messages takes < 1 second, as expected
> Consumption of messages is delayed, alternates back and forth between ~10
> seconds and ~20 seconds between ack time and next message being received.
> h4. Receive timestamps (see currentTime):
> Received Queue 1 0 - *currentTime*: 60961 msgId:
> 370d03c9-8f00-4e49-b38d-3fa1ec4a0b3e, msgTimeStamp: 11/14/2019 20:13:06
> Received Queue 1 1 - *currentTime*: 80741 msgId:
> 93f1f217-7be4-4a8e-a7a6-7edde541d260, msgTimeStamp: 11/14/2019 20:13:26
> Received Queue 1 2 - *currentTime*: 90886 msgId:
> 23919310-a1f3-4891-98c3-886e64639eb4, msgTimeStamp: 11/14/2019 20:13:36
> Received Queue 1 3 - *currentTime*: 110731 msgId:
> cb2bdc40-a146-4f47-8ad9-efd15e411ce5, msgTimeStamp: 11/14/2019 20:13:56
> Received Queue 1 4 - *currentTime*: 120933 msgId:
> b241ac14-3573-40ef-a611-5dac34ea0ab4, msgTimeStamp: 11/14/2019 20:14:06
> Received Queue 1 5 - *currentTime*: 140734 msgId:
> 0f7eda18-8998-41c2-aa8b-5cacfc791597, msgTimeStamp: 11/14/2019 20:14:25
> h2. To reproduce using the attached example:
> {{docker build -f ActiveMqTest/Dockerfile-ActiveMqTest -t 'activemqtest'
> ActiveMqTest/}}
> {{docker run activemqtest}}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
