You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@mina.apache.org by lg...@apache.org on 2015/12/09 11:07:09 UTC

[6/6] mina-sshd git commit: Added more detailed log messages as to the authentication progress

Added more detailed log messages as to the authentication progress


Project: http://git-wip-us.apache.org/repos/asf/mina-sshd/repo
Commit: http://git-wip-us.apache.org/repos/asf/mina-sshd/commit/0371baef
Tree: http://git-wip-us.apache.org/repos/asf/mina-sshd/tree/0371baef
Diff: http://git-wip-us.apache.org/repos/asf/mina-sshd/diff/0371baef

Branch: refs/heads/master
Commit: 0371baefc52c55961a2df43af5f86b5add5c71b8
Parents: 4cdbefc
Author: Lyor Goldstein <lg...@vmware.com>
Authored: Wed Dec 9 12:02:16 2015 +0200
Committer: Lyor Goldstein <lg...@vmware.com>
Committed: Wed Dec 9 12:02:16 2015 +0200

----------------------------------------------------------------------
 .../auth/UserAuthKeyboardInteractive.java       | 36 ++++++---
 .../client/session/ClientUserAuthService.java   | 78 +++++++++++++-------
 .../auth/UserAuthKeyboardInteractive.java       | 32 ++++++--
 .../apache/sshd/server/auth/UserAuthNone.java   |  3 +
 .../sshd/server/auth/UserAuthPassword.java      |  6 +-
 .../sshd/server/auth/UserAuthPublicKey.java     | 68 +++++++++++------
 .../server/session/ServerUserAuthService.java   | 76 +++++++++++++------
 7 files changed, 213 insertions(+), 86 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/mina-sshd/blob/0371baef/sshd-core/src/main/java/org/apache/sshd/client/auth/UserAuthKeyboardInteractive.java
