Support for both SPNEGO and Kerberos mechanisms. Improved logging

keycloak · Feb 11, 2015 · 07bda93 · 07bda93
1 parent 40f2fb9
commit 07bda93
Show file tree

Hide file tree

Showing 5 changed files with 46 additions and 40 deletions.
diff --git a/broker/kerberos/src/main/java/org/keycloak/broker/kerberos/KerberosConstants.java b/broker/kerberos/src/main/java/org/keycloak/broker/kerberos/KerberosConstants.java
@@ -22,4 +22,9 @@ public class KerberosConstants {
      */
     public static final String SPNEGO_OID = "1.3.6.1.5.5.2";
 
+    /**
+     * OID of Kerberos v5 mechanism. See http://www.oid-info.com/get/1.2.840.113554.1.2.2
+     */
+    public static final String KRB5_OID = "1.2.840.113554.1.2.2";
+
 }
diff --git a/broker/kerberos/src/main/java/org/keycloak/broker/kerberos/KerberosIdentityProvider.java b/broker/kerberos/src/main/java/org/keycloak/broker/kerberos/KerberosIdentityProvider.java
@@ -30,8 +30,6 @@ public KerberosIdentityProvider(KerberosIdentityProviderConfig config) {
 
     @Override
     public AuthenticationResponse handleRequest(AuthenticationRequest request) {
-        // TODO: trace
-        logger.info("handleRequest");
 
         // Just redirect to handleResponse for now
         URI redirectUri = UriBuilder.fromUri(request.getRedirectUri()).queryParam(KerberosConstants.RELAY_STATE_PARAM, request.getState()).build();
@@ -99,6 +97,10 @@ protected KerberosServerSubjectAuthenticator createKerberosSubjectAuthenticator(
     protected AuthenticationResponse sendNegotiateResponse(String negotiateToken) {
         String negotiateHeader = negotiateToken == null ? KerberosConstants.NEGOTIATE : KerberosConstants.NEGOTIATE + " " + negotiateToken;
 
+        if (logger.isTraceEnabled()) {
+            logger.trace("Sending back " + HttpHeaders.WWW_AUTHENTICATE + ": " + negotiateHeader);
+        }
+
         Response response = Response.status(Response.Status.UNAUTHORIZED)
                 .header(HttpHeaders.WWW_AUTHENTICATE, negotiateHeader)
                 .build();
@@ -111,7 +113,7 @@ protected FederatedIdentity getFederatedIdentity(SPNEGOAuthenticator spnegoAuthe
         FederatedIdentity user = new FederatedIdentity(kerberosUsername);
         user.setUsername(kerberosUsername);
 
-        // Just guessing email, but likely can't do anything better...
+        // Just guessing email
         String[] tokens = kerberosUsername.split("@");
         String email = tokens[0] + "@" + tokens[1].toLowerCase();
         user.setEmail(email);

diff --git a/.../kerberos/src/main/java/org/keycloak/broker/kerberos/KerberosIdentityProviderFactory.java b/.../kerberos/src/main/java/org/keycloak/broker/kerberos/KerberosIdentityProviderFactory.java
@@ -1,6 +1,5 @@
 package org.keycloak.broker.kerberos;
 
-import org.keycloak.broker.kerberos.KerberosIdentityProvider;
 import org.keycloak.broker.provider.AbstractIdentityProviderFactory;
 import org.keycloak.models.IdentityProviderModel;
 

diff --git a/broker/kerberos/src/main/java/org/keycloak/broker/kerberos/impl/SPNEGOAuthenticator.java b/broker/kerberos/src/main/java/org/keycloak/broker/kerberos/impl/SPNEGOAuthenticator.java
@@ -1,6 +1,7 @@
 package org.keycloak.broker.kerberos.impl;
 
 import java.io.IOException;
+import java.security.PrivilegedActionException;
 import java.security.PrivilegedExceptionAction;
 
 import javax.security.auth.Subject;
@@ -10,16 +11,14 @@
 import org.ietf.jgss.GSSCredential;
 import org.ietf.jgss.GSSException;
 import org.ietf.jgss.GSSManager;
-import org.ietf.jgss.Oid;
 import org.jboss.logging.Logger;
-import org.keycloak.broker.kerberos.KerberosConstants;
 
 /**
  * @author <a href="mailto:mposolda@redhat.com">Marek Posolda</a>
  */
 public class SPNEGOAuthenticator {
 
-    private static final Logger logger = Logger.getLogger(SPNEGOAuthenticator.class);
+    private static final Logger log = Logger.getLogger(SPNEGOAuthenticator.class);
 
     private static final GSSManager GSS_MANAGER = GSSManager.getInstance();
 
@@ -37,18 +36,21 @@ public SPNEGOAuthenticator(KerberosServerSubjectAuthenticator kerberosSubjectAut
     }
 
     public void authenticate() {
-        // TODO: debug
-        logger.info("SPNEGO Login with token: " + spnegoToken);
+        if (log.isTraceEnabled()) {
+            log.trace("SPNEGO Login with token: " + spnegoToken);
+        }
 
         try {
             Subject serverSubject = kerberosSubjectAuthenticator.authenticateServerSubject();
             authenticated = Subject.doAs(serverSubject, new AcceptSecContext());
         } catch (Exception e) {
-            logger.warn("SPNEGO login failed: " + e.getMessage());
-
-            // TODO: debug and check if it is shown in the log
-            if (logger.isInfoEnabled()) {
-                logger.info("SPNEGO login failed: " + e.getMessage(), e);
+            String message = e.getMessage();
+            if (e instanceof PrivilegedActionException && e.getCause() != null) {
+                message = e.getCause().getMessage();
+            }
+            log.warn("SPNEGO login failed: " + message);
+            if (log.isDebugEnabled()) {
+                log.debug("SPNEGO login failed: " + message, e);
             }
         } finally {
             kerberosSubjectAuthenticator.logoutServerSubject();
@@ -77,18 +79,21 @@ private class AcceptSecContext implements PrivilegedExceptionAction<Boolean> {
         public Boolean run() throws Exception {
             GSSContext gssContext = null;
             try {
-                // TODO: debug
-                logger.info("Going to establish security context");
+                if (log.isTraceEnabled()) {
+                    log.trace("Going to establish security context");
+                }
+
                 gssContext = establishContext();
                 logAuthDetails(gssContext);
 
-                // What should be done with delegation credential? Figure out if there are use-cases for storing it as claims in FederatedIdentity
-                if (gssContext.getCredDelegState()) {
-                    delegationCredential = gssContext.getDelegCred();
-                }
-
                 if (gssContext.isEstablished()) {
                     principal = gssContext.getSrcName().toString();
+
+                    // What should be done with delegation credential? Figure out if there are use-cases for storing it as claims in FederatedIdentity
+                    if (gssContext.getCredDelegState()) {
+                        delegationCredential = gssContext.getDelegCred();
+                    }
+
                     return true;
                 } else {
                     return false;
@@ -103,12 +108,7 @@ public Boolean run() throws Exception {
     }
 
     protected GSSContext establishContext() throws GSSException, IOException {
-        Oid spnegoOid = new Oid(KerberosConstants.SPNEGO_OID);
-        GSSCredential credential = GSS_MANAGER.createCredential(null,
-                GSSCredential.DEFAULT_LIFETIME,
-                spnegoOid,
-                GSSCredential.ACCEPT_ONLY);
-        GSSContext gssContext = GSS_MANAGER.createContext(credential);
+        GSSContext gssContext = GSS_MANAGER.createContext((GSSCredential) null);
 
         byte[] inputToken = Base64.decode(spnegoToken);
         byte[] respToken = gssContext.acceptSecContext(inputToken, 0, inputToken.length);
@@ -118,20 +118,18 @@ protected GSSContext establishContext() throws GSSException, IOException {
     }
 
     protected void logAuthDetails(GSSContext gssContext) throws GSSException {
-
-        // TODO: debug
-        if (logger.isInfoEnabled()) {
+        if (log.isDebugEnabled()) {
             String message = new StringBuilder("SPNEGO Security context accepted with token: " + responseToken)
-                    .append(", established: " + gssContext.isEstablished())
-                    .append(", credDelegState: " + gssContext.getCredDelegState())
-                    .append(", mutualAuthState: " + gssContext.getMutualAuthState())
-                    .append(", lifetime: " + gssContext.getLifetime())
-                    .append(", confState: " + gssContext.getConfState())
-                    .append(", integState: " + gssContext.getIntegState())
-                    .append(", srcName: " + gssContext.getSrcName())
-                    .append(", targName: " + gssContext.getTargName())
+                    .append(", established: ").append(gssContext.isEstablished())
+                    .append(", credDelegState: ").append(gssContext.getCredDelegState())
+                    .append(", mutualAuthState: ").append(gssContext.getMutualAuthState())
+                    .append(", lifetime: ").append(gssContext.getLifetime())
+                    .append(", confState: ").append(gssContext.getConfState())
+                    .append(", integState: ").append(gssContext.getIntegState())
+                    .append(", srcName: ").append(gssContext.getSrcName())
+                    .append(", targName: ").append(gssContext.getTargName())
                     .toString();
-            logger.info(message);
+            log.debug(message);
         }
     }
 

diff --git a/testsuite/integration/src/main/resources/log4j.properties b/testsuite/integration/src/main/resources/log4j.properties
@@ -14,9 +14,11 @@ log4j.logger.org.keycloak=info
 # Enable to view database updates
 # log4j.logger.org.keycloak.connections.jpa.updater.liquibase.LiquibaseJpaUpdaterProvider=debug
 # log4j.logger.org.keycloak.connections.mongo.updater.DefaultMongoUpdaterProvider=debug
-
 # log4j.logger.org.keycloak.connections.jpa.DefaultJpaConnectionProviderFactory=debug
 
+# Enable to view kerberos/spnego logging
+# log4j.logger.org.keycloak.broker.kerberos=trace
+
 log4j.logger.org.xnio=off
 log4j.logger.org.hibernate=off
 log4j.logger.org.jboss.resteasy=warn