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 2015/03/31 16:50:53 UTC
[jira] [Updated] (QPIDJMS-33) SASL EXTERNAL doesn't seem to work
against the C++ broker
[ https://issues.apache.org/jira/browse/QPIDJMS-33?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Robbie Gemmell updated QPIDJMS-33:
----------------------------------
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:
{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}
was:
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
> 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: dev-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org