Uploaded image for project: 'AMQ Broker'
  1. AMQ Broker
  2. ENTMQBR-976

[org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler] Sasl can't be initiated after transport has started processing

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Obsolete
    • Icon: Minor Minor
    • None
    • AMQ 7.0.3.GA
    • amqp-protocol

      While trying to reproduce ENTMQCL-600, which involved starting a stopping AMQ 7.0.3 broker in a loop while a client was reconnecting to it, I noticed the following error message. It has appeared only once (as far as I've noticed) and I was not able to reproduce it since.

      Does it signal any problem with the broker that needs to be investigated, or can it be safely ignored?

      I have seen this once before already, https://issues.apache.org/jira/browse/QPIDJMS-345

         /  \  | \  / | |  | | | |_) |_  _ | | ___ _ 
         / /\ \ | |\/| | |  | | |  _ <| '/ _ \| |/ / _ \ '|
        / __ \| |  | | || | | |_) | | | (_) |   <  __/ |
       /_/    \_\_|  |_|\_\_\ |/|_|  \_/|_|\_\___|_|
      
       Red Hat JBoss AMQ 7.0.3.GA
      
      
      17:08:48,099 INFO  [org.apache.activemq.artemis.integration.bootstrap] AMQ101000: Starting ActiveMQ Artemis Server
      17:08:48,206 INFO  [org.apache.activemq.artemis.core.server] AMQ221000: live Message Broker is starting with configuration Broker Configuration (clustered=true,journalDirectory=./data/journal,bindingsDirectory=./data/bindings,largeMessagesDirectory=./data/large-messages,pagingDirectory=./data/paging)
      17:08:50,516 WARN  [org.apache.activemq.artemis.core.server] AMQ222007: Security risk! Apache ActiveMQ Artemis is running with the default cluster admin user and default password. Please see the cluster chapter in the ActiveMQ Artemis User Guide for instructions on how to change this.
      17:08:50,581 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-server]. Adding protocol support for: CORE
      17:08:50,581 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-amqp-protocol]. Adding protocol support for: AMQP
      17:08:50,585 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-hornetq-protocol]. Adding protocol support for: HORNETQ
      17:08:50,585 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-mqtt-protocol]. Adding protocol support for: MQTT
      17:08:50,585 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-openwire-protocol]. Adding protocol support for: OPENWIRE
      17:08:50,586 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-stomp-protocol]. Adding protocol support for: STOMP
      17:08:50,681 INFO  [org.apache.activemq.artemis.core.server] AMQ221003: Deploying queue DLQ
      17:08:50,754 INFO  [org.apache.activemq.artemis.core.server] AMQ221003: Deploying queue ExpiryQueue
      17:08:50,759 INFO  [org.apache.activemq.artemis.core.server] AMQ221003: Deploying queue TPX
      17:08:51,047 INFO  [org.apache.activemq.artemis.core.server] AMQ221020: Started NIO Acceptor at 172.16.201.44:61616 for protocols [CORE,MQTT,AMQP,STOMP,HORNETQ,OPENWIRE]
      17:08:51,049 INFO  [org.apache.activemq.artemis.core.server] AMQ221020: Started NIO Acceptor at 172.16.201.44:5445 for protocols [HORNETQ,STOMP]
      17:08:51,053 INFO  [org.apache.activemq.artemis.core.server] AMQ221020: Started NIO Acceptor at 172.16.201.44:5672 for protocols [AMQP]
      17:08:51,054 INFO  [org.apache.activemq.artemis.core.server] AMQ221020: Started NIO Acceptor at 172.16.201.44:1883 for protocols [MQTT]
      17:08:51,058 INFO  [org.apache.activemq.artemis.core.server] AMQ221020: Started NIO Acceptor at 172.16.201.44:61613 for protocols [STOMP]
      17:08:51,059 INFO  [org.apache.activemq.artemis.core.server] AMQ221007: Server is now live
      17:08:51,059 INFO  [org.apache.activemq.artemis.core.server] AMQ221001: Apache ActiveMQ Artemis Message Broker version 2.0.0.amq-700013-redhat-1 [testamqbroker-master, nodeID=df61d787-f7b2-11e7-aa0b-fa163ed4dc1b] 
      17:08:53,058 WARN  [org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler] Sasl can't be initiated after transport has started processing: java.lang.IllegalStateException: Sasl can't be initiated after transport has started processing
      		at org.apache.qpid.proton.engine.impl.TransportImpl.sasl(TransportImpl.java:350) [proton-j-0.18.0.redhat-1.jar:]
      		at org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler.createServerSASL(ProtonHandler.java:150) [artemis-amqp-protocol-2.0.0.amq-700013-redhat-1.jar:]
      		at org.apache.activemq.artemis.protocol.amqp.proton.AMQPConnectionContext.onAuthInit(AMQPConnectionContext.java:323) [artemis-amqp-protocol-2.0.0.amq-700013-redhat-1.jar:]
      		at org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler.dispatchAuth(ProtonHandler.java:309) [artemis-amqp-protocol-2.0.0.amq-700013-redhat-1.jar:]
      		at org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler.inputBuffer(ProtonHandler.java:204) [artemis-amqp-protocol-2.0.0.amq-700013-redhat-1.jar:]
      		at org.apache.activemq.artemis.protocol.amqp.proton.AMQPConnectionContext.inputBuffer(AMQPConnectionContext.java:124) [artemis-amqp-protocol-2.0.0.amq-700013-redhat-1.jar:]
      		at org.apache.activemq.artemis.protocol.amqp.broker.ActiveMQProtonRemotingConnection.bufferReceived(ActiveMQProtonRemotingConnection.java:138) [artemis-amqp-protocol-2.0.0.amq-700013-redhat-1.jar:]
      		at org.apache.activemq.artemis.core.remoting.server.impl.RemotingServiceImpl$DelegatingBufferHandler.bufferReceived(RemotingServiceImpl.java:628) [artemis-server-2.0.0.amq-700013-redhat-1.jar:2.0.0.amq-700013-redhat-1]
      		at org.apache.activemq.artemis.core.remoting.impl.netty.ActiveMQChannelHandler.channelRead(ActiveMQChannelHandler.java:69) [artemis-core-client-2.0.0.amq-700013-redhat-1.jar:2.0.0.amq-700013-redhat-1]
      		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at io.netty.handler.codec.ByteToMessageDecoder.handlerRemoved(ByteToMessageDecoder.java:219) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at io.netty.channel.DefaultChannelPipeline.callHandlerRemoved0(DefaultChannelPipeline.java:631) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at io.netty.channel.DefaultChannelPipeline.remove(DefaultChannelPipeline.java:468) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at io.netty.channel.DefaultChannelPipeline.remove(DefaultChannelPipeline.java:428) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at org.apache.activemq.artemis.core.protocol.ProtocolHandler$ProtocolDecoder.decode(ProtocolHandler.java:185) [artemis-server-2.0.0.amq-700013-redhat-1.jar:2.0.0.amq-700013-redhat-1]
      		at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:411) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:248) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at org.apache.activemq.artemis.core.protocol.ProtocolHandler$ProtocolDecoder.channelRead(ProtocolHandler.java:128) [artemis-server-2.0.0.amq-700013-redhat-1.jar:2.0.0.amq-700013-redhat-1]
      		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1334) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:926) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:134) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:624) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:559) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:476) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:438) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858) [netty-all-4.1.9.Final-redhat-2.jar:4.1.9.Final-redhat-2]
      		at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_151]
      
      INFO  | main | Initialized dispatch-hawtio-console plugin
      17:08:54,046 INFO  [org.apache.activemq.artemis] AMQ241001: HTTP Server started at http://localhost:8161
      17:08:54,047 INFO  [org.apache.activemq.artemis] AMQ241002: Artemis Jolokia REST API available at http://localhost:8161/jolokia
      17:09:16,664 WARN  [org.apache.activemq.artemis.utils.actors.OrderedExecutor] Server locator is closed (maybe it was garbage collected): java.lang.IllegalStateException: Server locator is closed (maybe it was garbage collected)
      		at org.apache.activemq.artemis.core.client.impl.ServerLocatorImpl.assertOpen(ServerLocatorImpl.java:1803) [artemis-core-client-2.0.0.amq-700013-redhat-1.jar:2.0.0.amq-700013-redhat-1]
      		at org.apache.activemq.artemis.core.client.impl.ServerLocatorImpl.createSessionFactory(ServerLocatorImpl.java:739) [artemis-core-client-2.0.0.amq-700013-redhat-1.jar:2.0.0.amq-700013-redhat-1]
      		at org.apache.activemq.artemis.core.client.impl.ServerLocatorImpl.connect(ServerLocatorImpl.java:627) [artemis-core-client-2.0.0.amq-700013-redhat-1.jar:2.0.0.amq-700013-redhat-1]
      		at org.apache.activemq.artemis.core.client.impl.ServerLocatorImpl.connect(ServerLocatorImpl.java:609) [artemis-core-client-2.0.0.amq-700013-redhat-1.jar:2.0.0.amq-700013-redhat-1]
      		at org.apache.activemq.artemis.core.server.cluster.ClusterController$ConnectRunnable.run(ClusterController.java:414) [artemis-server-2.0.0.amq-700013-redhat-1.jar:2.0.0.amq-700013-redhat-1]
      		at org.apache.activemq.artemis.utils.actors.OrderedExecutor.doTask(OrderedExecutor.java:42) [artemis-commons-2.0.0.amq-700013-redhat-1.jar:2.0.0.amq-700013-redhat-1]
      		at org.apache.activemq.artemis.utils.actors.OrderedExecutor.doTask(OrderedExecutor.java:31) [artemis-commons-2.0.0.amq-700013-redhat-1.jar:2.0.0.amq-700013-redhat-1]
      		at org.apache.activemq.artemis.utils.actors.ProcessorBase$ExecutorTask.run(ProcessorBase.java:53) [artemis-commons-2.0.0.amq-700013-redhat-1.jar:2.0.0.amq-700013-redhat-1]
      		at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_151]
      		at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_151]
      		at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_151]
      
      INFO  | shutdown-hook | Destroyed dispatch-hawtio-console plugin
      17:09:16,944 INFO  [org.apache.activemq.artemis.core.server] AMQ221002: Apache ActiveMQ Artemis Message Broker version 2.0.0.amq-700013-redhat-1 [df61d787-f7b2-11e7-aa0b-fa163ed4dc1b] stopped, uptime 28.757 seconds
      [1]+  Exit 143                amq-broker-7.0.3/i0/bin/artemis run
      

              rh-ee-ataylor Andy Taylor
              jdanek@redhat.com Jiri Daněk
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

                Created:
                Updated:
                Resolved: