[
https://issues.apache.org/jira/browse/QPIDJMS-345?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Robbie Gemmell resolved QPIDJMS-345.
------------------------------------
Resolution: Invalid
Resolving as from the info given this appears to be a broker issue, with the
client behaving as expected in the situation.
The client threw an exception because it tried connecting using SASL and the
brokers initial response indicated it didnt support SASL. The logs show the
broker failing to initiate the SASL layer in proton for a connection, and that
presumably leaves the broker trasmitting the bare non-SASL AMQP header to the
client, thus causing the client to throw.
> TransportException: AMQP SASL header mismatch value 0, expecting 3. In state:
> HEADER4
> -------------------------------------------------------------------------------------
>
> Key: QPIDJMS-345
> URL: https://issues.apache.org/jira/browse/QPIDJMS-345
> Project: Qpid JMS
> Issue Type: Bug
> Components: qpid-jms-client
> Affects Versions: 0.27.0
> Reporter: Jiri Daněk
> Priority: Minor
> Labels: irreproducible
> Attachments: failedqpidjmstests.txt
>
>
> Reproducibility: I've been unable to reproduce this. I saw it once in a
> Travis Build, which I restarted (log from it is attached). I tried running
> the tests in a loop against Artemis 2.4.0 (RC1) and the tests always passed.
> Triggering the Travis build repeatedly also did not result in a fail.
> The Travis build in queston is
> https://travis-ci.org/rh-messaging/cli-java/builds/297841655. Log on Travis
> was overwritten by subsequent runs, it is attached to this issue.
> What the test does is to send to queue, browse the queue and receive from the
> queue. The error appeared after browsing and before receiving step.
> Command to run in loop was
> {noformat}
> ret=0
> while [[ ret -eq 0 ]]; do mvn package -pl :cli-qpid-jms -am; ret=$?; done
> {noformat}
> The Travis log is
> {noformat}
> [INFO]
> ------------------------------------------------------------------------
> [INFO] Building cli-qpid-jms 1.2.2-SNAPSHOT
> [INFO]
> ------------------------------------------------------------------------
> [INFO] Downloading:
> http://repo.maven.apache.org/maven2/org/apache/qpid/qpid-jms-client/0.27.0/qpid-jms-client-0.27.0.pom
> [INFO] Downloaded:
> http://repo.maven.apache.org/maven2/org/apache/qpid/qpid-jms-client/0.27.0/qpid-jms-client-0.27.0.pom
> (6.9 kB at 275 kB/s)
> [INFO] Downloading:
> http://repo.maven.apache.org/maven2/org/apache/qpid/proton-j/0.23.0/proton-j-0.23.0.pom
> [INFO] Downloaded:
> http://repo.maven.apache.org/maven2/org/apache/qpid/proton-j/0.23.0/proton-j-0.23.0.pom
> (2.2 kB at 83 kB/s)
> [INFO] Downloading:
> http://repo.maven.apache.org/maven2/org/apache/qpid/proton-j-parent/0.23.0/proton-j-parent-0.23.0.pom
> [INFO] Downloaded:
> http://repo.maven.apache.org/maven2/org/apache/qpid/proton-j-parent/0.23.0/proton-j-parent-0.23.0.pom
> (7.7 kB at 334 kB/s)
> [INFO] Downloading:
> http://repo.maven.apache.org/maven2/org/apache/qpid/qpid-jms-client/0.27.0/qpid-jms-client-0.27.0.jar
> [INFO] Downloading:
> http://repo.maven.apache.org/maven2/org/apache/qpid/proton-j/0.23.0/proton-j-0.23.0.jar
> [INFO] Downloaded:
> http://repo.maven.apache.org/maven2/org/apache/qpid/qpid-jms-client/0.27.0/qpid-jms-client-0.27.0.jar
> (722 kB at 6.2 MB/s)
> [INFO] Downloaded:
> http://repo.maven.apache.org/maven2/org/apache/qpid/proton-j/0.23.0/proton-j-0.23.0.jar
> (662 kB at 4.6 MB/s)
> {noformat}
> [...]
> {noformat}
> 07:13:37.718Sending: {'address': 'lalaLand_rp5skalpii5kotuqg634lisj1d',
> 'group-id': None, 'subject': None, 'user-id': None, 'correlation-id': None,
> 'content-encoding': None, 'priority': 4, 'type': None, 'ttl': 0,
> 'absolute-expiry-time': 0, 'content': None, 'redelivered': False,
> 'reply-to-group-id': None, 'durable': True, 'delivery-time': 1509952418102,
> 'group-sequence': '0', 'creation-time': 1509952418102, 'content-type': None,
> 'id': '1f05308b-151a-4a3c-8ffc-adcb15e160cc:1:1:1-1', 'reply-to': None,
> 'properties': {'JMSXDeliveryCount': 1}}
> Browsing: {'address': 'lalaLand_rp5skalpii5kotuqg634lisj1d', 'group-id':
> None, 'subject': None, 'user-id': None, 'correlation-id': None,
> 'content-encoding': None, 'priority': 4, 'type': None, 'ttl': 0,
> 'absolute-expiry-time': 0, 'content': None, 'redelivered': False,
> 'reply-to-group-id': None, 'durable': True, 'delivery-time': 1509952418102,
> 'group-sequence': '0', 'creation-time': 1509952418102, 'content-type': None,
> 'id': '1f05308b-151a-4a3c-8ffc-adcb15e160cc:1:1:1-1', 'reply-to': None,
> 'properties': {'JMSXDeliveryCount': 1}}
> 07:13:38,843 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:361)
> [proton-j-0.22.0.jar:]
> at
> org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler.createServerSASL(ProtonHandler.java:167)
> [artemis-amqp-protocol-2.4.0-SNAPSHOT.jar:]
> at
> org.apache.activemq.artemis.protocol.amqp.proton.AMQPConnectionContext.onAuthInit(AMQPConnectionContext.java:304)
> [artemis-amqp-protocol-2.4.0-SNAPSHOT.jar:]
> at
> org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler.dispatchAuth(ProtonHandler.java:423)
> [artemis-amqp-protocol-2.4.0-SNAPSHOT.jar:]
> at
> org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler.inputBuffer(ProtonHandler.java:221)
> [artemis-amqp-protocol-2.4.0-SNAPSHOT.jar:]
> at
> org.apache.activemq.artemis.protocol.amqp.proton.AMQPConnectionContext.inputBuffer(AMQPConnectionContext.java:150)
> [artemis-amqp-protocol-2.4.0-SNAPSHOT.jar:]
> at
> org.apache.activemq.artemis.protocol.amqp.broker.ActiveMQProtonRemotingConnection.bufferReceived(ActiveMQProtonRemotingConnection.java:141)
> [artemis-amqp-protocol-2.4.0-SNAPSHOT.jar:]
> at
> org.apache.activemq.artemis.core.remoting.server.impl.RemotingServiceImpl$DelegatingBufferHandler.bufferReceived(RemotingServiceImpl.java:642)
> [artemis-server-2.4.0-SNAPSHOT.jar:2.4.0-SNAPSHOT]
> at
> org.apache.activemq.artemis.core.remoting.impl.netty.ActiveMQChannelHandler.channelRead(ActiveMQChannelHandler.java:68)
> [artemis-core-client-2.4.0-SNAPSHOT.jar:2.4.0-SNAPSHOT]
> at
> io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
> [netty-all-4.1.16.Final.jar:4.1.16.Final]
> at
> io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
> [netty-all-4.1.16.Final.jar:4.1.16.Final]
> at
> io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
> [netty-all-4.1.16.Final.jar:4.1.16.Final]
> at
> io.netty.handler.codec.ByteToMessageDecoder.handlerRemoved(ByteToMessageDecoder.java:236)
> [netty-all-4.1.16.Final.jar:4.1.16.Final]
> at
> io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:494)
> [netty-all-4.1.16.Final.jar:4.1.16.Final]
> at
> io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:428)
> [netty-all-4.1.16.Final.jar:4.1.16.Final]
> at
> io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:265)
> [netty-all-4.1.16.Final.jar:4.1.16.Final]
> at
> org.apache.activemq.artemis.core.protocol.ProtocolHandler$ProtocolDecoder.channelRead(ProtocolHandler.java:124)
> [artemis-server-2.4.0-SNAPSHOT.jar:2.4.0-SNAPSHOT]
> at
> io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
> [netty-all-4.1.16.Final.jar:4.1.16.Final]
> at
> io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
> [netty-all-4.1.16.Final.jar:4.1.16.Final]
> at
> io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
> [netty-all-4.1.16.Final.jar:4.1.16.Final]
> at
> io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1359)
> [netty-all-4.1.16.Final.jar:4.1.16.Final]
> at
> io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
> [netty-all-4.1.16.Final.jar:4.1.16.Final]
> at
> io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
> [netty-all-4.1.16.Final.jar:4.1.16.Final]
> at
> io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:935)
> [netty-all-4.1.16.Final.jar:4.1.16.Final]
> at
> io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:797)
> [netty-all-4.1.16.Final.jar:4.1.16.Final]
> at
> io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:404)
> [netty-all-4.1.16.Final.jar:4.1.16.Final]
> at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:304)
> [netty-all-4.1.16.Final.jar:4.1.16.Final]
> at
> io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
> [netty-all-4.1.16.Final.jar:4.1.16.Final]
> at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_131]
> Receiving: 07:13:38,883 ERROR Failed to connect to remote at:
> amqp://127.0.0.1:5672
> 07:13:38,884 ERROR org.apache.qpid.proton.engine.TransportException: AMQP
> SASL header mismatch value 0, expecting 3. In state: HEADER4
> javax.jms.JMSException: org.apache.qpid.proton.engine.TransportException:
> AMQP SASL header mismatch value 0, expecting 3. In state: HEADER4
> at
> org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:86)
> at
> org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:108)
> at org.apache.qpid.jms.JmsConnection.connect(JmsConnection.java:167)
> at
> org.apache.qpid.jms.JmsConnectionFactory.createConnection(JmsConnectionFactory.java:203)
> at
> org.apache.qpid.jms.JmsConnectionFactory.createConnection(JmsConnectionFactory.java:190)
> at
> com.redhat.mqe.jms.AacConnectionManager.<init>(AacConnectionManager.java:105)
> at
> com.redhat.mqe.jms.AacConnectionManagerFactory.make(AacConnectionManagerFactory.java:30)
> at
> com.redhat.mqe.jms.AacConnectionManagerFactory.make(AacConnectionManagerFactory.java:25)
> at com.redhat.mqe.lib.CoreClient.createConnection(CoreClient.java:92)
> at
> com.redhat.mqe.lib.ReceiverClient.consumeMessage(ReceiverClient.java:157)
> at
> com.redhat.mqe.lib.ReceiverClient.startClient(ReceiverClient.java:133)
> at com.redhat.mqe.lib.Main.main(Main.java:46)
> at com.redhat.mqe.jms.Main.main(Main.java:29)
> at AacMainTest.main(MainTest.kt:124)
> at
> AbstractMainTest$sendBrowseAndReceiveSingleMessage$1.execute(AbstractMainTest.kt:142)
> at
> org.junit.jupiter.api.AssertTimeout.lambda$assertTimeoutPreemptively$7(AssertTimeout.java:97)
> at
> org.junit.jupiter.api.AssertTimeout.lambda$assertTimeoutPreemptively$10(AssertTimeout.java:117)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:748)
> Caused by: java.io.IOException:
> org.apache.qpid.proton.engine.TransportException: AMQP SASL header mismatch
> value 0, expecting 3. In state: HEADER4
> at
> org.apache.qpid.jms.util.IOExceptionSupport.create(IOExceptionSupport.java:45)
> at
> org.apache.qpid.jms.provider.ProviderFuture.failOnError(ProviderFuture.java:114)
> at
> org.apache.qpid.jms.provider.ProviderFuture.sync(ProviderFuture.java:91)
> at
> org.apache.qpid.jms.provider.amqp.AmqpProvider.connect(AmqpProvider.java:222)
> at org.apache.qpid.jms.JmsConnection.connect(JmsConnection.java:155)
> ... 18 more
> Caused by: org.apache.qpid.proton.engine.TransportException:
> org.apache.qpid.proton.engine.TransportException: AMQP SASL header mismatch
> value 0, expecting 3. In state: HEADER4
> at
> org.apache.qpid.proton.engine.TransportResultFactory$TransportResultImpl.checkIsOk(TransportResultFactory.java:116)
> at
> org.apache.qpid.jms.provider.amqp.AmqpProvider$17.run(AmqpProvider.java:784)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
> ... 3 more
> Caused by: org.apache.qpid.proton.engine.TransportException: AMQP SASL header
> mismatch value 0, expecting 3. In state: HEADER4
> at
> org.apache.qpid.proton.engine.impl.SaslFrameParser.input(SaslFrameParser.java:157)
> at
> org.apache.qpid.proton.engine.impl.SaslImpl$SaslTransportWrapper.reallyProcessInput(SaslImpl.java:636)
> at
> org.apache.qpid.proton.engine.impl.SaslImpl$SaslTransportWrapper.process(SaslImpl.java:607)
> at
> org.apache.qpid.proton.engine.impl.HandshakeSniffingTransportWrapper.process(HandshakeSniffingTransportWrapper.java:101)
> at
> org.apache.qpid.proton.engine.impl.TransportImpl.process(TransportImpl.java:1495)
> at
> org.apache.qpid.proton.engine.impl.TransportImpl.processInput(TransportImpl.java:1453)
> ... 8 more
> Results :
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
