[QPIDJMS-33] SASL EXTERNAL doesn't seem to work against the C++ broker - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Closed
Priority: Major
Resolution: Fixed
Affects Version/s: 0.1.0
Fix Version/s: 0.2.0
Component/s: qpid-jms-client
Labels:
None

Description

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:

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

Client log:

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)

To compare, broker log when the prototype AMQP 1.0 client from Rob is used:

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

Attachments

Activity

People

Assignee:: Robbie Gemmell

Reporter:: Jakub Scholz

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 26/Mar/15 14:03

Updated:: 06/Jan/16 12:33

Resolved:: 31/Mar/15 14:57