Issue #15740: Fix timeout issue with running KTPASS command on the KD…

…C. Add more debugging to remote command execution in order help with these sort of issues in the future.

dev/com.ibm.ws.security.spnego.fat.common/fat/src/com/ibm/ws/security/spnego/fat/config/KdcHelper.java

@@ -1,5 +1,5 @@
 /*******************************************************************************
- * Copyright (c) 2014, 2020 IBM Corporation and others.
+ * Copyright (c) 2014, 2021 IBM Corporation and others.
  * All rights reserved. This program and the accompanying materials
  * are made available under the terms of the Eclipse Public License v1.0
  * which accompanies this distribution, and is available at
@@ -21,18 +21,22 @@
 import java.io.PrintWriter;
 import java.net.ConnectException;
 import java.rmi.RemoteException;
+import java.util.Arrays;
 import java.util.EnumSet;
 import java.util.Map;
 import java.util.Set;
 import java.util.Vector;
 import java.util.concurrent.TimeUnit;
+import java.util.stream.Collectors;
 
 import org.apache.sshd.client.SshClient;
 import org.apache.sshd.client.channel.ChannelExec;
 import org.apache.sshd.client.channel.ClientChannelEvent;
 import org.apache.sshd.client.scp.ScpClient;
 import org.apache.sshd.client.scp.ScpClientCreator;
 import org.apache.sshd.client.session.ClientSession;
+import org.apache.sshd.common.channel.Channel;
+import org.apache.sshd.common.channel.ChannelListener;
 import org.junit.Ignore;
 
 import com.ibm.websphere.simplicity.ConnectionInfo;
@@ -878,13 +882,15 @@ protected ClientSession getSshSession(SshClient sshClient, Machine machine) thro
      * @throws IOException If there was an error executing the command.
      */
     protected ProgramOutput executeSshCommand(ClientSession sshSession, String command, int timeout) throws IOException {
-        Log.info(thisClass, "executeSshCommand", "Executing SSH command --> \"{1}\" with a {2}s timeout on session {0}", new Object[] { sshSession, command, timeout });
+        final String methodName = "executeSshCommand";
+        Log.info(thisClass, methodName, "Executing SSH command --> \"{1}\" with a {2}s timeout on session {0}", new Object[] { sshSession, command, timeout });
 
         try (ByteArrayOutputStream stderr = new ByteArrayOutputStream();
                         ByteArrayOutputStream stdout = new ByteArrayOutputStream();
                         ChannelExec channel = sshSession.createExecChannel(command)) {
             channel.setOut(stdout);
             channel.setErr(stderr);
+            channel.addChannelListener(new SshChannelListener());
             try {
                 long remainingTimeoutMs = TimeUnit.SECONDS.toMillis(timeout);
 
@@ -896,7 +902,7 @@ protected ProgramOutput executeSshCommand(ClientSession sshSession, String comma
                 remainingTimeoutMs -= System.currentTimeMillis() - startTimeMs;
 
                 if (remainingTimeoutMs <= 0) {
-                    Log.info(thisClass, "executeSshCommand", "The SSH command timed out.");
+                    Log.info(thisClass, methodName, "The SSH command timed out.");
                     throw new IOException("Timed out trying to open a channel with the host to execute the SSH command. The timeout was " + timeout + " seconds.");
                 }
 
@@ -909,17 +915,68 @@ protected ProgramOutput executeSshCommand(ClientSession sshSession, String comma
                  * Did the command timeout? If so throw an exception.
                  */
                 if (ccEvents.contains(ClientChannelEvent.TIMEOUT)) {
-                    Log.info(thisClass, "executeSshCommand", "The SSH command timed out.");
+                    Log.info(thisClass, methodName, "The SSH command timed out. The timeout was " + timeout + " seconds.");
                     throw new IOException("The SSH command timed out while executing. The timeout was " + timeout + " seconds.");
                 }
-                Log.info(thisClass, "executeSshCommand", "SSH command returned status of {0}", channel.getExitStatus());
+
                 return new ProgramOutput(command, channel.getExitStatus(), new String(stdout.toByteArray()), new String(stderr.toByteArray()));
             } finally {
-                channel.close(false);
+                try {
+                    channel.close(false);
+                } catch (Throwable t) {
+                    // Ignore.
+                }
+
+                logSshOutput(new String(stdout.toByteArray()).trim(), new String(stderr.toByteArray()).trim());
             }
         }
     }
 
+    /**
+     * Log stdout and stderr from an SSH channel.
+     *
+     * @param stdout Standard output from the channel.
+     * @param stderr Standard input from the channel.
+     */
+    private static void logSshOutput(String stdout, String stderr) {
+        final String methodName = "logSshOutput";
+
+        /*
+         * Process stdout.
+         */
+        if (stdout.isEmpty()) {
+            stdout = "    [STDOUT] <NONE>";
+        } else {
+            /*
+             * Add "    [STDOUT] " to the beginning of each line. The split
+             * method might be resource intensive if we have large strings.
+             */
+            stdout = Arrays.stream(stdout.split("\\r?\\n"))
+                            .filter(line -> true)
+                            .map(line -> "    [STDOUT] " + line + System.lineSeparator())
+                            .collect(Collectors.joining());
+        }
+
+        /*
+         * Process stderr.
+         */
+        if (stderr.isEmpty()) {
+            stderr = "    [STDERR] <NONE>";
+        } else {
+            /*
+             * Add "    [STDERR] " to the beginning of each line. The split
+             * method might be resource intensive if we have large strings.
+             */
+            stderr = Arrays.stream(stderr.split("\\r?\\n"))
+                            .filter(line -> true)
+                            .map(line -> "    [STDERR] " + line + System.lineSeparator())
+                            .collect(Collectors.joining());
+        }
+
+        Log.info(thisClass, methodName, "SSH command standard output: \n{0}", stdout);
+        Log.info(thisClass, methodName, "SSH command standard error: \n{0}", stderr);
+    }
+
     /**
      * Determine whether the remote file exists.
      *
@@ -1005,4 +1062,37 @@ protected boolean deleteRemoteFile(ClientSession sshSession, String remoteFile)
         Log.info(thisClass, "deleteRemoteFile", "Delete of remote file was successful? " + success);
         return success;
     }
+
+    /**
+     * Handler for listenting to SSH channel events.
+     */
+    class SshChannelListener implements ChannelListener {
+        private Class<?> thisClass = SshChannelListener.class;
+
+        @Override
+        public void channelInitialized(Channel channel) {
+            Log.info(thisClass, "channelInitialized", "Channel: " + channel);
+        }
+
+        @Override
+        public void channelOpenSuccess(Channel channel) {
+            Log.info(thisClass, "channelOpenSuccess", "Channel: " + channel);
+        }
+
+        @Override
+        public void channelOpenFailure(Channel channel,
+                                       Throwable reason) {
+            Log.error(thisClass, "channelOpenFailure", reason, "Channel: " + channel);
+        }
+
+        @Override
+        public void channelClosed(Channel channel, Throwable reason) {
+            Log.error(thisClass, "channelClosed", reason, "Channel: " + channel);
+        }
+
+        @Override
+        public void channelStateChanged(Channel channel, String hint) {
+            Log.info(thisClass, "channelStateChanged", "Channel: " + channel + ", hint: " + hint);
+        }
+    }
 }

dev/com.ibm.ws.security.spnego.fat.common/fat/src/com/ibm/ws/security/spnego/fat/config/MsKdcHelper.java

@@ -1,5 +1,5 @@
 /*******************************************************************************
- * Copyright (c) 2014, 2020 IBM Corporation and others.
+ * Copyright (c) 2014, 2021 IBM Corporation and others.
  * All rights reserved. This program and the accompanying materials
  * are made available under the terms of the Eclipse Public License v1.0
  * which accompanies this distribution, and is available at
@@ -221,8 +221,6 @@ public void setSpnForUser(String user, String spnHost) throws Exception {
         String setUserSpnCommand = "./" + remoteScriptName + " " + user + " HTTP " + spnHost;
         ProgramOutput output = executeRemoteCommand(remoteScriptName, setUserSpnCommand, true);
 
-        Log.info(thisClass, methodName, "command stdout: " + output.getStdout());
-        Log.info(thisClass, methodName, "command stderr: " + output.getStderr());
         if (output.getReturnCode() != 0) {
             throw new RemoteException("Setting SPN for user failed with return code " + output.getReturnCode());
         }
@@ -273,8 +271,6 @@ public void deleteSpnForUser(String user, String spn) throws Exception {
         String setUserSpnCommand = "./" + remoteScriptName + " " + user + " HTTP " + spn;
         ProgramOutput output = executeRemoteCommand(remoteScriptName, setUserSpnCommand, true);
 
-        Log.info(thisClass, methodName, "command stdout: " + output.getStdout());
-        Log.info(thisClass, methodName, "command stderr: " + output.getStderr());
         if (output.getReturnCode() != 0) {
             throw new RemoteException("Deleting SPN for user failed with return code " + output.getReturnCode());
         }
@@ -303,8 +299,6 @@ public void addSpnToKeytab(String user, String spn) throws Exception {
         ProgramOutput output = executeRemoteCommand(remoteScriptName, addSpnToKeytabCommand, true);
         InitClass.needToPushaddSPNKeytab = false;
 
-        Log.info(thisClass, methodName, "command stdout: " + output.getStdout());
-        Log.info(thisClass, methodName, "command stderr: " + output.getStderr());
         if (output.getReturnCode() != 0) {
             throw new RemoteException("Adding SPN to keytab failed with return code " + output.getReturnCode());
         }
@@ -444,19 +438,15 @@ private ProgramOutput executeRemoteCommand(String scriptFile, String command, bo
 
                     Log.info(thisClass, methodName, "Call chmod 777 on script using command: " + chmodCMD);
                     output = executeSshCommand(sshSession, chmodCMD, 30);
-                    Log.info(thisClass, methodName, "chmod command output: " + output.getStdout());
-                    Log.info(thisClass, methodName, "chmod command error:" + output.getStderr());
                 } else {
                     Log.info(thisClass, methodName, "The following command will not be run for: " + chmodCMD + " for the script file: " + scriptFile);
                 }
 
                 Log.info(thisClass, methodName, "Executing command --> " + command);
-                output = executeSshCommand(sshSession, command, 300);
+                output = executeSshCommand(sshSession, command, 60);
 
                 if (retryUponFailure && output.getReturnCode() != 0) {
                     Log.info(thisClass, methodName, "Remote command failed with return code " + output.getReturnCode());
-                    Log.info(thisClass, methodName, "command output: " + output.getStdout());
-                    Log.info(thisClass, methodName, "command error:" + output.getStderr());
                     Log.info(thisClass, methodName, "Sleeping for a few seconds to see if that helps resolve any problems encountered");
                     Thread.sleep(15 * 1000);
                     Log.info(thisClass, methodName, "Attempting to retry the command");

dev/com.ibm.ws.security.spnego.fat.common/fat/src/com/ibm/ws/security/spnego/fat/config/SPNEGOConstants.java

@@ -1,5 +1,5 @@
 /*******************************************************************************
- * Copyright (c) 2020 IBM Corporation and others.
+ * Copyright (c) 2020, 2021 IBM Corporation and others.
  * All rights reserved. This program and the accompanying materials
  * are made available under the terms of the Eclipse Public License v1.0
  * which accompanies this distribution, and is available at
@@ -52,7 +52,7 @@ public class SPNEGOConstants {
     public final static String CREATE_WIN_USER_LOCAL_FILE = SLASH_KERBEROS_SLASH + CREATE_WIN_USER_REMOTE_FILE;
     public final static String REMOVE_WIN_USER_REMOTE_FILE = "removeWinUsers.vbs";
     public final static String REMOTE_WIN_USER_LOCAL_FILE = SLASH_KERBEROS_SLASH + REMOVE_WIN_USER_REMOTE_FILE;
-    public final static String CREATE_WIN_KEYTAB_REMOTE_FILE = "createWinKeytabFile.bat";
+    public final static String CREATE_WIN_KEYTAB_REMOTE_FILE = "createWinKeytabFileOL.bat"; // "createWinKeytabFile.bat";
     public final static String CREATE_WIN_KEYTAB_LOCAL_FILE = SLASH_KERBEROS_SLASH + CREATE_WIN_KEYTAB_REMOTE_FILE;
     public final static String CREATE_WIN_USER_SET_SPN_REMOTE_FILE = "createUserAndSetSpn.bat";
     public final static String CREATE_WIN_USER_SET_SPN_LOCAL_FILE = SLASH_KERBEROS_SLASH + CREATE_WIN_USER_SET_SPN_REMOTE_FILE;

dev/com.ibm.ws.security.spnego_fat.1/bnd.bnd

@@ -30,6 +30,7 @@ tested.features: pages-3.0
 	com.ibm.ws.security.authentication.filter;version=latest,\
 	com.ibm.ws.security.jaas.common;version=latest,\
 	com.ibm.ws.security.kerberos.java8;version=latest,\
+	com.ibm.ws.security.spnego_fat;version=latest,\
 	com.ibm.ws.security.spnego.fat.common;version=latest,\
 	com.ibm.ws.security.token;version=latest,\
     com.ibm.ws.security.token.s4u2;version=latest,\

dev/com.ibm.ws.security.spnego_fat.1/build.gradle

@@ -1,5 +1,5 @@
 /*******************************************************************************
- * Copyright (c) 2020 IBM Corporation and others.
+ * Copyright (c) 2020, 2021 IBM Corporation and others.
  * All rights reserved. This program and the accompanying materials
  * are made available under the terms of the Eclipse Public License v1.0
  * which accompanies this distribution, and is available at
@@ -35,7 +35,16 @@ def appBuildDir = "${buildDir}/test-application"
 autoFVT.dependsOn ':com.ibm.ws.security.spnego.fat.common:SPNEGOTokenHelperFVT_EAR'
 autoFVT.dependsOn ':com.ibm.ws.webcontainer.security_test.servlets:war'
 autoFVT.doLast {
-
+
+  /******************************************************************
+   * Copy spnego_fat files.
+   ******************************************************************/
+  copy {
+    from new File(project(':com.ibm.ws.security.spnego_fat').projectDir, 'publish/files')
+    into new File(autoFvtDir, 'lib/LibertyFATTestFiles')
+    include '**'
+  }
+
 
   /******************************************************************
    * Setup server: BackendServer
@@ -46,8 +55,8 @@ autoFVT.doLast {
     into new File(autoFvtDir, 'publish/servers/' + server + '/apps')
     rename 'basicauth.zip', 'basicauth.war'
   }
-  copy { 
-    from 'publish/files/resources/security'
+  copy {
+    from new File(project(':com.ibm.ws.security.spnego_fat').projectDir, 'publish/files/resources/security')
     into new File(autoFvtDir, 'publish/servers/' + server + '/resources/security')
     include '**'
   }
@@ -58,7 +67,7 @@ autoFVT.doLast {
    ******************************************************************/
   server = 'com.ibm.ws.security.spnego.fat.setup'
   copy { 
-    from 'publish/files/resources/security'
+    from new File(project(':com.ibm.ws.security.spnego_fat').projectDir, 'publish/files/resources/security')
     into new File(autoFvtDir, 'publish/servers/' + server + '/resources/security')
     include '**'
   }
@@ -74,7 +83,7 @@ autoFVT.doLast {
     rename 'basicauth.zip', 'basicauth.war'
   }
   copy { 
-    from 'publish/files/server_modules/'
+    from new File(project(':com.ibm.ws.security.spnego_fat').projectDir, 'publish/files/server_modules')
     into new File(autoFvtDir, 'publish/servers/' + server + '/imports')
     include 'application_definition/**.xml'
     include 'configs/**.xml'
@@ -84,7 +93,7 @@ autoFVT.doLast {
     include 'spnego/serversettings/**.xml'
   }
   copy { 
-    from 'publish/files/resources/security'
+    from new File(project(':com.ibm.ws.security.spnego_fat').projectDir, 'publish/files/resources/security')
     into new File(autoFvtDir, 'publish/servers/' + server + '/resources/security')
     include '**'
   }
@@ -109,7 +118,7 @@ autoFVT.doLast {
     rename 'com.ibm.ws.security.spnego_fat.jar', 'CustomLoginModule.jar'
   }
   copy { 
-    from 'publish/files/server_modules/'
+    from new File(project(':com.ibm.ws.security.spnego_fat').projectDir, 'publish/files/server_modules')
     into new File(autoFvtDir, 'publish/servers/' + server + '/imports')
     include 'application_definition/spnegoTokenHelperFvt_location.xml'
     include 'configs/**.xml'
@@ -121,7 +130,7 @@ autoFVT.doLast {
     include 'spnego/serversettings/**.xml'
   }
   copy { 
-    from 'publish/files/resources/security'
+    from new File(project(':com.ibm.ws.security.spnego_fat').projectDir, 'publish/files/resources/security')
     into new File(autoFvtDir, 'publish/servers/' + server + '/resources/security')
     include '**'
   }
@@ -139,8 +148,8 @@ autoFVT.doLast {
     into new File(autoFvtDir, 'publish/servers/' + server + '/apps')
     rename 'basicauth.zip', 'basicauth.war'
   }
-  copy { 
-    from 'publish/files/server_modules/'
+  copy {
+    from new File(project(':com.ibm.ws.security.spnego_fat').projectDir, 'publish/files/server_modules')
     into new File(autoFvtDir, 'publish/servers/' + server + '/imports')
     include 'application_definition/**.xml'
     include 'configs/**.xml'
@@ -151,13 +160,13 @@ autoFVT.doLast {
     include 'spnego/authfilters/**.xml'
     include 'spnego/serversettings/**.xml'
   }
-  copy { 
-    from 'publish/files/server_modules/constrained_delegation/s4u2self_servers/config/'
+  copy {
+    from new File(project(':com.ibm.ws.security.spnego_fat').projectDir, 'publish/files/server_modules/constrained_delegation/s4u2self_servers/config')
     into new File(autoFvtDir, 'publish/servers/' + server + '/imports/constrained_delegation/config')
     include '**.xml'
   }
   copy { 
-    from 'publish/files/resources/security'
+    from new File(project(':com.ibm.ws.security.spnego_fat').projectDir, 'publish/files/resources/security')
     into new File(autoFvtDir, 'publish/servers/' + server + '/resources/security')
     include '**'
   }