Uploaded image for project: 'AMQ Broker'
  1. AMQ Broker
  2. ENTMQBR-948

GSSAPI IBM JDK - clients get authentication refused first time they connect to broker

    XMLWordPrintable

Details

    • Hide

      Initiate first connection on random/tmp queue.
      OR
      Don't use super-secured patched IBM JDK...

      Show
      Initiate first connection on random/tmp queue. OR Don't use super-secured patched IBM JDK...
    • Hide
      1. Set up Kerberos, install ibm jdk + patch for aes 256 ciphers (see linked/related issue for details).
      2. Create queue (not needed)
      3. Use any AMQP client with GSSAPI authentication (should not fail)
      4. Repeat previous step - authentication passes
      Show
      Set up Kerberos, install ibm jdk + patch for aes 256 ciphers (see linked/related issue for details). Create queue (not needed) Use any AMQP client with GSSAPI authentication (should not fail) Repeat previous step - authentication passes

    Description

      Right after broker is started, the first connection from any client is automatically refused by broker. Any other subsequent connection is fine. This only happens when IBM JDK is used for broker.

      broker log

      18:24:53.257 FINE  [javax.security.sasl] SASLIMPL01:Preferred qop property: null
18:24:53.257 FINE  [javax.security.sasl] SASLIMPL02:Preferred qop mask: 1
18:24:53.258 FINE  [javax.security.sasl] SASLIMPL03:Preferred qops : 1 
18:24:53.258 FINE  [javax.security.sasl] SASLIMPL04:Preferred strength property: null
18:24:53.258 FINE  [javax.security.sasl] SASLIMPL05:Cipher strengths: 4 2 1 
18:24:53.258 FINE  [javax.security.sasl] KRB5SRV01:Using service name: null
18:24:53.292 FINE  [javax.security.sasl] KRB5SRV02:Initialization complete
18:24:53.343 FINE  [javax.security.sasl] KRB5SRV05:Peer name is : charlie@MSGQE.COM, my name is : amqp/amq-server.msgqe.com@MSGQE.COM
18:24:53.347 FINE  [javax.security.sasl] KRB5SRV06:Supported protections: 1; recv max buf size: 65,536
18:24:53.358 INFO  [org.apache.activemq.artemis.protocol.amqp.sasl.GSSAPIServerSASL] Error on sasl input: java.security.PrivilegedActionException: javax.security.sasl.SaslException: Final handshake step failed [Caused by org.ietf.jgss.GSSException, major code: 11, minor code: 0
        major string: General failure, unspecified at GSSAPI level
        minor string: Error while decoding token: java.lang.ArrayIndexOutOfBoundsException: Array index out of range: 0]: java.security.PrivilegedActionException: javax.security.sasl.SaslException: Final handshake step failed [Caused by org.ietf.jgss.GSSException, major code: 11, minor code: 0
        major string: General failure, unspecified at GSSAPI level
        minor string: Error while decoding token: java.lang.ArrayIndexOutOfBoundsException: Array index out of range: 0]
        at java.security.AccessController.doPrivileged(AccessController.java:692) [vm.jar:1.8.0]
        at javax.security.auth.Subject.doAs(Subject.java:569) [rt.jar:1.8.0]
        at org.apache.activemq.artemis.protocol.amqp.sasl.GSSAPIServerSASL.processSASL(GSSAPIServerSASL.java:77) [artemis-amqp-protocol-2.4.0.amq-710001-redhat-1.jar:]
        at org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler.checkSASL(ProtonHandler.java:315) [artemis-amqp-protocol-2.4.0.amq-710001-redhat-1.jar:]
        at org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler.flush(ProtonHandler.java:274) [artemis-amqp-protocol-2.4.0.amq-710001-redhat-1.jar:]
        at org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler.inputBuffer(ProtonHandler.java:243) [artemis-amqp-protocol-2.4.0.amq-710001-redhat-1.jar:]
        at org.apache.activemq.artemis.protocol.amqp.proton.AMQPConnectionContext.inputBuffer(AMQPConnectionContext.java:150) [artemis-amqp-protocol-2.4.0.amq-710001-redhat-1.jar:]
        at org.apache.activemq.artemis.protocol.amqp.broker.ActiveMQProtonRemotingConnection.bufferReceived(ActiveMQProtonRemotingConnection.java:141) [artemis-amqp-protocol-2.4.0.amq-710001-redhat-1.jar:]
        at org.apache.activemq.artemis.core.remoting.server.impl.RemotingServiceImpl$DelegatingBufferHandler.bufferReceived(RemotingServiceImpl.java:642) [artemis-server-2.4.0.amq-710001-redhat-1.jar:2.4.0.amq-710001-redhat-1]
        at org.apache.activemq.artemis.core.remoting.impl.netty.ActiveMQChannelHandler.channelRead(ActiveMQChannelHandler.java:68) [artemis-core-client-2.4.0.amq-710001-redhat-1.jar:2.4.0.amq-710001-redhat-1]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-all-4.1.16.Final-redhat-1.jar:4.1.16.Final-redhat-1]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-all-4.1.16.Final-redhat-1.jar:4.1.16.Final-redhat-1]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-all-4.1.16.Final-redhat-1.jar:4.1.16.Final-redhat-1]
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1359) [netty-all-4.1.16.Final-redhat-1.jar:4.1.16.Final-redhat-1]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-all-4.1.16.Final-redhat-1.jar:4.1.16.Final-redhat-1]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-all-4.1.16.Final-redhat-1.jar:4.1.16.Final-redhat-1]
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:935) [netty-all-4.1.16.Final-redhat-1.jar:4.1.16.Final-redhat-1]
        at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:797) [netty-all-4.1.16.Final-redhat-1.jar:4.1.16.Final-redhat-1]
        at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:404) [netty-all-4.1.16.Final-redhat-1.jar:4.1.16.Final-redhat-1]
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:304) [netty-all-4.1.16.Final-redhat-1.jar:4.1.16.Final-redhat-1]
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858) [netty-all-4.1.16.Final-redhat-1.jar:4.1.16.Final-redhat-1]
        at java.lang.Thread.run(Thread.java:785) [vm.jar:2.6 (07-22-2017)]
