Improve sauce connect logging (#315)

* Extract SC monitor class

* Make it possible to customize ProcessOutputPrinter

* Make it easier to replace SCMonitor implementation

* Respect quietMode setting

* Make it possible to customize logger

* Print last healthcheck exception

* Refactor openConnection

* Change port to apiPort

* Improve constructors of TunnelManager

* Handle missing process streams properly

* Update version to 2.4-SNAPSHOT

* Improve error messages

* A new instance of SCMonitor should be created for each sauceconnect instance

* Pass logger to openConnection method

* Log more information in SCMonitor

* Provide a new approach for opening a connection

* Mark SC monitor as failed on healthcheck timeout

* Extract timeouts to const variables

* Allow to pass logger instance to closeTunnelsForPlan

* Log when making a request to a healthcheck endpoint

Author: budziam

Diff for: pom.xml

@@ -5,7 +5,7 @@
 
   <groupId>com.saucelabs</groupId>
   <artifactId>ci-sauce</artifactId>
-  <version>2.1-SNAPSHOT</version>
+  <version>2.4-SNAPSHOT</version>
   <packaging>jar</packaging>
 
 

Diff for: src/main/java/com/saucelabs/ci/sauceconnect/AbstractSauceTunnelManager.java

@@ -0,0 +1,47 @@
+package com.saucelabs.ci.sauceconnect;
+
+
+import java.io.*;
+
+
+public class DefaultProcessOutputPrinter implements ProcessOutputPrinter {
+    public Runnable getStdoutPrinter(InputStream stdout, PrintStream printStream) {
+        return () -> {
+            if (stdout == null || printStream == null) {
+                return;
+            }
+
+            try (BufferedReader reader = new BufferedReader(new InputStreamReader(stdout))) {
+                String line;
+                while ((line = reader.readLine()) != null) {
+                    print(printStream, "[sauceconnect] [stdout] " + line);
+                }
+            } catch (IOException e) {
+                //
+            }
+        };
+    }
+
+    public Runnable getStderrPrinter(InputStream stderr, PrintStream printStream) {
+        return () -> {
+            if (stderr == null || printStream == null) {
+                return;
+            }
+
+            try (BufferedReader reader = new BufferedReader(new InputStreamReader(stderr))) {
+                String line;
+                while ((line = reader.readLine()) != null) {
+                    print(printStream, "[sauceconnect] [stderr] " + line);
+                }
+            } catch (IOException e) {
+                //
+            }
+        };
+    }
+
+    private void print(PrintStream printStream, String line) {
+        if (printStream != null) {
+            printStream.println(line);
+        }
+    }
+}

Diff for: src/main/java/com/saucelabs/ci/sauceconnect/DefaultProcessOutputPrinter.java

@@ -0,0 +1,119 @@
+package com.saucelabs.ci.sauceconnect;
+
+import org.json.JSONObject;
+import org.slf4j.Logger;
+
+import java.net.URI;
+import java.net.http.HttpClient;
+import java.net.http.HttpRequest;
+import java.net.http.HttpResponse;
+import java.util.concurrent.Semaphore;
+
+/** Monitors SC Process via HTTP API */
+public class DefaultSCMonitor implements SCMonitor {
+    public static class Factory implements SCMonitorFactory {
+        public SCMonitor create(int port, Logger logger) {
+            return new DefaultSCMonitor(port, logger);
+        }
+    }
+
+    private Semaphore semaphore;
+    private final int port;
+    private final Logger logger;
+
+    private boolean failed;
+    private boolean apiResponse;
+
+    private HttpClient client = HttpClient.newHttpClient();
+    private static final int sleepTime = 1000;
+
+    private Exception lastHealtcheckException;
+
+    public DefaultSCMonitor(final int port, final Logger logger) {
+        this.port = port;
+        this.logger = logger;
+    }
+
+    public void setSemaphore(Semaphore semaphore) {
+        this.semaphore = semaphore;
+    }
+
+    public String getTunnelId() {
+      HttpRequest request = HttpRequest.newBuilder()
+            .uri(URI.create(String.format("http://localhost:%d/info", port)))
+            .GET()
+            .build();
+
+        try {
+            HttpResponse<String> response = client.send(request, HttpResponse.BodyHandlers.ofString());
+            String responseBody = response.body();
+            JSONObject jsonObject = new JSONObject(responseBody);
+            if (jsonObject.has("tunnel_id")) {
+                return jsonObject.getString("tunnel_id");
+            }
+        } catch (Exception e) {
+            this.logger.info("Failed to get tunnel id", e);
+            return null;
+        }
+        this.logger.info("Failed to get tunnel id");
+        return null;
+    }
+
+    public boolean isFailed() {
+        return failed;
+    }
+
+    public void markAsFailed() {
+        failed = true;
+    }
+
+    public Exception getLastHealtcheckException() {
+        return lastHealtcheckException;
+    }
+
+    public void run() {
+        while (this.semaphore.availablePermits() == 0 && !this.failed) {
+            pollEndpoint();
+
+            try {
+                Thread.sleep(sleepTime);
+            } catch ( java.lang.InterruptedException e ) {
+                return;
+            }
+        }
+    }
+
+    protected void pollEndpoint() {
+        URI uri = URI.create(String.format("http://localhost:%d/readyz", port));
+        HttpRequest request = HttpRequest.newBuilder()
+            .uri(uri)
+            .GET()
+            .build();
+
+        this.logger.trace("Polling health check endpoint uri={}", uri);
+
+        try {
+            HttpResponse<String> response = client.send(request, HttpResponse.BodyHandlers.ofString());
+            this.apiResponse = true;
+
+            if (response.statusCode() == 200) {
+                this.logger.info("Health check got connected status");
+                this.semaphore.release();
+                return;
+            }
+
+            this.lastHealtcheckException = new Exception("Invalid API response code: " + response.statusCode());
+        } catch ( Exception e ) {
+            this.lastHealtcheckException = e;
+            if ( this.apiResponse ) {
+                // We've had a successful API endpoint read, but then it stopped responding, which means the process failed to start
+                this.failed = true;
+                this.logger.warn("Health check API stopped responding", e);
+                this.semaphore.release();
+                return;
+            }
+        }
+
+        this.logger.trace("Waiting for sauceconnect to be ready err={}", this.lastHealtcheckException.toString());
+    }
+}

Diff for: src/main/java/com/saucelabs/ci/sauceconnect/DefaultSCMonitor.java

@@ -0,0 +1,79 @@
+package com.saucelabs.ci.sauceconnect;
+
+import org.slf4j.Marker;
+import org.slf4j.event.Level;
+import org.slf4j.helpers.MessageFormatter;
+
+import java.io.PrintStream;
+
+public class LoggerUsingPrintStream extends org.slf4j.helpers.AbstractLogger {
+  PrintStream printStream;
+
+  public LoggerUsingPrintStream(PrintStream printStream) {
+    this.printStream = printStream;
+  }
+
+  @Override
+  protected String getFullyQualifiedCallerName() {
+    return null;
+  }
+
+  @Override
+  protected void handleNormalizedLoggingCall(Level level, Marker marker, String s, Object[] objects, Throwable throwable) {
+    String msg = MessageFormatter.basicArrayFormat(s, objects);
+    printStream.println("[" + level + "] " + msg);
+    if (throwable != null) {
+      throwable.printStackTrace(printStream);
+    }
+  }
+
+  @Override
+  public boolean isTraceEnabled() {
+    return true;
+  }
+
+  @Override
+  public boolean isTraceEnabled(Marker marker) {
+    return true;
+  }
+
+  @Override
+  public boolean isDebugEnabled() {
+    return true;
+  }
+
+  @Override
+  public boolean isDebugEnabled(Marker marker) {
+    return true;
+  }
+
+  @Override
+  public boolean isInfoEnabled() {
+    return true;
+  }
+
+  @Override
+  public boolean isInfoEnabled(Marker marker) {
+    return true;
+  }
+
+  @Override
+  public boolean isWarnEnabled() {
+    return true;
+  }
+
+  @Override
+  public boolean isWarnEnabled(Marker marker) {
+    return true;
+  }
+
+  @Override
+  public boolean isErrorEnabled() {
+    return true;
+  }
+
+  @Override
+  public boolean isErrorEnabled(Marker marker) {
+    return true;
+  }
+}

Diff for: src/main/java/com/saucelabs/ci/sauceconnect/LoggerUsingPrintStream.java

@@ -0,0 +1,9 @@
+package com.saucelabs.ci.sauceconnect;
+
+import java.io.InputStream;
+import java.io.PrintStream;
+
+public interface ProcessOutputPrinter {
+  Runnable getStdoutPrinter(InputStream stdout, PrintStream printStream);
+  Runnable getStderrPrinter(InputStream stderr, PrintStream printStream);
+}

Diff for: src/main/java/com/saucelabs/ci/sauceconnect/ProcessOutputPrinter.java

@@ -0,0 +1,11 @@
+package com.saucelabs.ci.sauceconnect;
+
+import java.util.concurrent.Semaphore;
+
+public interface SCMonitor extends Runnable {
+    void setSemaphore(Semaphore semaphore);
+    String getTunnelId();
+    Exception getLastHealtcheckException();
+    void markAsFailed();
+    boolean isFailed();
+}

Diff for: src/main/java/com/saucelabs/ci/sauceconnect/SCMonitor.java

@@ -0,0 +1,7 @@
+package com.saucelabs.ci.sauceconnect;
+
+import org.slf4j.Logger;
+
+public interface SCMonitorFactory {
+    SCMonitor create(int port, Logger logger);
+}

Diff for: src/main/java/com/saucelabs/ci/sauceconnect/SCMonitorFactory.java

@@ -10,33 +10,26 @@
 import org.apache.commons.lang3.concurrent.LazyInitializer;
 import org.apache.commons.lang3.concurrent.LazyInitializer.Builder;
 import org.json.JSONObject;
+import org.slf4j.Logger;
 
-import java.io.BufferedInputStream;
-import java.io.File;
-import java.io.IOException;
-import java.io.InputStream;
-import java.io.PrintStream;
+import java.io.*;
 import java.net.URI;
+import java.net.URL;
 import java.net.http.HttpClient;
 import java.net.http.HttpRequest;
 import java.net.http.HttpResponse;
 import java.nio.file.Files;
 import java.nio.file.Path;
-import java.text.MessageFormat;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.HashMap;
-import java.util.List;
-
-import java.net.URL;
 
 /**
  * Handles launching Sauce Connect (binary executable).
  *
  * @author Ross Rowe
  */
-public class SauceConnectManager extends AbstractSauceTunnelManager
-    implements SauceTunnelManager {
+public class SauceConnectManager extends AbstractSauceTunnelManager implements SauceTunnelManager {
   private boolean useLatestSauceConnect = false;
 
   /** Remove all created files and directories on exit */
@@ -183,7 +176,7 @@ public SauceConnectManager(boolean quietMode) {
   public SauceConnectManager(boolean quietMode, String runner, int apiPort) {
     super(quietMode);
     this.runner = runner;
-    this.apiPort = DEFAULT_API_PORT;
+    this.apiPort = apiPort;
   }
 
   /**
@@ -192,7 +185,7 @@ public SauceConnectManager(boolean quietMode, String runner, int apiPort) {
    * @param sauceConnectJar File which contains the Sauce Connect executables (typically the CI
    *     plugin Jar file)
    * @param options the command line options used to launch Sauce Connect
-   * @param printStream the output stream to send log messages
+   * @param logger used for logging
    * @param sauceConnectPath if defined, Sauce Connect will be launched from the specified path and
    *     won't be extracted from the jar file
    * @return new ProcessBuilder instance which will launch Sauce Connect
@@ -206,7 +199,7 @@ protected Process prepAndCreateProcess(
       int apiPort,
       File sauceConnectJar,
       String options,
-      PrintStream printStream,
+      Logger logger,
       String sauceConnectPath,
       boolean legacy)
       throws SauceConnectException {
@@ -234,11 +227,11 @@ protected Process prepAndCreateProcess(
         if (!sauceConnectBinary.exists()) {
           synchronized (this) {
             if (!sauceConnectBinary.exists()) {
-              extractZipFile(workingDirectory, operatingSystem);
+              extractZipFile(workingDirectory, operatingSystem, logger);
             }
           }
         } else {
-          logMessage(printStream, sauceConnectBinary + " already exists, so not extracting");
+          logger.info("File {} already exists, so not extracting", sauceConnectBinary);
         }
       } else {
         sauceConnectBinary = new File(sauceConnectPath);
@@ -262,7 +255,7 @@ protected Process prepAndCreateProcess(
           args = addExtraInfo(args);
       }
 
-      LOGGER.info("Launching Sauce Connect {} {}", getCurrentVersion(), hideSauceConnectCommandlineSecrets(args));
+      logger.info("Launching Sauce Connect {} {}", getCurrentVersion(), hideSauceConnectCommandlineSecrets(args));
       return createProcess(args, sauceConnectBinary.getParentFile());
     } catch (IOException e) {
       throw new SauceConnectException(e);
@@ -400,7 +393,7 @@ protected String[] addExtraInfoLegacy(String[] args) {
    * @return the directory containing the extracted files
    * @throws IOException thrown if an error occurs extracting the files
    */
-  public File extractZipFile(File workingDirectory, OperatingSystem operatingSystem) throws IOException {
+  public File extractZipFile(File workingDirectory, OperatingSystem operatingSystem, Logger logger) throws IOException {
     String archiveFileName = operatingSystem.getFileName(useLatestSauceConnect);
     File unzipDir = getUnzipDir(workingDirectory, operatingSystem);
     unzipDir.mkdirs();
@@ -417,8 +410,7 @@ public File extractZipFile(File workingDirectory, OperatingSystem operatingSyste
 
     File sauceConnectBinary = new File(unzipDir, operatingSystem.getExecutable());
     if (!sauceConnectBinary.canExecute() && !sauceConnectBinary.setExecutable(true)) {
-      LOGGER.warn("Unable to set the execute permission for SauceConnect binary file located at {}",
-          sauceConnectBinary);
+      logger.warn("Unable to set the execute permission for SauceConnect binary file located at {}", sauceConnectBinary);
     }
     return unzipDir;
   }