Uploaded image for project: 'JBoss Enterprise Application Platform'
  1. JBoss Enterprise Application Platform
  2. JBEAP-6443

XNIO bridge for Artemis doesn't work with newer versions of Netty and Artemis.

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Blocker Blocker
    • 7.1.0.DR12
    • 7.1.0.DR6
    • ActiveMQ
    • Regression
    • Hide

      Steps to reproduce the issue - NOT 100% reproducer:

      git clone git://git.app.eng.bos.redhat.com/jbossqe/eap-tests-hornetq.git
cd eap-tests-hornetq/scripts/
scp jbossqa@10.40.4.81:~/tmp/jboss-eap-7.1.0.DR6-artemis-140.zip . # see private comment below for password
# change path per location of jboss-eap-7.1.0.DR6-artemis-140.zip
groovy -DEAP_ZIP_URL=file:///home/mnovak/tmp/jboss-eap-7.1.0.DR6-artemis-140.zip PrepareServers7.groovy
export WORKSPACE=$PWD
export JBOSS_HOME_1=$WORKSPACE/server1/jboss-eap
export JBOSS_HOME_2=$WORKSPACE/server2/jboss-eap
export JBOSS_HOME_3=$WORKSPACE/server3/jboss-eap
export JBOSS_HOME_4=$WORKSPACE/server4/jboss-eap
cd ../jboss-hornetq-testsuite/
sh repeat_test_until_fail.sh JmsMessagesTestCase#testThatDivertedMessagesIsAlsoScheduledNonExclusiveLargeMessage | tee test.log
      Show
      Steps to reproduce the issue - NOT 100% reproducer: git clone git: //git.app.eng.bos.redhat.com/jbossqe/eap-tests-hornetq.git cd eap-tests-hornetq/scripts/ scp jbossqa@10.40.4.81:~/tmp/jboss-eap-7.1.0.DR6-artemis-140.zip . # see private comment below for password # change path per location of jboss-eap-7.1.0.DR6-artemis-140.zip groovy -DEAP_ZIP_URL=file: ///home/mnovak/tmp/jboss-eap-7.1.0.DR6-artemis-140.zip PrepareServers7.groovy export WORKSPACE=$PWD export JBOSS_HOME_1=$WORKSPACE/server1/jboss-eap export JBOSS_HOME_2=$WORKSPACE/server2/jboss-eap export JBOSS_HOME_3=$WORKSPACE/server3/jboss-eap export JBOSS_HOME_4=$WORKSPACE/server4/jboss-eap cd ../jboss-hornetq-testsuite/ sh repeat_test_until_fail.sh JmsMessagesTestCase#testThatDivertedMessagesIsAlsoScheduledNonExclusiveLargeMessage | tee test.log

      Edit:
      Issue described below can be solved by upgrade to newer netty version. This however brings issue with xnio-netty-transport which must be modified to be able to work with newer version of netty. See comment [1] for symptoms. This issue has basically transformed to fixing xnio-netty-transport library.

      Original issue is blocker because it's regression against previous EAP 7.1.0.DRx versions. If xnio-netty-transport is not fixed with upgrade of netty then it's also blocker as no client will be able to connect to EAP server.

      [1] https://issues.jboss.org/browse/JBEAP-6443?focusedCommentId=13318622&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-13318622

      Original description:
      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:

      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

      Response from server comes ~10s later - it's packet SessionReceiveMessage:

      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]

      in the mean time client is waiting on - ---org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl.receive(ClientConsumerImpl.java:261):

       wait(Long.MAX_VALUE);

      and is waiting for notify. From server log I can see that SessionReceiveMessage was send at:

      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

      but it wasn't flushed and for some reason is actually send ~10s later with the large message:

      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

        1. server-trace.zip
          1.44 MB
        2. test.log
          136 kB
        3. test-suite.log
          4.01 MB

              jmesnil1@redhat.com Jeff Mesnil
              mnovak1@redhat.com Miroslav Novak
              Votes:
              0 Vote for this issue
              Watchers:
              9 Start watching this issue

                Created:
                Updated:
                Resolved: