JAkub Scholz created QPIDJMS-33: ----------------------------------- Summary: 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: 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 -- This message was sent by Atlassian JIRA (v6.3.4#6332) --------------------------------------------------------------------- To unsubscribe, e-mail: dev-unsubscr...@qpid.apache.org For additional commands, e-mail: dev-h...@qpid.apache.org