You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@qpid.apache.org by "Robbie Gemmell (JIRA)" <ji...@apache.org> on 2017/11/06 09:47:00 UTC
[jira] [Resolved] (QPIDJMS-345) TransportException: AMQP SASL
header mismatch value 0, expecting 3. In state: HEADER4
[ 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: dev-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org