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

This change makes the vagrant tasks extend LoggedExec, so that the entire vagrant output can be dumped on failure (and completely logged when using --info). It should help for debugging issues like #18122.
2016-05-04 17:29:23 -07:00 · 2016-05-04 17:29:23 -07:00 · 8fc51380de
parent 67c0734bf3
commit 8fc51380de
6 changed files with 122 additions and 147 deletions
--- a/buildSrc/src/main/groovy/org/elasticsearch/gradle/LoggedExec.groovy
+++ b/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()
-            errorOutput = standardOutput
+            standardOutput = output
+            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}")
                }
            }
--- a/buildSrc/src/main/groovy/org/elasticsearch/gradle/vagrant/BatsOverVagrantTask.groovy
+++ b/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 {
-  String command
-  String boxName
-  ExecAction execAction
+public class BatsOverVagrantTask extends VagrantCommandTask {

-  BatsOverVagrantTask() {
-    execAction = getExecActionFactory().newExecAction()
-  }
+    @Input
+    String command

-  @Inject
-  ProgressLoggerFactory getProgressLoggerFactory() {
-    throw new UnsupportedOperationException();
-  }
+    BatsOverVagrantTask() {
+        project.afterEvaluate {
+            args 'ssh', boxName, '--command', command
+        }
+    }

-  @Inject
-  ExecActionFactory getExecActionFactory() {
-    throw new UnsupportedOperationException();
-  }
-
-  void boxName(String boxName) {
-    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();
-  }
+    @Override
+    protected OutputStream createLoggerOutputStream() {
+        return new TapLoggerOutputStream(
+                command: commandLine.join(' '),
+                factory: getProgressLoggerFactory(),
+                logger: logger)
+    }
 }
--- a/buildSrc/src/main/groovy/org/elasticsearch/gradle/vagrant/TapLoggerOutputStream.groovy
+++ b/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() {
--- a/buildSrc/src/main/groovy/org/elasticsearch/gradle/vagrant/VagrantCommandTask.groovy
+++ b/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.gradle.api.tasks.TaskAction
+import org.apache.commons.io.output.TeeOutputStream
+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 {
-  List<Object> commandLine
-  String boxName
-  ExecAction execAction
+public class VagrantCommandTask extends LoggedExec {

-  VagrantCommandTask() {
-    execAction = getExecActionFactory().newExecAction()
-  }
+    @Input
+    String boxName

-  @Inject
-  ProgressLoggerFactory getProgressLoggerFactory() {
-    throw new UnsupportedOperationException();
-  }
+    public VagrantCommandTask() {
+        executable = 'vagrant'
+        project.afterEvaluate {
+            // It'd be nice if --machine-readable were, well, nice
+            standardOutput = new TeeOutputStream(standardOutput, createLoggerOutputStream())
+        }
+    }

-  @Inject
-  ExecActionFactory getExecActionFactory() {
-    throw new UnsupportedOperationException();
-  }
+    protected OutputStream createLoggerOutputStream() {
+        return 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: ")
+    }

-  void boxName(String boxName) {
-    this.boxName = boxName
-  }
-
-  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();
-  }
+    @Inject
+    ProgressLoggerFactory getProgressLoggerFactory() {
+        throw new UnsupportedOperationException();
+    }
 }
--- a/buildSrc/src/main/groovy/org/elasticsearch/gradle/vagrant/VagrantLoggerOutputStream.groovy
+++ b/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 {
-  static final String HEADING_PREFIX = '==> '
+public class VagrantLoggerOutputStream extends LoggingOutputStream {
+    private static final String HEADING_PREFIX = '==> '

-  ProgressLogger progressLogger
-  String squashedPrefix
-  String lastLine = ''
-  boolean inProgressReport = false
-  String heading = ''
+    ProgressLoggerFactory progressLoggerFactory

-  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() {
-    if (end == start) return
-    line(new String(buffer, start, end - start))
-    start = end
-  }
+    private ProgressLogger progressLogger
+    String squashedPrefix
+    String lastLine = ''
+    boolean inProgressReport = false
+    String heading = ''

-  void line(String line) {
-    // debugPrintLine(line) // Uncomment me to log every incoming line
-    if (line.startsWith('\r\u001b')) {
-      /* 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
+    VagrantLoggerOutputStream(Map args) {
+        progressLogger = args.factory.newOperation(VagrantLoggerOutputStream)
+        progressLogger.setDescription("Vagrant output for `$args.command`")
+        progressLogger.started()
+        progressLogger.progress("Starting `$args.command`...")
+        squashedPrefix = args.squashedPrefix
    }
-    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])
-      }
+    void flush() {
+        if (end == start) return
+        line(new String(buffer, start, end - start))
+        start = end
    }
-    System.out.print '\n'
-  }

-  void debugLogLine(line) {
-    System.out.print '>>>>>>>>>>> '
-    System.out.print line
-    System.out.print '\n'
-  }
+    void line(String line) {
+        // debugPrintLine(line) // Uncomment me to log every incoming line
+        if (line.startsWith('\r\u001b')) {
+            /* 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'
+    }
 }
--- a/qa/vagrant/build.gradle
+++ b/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