Caused by: javax.security.sasl.SaslException: Final handshake step failed [Caused by org.ietf.jgss.GSSException, major code: 11, minor code: 0
        major string: General failure, unspecified at GSSAPI level
        minor string: Error while decoding token: java.lang.ArrayIndexOutOfBoundsException: Array index out of range: 0]
        at com.ibm.security.sasl.gsskerb.GssKrb5Server.doHandshake2(GssKrb5Server.java:347) [ibmsaslprovider.jar:8.0 build_20150506]
        at com.ibm.security.sasl.gsskerb.GssKrb5Server.evaluateResponse(GssKrb5Server.java:178) [ibmsaslprovider.jar:8.0 build_20150506]
        at org.apache.activemq.artemis.protocol.amqp.sasl.GSSAPIServerSASL.lambda$processSASL$1(GSSAPIServerSASL.java:77) [artemis-amqp-protocol-2.4.0.amq-710001-redhat-1.jar:]
        at org.apache.activemq.artemis.protocol.amqp.sasl.GSSAPIServerSASL$$Lambda$36.0000000020287D60.run(Unknown Source)
        at java.security.AccessController.doPrivileged(AccessController.java:686) [vm.jar:1.8.0]
        ... 21 more
Caused by: org.ietf.jgss.GSSException, major code: 11, minor code: 0
        major string: General failure, unspecified at GSSAPI level
        minor string: Error while decoding token: java.lang.ArrayIndexOutOfBoundsException: Array index out of range: 0
        at com.ibm.security.jgss.i18n.I18NException.throwGSSException(Unknown Source) [ibmjgssprovider.jar:8.0 build_20170710]
        at com.ibm.security.jgss.mech.krb5.X.g(Unknown Source) [ibmjgssprovider.jar:8.0 build_20170710]
        at com.ibm.security.jgss.mech.krb5.X.b(Unknown Source) [ibmjgssprovider.jar:8.0 build_20170710]
        at com.ibm.security.jgss.mech.krb5.g.unwrap(Unknown Source) [ibmjgssprovider.jar:8.0 build_20170710]
        at com.ibm.security.jgss.GSSContextImpl.unwrap(Unknown Source) [ibmjgssprovider.jar:8.0 build_20170710]
        at com.ibm.security.sasl.gsskerb.GssKrb5Server.doHandshake2(GssKrb5Server.java:270) [ibmsaslprovider.jar:8.0 build_20150506]
        ... 25 more

