]
Jeff Mesnil moved JBEAP-6518 to WFLY-7352:
------------------------------------------
Project: WildFly (was: JBoss Enterprise Application Platform)
Key: WFLY-7352 (was: JBEAP-6518)
Workflow: GIT Pull Request workflow (was: CDW with loose statuses v1)
Component/s: JMS
(was: ActiveMQ)
Affects Version/s: (was: 7.1.0.DR6)
XNIO bridge for Artemis doesn't work with newer versions of Netty
and Artemis.
------------------------------------------------------------------------------
Key: WFLY-7352
URL:
https://issues.jboss.org/browse/WFLY-7352
Project: WildFly
Issue Type: Bug
Components: JMS
Reporter: Jeff Mesnil
Assignee: Jeff Mesnil
Priority: Blocker
Test scenario:
1. Start server EAP 7.1.0.DR6 (with Artemis 1.4.0) with queue InQueue and OutQueue.
Configure non-exclusive divert from InQueue to OutQueue.
2. Send large message to InQueue with scheduled delivery 10 seconds
3. Start consumer on OutQueue with receive timeout 1000ms and check that NO message was
received
4. Start consumer on InQueue with receive timeout 1000ms and check that NO message was
received
5. Start consumer on InQueue with receive timeout 11000ms and check that message is
received
6. Start consumer on OutQueue with receive timeout 11000ms and check that message is
received
Result:
Sometimes happens that consumer in step 3. receives a message. By checking trace logs,
consumer in step 3. was receiving message 9664ms instead of ~1000ms.
In attachment is trace log from client and server and test log with client thread dump
during ~10s receive.
Investigation:
In the moment when client tries to receive a message there is send
SessionForceConsumerDelivery packet by client:
{code}
15:07:07,589 Thread-11 INFO
[org.jboss.qa.artemis.test.messages.JmsMessagesTestCase$ReceiveThread:474] Start message
comsumption from original queue with receive timeout 1000ms
15:07:07,590 Thread-11 TRACE
[org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl:386]
org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl@332729ad{consumerContext=ActiveMQConsumerContext{id=0},
queueName=jms.queue.OutQueue}:: receive(1000)
15:07:07,590 Thread-11 TRACE
[org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl:191]
org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl@332729ad{consumerContext=ActiveMQConsumerContext{id=0},
queueName=jms.queue.OutQueue}::receive(1000, false)
15:07:08,591 Thread-11 TRACE
[org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl:370]
org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl@332729ad{consumerContext=ActiveMQConsumerContext{id=0},
queueName=jms.queue.OutQueue}::Returning null
15:07:08,591 Thread-11 TRACE
[org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl:392]
org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl@332729ad{consumerContext=ActiveMQConsumerContext{id=0},
queueName=jms.queue.OutQueue}:: receive(1000) -> null, trying again with receive(0)
15:07:08,591 Thread-11 TRACE
[org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl:191]
org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl@332729ad{consumerContext=ActiveMQConsumerContext{id=0},
queueName=jms.queue.OutQueue}::receive(0, true)
15:07:08,592 Thread-11 TRACE
[org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl:301]
org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl@332729ad{consumerContext=ActiveMQConsumerContext{id=0},
queueName=jms.queue.OutQueue}::Forcing delivery
15:07:08,593 Thread-11 TRACE
[org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl:248] Sending packet
nonblocking PACKET(SessionForceConsumerDelivery)[type=78, channelID=11,
packetObject=SessionForceConsumerDelivery, consumerID=0, sequence=0] on channeID=11
15:07:08,604 Thread-11 TRACE
[org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl:286] Writing buffer for
channelID=11
{code}
Response from server comes ~10s later - it's packet SessionReceiveMessage:
{code}
15:07:17,250 Thread-0 (ActiveMQ-client-netty-threads-1138697171) TRACE
[org.apache.activemq.artemis.core.protocol.core.impl.RemotingConnectionImpl:354] handling
packet PACKET(SessionReceiveMessage)[type=75, chan
nelID=11, packetObject=SessionReceiveMessage, message=ClientMessageImpl[messageID=44,
durable=false,
address=jms.queue.OutQueue,userID=null,properties=TypedProperties[_hornetq.forced.delivery.seq=0]],
consumerID
=0, deliveryCount=0]
{code}
in the mean time client is waiting on -
---org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl.receive(ClientConsumerImpl.java:261):
{noformat}
wait(Long.MAX_VALUE);
{noformat}
and is waiting for notify. From server log I can see that SessionReceiveMessage was send
at:
{code}
15:07:08,621 TRACE [org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl]
(Thread-18
(ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$2@39cb2b3a-1512482465))
Sending packet nonblocking PACKET(SessionReceiveMessage)[type=75, channelID=11,
packetObject=SessionReceiveMessage,
message=ServerMessage[messageID=44,durable=false,userID=null,priority=0, bodySize=50,
timestamp=0,expiration=0, durable=false,
address=jms.queue.OutQueue,properties=TypedProperties[_hornetq.forced.delivery.seq=0]]@1525441837,
consumerID=0, deliveryCount=0] on channeID=11
15:07:08,633 TRACE [org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl]
(Thread-18
(ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$2@39cb2b3a-1512482465))
Writing buffer for channelID=11
{code}
but it wasn't flushed and for some reason is actually send ~10s later with the large
message:
{code}
15:07:17,236 TRACE [org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl]
(Thread-27
(ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$2@39cb2b3a-1512482465))
Sending pa
cket nonblocking PACKET(SessionReceiveLargeMessage)[type=76, channelID=11,
packetObject=SessionReceiveLargeMessage, consumerID=0, deliveryCount=1,
largeMessageSize=409605, message=LargeServerMessage[messageID=40
,durable=true,userID=1befe4c2-920f-11e6-9ae8-3ca9f4349bfc,priority=4, timestamp=Fri Oct
14 15:07:07 CEST 2016,expiration=0, durable=true,
address=jms.queue.OutQueue,properties=TypedProperties[__AMQ_CID=1bdc35af-
920f-11e6-9ae8-3ca9f4349bfc,_AMQ_SCHED_DELIVERY=1476450437224,_AMQ_ORIG_ADDRESS=jms.queue.InQueue,_AMQ_ORIG_MESSAGE_ID=36,counter=0,_AMQ_DUPL_ID=16c2be09-573a-4e02-a369-6a36c2f32fbd,_AMQ_LARGE_SIZE=409605]]@1994
218683] on channeID=11
15:07:17,246 TRACE [org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl]
(Thread-27
(ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$2@39cb2b3a-1512482465))
Writing bu
ffer for channelID=11
15:07:17,247 TRACE [org.xnio.nio.selector] (default I/O-1) Selected on
sun.nio.ch.EPollSelectorImpl@61ea580a
15:07:17,247 TRACE [org.xnio.nio] (default I/O-1) Running task
io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask@5c93c5d7
{code}