Merge pull request #18147 from rjernst/vagrant_logging

Tests: improve logging for vagrant to emit entire output on failure

buildSrc/src/main/groovy/org/elasticsearch/gradle/LoggedExec.groovy

@@ -26,14 +26,17 @@ import org.gradle.api.tasks.Exec
  * A wrapper around gradle's Exec task to capture output and log on error.
  */
 class LoggedExec extends Exec {
+
+    protected ByteArrayOutputStream output = new ByteArrayOutputStream()
+
     LoggedExec() {
         if (logger.isInfoEnabled() == false) {
-            standardOutput = new ByteArrayOutputStream()
+            standardOutput = output
-            errorOutput = standardOutput
+            errorOutput = output
             ignoreExitValue = true
             doLast {
                 if (execResult.exitValue != 0) {
-                    standardOutput.toString('UTF-8').eachLine { line -> logger.error(line) }
+                    output.toString('UTF-8').eachLine { line -> logger.error(line) }
                     throw new GradleException("Process '${executable} ${args.join(' ')}' finished with non-zero exit value ${execResult.exitValue}")
                 }
             }

buildSrc/src/main/groovy/org/elasticsearch/gradle/vagrant/BatsOverVagrantTask.groovy

@@ -19,6 +19,7 @@
 package org.elasticsearch.gradle.vagrant
 
 import org.gradle.api.DefaultTask
+import org.gradle.api.tasks.Input
 import org.gradle.api.tasks.TaskAction
 import org.gradle.logging.ProgressLoggerFactory
 import org.gradle.process.internal.ExecAction
@@ -30,41 +31,22 @@ import javax.inject.Inject
  * Runs bats over vagrant. Pretty much like running it using Exec but with a
  * nicer output formatter.
  */
-class BatsOverVagrantTask extends DefaultTask {
+public class BatsOverVagrantTask extends VagrantCommandTask {
-  String command
-  String boxName
-  ExecAction execAction
 
-  BatsOverVagrantTask() {
+    @Input
-    execAction = getExecActionFactory().newExecAction()
+    String command
-  }
 
-  @Inject
+    BatsOverVagrantTask() {
-  ProgressLoggerFactory getProgressLoggerFactory() {
+        project.afterEvaluate {
-    throw new UnsupportedOperationException();
+            args 'ssh', boxName, '--command', command
-  }
+        }
+    }
 
-  @Inject
+    @Override
-  ExecActionFactory getExecActionFactory() {
+    protected OutputStream createLoggerOutputStream() {
-    throw new UnsupportedOperationException();
+        return new TapLoggerOutputStream(
-  }
+                command: commandLine.join(' '),
-
+                factory: getProgressLoggerFactory(),
-  void boxName(String boxName) {
+                logger: logger)
-    this.boxName = boxName
+    }
-  }
-
-  void command(String command) {
-    this.command = command
-  }
-
-  @TaskAction
-  void exec() {
-    // It'd be nice if --machine-readable were, well, nice
-    execAction.commandLine(['vagrant', 'ssh', boxName, '--command', command])
-    execAction.setStandardOutput(new TapLoggerOutputStream(
-      command: command,
-      factory: getProgressLoggerFactory(),
-      logger: logger))
-    execAction.execute();
-  }
 }

buildSrc/src/main/groovy/org/elasticsearch/gradle/vagrant/TapLoggerOutputStream.groovy

@@ -47,9 +47,9 @@ class TapLoggerOutputStream extends LoggingOutputStream {
   TapLoggerOutputStream(Map args) {
     logger = args.logger
     progressLogger = args.factory.newOperation(VagrantLoggerOutputStream)
-    progressLogger.setDescription("TAP output for $args.command")
+    progressLogger.setDescription("TAP output for `$args.command`")
     progressLogger.started()
-    progressLogger.progress("Starting $args.command...")
+    progressLogger.progress("Starting `$args.command`...")
   }
 
   void flush() {

buildSrc/src/main/groovy/org/elasticsearch/gradle/vagrant/VagrantCommandTask.groovy

@@ -18,11 +18,10 @@
  */
 package org.elasticsearch.gradle.vagrant
 
-import org.gradle.api.DefaultTask
+import org.apache.commons.io.output.TeeOutputStream
-import org.gradle.api.tasks.TaskAction
+import org.elasticsearch.gradle.LoggedExec
+import org.gradle.api.tasks.Input
 import org.gradle.logging.ProgressLoggerFactory
-import org.gradle.process.internal.ExecAction
-import org.gradle.process.internal.ExecActionFactory
 
 import javax.inject.Inject
 
@@ -30,43 +29,30 @@ import javax.inject.Inject
  * Runs a vagrant command. Pretty much like Exec task but with a nicer output
  * formatter and defaults to `vagrant` as first part of commandLine.
  */
-class VagrantCommandTask extends DefaultTask {
+public class VagrantCommandTask extends LoggedExec {
-  List<Object> commandLine
-  String boxName
-  ExecAction execAction
 
-  VagrantCommandTask() {
+    @Input
-    execAction = getExecActionFactory().newExecAction()
+    String boxName
-  }
 
-  @Inject
+    public VagrantCommandTask() {
-  ProgressLoggerFactory getProgressLoggerFactory() {
+        executable = 'vagrant'
-    throw new UnsupportedOperationException();
+        project.afterEvaluate {
-  }
+            // It'd be nice if --machine-readable were, well, nice
+            standardOutput = new TeeOutputStream(standardOutput, createLoggerOutputStream())
+        }
+    }
 
-  @Inject
+    protected OutputStream createLoggerOutputStream() {
-  ExecActionFactory getExecActionFactory() {
+        return new VagrantLoggerOutputStream(
-    throw new UnsupportedOperationException();
+            command: commandLine.join(' '),
-  }
+            factory: getProgressLoggerFactory(),
+            /* Vagrant tends to output a lot of stuff, but most of the important
+              stuff starts with ==> $box */
+            squashedPrefix: "==> $boxName: ")
+    }
 
-  void boxName(String boxName) {
+    @Inject
-    this.boxName = boxName
+    ProgressLoggerFactory getProgressLoggerFactory() {
-  }
+        throw new UnsupportedOperationException();
-
+    }
-  void commandLine(Object... commandLine) {
-    this.commandLine = commandLine
-  }
-
-  @TaskAction
-  void exec() {
-    // It'd be nice if --machine-readable were, well, nice
-    execAction.commandLine(['vagrant'] + commandLine)
-    execAction.setStandardOutput(new VagrantLoggerOutputStream(
-      command: commandLine.join(' '),
-      factory: getProgressLoggerFactory(),
-      /* Vagrant tends to output a lot of stuff, but most of the important
-        stuff starts with ==> $box */
-      squashedPrefix: "==> $boxName: "))
-    execAction.execute();
-  }
 }

buildSrc/src/main/groovy/org/elasticsearch/gradle/vagrant/VagrantLoggerOutputStream.groovy

@@ -20,6 +20,7 @@ package org.elasticsearch.gradle.vagrant
 
 import com.carrotsearch.gradle.junit4.LoggingOutputStream
 import org.gradle.logging.ProgressLogger
+import org.gradle.logging.ProgressLoggerFactory
 
 /**
  * Adapts an OutputStream being written to by vagrant into a ProcessLogger. It
@@ -42,79 +43,82 @@ import org.gradle.logging.ProgressLogger
  * to catch so it can render the output like
  * "Heading text > stdout from the provisioner".
  */
-class VagrantLoggerOutputStream extends LoggingOutputStream {
+public class VagrantLoggerOutputStream extends LoggingOutputStream {
-  static final String HEADING_PREFIX = '==> '
+    private static final String HEADING_PREFIX = '==> '
 
-  ProgressLogger progressLogger
+    ProgressLoggerFactory progressLoggerFactory
-  String squashedPrefix
-  String lastLine = ''
-  boolean inProgressReport = false
-  String heading = ''
 
-  VagrantLoggerOutputStream(Map args) {
-    progressLogger = args.factory.newOperation(VagrantLoggerOutputStream)
-    progressLogger.setDescription("Vagrant $args.command")
-    progressLogger.started()
-    progressLogger.progress("Starting vagrant $args.command...")
-    squashedPrefix = args.squashedPrefix
-  }
 
-  void flush() {
+    private ProgressLogger progressLogger
-    if (end == start) return
+    String squashedPrefix
-    line(new String(buffer, start, end - start))
+    String lastLine = ''
-    start = end
+    boolean inProgressReport = false
-  }
+    String heading = ''
 
-  void line(String line) {
+    VagrantLoggerOutputStream(Map args) {
-    // debugPrintLine(line) // Uncomment me to log every incoming line
+        progressLogger = args.factory.newOperation(VagrantLoggerOutputStream)
-    if (line.startsWith('\r\u001b')) {
+        progressLogger.setDescription("Vagrant output for `$args.command`")
-      /* We don't want to try to be a full terminal emulator but we want to
+        progressLogger.started()
-        keep the escape sequences from leaking and catch _some_ of the
+        progressLogger.progress("Starting `$args.command`...")
-        meaning. */
+        squashedPrefix = args.squashedPrefix
-      line = line.substring(2)
-      if ('[K' == line) {
-        inProgressReport = true
-      }
-      return
     }
-    if (line.startsWith(squashedPrefix)) {
-      line = line.substring(squashedPrefix.length())
-      inProgressReport = false
-      lastLine = line
-      if (line.startsWith(HEADING_PREFIX)) {
-        line = line.substring(HEADING_PREFIX.length())
-        heading = line + ' > '
-      } else {
-        line = heading + line
-      }
-    } else if (inProgressReport) {
-      inProgressReport = false
-      line = lastLine + line
-    } else {
-      return
-    }
-    // debugLogLine(line) // Uncomment me to log every line we add to the logger
-    progressLogger.progress(line)
-  }
 
-  void debugPrintLine(line) {
+    void flush() {
-    System.out.print '----------> '
+        if (end == start) return
-    for (int i = start; i < end; i++) {
+        line(new String(buffer, start, end - start))
-      switch (buffer[i] as char) {
+        start = end
-      case ' '..'~':
-        System.out.print buffer[i] as char
-        break
-      default:
-        System.out.print '%'
-        System.out.print Integer.toHexString(buffer[i])
-      }
     }
-    System.out.print '\n'
-  }
 
-  void debugLogLine(line) {
+    void line(String line) {
-    System.out.print '>>>>>>>>>>> '
+        // debugPrintLine(line) // Uncomment me to log every incoming line
-    System.out.print line
+        if (line.startsWith('\r\u001b')) {
-    System.out.print '\n'
+            /* We don't want to try to be a full terminal emulator but we want to
-  }
+              keep the escape sequences from leaking and catch _some_ of the
+              meaning. */
+            line = line.substring(2)
+            if ('[K' == line) {
+                inProgressReport = true
+            }
+            return
+        }
+        if (line.startsWith(squashedPrefix)) {
+            line = line.substring(squashedPrefix.length())
+            inProgressReport = false
+            lastLine = line
+            if (line.startsWith(HEADING_PREFIX)) {
+                line = line.substring(HEADING_PREFIX.length())
+                heading = line + ' > '
+            } else {
+                line = heading + line
+            }
+        } else if (inProgressReport) {
+            inProgressReport = false
+            line = lastLine + line
+        } else {
+            return
+        }
+        // debugLogLine(line) // Uncomment me to log every line we add to the logger
+        progressLogger.progress(line)
+    }
+
+    void debugPrintLine(line) {
+        System.out.print '----------> '
+        for (int i = start; i < end; i++) {
+            switch (buffer[i] as char) {
+                case ' '..'~':
+                    System.out.print buffer[i] as char
+                    break
+                default:
+                    System.out.print '%'
+                    System.out.print Integer.toHexString(buffer[i])
+            }
+        }
+        System.out.print '\n'
+    }
+
+    void debugLogLine(line) {
+        System.out.print '>>>>>>>>>>> '
+        System.out.print line
+        System.out.print '\n'
+    }
 }

qa/vagrant/build.gradle

@@ -156,7 +156,7 @@ for (String box : availableBoxes) {
   // always add a halt task for all boxes, so clean makes sure they are all shutdown
   Task halt = tasks.create("vagrant${boxTask}#halt", VagrantCommandTask) {
     boxName box
-    commandLine 'halt', box
+    args 'halt', box
   }
   stop.dependsOn(halt)
   if (boxes.contains(box) == false) {
@@ -176,7 +176,7 @@ for (String box : availableBoxes) {
       vagrant's default but its possible to change that default and folks do.
       But the boxes that we use are unlikely to work properly with other
       virtualization providers. Thus the lock. */
-    commandLine 'up', box, '--provision', '--provider', 'virtualbox'
+    args 'up', box, '--provision', '--provider', 'virtualbox'
     /* It'd be possible to check if the box is already up here and output
       SKIPPED but that would require running vagrant status which is slow! */
     dependsOn checkVagrantVersion