[
https://issues.apache.org/jira/browse/AMQ-7343?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Dominic Gagne updated AMQ-7343:
-------------------------------
Attachment: ActiveMqTest_consumption.zip
> 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.
> 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.
> 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)