----------------------------------------------------------------------
diff --git a/sshd-core/src/main/java/org/apache/sshd/client/auth/UserAuthKeyboardInteractive.java b/sshd-core/src/main/java/org/apache/sshd/client/auth/UserAuthKeyboardInteractive.java
index 553a544..203c3d1 100644
--- a/sshd-core/src/main/java/org/apache/sshd/client/auth/UserAuthKeyboardInteractive.java
+++ b/sshd-core/src/main/java/org/apache/sshd/client/auth/UserAuthKeyboardInteractive.java
@@ -160,6 +160,9 @@ public class UserAuthKeyboardInteractive extends AbstractUserAuth {
 
             String[] rep = getUserResponses(name, instruction, language_tag, prompt, echo);
             if (rep == null) {
+                if (log.isDebugEnabled()) {
+                    log.debug("process({})[{}] no responses for {}", session, service, name);
+                }
                 return false;
             }
 
@@ -173,19 +176,24 @@ public class UserAuthKeyboardInteractive extends AbstractUserAuth {
              * However it is the server's (!) responsibility to fail, so we only warn...
              */
             if (num != rep.length) {
-                log.warn("process({}) Mismatched prompts ({}) vs. responses count ({})", session, num, rep.length);
+                log.warn("process({})[{}] Mismatched prompts ({}) vs. responses count ({})",
+                         session, service, num, rep.length);
             }
 
             buffer = session.prepareBuffer(SshConstants.SSH_MSG_USERAUTH_INFO_RESPONSE, BufferUtils.clear(buffer));
             buffer.putInt(rep.length);
-            for (String r : rep) {
+            for (int index = 0; index < rep.length; index++) {
+                String r = rep[index];
+                if (log.isTraceEnabled()) {
+                    log.trace("process({})[{}] response #{}: {}", session, service, index + 1, r);
+                }
                 buffer.putString(r);
             }
             session.writePacket(buffer);
             return true;
         }
 
-        throw new IllegalStateException("process(" + session + ")[" + service + ")"
+        throw new IllegalStateException("process(" + session + ")[" + service + "]"
                 + " received unknown packet: cmd=" + SshConstants.getCommandMessageName(cmd));
     }
 
@@ -221,20 +229,30 @@ public class UserAuthKeyboardInteractive extends AbstractUserAuth {
      * a warning...)
      */
     protected String[] getUserResponses(String name, String instruction, String lang, String[] prompt, boolean[] echo) {
+        ClientSession session = getClientSession();
         int num = GenericUtils.length(prompt);
         if (num == 0) {
+            if (log.isDebugEnabled()) {
+                log.debug("getUserResponses({}) no prompts for interaction={}", session, name);
+            }
             return GenericUtils.EMPTY_STRING_ARRAY;
         }
 
         String candidate = getCurrentPasswordCandidate();
         if (useCurrentPassword(candidate, name, instruction, lang, prompt, echo)) {
-            return new String[]{candidate};
-        } else {
-            ClientSession session = getClientSession();
-            UserInteraction ui = session.getUserInteraction();
-            if ((ui != null) && ui.isInteractionAllowed(session)) {
-                return ui.interactive(session, name, instruction, lang, prompt, echo);
+            if (log.isDebugEnabled()) {
+                log.debug("getUserResponses({}) use password candidate for interaction={}", session, name);
             }
+            return new String[]{candidate};
+        }
+
+        UserInteraction ui = session.getUserInteraction();
+        if ((ui != null) && ui.isInteractionAllowed(session)) {
+            return ui.interactive(session, name, instruction, lang, prompt, echo);
+        }
+
+        if (log.isDebugEnabled()) {
+            log.debug("getUserResponses({}) no user interaction for name={}", session, name);
         }
 
         return null;

http://git-wip-us.apache.org/repos/asf/mina-sshd/blob/0371baef/sshd-core/src/main/java/org/apache/sshd/client/session/ClientUserAuthService.java
----------------------------------------------------------------------
diff --git a/sshd-core/src/main/java/org/apache/sshd/client/session/ClientUserAuthService.java b/sshd-core/src/main/java/org/apache/sshd/client/session/ClientUserAuthService.java
index 0e2fe5c..1e3ca06 100644
--- a/sshd-core/src/main/java/org/apache/sshd/client/session/ClientUserAuthService.java
+++ b/sshd-core/src/main/java/org/apache/sshd/client/session/ClientUserAuthService.java
@@ -52,7 +52,7 @@ public class ClientUserAuthService extends AbstractCloseable implements Service,
      */
     private final AuthFuture authFuture;
 
-    private final ClientSessionImpl session;
+    private final ClientSessionImpl clientSession;
 
     private List<Object> identities;
     private String service;
@@ -68,27 +68,35 @@ public class ClientUserAuthService extends AbstractCloseable implements Service,
         if (!(s instanceof ClientSessionImpl)) {
             throw new IllegalStateException("Client side service used on server side");
         }
-        session = (ClientSessionImpl) s;
-        authFuture = new DefaultAuthFuture(session.getLock());
-        authFactories = session.getUserAuthFactories();
+        clientSession = (ClientSessionImpl) s;
+        authFuture = new DefaultAuthFuture(clientSession.getLock());
+        authFactories = clientSession.getUserAuthFactories();
         clientMethods = new ArrayList<>();
 
-        String prefs = PropertyResolverUtils.getString(session, ClientAuthenticationManager.PREFERRED_AUTHS);
-        if (!GenericUtils.isEmpty(prefs)) {
-            for (String pref : prefs.split(",")) {
+        String prefs = PropertyResolverUtils.getString(s, ClientAuthenticationManager.PREFERRED_AUTHS);
+        if (GenericUtils.isEmpty(prefs)) {
+            for (NamedFactory<UserAuth> factory : authFactories) {
+                clientMethods.add(factory.getName());
+            }
+        } else {
+            if (log.isDebugEnabled()) {
+                log.debug("ClientUserAuthService({}) use configured preferrences: {}", s, prefs);
+            }
+
+            for (String pref : GenericUtils.split(prefs, ',')) {
                 NamedFactory<UserAuth> factory = NamedResource.Utils.findByName(pref, String.CASE_INSENSITIVE_ORDER, authFactories);
                 if (factory != null) {
                     clientMethods.add(pref);
                 } else {
                     if (log.isDebugEnabled()) {
-                        log.debug("ClientUserAuthService({}) skip unknown prefered authentication method: {}", s, pref);
+                        log.debug("ClientUserAuthService({}) skip unknown preferred authentication method: {}", s, pref);
                     }
                 }
             }
-        } else {
-            for (NamedFactory<UserAuth> factory : authFactories) {
-                clientMethods.add(factory.getName());
-            }
+        }
+
+        if (log.isDebugEnabled()) {
+            log.debug("ClientUserAuthService({}) client methods: {}", s, clientMethods);
         }
     }
 
@@ -99,7 +107,7 @@ public class ClientUserAuthService extends AbstractCloseable implements Service,
 
     @Override
     public ClientSession getClientSession() {
-        return session;
+        return clientSession;
     }
 
     @Override
@@ -111,12 +119,14 @@ public class ClientUserAuthService extends AbstractCloseable implements Service,
         this.identities = new ArrayList<>(identities);
         this.service = service;
 
+        ClientSession session = getClientSession();
+        String username = session.getUsername();
         if (log.isDebugEnabled()) {
-            log.debug("auth({})[{}] Send SSH_MSG_USERAUTH_REQUEST for 'none'", getClientSession(), service);
+            log.debug("auth({})[{}] Send SSH_MSG_USERAUTH_REQUEST for 'none'", session, service);
         }
-        String username = session.getUsername();
+
         Buffer buffer = session.createBuffer(SshConstants.SSH_MSG_USERAUTH_REQUEST, username.length() + service.length() + Integer.SIZE);
-        buffer.putString(session.getUsername());
+        buffer.putString(username);
         buffer.putString(service);
         buffer.putString("none");
         session.writePacket(buffer);
@@ -126,6 +136,7 @@ public class ClientUserAuthService extends AbstractCloseable implements Service,
 
     @Override
     public void process(int cmd, Buffer buffer) throws Exception {
+        ClientSession session = getClientSession();
         if (this.authFuture.isSuccess()) {
             throw new IllegalStateException("UserAuth message delivered to authenticated client");
         } else if (this.authFuture.isDone()) {
@@ -159,41 +170,51 @@ public class ClientUserAuthService extends AbstractCloseable implements Service,
      */
     protected void processUserAuth(Buffer buffer) throws Exception {
         int cmd = buffer.getUByte();
+        ClientSession session = getClientSession();
         if (cmd == SshConstants.SSH_MSG_USERAUTH_SUCCESS) {
             if (log.isDebugEnabled()) {
                 log.debug("processUserAuth({}) SSH_MSG_USERAUTH_SUCCESS Succeeded with {}",
-                          getClientSession(), userAuth);
+                          session, userAuth);
             }
             if (userAuth != null) {
-                userAuth.destroy();
-                userAuth = null;
+                try {
+                    userAuth.destroy();
+                } finally {
+                    userAuth = null;
+                }
             }
             session.setAuthenticated();
-            session.switchToNextService();
+            ((ClientSessionImpl) session).switchToNextService();
             // Will wake up anyone sitting in waitFor
             authFuture.setAuthed(true);
             return;
         }
+
         if (cmd == SshConstants.SSH_MSG_USERAUTH_FAILURE) {
             String mths = buffer.getString();
             boolean partial = buffer.getBoolean();
             if (log.isDebugEnabled()) {
                 log.debug("processUserAuth({}) Received SSH_MSG_USERAUTH_FAILURE - partial={}, methods={}",
-                          getClientSession(), partial, mths);
+                          session, partial, mths);
             }
             if (partial || (serverMethods == null)) {
                 serverMethods = Arrays.asList(GenericUtils.split(mths, ','));
                 if (userAuth != null) {
-                    userAuth.destroy();
-                    userAuth = null;
+                    try {
+                        userAuth.destroy();
+                    } finally {
+                        userAuth = null;
+                    }
                 }
             }
             tryNext();
             return;
         }
+
         if (userAuth == null) {
-            throw new IllegalStateException("Received unknown packet");
+            throw new IllegalStateException("Received unknown packet: " + SshConstants.getCommandMessageName(cmd));
         }
+
         buffer.rpos(buffer.rpos() - 1);
         if (!userAuth.process(buffer)) {
             tryNext();
@@ -201,6 +222,7 @@ public class ClientUserAuthService extends AbstractCloseable implements Service,
     }
 
     protected void tryNext() throws Exception {
+        ClientSession session = getClientSession();
         // Loop until we find something to try
         while (true) {
             if (userAuth == null) {
@@ -218,10 +240,12 @@ public class ClientUserAuthService extends AbstractCloseable implements Service,
 
             if (currentMethod >= clientMethods.size()) {
                 if (log.isDebugEnabled()) {
-                    log.debug("tryNext({}) exhausted all methods", getClientSession());
+                    log.debug("tryNext({}) exhausted all methods - client={}, server={}",
+                              session, clientMethods, serverMethods);
                 }
 
-                authFuture.setAuthed(false);
+                // also wake up anyone sitting in waitFor
+                authFuture.setException(new SshException(SshConstants.SSH2_DISCONNECT_NO_MORE_AUTH_METHODS_AVAILABLE, "No more authentication methods available"));
                 return;
             }
 
@@ -231,7 +255,7 @@ public class ClientUserAuthService extends AbstractCloseable implements Service,
                 throw new UnsupportedOperationException("Failed to find a user-auth factory for method=" + method);
             }
             if (log.isDebugEnabled()) {
-                log.debug("tryNext({}) attempting method={}", getClientSession(), method);
+                log.debug("tryNext({}) attempting method={}", session, method);
             }
 
             userAuth.init(session, service, identities);

http://git-wip-us.apache.org/repos/asf/mina-sshd/blob/0371baef/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthKeyboardInteractive.java
----------------------------------------------------------------------
diff --git a/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthKeyboardInteractive.java b/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthKeyboardInteractive.java
index a384520..9639929 100644
--- a/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthKeyboardInteractive.java
+++ b/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthKeyboardInteractive.java
@@ -24,6 +24,7 @@ import java.util.List;
 
 import org.apache.sshd.common.SshConstants;
 import org.apache.sshd.common.SshException;
+import org.apache.sshd.common.util.GenericUtils;
 import org.apache.sshd.common.util.buffer.Buffer;
 import org.apache.sshd.common.util.buffer.BufferUtils;
 import org.apache.sshd.server.auth.keyboard.InteractiveChallenge;
@@ -45,13 +46,15 @@ public class UserAuthKeyboardInteractive extends AbstractUserAuth {
     @Override
     protected Boolean doAuth(Buffer buffer, boolean init) throws Exception {
         ServerSession session = getServerSession();
+        String username = getUsername();
         KeyboardInteractiveAuthenticator auth = session.getKeyboardInteractiveAuthenticator();
         if (init) {
             String lang = buffer.getString();
             String subMethods = buffer.getString();
             if (auth == null) {
                 if (log.isDebugEnabled()) {
-                    log.debug("doAuth({}) no interactive authenticator to generate challenge", session);
+                    log.debug("doAuth({}@{})[methods={}, lang={}] - no interactive authenticator to generate challenge",
+                              username, session, subMethods, lang);
                 }
                 return false;
             }
@@ -59,11 +62,19 @@ public class UserAuthKeyboardInteractive extends AbstractUserAuth {
             InteractiveChallenge challenge = auth.generateChallenge(session, getUsername(), lang, subMethods);
             if (challenge == null) {
                 if (log.isDebugEnabled()) {
-                    log.debug("doAuth({}) no interactive challenge generated", session);
+                    log.debug("doAuth({}@{})[methods={}, lang={}] - no interactive challenge generated",
+                              username, session, subMethods, lang);
                 }
                 return false;
             }
 
+            if (log.isDebugEnabled()) {
+                log.debug("doAuth({}@{})[methods={}, lang={}] challenge name={}, instruction={}, lang={}, num. prompts={}",
+                          username, session, subMethods, lang,
+                          challenge.getInteractionName(), challenge.getInteractionInstruction(),
+                          challenge.getLanguageTag(), GenericUtils.size(challenge.getPrompts()));
+            }
+
             // Prompt for password
             buffer = session.prepareBuffer(SshConstants.SSH_MSG_USERAUTH_INFO_REQUEST, BufferUtils.clear(buffer));
             challenge.append(buffer);
@@ -78,17 +89,28 @@ public class UserAuthKeyboardInteractive extends AbstractUserAuth {
             int num = buffer.getInt();
             List<String> responses = (num <= 0) ? Collections.<String>emptyList() : new ArrayList<String>(num);
             for (int index = 0; index < num; index++) {
-                responses.add(buffer.getString());
+                String value = buffer.getString();
+                if (log.isTraceEnabled()) {
+                    log.trace("doAuth({}@{}) response #{}: {}", username, session, index + 1, value);
+                }
+                responses.add(value);
             }
 
             if (auth == null) {
                 if (log.isDebugEnabled()) {
-                    log.debug("doAuth({}) no interactive authenticator to validate responses", session);
+                    log.debug("doAuth({}@{}) no interactive authenticator to validate {} responses",
+                              username, session, num);
                 }
                 return false;
             }
 
-            return auth.authenticate(session, getUsername(), responses);
+            boolean authed = auth.authenticate(session, username, responses);
+            if (log.isDebugEnabled()) {
+                log.debug("doAuth({}@{}) authenticate {} responses result: {}",
+                          username, session, num, authed);
+            }
+
+            return authed;
         }
     }
 }

http://git-wip-us.apache.org/repos/asf/mina-sshd/blob/0371baef/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthNone.java
----------------------------------------------------------------------
diff --git a/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthNone.java b/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthNone.java
index 8cc708e..8b20eed 100644
--- a/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthNone.java
+++ b/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthNone.java
@@ -34,6 +34,9 @@ public class UserAuthNone extends AbstractUserAuth {
 
     @Override
     public Boolean doAuth(Buffer buffer, boolean init) {
+        if (log.isDebugEnabled()) {
+            log.debug("doAuth({}@{}) init={}", getUsername(), getServerSession(), init);
+        }
         return Boolean.TRUE;
     }
 }

http://git-wip-us.apache.org/repos/asf/mina-sshd/blob/0371baef/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthPassword.java
----------------------------------------------------------------------
diff --git a/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthPassword.java b/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthPassword.java
index d59720b..b0e72d4 100644
--- a/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthPassword.java
+++ b/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthPassword.java
@@ -77,7 +77,11 @@ public class UserAuthPassword extends AbstractUserAuth {
         }
 
         try {
-            return auth.authenticate(username, password, session);
+            boolean authed = auth.authenticate(username, password, session);
+            if (log.isDebugEnabled()) {
+                log.debug("checkPassword({}) authentication result: {}", session, authed);
+            }
+            return authed;
         } catch (PasswordChangeRequiredException e) {
             if (log.isDebugEnabled()) {
                 log.debug("checkPassword({}) password change required: {}", session, e.getMessage());

http://git-wip-us.apache.org/repos/asf/mina-sshd/blob/0371baef/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthPublicKey.java
----------------------------------------------------------------------
diff --git a/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthPublicKey.java b/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthPublicKey.java
index 5299a84..08b05b7 100644
--- a/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthPublicKey.java
+++ b/sshd-core/src/main/java/org/apache/sshd/server/auth/UserAuthPublicKey.java
@@ -55,10 +55,11 @@ public class UserAuthPublicKey extends AbstractUserAuth {
         buffer.wpos(buffer.rpos() + len);
 
         ServerSession session = getServerSession();
+        String username = getUsername();
         PublicKey key = buffer.getRawPublicKey();
         if (log.isDebugEnabled()) {
-            log.debug("doAuth({}) verify key type={}, fingerprint={}",
-                      session, alg, KeyUtils.getFingerPrint(key));
+            log.debug("doAuth({}@{}) verify key type={}, fingerprint={}",
+                      username, session, alg, KeyUtils.getFingerPrint(key));
         }
 
         Signature verifier = ValidateUtils.checkNotNull(
@@ -72,38 +73,63 @@ public class UserAuthPublicKey extends AbstractUserAuth {
         PublickeyAuthenticator authenticator = session.getPublickeyAuthenticator();
         if (authenticator == null) {
             if (log.isDebugEnabled()) {
-                log.debug("doAuth({}) no authenticator", session);
+                log.debug("doAuth({}@{}) key type={}, fingerprint={} - no authenticator",
+                          username, session, alg, KeyUtils.getFingerPrint(key));
             }
             return false;
         }
 
-        if (!authenticator.authenticate(getUsername(), key, session)) {
+        boolean authed = authenticator.authenticate(username, key, session);
+        if (log.isDebugEnabled()) {
+            log.debug("doAuth({}@{}) key type={}, fingerprint={} - authentication result: {}",
+                      username, session, alg, KeyUtils.getFingerPrint(key), authed);
+        }
+        if (!authed) {
             return Boolean.FALSE;
         }
 
         if (!hasSig) {
+            if (log.isDebugEnabled()) {
+                log.debug("doAuth({}@{}) send SSH_MSG_USERAUTH_PK_OK for key type={}, fingerprint={}",
+                           username, session, alg, KeyUtils.getFingerPrint(key));
+            }
+
             Buffer buf = session.prepareBuffer(SshConstants.SSH_MSG_USERAUTH_PK_OK, BufferUtils.clear(buffer));
             buf.putString(alg);
             buf.putRawBytes(buffer.array(), oldPos, 4 + len);
             session.writePacket(buf);
             return null;
-        } else {
-            Buffer buf = new ByteArrayBuffer();
-            buf.putBytes(session.getKex().getH());
-            buf.putByte(SshConstants.SSH_MSG_USERAUTH_REQUEST);
-            buf.putString(getUsername());
-            buf.putString(getService());
-            buf.putString(getName());
-            buf.putBoolean(true);
-            buf.putString(alg);
-            buffer.rpos(oldPos);
-            buffer.wpos(oldPos + 4 + len);
-            buf.putBuffer(buffer);
-            verifier.update(buf.array(), buf.rpos(), buf.available());
-            if (!verifier.verify(sig)) {
-                throw new Exception("Key verification failed");
-            }
-            return Boolean.TRUE;
         }
+
+        // verify signature
+        Buffer buf = new ByteArrayBuffer();
+        buf.putBytes(session.getKex().getH());
+        buf.putByte(SshConstants.SSH_MSG_USERAUTH_REQUEST);
+        buf.putString(username);
+        buf.putString(getService());
+        buf.putString(getName());
+        buf.putBoolean(true);
+        buf.putString(alg);
+        buffer.rpos(oldPos);
+        buffer.wpos(oldPos + 4 + len);
+        buf.putBuffer(buffer);
+        verifier.update(buf.array(), buf.rpos(), buf.available());
+        if (log.isTraceEnabled()) {
+            log.trace("doAuth({}@{}) key type={}, fingerprint={} - verification data={}",
+                      username, session, alg, KeyUtils.getFingerPrint(key), buf.printHex());
+            log.trace("doAuth({}@{}) key type={}, fingerprint={} - expected signature={}",
+                    username, session, alg, KeyUtils.getFingerPrint(key), BufferUtils.printHex(sig));
+        }
+
+        if (!verifier.verify(sig)) {
+            throw new Exception("Key verification failed");
+        }
+
+        if (log.isDebugEnabled()) {
+            log.debug("doAuth({}@{}) key type={}, fingerprint={} - verified",
+                      username, session, alg, KeyUtils.getFingerPrint(key));
+        }
+
+        return Boolean.TRUE;
     }
 }

http://git-wip-us.apache.org/repos/asf/mina-sshd/blob/0371baef/sshd-core/src/main/java/org/apache/sshd/server/session/ServerUserAuthService.java
----------------------------------------------------------------------
diff --git a/sshd-core/src/main/java/org/apache/sshd/server/session/ServerUserAuthService.java b/sshd-core/src/main/java/org/apache/sshd/server/session/ServerUserAuthService.java
index 977bdc4..a67b40f 100644
--- a/sshd-core/src/main/java/org/apache/sshd/server/session/ServerUserAuthService.java
+++ b/sshd-core/src/main/java/org/apache/sshd/server/session/ServerUserAuthService.java
@@ -45,7 +45,7 @@ import org.apache.sshd.server.auth.UserAuthNoneFactory;
  */
 public class ServerUserAuthService extends AbstractCloseable implements Service, ServerSessionHolder {
 
-    private final ServerSession session;
+    private final ServerSession serverSession;
     private List<NamedFactory<UserAuth>> userAuthFactories;
     private List<List<String>> authMethods;
     private String authUserName;
@@ -62,22 +62,25 @@ public class ServerUserAuthService extends AbstractCloseable implements Service,
             throw new SshException("Session already authenticated");
         }
 
-        this.session = (ServerSession) s;
-        maxAuthRequests = PropertyResolverUtils.getIntProperty(session, ServerAuthenticationManager.MAX_AUTH_REQUESTS, ServerAuthenticationManager.DEFAULT_MAX_AUTH_REQUESTS);
+        serverSession = (ServerSession) s;
+        maxAuthRequests = PropertyResolverUtils.getIntProperty(s, ServerAuthenticationManager.MAX_AUTH_REQUESTS, ServerAuthenticationManager.DEFAULT_MAX_AUTH_REQUESTS);
 
-        List<NamedFactory<UserAuth>> factories = session.getUserAuthFactories();
+        List<NamedFactory<UserAuth>> factories = serverSession.getUserAuthFactories();
         userAuthFactories = new ArrayList<>(factories);
         // Get authentication methods
         authMethods = new ArrayList<>();
 
-        String mths = PropertyResolverUtils.getString(session, ServerFactoryManager.AUTH_METHODS);
+        String mths = PropertyResolverUtils.getString(s, ServerFactoryManager.AUTH_METHODS);
         if (GenericUtils.isEmpty(mths)) {
             for (NamedFactory<UserAuth> uaf : factories) {
                 authMethods.add(new ArrayList<>(Collections.singletonList(uaf.getName())));
             }
         } else {
+            if (log.isDebugEnabled()) {
+                log.debug("ServerUserAuthService({}) using configured methods={}", s, mths);
+            }
             for (String mthl : mths.split("\\s")) {
-                authMethods.add(new ArrayList<>(Arrays.asList(mthl.split(","))));
+                authMethods.add(new ArrayList<>(Arrays.asList(GenericUtils.split(mthl, ','))));
             }
         }
         // Verify all required methods are supported
@@ -91,7 +94,8 @@ public class ServerUserAuthService extends AbstractCloseable implements Service,
         }
 
         if (log.isDebugEnabled()) {
-            log.debug("Authorized authentication methods: {}", NamedResource.Utils.getNames(userAuthFactories));
+            log.debug("ServerUserAuthService({}) authorized authentication methods: {}",
+                      s, NamedResource.Utils.getNames(userAuthFactories));
         }
     }
 
@@ -107,17 +111,21 @@ public class ServerUserAuthService extends AbstractCloseable implements Service,
 
     @Override
     public ServerSession getServerSession() {
-        return session;
+        return serverSession;
     }
 
     @Override
     public void process(int cmd, Buffer buffer) throws Exception {
         Boolean authed = Boolean.FALSE;
+        ServerSession session = getServerSession();
 
         if (cmd == SshConstants.SSH_MSG_USERAUTH_REQUEST) {
-            if (this.currentAuth != null) {
-                this.currentAuth.destroy();
-                this.currentAuth = null;
+            if (currentAuth != null) {
+                try {
+                    currentAuth.destroy();
+                } finally {
+                    currentAuth = null;
+                }
             }
 
             String username = buffer.getString();
@@ -125,7 +133,7 @@ public class ServerUserAuthService extends AbstractCloseable implements Service,
             String method = buffer.getString();
             if (log.isDebugEnabled()) {
                 log.debug("process({}) Received SSH_MSG_USERAUTH_REQUEST user={}, service={}, method={}",
-                          getServerSession(), username, service, method);
+                          session, username, service, method);
             }
 
             if (this.authUserName == null || this.authService == null) {
@@ -141,26 +149,30 @@ public class ServerUserAuthService extends AbstractCloseable implements Service,
             // TODO: verify that the service is supported
             this.authMethod = method;
             if (nbAuthRequests++ > maxAuthRequests) {
-                session.disconnect(SshConstants.SSH2_DISCONNECT_PROTOCOL_ERROR, "Too many authentication failures");
+                session.disconnect(SshConstants.SSH2_DISCONNECT_PROTOCOL_ERROR, "Too many authentication failures: " + nbAuthRequests);
                 return;
             }
 
             if (log.isDebugEnabled()) {
-                log.debug("process({}) Authenticating user '{}' with service '{}' and method '{}'",
-                          getServerSession(), username, service, method);
+                log.debug("process({}) Authenticating user '{}' with service '{}' and method '{}' (attempt {} / {})",
+                          session, username, service, method, nbAuthRequests, maxAuthRequests);
             }
 
             NamedFactory<UserAuth> factory = NamedResource.Utils.findByName(method, String.CASE_INSENSITIVE_ORDER, userAuthFactories);
             if (factory != null) {
-                currentAuth = factory.create();
+                currentAuth = ValidateUtils.checkNotNull(factory.create(), "No authenticator created for method=%s", method);
                 try {
                     authed = currentAuth.auth(session, username, service, buffer);
                 } catch (Exception e) {
                     if (log.isDebugEnabled()) {
                         log.debug("process({}) Failed ({}) to authenticate using method={}: {}",
-                                  getServerSession(), e.getClass().getSimpleName(), method, e.getMessage());
+                                  session, e.getClass().getSimpleName(), method, e.getMessage());
                     }
                 }
+            } else {
+                if (log.isDebugEnabled()) {
+                    log.debug("process({}) no authentication factory for method={}", session, method);
+                }
             }
         } else {
             if (this.currentAuth == null) {
@@ -169,8 +181,9 @@ public class ServerUserAuthService extends AbstractCloseable implements Service,
             }
             if (log.isDebugEnabled()) {
                 log.debug("process({}) Received authentication message={} for mechanism={}",
-                          getServerSession(), SshConstants.getCommandMessageName(cmd), currentAuth.getName());
+                          session, SshConstants.getCommandMessageName(cmd), currentAuth.getName());
             }
+
             buffer.rpos(buffer.rpos() - 1);
             try {
                 authed = currentAuth.next(buffer);
@@ -178,7 +191,7 @@ public class ServerUserAuthService extends AbstractCloseable implements Service,
                 // Continue
                 if (log.isDebugEnabled()) {
                     log.debug("process({}) Failed ({}) to authenticate using method={}: {}",
-                              getServerSession(), e.getClass().getSimpleName(), currentAuth.getName(), e.getMessage());
+                              session, e.getClass().getSimpleName(), currentAuth.getName(), e.getMessage());
                 }
             }
         }
@@ -196,12 +209,13 @@ public class ServerUserAuthService extends AbstractCloseable implements Service,
         String username = (currentAuth == null) ? null : currentAuth.getUsername();
         if (log.isDebugEnabled()) {
             log.debug("handleAuthenticationInProgress({}@{}) {}",
-                      username, session, SshConstants.getCommandMessageName(cmd));
+                      username, getServerSession(), SshConstants.getCommandMessageName(cmd));
         }
     }
 
     protected void handleAuthenticationSuccess(int cmd, Buffer buffer) throws Exception {
         String username = ValidateUtils.checkNotNull(currentAuth, "No current auth").getUsername();
+        ServerSession session = getServerSession();
         if (log.isDebugEnabled()) {
             log.debug("handleAuthenticationSuccess({}@{}) {}",
                       username, session, SshConstants.getCommandMessageName(cmd));
@@ -242,6 +256,11 @@ public class ServerUserAuthService extends AbstractCloseable implements Service,
                 buffer = session.createBuffer(SshConstants.SSH_MSG_USERAUTH_BANNER, welcomeBanner.length() + lang.length() + Long.SIZE);
                 buffer.putString(welcomeBanner);
                 buffer.putString(lang);
+
+                if (log.isDebugEnabled()) {
+                    log.debug("handleAuthenticationSuccess({}@{}) send banner (length={}, lang={})",
+                              username, session, welcomeBanner.length(), lang);
+                }
                 session.writePacket(buffer);
             }
 
@@ -263,7 +282,12 @@ public class ServerUserAuthService extends AbstractCloseable implements Service,
                     sb.append(l.get(0));
                 }
             }
-            buffer.putString(sb.toString());
+
+            String remaining = sb.toString();
+            if (log.isDebugEnabled()) {
+                log.debug("handleAuthenticationSuccess({}@{}) remaining methods={}", username, session, remaining);
+            }
+            buffer.putString(remaining);
             buffer.putBoolean(true);    // partial success ...
             session.writePacket(buffer);
         }
@@ -277,6 +301,7 @@ public class ServerUserAuthService extends AbstractCloseable implements Service,
 
     protected void handleAuthenticationFailure(int cmd, Buffer buffer) throws Exception {
         String username = (currentAuth == null) ? null : currentAuth.getUsername();
+        ServerSession session = getServerSession();
         if (log.isDebugEnabled()) {
             log.debug("handleAuthenticationFailure({}@{}) {}",
                       username, session, SshConstants.getCommandMessageName(cmd));
@@ -295,7 +320,12 @@ public class ServerUserAuthService extends AbstractCloseable implements Service,
                 }
             }
         }
-        buffer.putString(sb.toString());
+
+        String remaining = sb.toString();
+        if (log.isDebugEnabled()) {
+            log.debug("handleAuthenticationFailure({}@{}) remaining methods: {}", username, session, remaining);
+        }
+        buffer.putString(remaining);
         buffer.putBoolean(false);   // no partial success ...
         session.writePacket(buffer);
 
@@ -309,6 +339,6 @@ public class ServerUserAuthService extends AbstractCloseable implements Service,
     }
 
     public ServerFactoryManager getFactoryManager() {
-        return session.getFactoryManager();
+        return serverSession.getFactoryManager();
     }
 }