Overhaul of SlaveLaunchLogs (#517)

* agent-logs sketch

* `SlaveLaunchLogsTest.onlineInboundAgent`

* `SlaveLaunchLogsTest.offlineAgent`

* Javadoc

* Exploring `SlaveLaunchLogs` behavior

* More `SlaveLaunchLogsTest`

* `SlaveLaunchLogsTest.passwords`

* Worked out a better `SlaveLaunchLogs`, but depends on patch to `SlaveComputer`

* Need to flush logs also for `deletedAgent`

* Reverting changes extracted to #518

* Setting a timestamp, switching category

* RC

* No need to assert that `SupportTestUtils.invokeComponentToString` is non-null

* `Security2186Test` failure caused by renamed bundle entry

* File handle leak caught by Windows tests

* Better handling of rotated logs

* More robust way to wait for `Connection terminated` message

* `SlaveLaunchLogsTest.offlineAgent` still flaky on Windows

* jenkinsci/jenkins#9009 released

* Working around lack of JENKINS-72799 to avoid requiring a weekly core

* SpotBugs

---------

Co-authored-by: Allan Burdajewicz <aburdajewicz@cloudbees.com>

Author: jglick

pom.xml

@@ -153,6 +153,12 @@
         </exclusion>
       </exclusions>
     </dependency>
+    <dependency>
+      <groupId>org.awaitility</groupId>
+      <artifactId>awaitility</artifactId>
+      <version>4.2.0</version>
+      <scope>test</scope>
+    </dependency>
     <!-- MockFolder that was used for SupportAbstractItem test does not have UI, hence need full Folder implementation.-->
     <dependency>
       <groupId>org.jenkins-ci.plugins</groupId>

src/main/java/com/cloudbees/jenkins/support/api/LaunchLogsFileContent.java

@@ -1,6 +1,7 @@
 package com.cloudbees.jenkins.support.api;
 
 import com.cloudbees.jenkins.support.filter.PasswordRedactor;
+import com.cloudbees.jenkins.support.impl.SlaveLaunchLogs;
 import java.io.ByteArrayInputStream;
 import java.io.File;
 import java.io.FileInputStream;
@@ -11,6 +12,9 @@
 import java.util.stream.Collectors;
 import org.apache.commons.io.IOUtils;
 
+/**
+ * @see SlaveLaunchLogs
+ */
 public class LaunchLogsFileContent extends FileContent {
 
     public LaunchLogsFileContent(String name, String[] filterableParameters, File file, long maxSize) {

src/main/java/com/cloudbees/jenkins/support/impl/SlaveLaunchLogs.java

@@ -26,25 +26,45 @@
 
 import static com.cloudbees.jenkins.support.impl.JenkinsLogs.ROTATED_LOGFILE_FILTER;
 
+import com.cloudbees.jenkins.support.SupportPlugin;
 import com.cloudbees.jenkins.support.api.Container;
 import com.cloudbees.jenkins.support.api.LaunchLogsFileContent;
 import com.cloudbees.jenkins.support.api.ObjectComponent;
 import com.cloudbees.jenkins.support.api.ObjectComponentDescriptor;
 import com.cloudbees.jenkins.support.timer.FileListCapComponent;
 import edu.umd.cs.findbugs.annotations.NonNull;
 import hudson.Extension;
+import hudson.ExtensionList;
+import hudson.FilePath;
+import hudson.console.ConsoleLogFilter;
+import hudson.console.LineTransformationOutputStream;
+import hudson.init.Terminator;
 import hudson.model.AbstractModelObject;
 import hudson.model.Computer;
-import hudson.model.Node;
+import hudson.model.Run;
+import hudson.model.TaskListener;
+import hudson.remoting.Channel;
 import hudson.security.Permission;
-import hudson.slaves.Cloud;
+import hudson.slaves.ComputerListener;
+import hudson.slaves.JNLPLauncher;
+import hudson.slaves.SlaveComputer;
+import hudson.util.io.RewindableRotatingFileOutputStream;
 import java.io.File;
-import java.util.ArrayList;
+import java.io.IOException;
+import java.io.OutputStream;
+import java.nio.charset.StandardCharsets;
+import java.time.Instant;
+import java.time.format.DateTimeFormatter;
+import java.time.temporal.ChronoUnit;
 import java.util.Collections;
-import java.util.List;
+import java.util.Map;
 import java.util.Set;
+import java.util.concurrent.ConcurrentHashMap;
 import java.util.concurrent.TimeUnit;
+import java.util.logging.Level;
+import java.util.logging.Logger;
 import jenkins.model.Jenkins;
+import org.apache.commons.io.output.TeeOutputStream;
 import org.jenkinsci.Symbol;
 import org.kohsuke.stapler.DataBoundConstructor;
 
@@ -54,6 +74,11 @@
 @Extension
 public class SlaveLaunchLogs extends ObjectComponent<Computer> {
 
+    private static final int MAX_ROTATE_LOGS =
+            Integer.getInteger(SlaveLaunchLogs.class.getName() + ".MAX_ROTATE_LOGS", 9);
+
+    private static final Logger LOGGER = Logger.getLogger(SlaveLaunchLogs.class.getName());
+
     @DataBoundConstructor
     public SlaveLaunchLogs() {
         super();
@@ -73,128 +98,149 @@ public String getDisplayName() {
 
     @Override
     public void addContents(@NonNull Container container) {
-        addAgentsLaunchLogs(container);
+        ExtensionList.lookupSingleton(LogArchiver.class).addContents(container);
     }
 
     @NonNull
     @Override
     public ComponentCategory getCategory() {
-        return ComponentCategory.AGENT; // TODO or LOGS?
+        return ComponentCategory.LOGS;
     }
 
     @Override
     public void addContents(@NonNull Container container, Computer item) {
-        if (item.getNode() == null) {
-            return;
-        }
-        File lastLog = item.getLogFile();
-        if (lastLog.exists()) {
-            Agent agent = new Agent(new File(Jenkins.get().getRootDir(), "logs/slaves/" + item.getName()), lastLog);
-            if (!agent.isTooOld()) {
-                addAgentLaunchLogs(container, agent);
+        if (item.getNode() != null
+                && item.getLogFile().lastModified() >= System.currentTimeMillis() - TimeUnit.DAYS.toMillis(7)) {
+            File dir = new File(Jenkins.get().getRootDir(), "logs/slaves/" + item.getName());
+            File[] files = dir.listFiles(ROTATED_LOGFILE_FILTER);
+            if (files != null) {
+                for (File f : files) {
+                    container.add(new LaunchLogsFileContent(
+                            "nodes/slave/{0}/launchLogs/{1}",
+                            new String[] {dir.getName(), f.getName()}, f, FileListCapComponent.MAX_FILE_SIZE));
+                }
             }
         }
     }
 
-    /**
-     * <p>
-     * In the presence of {@link Cloud} plugins like EC2, we want to find past agents, not just current ones.
-     * So we don't try to loop through {@link Node} here but just try to look at the file systems to find them
-     * all.
-     *
-     * <p>
-     * Generally these cloud plugins do not clean up old logs, so if run for a long time, the log directory
-     * will be full of old files that are not very interesting. Use some heuristics to cut off logs
-     * that are old.
-     */
-    private void addAgentsLaunchLogs(Container result) {
-
-        List<Agent> all = new ArrayList<>();
-
-        { // find all the agent launch log files and sort them newer ones first
-            File agentLogsDir = new File(Jenkins.get().getRootDir(), "logs/slaves");
-            File[] logs = agentLogsDir.listFiles();
-            if (logs != null) {
-                for (File dir : logs) {
-                    File lastLog = new File(dir, "slave.log");
-                    if (lastLog.exists()) {
-                        Agent s = new Agent(dir, lastLog);
-                        if (s.isTooOld()) continue; // we don't care
-                        all.add(s);
-                    }
-                }
-            }
+    @Extension
+    public static final class LogArchiver extends ConsoleLogFilter {
 
-            Collections.sort(all);
-        }
-        { // this might be still too many, so try to cap them.
-            int acceptableSize = Math.max(256, Jenkins.get().getNodes().size() * 5);
+        private final File logDir;
+        private final RewindableRotatingFileOutputStream stream;
 
-            if (all.size() > acceptableSize) all = all.subList(0, acceptableSize);
+        public LogArchiver() throws IOException {
+            logDir = new File(SupportPlugin.getLogsDirectory(), "agent-launches");
+            stream = new RewindableRotatingFileOutputStream(new File(logDir, "all.log"), MAX_ROTATE_LOGS);
+            stream.rewind();
         }
 
-        // now add them all
-        all.forEach(it -> addAgentLaunchLogs(result, it));
-    }
-
-    private void addAgentLaunchLogs(Container container, Agent agent) {
-        File[] files = agent.dir.listFiles(ROTATED_LOGFILE_FILTER);
-        if (files != null) {
-            for (File f : files) {
-                container.add(new LaunchLogsFileContent(
-                        "nodes/slave/{0}/launchLogs/{1}",
-                        new String[] {agent.getName(), f.getName()}, f, FileListCapComponent.MAX_FILE_SIZE));
+        @Override
+        public OutputStream decorateLogger(Computer computer, OutputStream logger) {
+            if (computer instanceof SlaveComputer) {
+                return new TeeOutputStream(logger, new PrefixedStream(stream, computer.getName()));
+            } else {
+                return logger;
             }
         }
-    }
 
-    static class Agent implements Comparable<Agent> {
-        /**
-         * Launch log directory of the agent: logs/slaves/NAME
-         */
-        final File dir;
-
-        final long time;
+        @SuppressWarnings("rawtypes")
+        @Override
+        public OutputStream decorateLogger(Run build, OutputStream logger) throws IOException, InterruptedException {
+            return logger;
+        }
 
-        Agent(File dir, File lastLog) {
-            this.dir = dir;
-            this.time = lastLog.lastModified();
+        public void addContents(@NonNull Container container) {
+            File[] files = logDir.listFiles(ROTATED_LOGFILE_FILTER);
+            if (files != null) {
+                for (File f : files) {
+                    container.add(new LaunchLogsFileContent(
+                            "nodes/slave/launches/" + f.getName(),
+                            new String[0],
+                            f,
+                            FileListCapComponent.MAX_FILE_SIZE));
+                }
+            }
         }
 
-        /** Agent name */
-        String getName() {
-            return dir.getName();
+        @Terminator
+        public static void close() {
+            try {
+                ExtensionList.lookupSingleton(LogArchiver.class).stream.close();
+            } catch (IOException x) {
+                LOGGER.log(Level.WARNING, null, x);
+            }
         }
+    }
+
+    // TODO delete if updating to 2.440.3 and JENKINS-72799 is backported, else 2.448+
+    @Extension
+    public static final class Jenkins72799Hack extends ComputerListener {
 
         /**
-         * Use the primary log file's timestamp to compare newer agents from older agents.
-         *
-         * sort in descending order; newer ones first.
+         * Names of inbound agents which have recently gotten to {@link #preLaunch}
+         * but for which we did not receive typical output in {@link SlaveComputer#setChannel(Channel, OutputStream, Channel.Listener)}
+         * prior to {@link #preOnline}.
          */
-        public int compareTo(Agent that) {
-            return Long.compare(that.time, this.time);
+        private final Map<String, Boolean> launching = new ConcurrentHashMap<>();
+
+        @Override
+        public void preLaunch(Computer c, TaskListener taskListener) {
+            if (c instanceof SlaveComputer && ((SlaveComputer) c).getLauncher() instanceof JNLPLauncher) {
+                String name = c.getName();
+                LOGGER.fine(() -> "preLaunch " + name);
+                launching.put(name, true);
+            }
         }
 
         @Override
-        public boolean equals(Object o) {
-            if (this == o) return true;
-            if (o == null || getClass() != o.getClass()) return false;
+        public void preOnline(Computer c, Channel channel, FilePath root, TaskListener listener) throws IOException {
+            if (c instanceof SlaveComputer && ((SlaveComputer) c).getLauncher() instanceof JNLPLauncher) {
+                String name = c.getName();
+                if (launching.put(name, false)) {
+                    LOGGER.fine(() -> "preOnline " + name + " need to work around lack of JENKINS-72799");
+                    OutputStream stream = ExtensionList.lookupSingleton(LogArchiver.class).stream;
+                    synchronized (stream) {
+                        String nowish = DateTimeFormatter.ISO_INSTANT.format(
+                                Instant.now().truncatedTo(ChronoUnit.MILLIS));
+                        for (String line : c.getLog().trim().split("\n")) {
+                            LOGGER.fine(() -> "adding: " + line);
+                            stream.write(
+                                    ("[" + nowish + " " + name + "] " + line + "\n").getBytes(StandardCharsets.UTF_8));
+                        }
+                    }
+                } else {
+                    LOGGER.fine(() -> "preOnline " + name + " OK, have JENKINS-72799");
+                }
+            }
+        }
+    }
 
-            Agent agent = (Agent) o;
+    static class PrefixedStream extends LineTransformationOutputStream.Delegating {
+        private final String name;
 
-            return time == agent.time;
+        PrefixedStream(OutputStream out, String name) {
+            super(out);
+            this.name = name;
         }
 
         @Override
-        public int hashCode() {
-            return (int) (time ^ (time >>> 32));
-        }
-
-        /**
-         * If the file is more than 7 days old, it is considered too old.
-         */
-        public boolean isTooOld() {
-            return time < System.currentTimeMillis() - TimeUnit.DAYS.toMillis(7);
+        protected void eol(byte[] b, int len) throws IOException {
+            if (new String(b, 0, len, StandardCharsets.UTF_8).startsWith("Remoting version: ")) {
+                LOGGER.fine(() -> "receiving expected setChannel text on " + name);
+                ExtensionList.lookupSingleton(Jenkins72799Hack.class).launching.put(name, false);
+            }
+            synchronized (out) {
+                out.write('[');
+                out.write(DateTimeFormatter.ISO_INSTANT
+                        .format(Instant.now().truncatedTo(ChronoUnit.MILLIS))
+                        .getBytes(StandardCharsets.US_ASCII));
+                out.write(' ');
+                out.write(name.getBytes(StandardCharsets.UTF_8));
+                out.write(']');
+                out.write(' ');
+                out.write(b, 0, len);
+            }
         }
     }
 

src/test/java/com/cloudbees/jenkins/support/Security2186Test.java

@@ -75,8 +75,7 @@ public void secretsFilterWhenSystemPropertyContainsPasswordThenValueRedacted() t
         verifyFileIfContainsPassword(zip, "nodes/master/system.properties", "test2186.trustStorePassword");
         verifyFileIfContainsPassword(zip, "nodes/master/environment.txt", "test2186.trustStorePassword");
         verifyFileIfContainsPassword(zip, "nodes/slave/slave0/config.xml", "-Dtest2186.trustStoreAgentPassword");
-        verifyFileIfContainsPassword(
-                zip, "nodes/slave/slave0/launchLogs/slave.log", "-Dtest2186.trustStoreAgentPassword");
+        verifyFileIfContainsPassword(zip, "nodes/slave/launches/all.log", "-Dtest2186.trustStoreAgentPassword");
     }
 
     private void verifyFileIfContainsPassword(ZipFile zip, String fileName, String expectedPasswordKey)