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: [email protected]
For additional commands, e-mail: [email protected]