(next message)

18:24:53.372 FINE  [org.apache.qpid.proton.engine.impl.SaslImpl] SASL negotiation done: SaslImpl [_outcome=PN_SASL_AUTH, state=PN_SASL_FAIL, done=true, role=SERVER]
18:24:53.434 DEBUG [org.apache.activemq.artemis.core.remoting.server.impl.RemotingServiceImpl] RemotingServiceImpl::removing connection ID 977275ab
18:24:55.438 DEBUG [org.apache.activemq.artemis.core.server.reload.ReloadManagerImpl] Validating lastModified 1512752949000 modified = 1512752949000 on file:/opt/jboss-amq-7-i0//etc/broker.xml
18:24:59.815 FINE  [javax.security.sasl] SASLIMPL01:Preferred qop property: null
18:24:59.816 FINE  [javax.security.sasl] SASLIMPL02:Preferred qop mask: 1
18:24:59.816 FINE  [javax.security.sasl] SASLIMPL03:Preferred qops : 1 
18:24:59.816 FINE  [javax.security.sasl] SASLIMPL04:Preferred strength property: null
18:24:59.816 FINE  [javax.security.sasl] SASLIMPL05:Cipher strengths: 4 2 1 
18:24:59.817 FINE  [javax.security.sasl] KRB5SRV01:Using service name: null
18:24:59.818 FINE  [javax.security.sasl] KRB5SRV02:Initialization complete
18:24:59.831 FINE  [javax.security.sasl] KRB5SRV05:Peer name is : charlie@MSGQE.COM, my name is : amqp/amq-server.msgqe.com@MSGQE.COM
18:24:59.834 FINE  [javax.security.sasl] KRB5SRV06:Supported protections: 1; recv max buf size: 65,536
18:24:59.841 FINE  [javax.security.sasl] KRB5SRV10:Selected protection: 1; privacy: false; integrity: false
18:24:59.841 FINE  [javax.security.sasl] KRB5SRV11:Client max recv size: 65,535; server max send size: 65,535; rawSendSize: 65,482
18:24:59.842 FINE  [javax.security.sasl] KRB5SRV12:Authzid: charlie@MSGQE.COM
18:24:59.842 FINE  [org.apache.qpid.proton.engine.impl.SaslImpl] SASL negotiation done: SaslImpl [_outcome=PN_SASL_OK, state=PN_SASL_PASS, done=true, role=SERVER]
18:24:59.847 FINE  [proton.trace] IN: CH[0] : Open{ containerId='a1666a4b-1fd4-4b1f-b1f7-5e098ff8dda0', hostname='null', maxFrameSize=4294967295, channelMax=32767, idleTimeOut=null, outgoingLocales=null, incomingLocales=null, offeredCapabilities=null, desiredCapabilities=null, properties={qpid.client_process=aac0_sender, qpid.client_pid=26527, qpid.client_ppid=18362}}
18:24:59.851 FINE  [proton.trace] IN: CH[0] : Begin{remoteChannel=null, nextOutgoingId=0, incomingWindow=2147483647, outgoingWindow=2147483647, handleMax=4294967295, offeredCapabilities=null, desiredCapabilities=null, properties=null}
18:24:59.869 DEBUG [org.apache.activemq.artemis.spi.core.security.jaas.Krb5LoginModule] login [charlie@MSGQE.COM]
18:24:59.871 DEBUG [org.apache.activemq.artemis.spi.core.security.jaas.PropertiesLoader] Initialized debug
18:24:59.876 DEBUG [org.apache.activemq.artemis.spi.core.security.jaas.ReloadableProperties] Load of: PropsFile=/opt/jboss-amq-7-i0/etc/artemis-users.properties
18:24:59.877 DEBUG [org.apache.activemq.artemis.spi.core.security.jaas.ReloadableProperties] Load of: PropsFile=/opt/jboss-amq-7-i0/etc/artemis-roles.properties
18:24:59.878 DEBUG [org.apache.activemq.artemis.spi.core.security.jaas.Krb5LoginModule] commit, result: true
18:24:59.878 DEBUG [org.apache.activemq.artemis.spi.core.security.jaas.PropertiesLoginModule] commit, result: false
18:24:59.899 FINE  [proton.trace] IN: CH[0] : Attach{name='lalaQ_b39766f5-6f49-4060-a65b-28bed4b335f7', handle=0, role=SENDER, sndSettleMode=MIXED, rcvSettleMode=FIRST, source=Source{address='lalaQ', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter=null, defaultOutcome=null, outcomes=null, capabilities=null}, target=Target{address='lalaQ', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null}, unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0, maxMessageSize=0, offeredCapabilities=null, desiredCapabilities=null, properties=null}
18:24:59.910 DEBUG [org.apache.activemq.artemis.spi.core.security.jaas.Krb5LoginModule] login [charlie@MSGQE.COM]
18:24:59.910 DEBUG [org.apache.activemq.artemis.spi.core.security.jaas.PropertiesLoader] Initialized debug
18:24:59.911 DEBUG [org.apache.activemq.artemis.spi.core.security.jaas.Krb5LoginModule] commit, result: true
18:24:59.914 DEBUG [org.apache.activemq.artemis.spi.core.security.jaas.PropertiesLoginModule] commit, result: false
18:24:59.928 FINE  [proton.trace] IN: CH[0] : Transfer{handle=0, deliveryId=0, deliveryTag=\x00\x00\x00\x00, messageFormat=0, settled=false, more=false, rcvSettleMode=null, state=null, resume=false, aborted=false, batchable=false}[\x00Sp\xc0\x04\x02BP\x00\x00St\xc1\x01\x00]
18:24:59.948 DEBUG [org.apache.activemq.artemis.core.server.impl.QueueImpl] QueueImpl[name=lalaQ, postOffice=PostOfficeImpl [server=ActiveMQServerImpl::serverUUID=ae9a9103-dc32-11e7-97c8-5254000a0c36], temp=false]@b5f98aed doing deliver. messageReferences=0
18:24:59.949 FINE  [proton.trace] IN: CH[0] : End{error=null}
18:24:59.959 FINE  [proton.trace] IN: CH[0] : Close{error=null}
18:24:59.960 DEBUG [org.apache.activemq.artemis.core.remoting.server.impl.RemotingServiceImpl] RemotingServiceImpl::removing connection ID 20c28150

      Client logs

      ============== Qpid JMS client
