[
https://issues.apache.org/jira/browse/QPIDJMS-33?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14388651#comment-14388651
]
Robbie Gemmell commented on QPIDJMS-33:
---------------------------------------
The issue was that the client couldnt 'see' the 0-byte challenge from the
server, which is a bit of an issue with Proton's sasl interface (which Andrew
is in the middle of redoing), and so it never tried to send the needed 0-byte
response. However, as I mentioned on the mailing list I was surprised the
broker was challenging at all, but from rfeading the RFC I can see it should do
that when the client fails to send the initial response, which we were indeed
failing to do (as is the old client by the looks of the broker logs above). I
updated our handling so that the 0-byte initial response is actually sent (it
was being dropped incorrectly as 'no response'), which means the broker no
longer needs to challenge for it at all.
> SASL EXTERNAL doesn't seem to work against the C++ broker
> ---------------------------------------------------------
>
> Key: QPIDJMS-33
> URL: https://issues.apache.org/jira/browse/QPIDJMS-33
> Project: Qpid JMS
> Issue Type: Bug
> Components: qpid-jms-client
> Affects Versions: 0.1.0
> Reporter: JAkub Scholz
> Fix For: 0.2.0
>
>
> It looks like the client selects the EXTERNAL mechanism when it is offered by
> the broker, but it looks like it never responds to the challenge sent by the
> broker (Qpid C++ 0.22 / MRG-M 3.0).
> Broker log:
> {noformat}
> 2015-03-26 11:38:41 [Network] trace Accepting SSL connection.
> 2015-03-26 11:38:41 [Network] info Set TCP_NODELAY on connection to
> 172.23.39.79:53580
> 2015-03-26 11:38:41 [Network] trace Accepting SSL connection.
> 2015-03-26 11:38:41 [System] debug RECV
> [qpid.172.16.153.11:10126-172.23.39.79:53580]: INIT(1-0)
> 2015-03-26 11:38:41 [Broker] info Using AMQP 1.0 (with SASL layer)
> 2015-03-26 11:38:41 [Security] debug External ssf=128 and
> auth=CBKFR_TESTCALMMACC1
> 2015-03-26 11:38:41 [Security] debug min_ssf: 0, max_ssf: 0, external_ssf: 128
> 2015-03-26 11:38:41 [Security] debug external auth detected and set to
> CBKFR_TESTCALMMACC1
> 2015-03-26 11:38:41 [Model] trace Mgmt create connection.
> id:qpid.172.16.153.11:10126-172.23.39.79:53580
> 2015-03-26 11:38:41 [Management] debug Management object (V1) added:
> org.apache.qpid.broker:connection:qpid.172.16.153.11:10126-172.23.39.79:53580
> 2015-03-26 11:38:41 [Security] trace ACL ConnectionCounter new connection:
> qpid.172.16.153.11:10126-172.23.39.79:53580
> 2015-03-26 11:38:41 [Security] info SASL: Mechanism list: EXTERNAL
> 2015-03-26 11:38:41 [Security] trace Completed encoding of frame of 30 bytes
> 2015-03-26 11:38:41 [Protocol] debug
> qpid.172.16.153.11:10126-172.23.39.79:53580 Sent SASL-MECHANISMS(EXTERNAL) 30
> 2015-03-26 11:38:41 [Protocol] debug
> qpid.172.16.153.11:10126-172.23.39.79:53580 writing protocol header: 1-0
> 2015-03-26 11:38:41 [Security] trace
> qpid.172.16.153.11:10126-172.23.39.79:53580 Sasl::encode(65536): 38
> 2015-03-26 11:38:41 [Security] trace
> qpid.172.16.153.11:10126-172.23.39.79:53580 Sasl::decode(1): 0
> 2015-03-26 11:38:41 [Security] trace Reading SASL frame of size 24
> 2015-03-26 11:38:41 [Security] trace Reading SASL-INIT
> 2015-03-26 11:38:41 [Protocol] debug
> qpid.172.16.153.11:10126-172.23.39.79:53580 Received SASL-INIT(EXTERNAL, )
> 2015-03-26 11:38:41 [Security] info SASL: Starting authentication with
> mechanism: EXTERNAL
> 2015-03-26 11:38:41 [Security] trace Completed encoding of frame of 22 bytes
> 2015-03-26 11:38:41 [Protocol] debug
> qpid.172.16.153.11:10126-172.23.39.79:53580 Sent SASL-CHALLENGE() 22
> 2015-03-26 11:38:41 [Security] info
> qpid.172.16.153.11:10126-172.23.39.79:53580 Challenge issued
> 2015-03-26 11:38:41 [Security] trace
> qpid.172.16.153.11:10126-172.23.39.79:53580 Sasl::decode(24): 24
> 2015-03-26 11:38:41 [Security] trace
> qpid.172.16.153.11:10126-172.23.39.79:53580 Sasl::encode(65536): 22
> {noformat}
> Client log:
> {noformat}
> 2015-03-26 12:50:31 +0100 [main] TRACE org.apache.qpid.jms.util.IdGenerator -
> Using port 0
> 2015-03-26 12:50:31 +0100 [main] DEBUG
> io.netty.util.internal.logging.InternalLoggerFactory - Using SLF4J as the
> default logging framework
> 2015-03-26 12:50:31 +0100 [main] DEBUG
> io.netty.channel.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 8
> 2015-03-26 12:50:32 +0100 [main] DEBUG
> io.netty.util.internal.PlatformDependent - Platform: Windows
> 2015-03-26 12:50:32 +0100 [main] DEBUG
> io.netty.util.internal.PlatformDependent - Java version: 7
> 2015-03-26 12:50:32 +0100 [main] DEBUG
> io.netty.util.internal.PlatformDependent - -Dio.netty.noUnsafe: false
> 2015-03-26 12:50:32 +0100 [main] DEBUG
> io.netty.util.internal.PlatformDependent0 - java.nio.ByteBuffer.cleaner:
> available
> 2015-03-26 12:50:32 +0100 [main] DEBUG
> io.netty.util.internal.PlatformDependent0 - java.nio.Buffer.address: available
> 2015-03-26 12:50:32 +0100 [main] DEBUG
> io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe:
> available
> 2015-03-26 12:50:32 +0100 [main] DEBUG
> io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory:
> available
> 2015-03-26 12:50:32 +0100 [main] DEBUG
> io.netty.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: true
> 2015-03-26 12:50:32 +0100 [main] DEBUG
> io.netty.util.internal.PlatformDependent - sun.misc.Unsafe: available
> 2015-03-26 12:50:32 +0100 [main] DEBUG
> io.netty.util.internal.PlatformDependent - -Dio.netty.noJavassist: false
> 2015-03-26 12:50:32 +0100 [main] DEBUG
> io.netty.util.internal.PlatformDependent - Javassist: unavailable
> 2015-03-26 12:50:32 +0100 [main] DEBUG
> io.netty.util.internal.PlatformDependent - You don't have Javassist in your
> class path or you don't have enough permission to load dynamically generated
> classes. Please check the configuration for better performance.
> 2015-03-26 12:50:32 +0100 [main] DEBUG
> io.netty.util.internal.PlatformDependent - -Dio.netty.tmpdir:
> C:\Users\schojak\AppData\Local\Temp (java.io.tmpdir)
> 2015-03-26 12:50:32 +0100 [main] DEBUG
> io.netty.util.internal.PlatformDependent - -Dio.netty.bitMode: 32
> (sun.arch.data.model)
> 2015-03-26 12:50:32 +0100 [main] DEBUG
> io.netty.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false
> 2015-03-26 12:50:32 +0100 [main] DEBUG io.netty.channel.nio.NioEventLoop -
> -Dio.netty.noKeySetOptimization: false
> 2015-03-26 12:50:32 +0100 [main] DEBUG io.netty.channel.nio.NioEventLoop -
> -Dio.netty.selectorAutoRebuildThreshold: 512
> 2015-03-26 12:50:32 +0100 [main] TRACE io.netty.channel.nio.NioEventLoop -
> Instrumented an optimized java.util.Set into:
> sun.nio.ch.WindowsSelectorImpl@1249338
> 2015-03-26 12:50:32 +0100 [main] DEBUG io.netty.buffer.PooledByteBufAllocator
> - -Dio.netty.allocator.numHeapArenas: 2
> 2015-03-26 12:50:32 +0100 [main] DEBUG io.netty.buffer.PooledByteBufAllocator
> - -Dio.netty.allocator.numDirectArenas: 2
> 2015-03-26 12:50:32 +0100 [main] DEBUG io.netty.buffer.PooledByteBufAllocator
> - -Dio.netty.allocator.pageSize: 8192
> 2015-03-26 12:50:32 +0100 [main] DEBUG io.netty.buffer.PooledByteBufAllocator
> - -Dio.netty.allocator.maxOrder: 11
> 2015-03-26 12:50:32 +0100 [main] DEBUG io.netty.buffer.PooledByteBufAllocator
> - -Dio.netty.allocator.chunkSize: 16777216
> 2015-03-26 12:50:32 +0100 [main] DEBUG
> io.netty.util.internal.ThreadLocalRandom - -Dio.netty.initialSeedUniquifier:
> 0x0f38d78456072178
> 2015-03-26 12:50:32 +0100 [main] DEBUG io.netty.channel.ChannelOutboundBuffer
> - -Dio.netty.threadLocalDirectBufferSize: 65536
> 2015-03-26 12:50:32 +0100 [main] DEBUG io.netty.buffer.ByteBufUtil -
> -Dio.netty.allocator.type: unpooled
> 2015-03-26 12:50:32 +0100 [nioEventLoopGroup-2-1] TRACE
> org.apache.qpid.jms.transports.TransportSupport - Attempt to load KeyStore
> from location
> c:/opt/!_AMQP/IdeaProjects/Qpid-JMS-1.0/src/main/resources/CBKFR_TESTCALMMACC1.keystore
> of type jks
> 2015-03-26 12:50:32 +0100 [nioEventLoopGroup-2-1] TRACE
> org.apache.qpid.jms.transports.TransportSupport - Attempt to load TrustStore
> from location
> c:/opt/!_AMQP/IdeaProjects/Qpid-JMS-1.0/src/main/resources/truststore_eurex
> of type jks
> 2015-03-26 12:50:32 +0100 [nioEventLoopGroup-2-1] DEBUG
> io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetectionLevel: simple
> 2015-03-26 12:50:32 +0100 [nioEventLoopGroup-2-1] TRACE
> org.apache.qpid.jms.transports.netty.NettyTcpTransport - Channel has become
> active! Channel is [id: 0x99d9b94d, /172.23.39.79:54111 =>
> cbgc01.xeop.de/172.16.153.11:10126]
> 2015-03-26 12:50:32 +0100 [nioEventLoopGroup-2-1] TRACE
> org.apache.qpid.jms.transports.netty.NettySslTransport - SSL Handshake has
> completed: [id: 0x99d9b94d, /172.23.39.79:54111 =>
> cbgc01.xeop.de/172.16.153.11:10126]
> 2015-03-26 12:50:32 +0100
> [AmqpProvider:(1):[amqps://cbgc01.xeop.de:10126?transport.keyStorePassword=123456&transport.trustStorePassword=123456&transport.verifyHost=false&transport.keyStoreLocation=c%253A%252Fopt%252F%2521_AMQP%252FIdeaProjects%252FQpid-JMS-1.0%252Fsrc%252Fmain%252Fresources%252FCBKFR_TESTCALMMACC1.keystore&transport.trustStoreLocation=c%253A%252Fopt%252F%2521_AMQP%252FIdeaProjects%252FQpid-JMS-1.0%252Fsrc%252Fmain%252Fresources%252Ftruststore_eurex]]
> TRACE org.apache.qpid.jms.transports.netty.NettyTcpTransport - Attempted
> write of: 8 bytes
> 2015-03-26 12:50:32 +0100 [nioEventLoopGroup-2-1] TRACE
> org.apache.qpid.jms.transports.netty.NettyTcpTransport - New data read: 38
> bytes incoming: UnpooledHeapByteBuf(ridx: 0, widx: 38, cap: 1024)
> 2015-03-26 12:50:32 +0100
> [AmqpProvider:(1):[amqps://cbgc01.xeop.de:10126?transport.keyStorePassword=123456&transport.trustStorePassword=123456&transport.verifyHost=false&transport.keyStoreLocation=c%253A%252Fopt%252F%2521_AMQP%252FIdeaProjects%252FQpid-JMS-1.0%252Fsrc%252Fmain%252Fresources%252FCBKFR_TESTCALMMACC1.keystore&transport.trustStoreLocation=c%253A%252Fopt%252F%2521_AMQP%252FIdeaProjects%252FQpid-JMS-1.0%252Fsrc%252Fmain%252Fresources%252Ftruststore_eurex]]
> TRACE org.apache.qpid.jms.provider.amqp.AmqpProvider - Received from Broker
> 38 bytes: UnpooledHeapByteBuf(ridx: 0, widx: 38, cap: 1024)
> 2015-03-26 12:50:32 +0100
> [AmqpProvider:(1):[amqps://cbgc01.xeop.de:10126?transport.keyStorePassword=123456&transport.trustStorePassword=123456&transport.verifyHost=false&transport.keyStoreLocation=c%253A%252Fopt%252F%2521_AMQP%252FIdeaProjects%252FQpid-JMS-1.0%252Fsrc%252Fmain%252Fresources%252FCBKFR_TESTCALMMACC1.keystore&transport.trustStoreLocation=c%253A%252Fopt%252F%2521_AMQP%252FIdeaProjects%252FQpid-JMS-1.0%252Fsrc%252Fmain%252Fresources%252Ftruststore_eurex]]
> TRACE org.apache.qpid.jms.provider.amqp.AmqpProvider - New Proton Event:
> CONNECTION_INIT
> 2015-03-26 12:50:32 +0100
> [AmqpProvider:(1):[amqps://cbgc01.xeop.de:10126?transport.keyStorePassword=123456&transport.trustStorePassword=123456&transport.verifyHost=false&transport.keyStoreLocation=c%253A%252Fopt%252F%2521_AMQP%252FIdeaProjects%252FQpid-JMS-1.0%252Fsrc%252Fmain%252Fresources%252FCBKFR_TESTCALMMACC1.keystore&transport.trustStoreLocation=c%253A%252Fopt%252F%2521_AMQP%252FIdeaProjects%252FQpid-JMS-1.0%252Fsrc%252Fmain%252Fresources%252Ftruststore_eurex]]
> TRACE org.apache.qpid.jms.provider.amqp.AmqpProvider - New Proton Event:
> SESSION_INIT
> 2015-03-26 12:50:32 +0100
> [AmqpProvider:(1):[amqps://cbgc01.xeop.de:10126?transport.keyStorePassword=123456&transport.trustStorePassword=123456&transport.verifyHost=false&transport.keyStoreLocation=c%253A%252Fopt%252F%2521_AMQP%252FIdeaProjects%252FQpid-JMS-1.0%252Fsrc%252Fmain%252Fresources%252FCBKFR_TESTCALMMACC1.keystore&transport.trustStoreLocation=c%253A%252Fopt%252F%2521_AMQP%252FIdeaProjects%252FQpid-JMS-1.0%252Fsrc%252Fmain%252Fresources%252Ftruststore_eurex]]
> TRACE org.apache.qpid.jms.provider.amqp.AmqpProvider - New Proton Event:
> CONNECTION_LOCAL_OPEN
> 2015-03-26 12:50:32 +0100
> [AmqpProvider:(1):[amqps://cbgc01.xeop.de:10126?transport.keyStorePassword=123456&transport.trustStorePassword=123456&transport.verifyHost=false&transport.keyStoreLocation=c%253A%252Fopt%252F%2521_AMQP%252FIdeaProjects%252FQpid-JMS-1.0%252Fsrc%252Fmain%252Fresources%252FCBKFR_TESTCALMMACC1.keystore&transport.trustStoreLocation=c%253A%252Fopt%252F%2521_AMQP%252FIdeaProjects%252FQpid-JMS-1.0%252Fsrc%252Fmain%252Fresources%252Ftruststore_eurex]]
> INFO org.apache.qpid.jms.sasl.SaslMechanismFinder - Best match for SASL auth
> was: SASL-EXTERNAL
> 2015-03-26 12:50:32 +0100
> [AmqpProvider:(1):[amqps://cbgc01.xeop.de:10126?transport.keyStorePassword=123456&transport.trustStorePassword=123456&transport.verifyHost=false&transport.keyStoreLocation=c%253A%252Fopt%252F%2521_AMQP%252FIdeaProjects%252FQpid-JMS-1.0%252Fsrc%252Fmain%252Fresources%252FCBKFR_TESTCALMMACC1.keystore&transport.trustStoreLocation=c%253A%252Fopt%252F%2521_AMQP%252FIdeaProjects%252FQpid-JMS-1.0%252Fsrc%252Fmain%252Fresources%252Ftruststore_eurex]]
> TRACE org.apache.qpid.jms.transports.netty.NettyTcpTransport - Attempted
> write of: 24 bytes
> 2015-03-26 12:50:32 +0100 [nioEventLoopGroup-2-1] TRACE
> org.apache.qpid.jms.transports.netty.NettyTcpTransport - New data read: 22
> bytes incoming: UnpooledHeapByteBuf(ridx: 0, widx: 22, cap: 53)
> 2015-03-26 12:50:32 +0100
> [AmqpProvider:(1):[amqps://cbgc01.xeop.de:10126?transport.keyStorePassword=123456&transport.trustStorePassword=123456&transport.verifyHost=false&transport.keyStoreLocation=c%253A%252Fopt%252F%2521_AMQP%252FIdeaProjects%252FQpid-JMS-1.0%252Fsrc%252Fmain%252Fresources%252FCBKFR_TESTCALMMACC1.keystore&transport.trustStoreLocation=c%253A%252Fopt%252F%2521_AMQP%252FIdeaProjects%252FQpid-JMS-1.0%252Fsrc%252Fmain%252Fresources%252Ftruststore_eurex]]
> TRACE org.apache.qpid.jms.provider.amqp.AmqpProvider - Received from Broker
> 22 bytes: UnpooledHeapByteBuf(ridx: 0, widx: 22, cap: 53)
> {noformat}
> To compare, broker log when the prototype AMQP 1.0 client from Rob is used:
> {noformat}
> 2015-03-26 11:42:05 [Network] trace Accepting SSL connection.
> 2015-03-26 11:42:05 [Network] info Set TCP_NODELAY on connection to
> 172.23.39.79:53601
> 2015-03-26 11:42:05 [Network] trace Accepting SSL connection.
> 2015-03-26 11:42:05 [System] debug RECV
> [qpid.172.16.153.11:10126-172.23.39.79:53601]: INIT(1-0)
> 2015-03-26 11:42:05 [Broker] info Using AMQP 1.0 (with SASL layer)
> 2015-03-26 11:42:05 [Security] debug External ssf=128 and
> auth=CBKFR_TESTCALMMACC1
> 2015-03-26 11:42:05 [Security] debug min_ssf: 0, max_ssf: 0, external_ssf: 128
> 2015-03-26 11:42:05 [Security] debug external auth detected and set to
> CBKFR_TESTCALMMACC1
> 2015-03-26 11:42:05 [Model] trace Mgmt create connection.
> id:qpid.172.16.153.11:10126-172.23.39.79:53601
> 2015-03-26 11:42:05 [Management] debug Management object (V1) added:
> org.apache.qpid.broker:connection:qpid.172.16.153.11:10126-172.23.39.79:53601
> 2015-03-26 11:42:05 [Security] trace ACL ConnectionCounter new connection:
> qpid.172.16.153.11:10126-172.23.39.79:53601
> 2015-03-26 11:42:05 [Security] info SASL: Mechanism list: EXTERNAL
> 2015-03-26 11:42:05 [Security] trace Completed encoding of frame of 30 bytes
> 2015-03-26 11:42:05 [Protocol] debug
> qpid.172.16.153.11:10126-172.23.39.79:53601 Sent SASL-MECHANISMS(EXTERNAL) 30
> 2015-03-26 11:42:05 [Protocol] debug
> qpid.172.16.153.11:10126-172.23.39.79:53601 writing protocol header: 1-0
> 2015-03-26 11:42:05 [Security] trace
> qpid.172.16.153.11:10126-172.23.39.79:53601 Sasl::encode(65536): 38
> 2015-03-26 11:42:05 [Security] trace
> qpid.172.16.153.11:10126-172.23.39.79:53601 Sasl::decode(1): 0
> 2015-03-26 11:42:05 [Security] trace Reading SASL frame of size 41
> 2015-03-26 11:42:05 [Security] trace Reading SASL-INIT
> 2015-03-26 11:42:05 [Protocol] debug
> qpid.172.16.153.11:10126-172.23.39.79:53601 Received SASL-INIT(EXTERNAL, )
> 2015-03-26 11:42:05 [Security] info SASL: Starting authentication with
> mechanism: EXTERNAL
> 2015-03-26 11:42:05 [Security] trace Completed encoding of frame of 22 bytes
> 2015-03-26 11:42:05 [Protocol] debug
> qpid.172.16.153.11:10126-172.23.39.79:53601 Sent SASL-CHALLENGE() 22
> 2015-03-26 11:42:05 [Security] info
> qpid.172.16.153.11:10126-172.23.39.79:53601 Challenge issued
> 2015-03-26 11:42:05 [Security] trace
> qpid.172.16.153.11:10126-172.23.39.79:53601 Sasl::decode(41): 41
> 2015-03-26 11:42:05 [Security] trace
> qpid.172.16.153.11:10126-172.23.39.79:53601 Sasl::encode(65536): 22
> 2015-03-26 11:42:05 [Security] trace
> qpid.172.16.153.11:10126-172.23.39.79:53601 Sasl::decode(1): 0
> 2015-03-26 11:42:05 [Security] trace Reading SASL frame of size 16
> 2015-03-26 11:42:05 [Security] trace Reading SASL-RESPONSE (\xA0\x00) 1
> elements
> 2015-03-26 11:42:05 [Protocol] debug
> qpid.172.16.153.11:10126-172.23.39.79:53601 Received SASL-RESPONSE()
> 2015-03-26 11:42:05 [Security] trace ACL: Connection quota for user
> CBKFR_TESTCALMMACC1@QPID0126 chosen through value for 'all' : 65530
> 2015-03-26 11:42:05 [Security] trace ACL ConnectionApprover totalLimit=500
> curValue=2 result=allow
> 2015-03-26 11:42:05 [Security] trace ACL ConnectionApprover
> user=CBKFR_TESTCALMMACC1@QPID0126 limit=65530 curValue=1 result=allow
> 2015-03-26 11:42:05 [Security] trace Completed encoding of frame of 16 bytes
> 2015-03-26 11:42:05 [Protocol] debug
> qpid.172.16.153.11:10126-172.23.39.79:53601 Sent SASL-OUTCOME(0) 16
> 2015-03-26 11:42:05 [Security] info
> qpid.172.16.153.11:10126-172.23.39.79:53601 Authenticated as
> CBKFR_TESTCALMMACC1@QPID0126
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
