[jboss-jira] [JBoss JIRA] (WFLY-7352) XNIO bridge for Artemis doesn't work with newer versions of Netty and Artemis.

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}