1root@msgqa-26-rhel6x-0:~# java  -Djava.security.auth.login.config=/var/dtests/node_data/gssapi/msgqe.com/qpid-jms-client/ibm-jdk/alice.login.config  -Djava.security.krb5.conf=/var/dtests/node_data/gssapi/msgqe.com/msgqe_krb5.conf  -jar /var/dtests/node_data/clients/aac1.jar sender  --log-msgs dict --broker amq-server.msgqe.com:5672 --conn-auth-mechanisms GSSAPI --address lalaQ --count 1
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: debug=true
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: principal=alice
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: credsType=initiate and accept
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] config: useDefaultCcache=false
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] config: useCcache=null
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] config: useDefaultKeytab=false
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] config: useKeytab=/var/dtests/node_data/gssapi/msgqe.com/keytabs/alice.keytab
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: forwardable=false (default)
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: renewable=false (default)
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: proxiable=false (default)
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: tryFirstPass=false (default)
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: useFirstPass=false (default)
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: moduleBanner=false (default)
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: interactive login? no
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] Try keytab for principal=alice
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] Done retrieving Kerberos creds from keytab
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] Retrieving Kerberos creds from cache for principal=alice
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] Non-interactive login; no callbacks necessary.
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] No Kerberos creds in cache for principal alice
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] Doing Kerberos login for principal alice@MSGQE.COM
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] Kerberos login complete
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] Login successful
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] kprincipal : alice@MSGQE.COM
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] alice@MSGQE.COM added to Subject
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] Kerberos ticket added to Subject
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] KeyTab added to Subject
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] added key of type aes256-cts-hmac-sha1-96
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] added key of type aes128-cts-hmac-sha1-96 
18:35:54,073 ERROR Failed to connect to remote at: amqp://amq-server.msgqe.com:5672?amqp.saslMechanisms=GSSAPI
18:35:54,110 ERROR Client failed to authenticate using SASL: GSSAPI
javax.jms.JMSSecurityException: Client failed to authenticate using SASL: GSSAPI
	at org.apache.qpid.jms.provider.amqp.AmqpSaslAuthenticator.recordFailure(AmqpSaslAuthenticator.java:157)
	at org.apache.qpid.jms.provider.amqp.AmqpSaslAuthenticator.handleSaslFail(AmqpSaslAuthenticator.java:136)
	at org.apache.qpid.jms.provider.amqp.AmqpSaslAuthenticator.tryAuthenticate(AmqpSaslAuthenticator.java:68)
	at org.apache.qpid.jms.provider.amqp.AmqpProvider.processSaslAuthentication(AmqpProvider.java:954)
	at org.apache.qpid.jms.provider.amqp.AmqpProvider.processUpdates(AmqpProvider.java:938)
	at org.apache.qpid.jms.provider.amqp.AmqpProvider.access$1800(AmqpProvider.java:101)
	at org.apache.qpid.jms.provider.amqp.AmqpProvider$17.run(AmqpProvider.java:789)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:522)
	at java.util.concurrent.FutureTask.run(FutureTask.java:277)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:191)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1160)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.lang.Thread.run(Thread.java:785)


1root@msgqa-26-rhel6x-0:~# java  -Djava.security.auth.login.config=/var/dtests/node_data/gssapi/msgqe.com/qpid-jms-client/ibm-jdk/alice.login.config  -Djava.security.krb5.conf=/var/dtests/node_data/gssapi/msgqe.com/msgqe_krb5.conf  -jar /var/dtests/node_data/clients/aac1.jar sender  --log-msgs dict --broker amq-server.msgqe.com:5672 --conn-auth-mechanisms GSSAPI --address lalaQ --count 1
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: debug=true
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: principal=alice
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: credsType=initiate and accept
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] config: useDefaultCcache=false
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] config: useCcache=null
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] config: useDefaultKeytab=false
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] config: useKeytab=/var/dtests/node_data/gssapi/msgqe.com/keytabs/alice.keytab
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: forwardable=false (default)
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: renewable=false (default)
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: proxiable=false (default)
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: tryFirstPass=false (default)
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: useFirstPass=false (default)
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: moduleBanner=false (default)
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] JAAS config: interactive login? no
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] Try keytab for principal=alice
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] Done retrieving Kerberos creds from keytab
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] Retrieving Kerberos creds from cache for principal=alice
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] Non-interactive login; no callbacks necessary.
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] No Kerberos creds in cache for principal alice
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] Doing Kerberos login for principal alice@MSGQE.COM
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] Kerberos login complete
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] Login successful
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] kprincipal : alice@MSGQE.COM
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] alice@MSGQE.COM added to Subject
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] Kerberos ticket added to Subject
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] KeyTab added to Subject
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] added key of type aes256-cts-hmac-sha1-96
[JGSS_DBG_CRED]  AmqpProvider :(1):[amqp://amq-server.msgqe.com:5672] added key of type aes128-cts-hmac-sha1-96 
{'address': 'lalaQ', 'group-id': None, 'subject': None, 'user-id': None, 'correlation-id': None, 'content-encoding': None, 'priority': 4, 'type': None, 'ttl': 0, 'absolute-expiry-time': 0, 'content': None, 'redelivered': False, 'reply-to-group-id': None, 'durable': True, 'delivery-time': 1512754562200, 'group-sequence': '0', 'creation-time': 1512754562200, 'content-type': None, 'id': 'a9b7bc66-7644-445d-8617-1d09c7864af9:1:1:1-1', 'reply-to': None, 'properties': {'JMSXDeliveryCount': 1}}

      ============== Qpid Proton python
root@msgqa-26-rhel6x-0:~# KRB5_CONFIG=/var/dtests/node_data/gssapi/msgqe.com/msgqe_krb5.conf  /var/dtests/node_data/clients/aac5_sender.py  --broker-url "amq-server.msgqe.com:5672/lalaQ" --log-msgs dict --count 1
Traceback (most recent call last):
  File "/var/dtests/node_data/clients/aac5_sender.py", line 374, in <module>
    main()
  File "/var/dtests/node_data/clients/aac5_sender.py", line 367, in main
    container.run()
  File "/usr/lib64/python2.6/site-packages/proton/reactor.py", line 148, in run
    while self.process(): pass
  File "/usr/lib64/python2.6/site-packages/proton/reactor.py", line 174, in process
    self._check_errors()
  File "/usr/lib64/python2.6/site-packages/proton/reactor.py", line 170, in _check_errors
    _compat.raise_(exc, value, tb)
  File "/usr/lib64/python2.6/site-packages/proton/__init__.py", line 4081, in dispatch
    ev.dispatch(self.handler)
  File "/usr/lib64/python2.6/site-packages/proton/__init__.py", line 3990, in dispatch
    result = dispatch(handler, type.method, self)
  File "/usr/lib64/python2.6/site-packages/proton/__init__.py", line 3870, in dispatch
    return handler.on_unhandled(method, *args)
  File "/var/dtests/node_data/clients/python/Aac5CoreClient.py", line 307, in on_unhandled
    raise ClientException(err_message)
Aac5CoreClient.ClientException: Transport error: amqp:unauthorized-access - Authentication failed [mech=GSSAPI]

1root@msgqa-26-rhel6x-0:~# KRB5_CONFIG=/var/dtests/node_data/gssapi/msgqe.com/msgqe_krb5.conf  /var/dtests/node_data/clients/aac5_sender.py  --broker-url "amq-server.msgqe.com:5672/lalaQ" --log-msgs dict --count 1
{'address': None, 'annotations': None, 'body': 'None', 'content': 'None', 'content_encoding': 'None', 'content_type': 'text/plain', 'correlation_id': None, 'creation_time': 0.000000, 'delivery_count': 0, 'durable': False, 'expiration': 0, 'first_acquirer': False, 'group_id': None, 'group_sequence': 0, 'id': None, 'inferred': False, 'instructions': None, 'priority': 4, 'properties': {}, 'reply_to': None, 'reply_to_group_id': None, 'subject': None, 'ttl': 0, 'user_id': ''}

      root@msgqa-26-rhel6x-0:~# KRB5_TRACE=/dev/stdout PN_TRACE_FRM=1 KRB5_CONFIG=/var/dtests/node_data/gssapi/msgqe.com/msgqe_krb5.conf  /var/dtests/node_data/clients/aac0_sender  --log-msgs dict --broker amq-server.msgqe.com:5672 --connection-options "{  sasl_mechanisms : 'GSSAPI', protocol : 'amqp1.0' }" --address lalaQ --count 1
[26518] 1512753892.93214: ccselect module realm chose cache FILE:/tmp/krb5cc_0 with client principal charlie@MSGQE.COM for server principal amqp/amq-server.msgqe.com@MSGQE.COM
[26518] 1512753892.93373: Retrieving charlie@MSGQE.COM -> krb5_ccache_conf_data/proxy_impersonator@X-CACHECONF: from FILE:/tmp/krb5cc_0 with result: -1765328243/Matching credential not found
[26518] 1512753892.93412: Getting credentials charlie@MSGQE.COM -> amqp/amq-server.msgqe.com@MSGQE.COM using ccache FILE:/tmp/krb5cc_0
[26518] 1512753892.93494: Retrieving charlie@MSGQE.COM -> amqp/amq-server.msgqe.com@MSGQE.COM from FILE:/tmp/krb5cc_0 with result: 0/Success
[26518] 1512753892.93636: Creating authenticator for charlie@MSGQE.COM -> amqp/amq-server.msgqe.com@MSGQE.COM, seqnum 188997331, subkey aes256-cts/DE8C, session key aes256-cts/CF05
[26518] 1512753893.351856: ccselect module realm chose cache FILE:/tmp/krb5cc_0 with client principal charlie@MSGQE.COM for server principal amqp/amq-server.msgqe.com@MSGQE.COM
[26518] 1512753893.351919: Retrieving charlie@MSGQE.COM -> krb5_ccache_conf_data/proxy_impersonator@X-CACHECONF: from FILE:/tmp/krb5cc_0 with result: -1765328243/Matching credential not found
[26518] 1512753893.352031: Read AP-REP, time 1512753892.93651, subkey aes256-cts/DE8C, seqnum 42
Authentication failed



1root@msgqa-26-rhel6x-0:~# KRB5_TRACE=/dev/stdout PN_TRACE_FRM=1 KRB5_CONFIG=/var/dtests/node_data/gssapi/msgqe.com/msgqe_krb5.conf  /var/dtests/node_data/clients/aac0_sender  --log-msgs dict --broker amq-server.msgqe.com:5672 --connection-options "{  sasl_mechanisms : 'GSSAPI', protocol : 'amqp1.0' }" --address lalaQ --count 1
[26527] 1512753899.783548: ccselect module realm chose cache FILE:/tmp/krb5cc_0 with client principal charlie@MSGQE.COM for server principal amqp/amq-server.msgqe.com@MSGQE.COM
[26527] 1512753899.783678: Retrieving charlie@MSGQE.COM -> krb5_ccache_conf_data/proxy_impersonator@X-CACHECONF: from FILE:/tmp/krb5cc_0 with result: -1765328243/Matching credential not found
[26527] 1512753899.783716: Getting credentials charlie@MSGQE.COM -> amqp/amq-server.msgqe.com@MSGQE.COM using ccache FILE:/tmp/krb5cc_0
[26527] 1512753899.783796: Retrieving charlie@MSGQE.COM -> amqp/amq-server.msgqe.com@MSGQE.COM from FILE:/tmp/krb5cc_0 with result: 0/Success
[26527] 1512753899.783934: Creating authenticator for charlie@MSGQE.COM -> amqp/amq-server.msgqe.com@MSGQE.COM, seqnum 747952340, subkey aes256-cts/B7F7, session key aes256-cts/CF05
[26527] 1512753899.833096: ccselect module realm chose cache FILE:/tmp/krb5cc_0 with client principal charlie@MSGQE.COM for server principal amqp/amq-server.msgqe.com@MSGQE.COM
[26527] 1512753899.833155: Retrieving charlie@MSGQE.COM -> krb5_ccache_conf_data/proxy_impersonator@X-CACHECONF: from FILE:/tmp/krb5cc_0 with result: -1765328243/Matching credential not found
[26527] 1512753899.833292: Read AP-REP, time 1512753899.783949, subkey aes256-cts/B7F7, seqnum 947
[0x1ff6220]:  -> AMQP
[0x1ff6220]:  <- AMQP
[0x1ff6220]:0 -> @open(16) [container-id="a1666a4b-1fd4-4b1f-b1f7-5e098ff8dda0", channel-max=32767, properties={:"qpid.client_process"=:"aac0_sender", :"qpid.client_pid"=26527, :"qpid.client_ppid"=18362}]
[0x1ff6220]:0 <- @open(16) [container-id="amq", max-frame-size=4294967295, channel-max=65535, idle-time-out=30000, offered-capabilities=@PN_SYMBOL[:"sole-connection-for-container", :"DELAYED_DELIVERY", :"SHARED-SUBS", :"ANONYMOUS-RELAY"], properties={:product="apache-activemq-artemis", :version="2.4.0.amq-710001-redhat-1"}]
[0x1ff6220]:0 -> @begin(17) [next-outgoing-id=0, incoming-window=2147483647, outgoing-window=2147483647]
[0x1ff6220]:0 <- @begin(17) [remote-channel=0, next-outgoing-id=1, incoming-window=2147483647, outgoing-window=2147483647, handle-max=65535]
[0x1ff6220]:0 -> @attach(18) [name="lalaQ_b39766f5-6f49-4060-a65b-28bed4b335f7", handle=0, role=false, snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) [address="lalaQ", durable=0, timeout=0, dynamic=false], target=@target(41) [address="lalaQ", durable=0, timeout=0, dynamic=false], initial-delivery-count=0, max-message-size=0]
[0x1ff6220]:0 <- @attach(18) [name="lalaQ_b39766f5-6f49-4060-a65b-28bed4b335f7", handle=0, role=true, snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) [address="lalaQ"], target=@target(41) [address="lalaQ"]]
[0x1ff6220]:0 <- @flow(19) [next-incoming-id=0, incoming-window=2147483647, next-outgoing-id=1, outgoing-window=2147483647, handle=0, delivery-count=0, link-credit=1000]
{'redelivered': False, 'reply_to': None, 'subject': None, 'content_type': None, 'id': None, 'user_id': None, 'correlation_id': None, 'priority': 0, 'durable': False, 'ttl': 0, 'properties': {}, 'content': None}
[0x1ff6220]:0 -> @transfer(20) [handle=0, delivery-id=0, delivery-tag=b"\x00\x00\x00\x00", message-format=0, settled=false, more=false, resume=false, aborted=false, batchable=false] (15) "\x00Sp\xc0\x04\x02BP\x00\x00St\xc1\x01\x00"
[0x1ff6220]:0 <- @disposition(21) [role=true, first=0, last=0, settled=true, state=@accepted(36) []]
[0x1ff6220]:0 -> @end(23) []
[0x1ff6220]:0 <- @end(23) []
[0x1ff6220]:0 -> @close(24) []
[0x1ff6220]:  -> EOS
[0x1ff6220]:0 <- @close(24) []
[0x1ff6220]:  <- EOS

      Attachments

        1. artemis_debug_gssapi_both.log
          632 kB
        2. artemis_debug_gssapi_both.log
          596 kB
        3. artemis_debug_gssapi.log
          596 kB
        4. artemis.log
          52 kB
        5. clients.log
          152 kB

        Issue Links

          blocks

          Story - Created by Jira Software - do not edit or delete. Issue type for a user story. ENTMQBR-789 Add support for Ldap role mapping of kerberos authenticated users

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Closed

          Story - Created by Jira Software - do not edit or delete. Issue type for a user story. ENTMQBR-790 Add support for authentication to ldap via kerberos for ldapLoginModule

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Closed

          Activity

            People

              gtully@redhat.com Gary Tully
              mtoth@redhat.com Michal Toth
              Michal Toth Michal Toth
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: