Uploaded image for project: 'WildFly'
  1. WildFly
  2. WFLY-7352

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

    XMLWordPrintable

Details

    • Bug
    • Status: Closed (View Workflow)
    • Blocker
    • Resolution: Done
    • None
    • 11.0.0.Alpha1
    • JMS
    • None
    • 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

    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
      

      Attachments

        Issue Links

          Activity

            People

              jmesnil1@redhat.com Jeff Mesnil
              jmesnil1@redhat.com Jeff Mesnil
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: