Author: Henk-Jan Message: We're trying to configure an application using Kerberos authentication. Invoking the service fails with the following error message:
security.wssecurity.WSSContextImpl.s02: com.ibm.websphere.security.WSSecurityException: Exception org.apache.axis2.AxisFault: CWWSS6521E: The Login failed because of an exception: javax.security.auth.login.LoginException: CWWSS7212E: Cannot verify security context token using the reference information from the derived key token element ocurred while running action: com.ibm.ws.wssecurity.handler.WSSecurityConsumerHandler$1@37fa37fa We're using WAS version 7.0.0.19 and a WCF client to access the service. Analysing the logfile, we conclude: - the specified keytab file is being found and used (SPN HTTP/rs6sv303.office01.internalcorp....@office01.internalcorp.net) - the kerberos user identity is correctly determined (eo30021) However, there are some strange error messages we cannot explain: 6/13/12 15:21:06:958 CEST 0000002d TokenHolder > setInboundTokenToContext(TGSAuthToken newtoken, MessageContext messageContext) Entry 6/13/12 15:21:06:958 CEST 0000002d TokenHolder 3 The operation context is NULL!!! and 6/13/12 15:21:06:993 CEST 0000002d DKTConsumeLog > initialize(Subject subject, CallbackHandler handler, Map sharedState, Map options) Entry 6/13/12 15:21:06:993 CEST 0000002d WSSAuditServi > isEventRequired(WSSAuditService.WSSAuditEventType eventTypeSECURITY_AUTHN, WSSAuditService.WSSAuditOutcome out comeSUCCESS, Map<Object, Object> context) Entry 6/13/12 15:21:06:993 CEST 0000002d WSSAuditServi 3 Usage error, context should not be null 6/13/12 15:21:06:993 CEST 0000002d WSSAuditServi < isRequired returns: false Exit Can anybody point me into a direction where I should look for a solution for this error message? Thanks, Henk-Jan. The logfile contains much more information which I won't include right away, but I think this part is the most relevant part: 6/13/12 15:21:06:941 CEST 0000002d KRBSPNList > KRBSPNList() Entry 6/13/12 15:21:06:941 CEST 0000002d KRBSPNList > loadProvSPN() Entry 6/13/12 15:21:06:941 CEST 0000002d KRBSPNList > getKeyTabEntries() Entry 6/13/12 15:21:06:942 CEST 0000002d KRBSPNList 3 Obtained KeyTab Instance 6/13/12 15:21:06:942 CEST 0000002d KRBSPNList 3 kverno 4 spn HTTP/rs6sv303.office01.internalcorp....@office01.internalcorp.net 6/13/12 15:21:06:944 CEST 0000002d KRBSPN > KRBSPN() Entry 6/13/12 15:21:06:944 CEST 0000002d KRBSPN < KRBSPN() Exit 6/13/12 15:21:06:944 CEST 0000002d KRBSPN > setSPN(name, realm) Entry 6/13/12 15:21:06:944 CEST 0000002d KRBSPN < setSPN(name, realm) Exit 6/13/12 15:21:06:944 CEST 0000002d KRBSPN > KRBSPN() Entry 6/13/12 15:21:06:944 CEST 0000002d KRBSPN < KRBSPN() Exit 6/13/12 15:21:06:944 CEST 0000002d KRBSPNList 3 Custom SPN added to listhttp://HTTP/rs6sv303.OFFICE01.INTERNALCORP.NET 6/13/12 15:21:06:944 CEST 0000002d KRBSPNList < getKeyTabEntries() Exit 6/13/12 15:21:06:945 CEST 0000002d KRBSPNList < loadProvSPN() Exit 6/13/12 15:21:06:945 CEST 0000002d KRBSPNList < KRBSPNList() Exit 6/13/12 15:21:06:945 CEST 0000002d KRB5Util > isSubKeyEncTypeSupported()... Entry 6/13/12 15:21:06:946 CEST 0000002d KRB5Util 3 CONTEXT_SUB_KEY_ENC: 23 6/13/12 15:21:06:946 CEST 0000002d KRB5Util 3 CONTEXT_SUB_KEY_ENC: java.lang.Integer 6/13/12 15:21:06:946 CEST 0000002d KRB5Util 3 Current Kerberos subkey encryption type value: 23 6/13/12 15:21:06:946 CEST 0000002d KRB5Util 3 Current Kerberos subkey encryption type: rc4-hmac 6/13/12 15:21:06:946 CEST 0000002d KRB5Util 3 Kerberos encryption type: rc4-hmac is tolerated. 6/13/12 15:21:06:946 CEST 0000002d KRB5Util 3 Supported Kerberos sub key encryption type in Web services security: aes128-cts-hmac-sha1-96 , aes256-cts-hmac- sha1-96, des3-cbc-sha1 6/13/12 15:21:06:946 CEST 0000002d KRB5Util < isSubKeyEncTypeSupported()... Exit 6/13/12 15:21:06:947 CEST 0000002d KRBConsumeLog 3 Key of type: [B with encryption type: java.lang.Integer from token as follows...^M 0000: 4d091fe9 3ef84da8 69487b05 910d8fd8 M... >.M. iH{. .... 0010: 6/13/12 15:21:06:947 CEST 0000002d KRBConsumeLog 3 Request token processed OK 6/13/12 15:21:06:947 CEST 0000002d KRBConsumeLog 3 getAuthenticatedUsername: WebSphere Security principal = eo30021 6/13/12 15:21:06:947 CEST 0000002d KRBConsumeLog 3 Kerberos client principal: eo30021 6/13/12 15:21:06:949 CEST 0000002d CacheableToke > CacheableTokenCacheImpl Entry 6/13/12 15:21:06:950 CEST 0000002d CacheableToke < CacheableTokenCacheImpl Exit 6/13/12 15:21:06:950 CEST 0000002d WSSecurityFac 3 factory key = com.ibm.ws.wssecurity.platform.cacheableTokenCache 6/13/12 15:21:06:950 CEST 0000002d WSSecurityFac 3 factory impl class = com.ibm.ws.wssecurity.platform.websphere.auth.CacheableTokenCacheImpl 6/13/12 15:21:06:950 CEST 0000002d CacheableToke > setDistributedMap(boolean 0) Entry 6/13/12 15:21:06:950 CEST 0000002d CacheableToke 3 Distributed Map For Service created! 6/13/12 15:21:06:950 CEST 0000002d CacheableToke 3 Invalid Listener enabled = true 6/13/12 15:21:06:950 CEST 0000002d CacheableToke < setDistributedMap(boolean 0) Exit 6/13/12 15:21:06:950 CEST 0000002d KRB5TokenCach > getSha1FromBytes() Entry 6/13/12 15:21:06:951 CEST 0000002d KRB5TokenCach < getSha1FromBytes() return /G5KotjIaIUvW0KlN1McFLAP/Jo= Exit 6/13/12 15:21:06:956 CEST 0000002d TGSAuthToken 3 Found sub key of type: [B from kerberos token. 6/13/12 15:21:06:956 CEST 0000002d TGSAuthToken 3 Got contextDelegatedKerberosTicket 6/13/12 15:21:06:957 CEST 0000002d TGSAuthToken 3 TGT Ticket expiration time=Wed Jun 13 23:21:06 CEST 2012 6/13/12 15:21:06:957 CEST 0000002d TGSAuthToken 3 Service Ticket expiration time=Wed Jun 13 20:39:03 CEST 2012 6/13/12 15:21:06:957 CEST 0000002d KRBConsumeLog < validate() Exit 6/13/12 15:21:06:958 CEST 0000002d TokenHolder > setInboundTokenToContext(TGSAuthToken newtoken, MessageContext messageContext) Entry 6/13/12 15:21:06:958 CEST 0000002d TokenHolder 3 The operation context is NULL!!! 6/13/12 15:21:06:958 CEST 0000002d TokenHolder 3 Added token uuid = /G5KotjIaIUvW0KlN1McFLAP/Jo= to the message context 6/13/12 15:21:06:958 CEST 0000002d TokenHolder < setInboundTokenToContext(TGSAuthToken newtoken, MessageContext messageContext) Exit 6/13/12 15:21:06:966 CEST 0000002d WSSecurityFac 3 factory key = com.ibm.ws.wssecurity.platform.krbAuthnTokenFactory 6/13/12 15:21:06:966 CEST 0000002d WSSecurityFac 3 factory impl class = com.ibm.ws.wssecurity.platform.websphere.token.KRBAuthnTokenFactoryImpl 6/13/12 15:21:06:966 CEST 0000002d KRBGenerateLo > createKrbTokenImpl() Entry 6/13/12 15:21:06:973 CEST 0000002d KRBAuthnToken > KRBAuthnTokenImpl(map): Entry 6/13/12 15:21:06:974 CEST 0000002d KRBAuthnToken < KRBAuthnTokenImpl(map) = token name: com.ibm.wsspi.wssecurity.token.krbAuthnToken version: 1 hashCode: -1624995704 uniqueId: null kerberos principal: eo30021 realm: null expiration: Wed Jun 13 23:21:06 CEST 2012 renew until: null isReadOnly: false isAddressless: false isForwardable: false isRenewable: false KerberosTicket: Kerberos TGT is null. GSSCredential: null Exit 6/13/12 15:21:06:974 CEST 0000002d KRBGenerateLo < createKrbTokenImpl() Exit ... 6/13/12 15:21:06:990 CEST 0000002d KRBConsumeLog 3 Kerberos client principal: eo30021 6/13/12 15:21:06:990 CEST 0000002d KRBConsumeLog < processBST() Exit 6/13/12 15:21:06:990 CEST 0000002d KRBConsumeLog 3 Principal from request Kerberos token: eo30021 6/13/12 15:21:06:990 CEST 0000002d KRBConsumeLog 3 Expired time for request TGT Kerberos token: 1339622466956 6/13/12 15:21:06:990 CEST 0000002d KRBConsumeLog 3 No Kerberos ticket is accessible at the moment. 6/13/12 15:21:06:990 CEST 0000002d TokenHolder > setInboundTokenToContext(SecurityToken token, MessageContext messageContext) Entry 6/13/12 15:21:06:990 CEST 0000002d TokenHolder 3 The operation context is NULL!!! 6/13/12 15:21:06:990 CEST 0000002d TokenHolder 3 Added token uuid = /G5KotjIaIUvW0KlN1McFLAP/Jo= to the message context 6/13/12 15:21:06:990 CEST 0000002d TokenHolder < setInboundTokenToContext(SecurityToken token, MessageContext messageContext) Exit 6/13/12 15:21:06:990 CEST 0000002d KRBConsumeLog < login() Exit 6/13/12 15:21:06:993 CEST 0000002d DKTConsumeLog > initialize(Subject subject, CallbackHandler handler, Map sharedState, Map options) Entry 6/13/12 15:21:06:993 CEST 0000002d WSSAuditServi > isEventRequired(WSSAuditService.WSSAuditEventType eventTypeSECURITY_AUTHN, WSSAuditService.WSSAuditOutcome out comeSUCCESS, Map<Object, Object> context) Entry 6/13/12 15:21:06:993 CEST 0000002d WSSAuditServi 3 Usage error, context should not be null 6/13/12 15:21:06:993 CEST 0000002d WSSAuditServi < isRequired returns: false Exit 6/13/12 15:21:06:993 CEST 0000002d WSSAuditServi > isEventRequired(WSSAuditService.WSSAuditEventType eventTypeSECURITY_AUTHN, WSSAuditService.WSSAuditOutcome out comeDENIED, Map<Object, Object> context) Entry 6/13/12 15:21:06:993 CEST 0000002d WSSAuditServi 3 Usage error, context should not be null 6/13/12 15:21:06:993 CEST 0000002d WSSAuditServi < isRequired returns: false Exit 6/13/12 15:21:06:993 CEST 0000002d DKTConsumeLog < initialize(Subject, CallbackHandler, Map, Map) Exit 6/13/12 15:21:06:993 CEST 0000002d DKTConsumeLog > login() Entry 6/13/12 15:21:06:993 CEST] 0000002d CommonCallbac > handle(Callback[ callbacks[Ljavax.security.auth.callback.Callback;@10bd10bd) Entry 6/13/12 15:21:06:993 CEST] 0000002d CommonCallbac < handle(Callback[ callbacks) Exit 6/13/12 15:21:06:993 CEST 0000002d KRBConsumeLog > commit() Entry To respond to this post, please click the following link: <http://www.ibm.com/developerworks/forums/thread.jspa?messageID=14837917> ____________________________________ Unsubscribe via the "binocular" icon on the web
