Capture and report stdout/stderr of the browser while running a test

tools/testing/dart/browser_controller.dart

 // Copyright (c) 2013, the Dart project authors.  Please see the AUTHORS file
 // for details. All rights reserved. Use of this source code is governed by a
 // BSD-style license that can be found in the LICENSE file.
 library browser;
 
 import "dart:async";
 import "dart:convert" show LineSplitter, UTF8;
 import "dart:core";
 import "dart:io";
 
 import 'android.dart';
 import 'utils.dart';
 
+class BrowserOutput {
+  final StringBuffer stdout = new StringBuffer();
+  final StringBuffer stderr = new StringBuffer();
+  final StringBuffer eventLog = new StringBuffer();
+}
+
 /** Class describing the interface for communicating with browsers. */
 abstract class Browser {
-  StringBuffer _stdout = new StringBuffer();
-  StringBuffer _stderr = new StringBuffer();
-  StringBuffer _usageLog = new StringBuffer();
+  BrowserOutput _allBrowserOutput = new BrowserOutput();
+  BrowserOutput _testBrowserOutput = new BrowserOutput();
+
   // This is called after the process is closed, before the done future
   // is completed.
   // Subclasses can use this to cleanup any browser specific resources
   // (temp directories, profiles, etc). The function is expected to do
   // it's work synchronously.
   Function _cleanup;
 
   /** The version of the browser - normally set when starting a browser */
   String version = "";
   /**
@@ skipping 43 matching lines @@
 
   // TODO(kustermann): add standard support for chrome on android
   static bool supportedBrowser(String name) {
     return SUPPORTED_BROWSERS.contains(name);
   }
 
   void _logEvent(String event) {
     String toLog = "$this ($id) - $event \n";
     if (debugPrint) print("usageLog: $toLog");
     if (logger != null) logger(toLog);
-    _usageLog.write(toLog);
+
+    _allBrowserOutput.eventLog.write(toLog);
+    _testBrowserOutput.eventLog.write(toLog);
   }
 
   void _addStdout(String output) {
     if (debugPrint) print("stdout: $output");
-    _stdout.write(output);
+
+    _allBrowserOutput.stdout.write(output);
+    _testBrowserOutput.stdout.write(output);
   }
 
   void _addStderr(String output) {
     if (debugPrint) print("stderr: $output");
-    _stderr.write(output);
+
+    _allBrowserOutput.stderr.write(output);
+    _testBrowserOutput.stderr.write(output);
   }
 
   Future close() {
     _logEvent("Close called on browser");
     if (process != null) {
       if (process.kill(ProcessSignal.SIGKILL)) {
         _logEvent("Successfully sent kill signal to process.");
       } else {
         _logEvent("Sending kill signal failed.");
       }
@@ skipping 54 matching lines @@
         }).whenComplete(() => doneCompleter.complete(true));
       });
       return true;
     }).catchError((error) {
       _logEvent("Running $command $arguments failed with $error");
       return false;
     });
   }
 
   /**
-   * Get any stdout that the browser wrote during execution.
+   * Get the output that was written so far to stdout/stderr/eventLog.
    */
-  String get stdout => _stdout.toString();
-  String get stderr => _stderr.toString();
-  String get usageLog => _usageLog.toString();
+  BrowserOutput get allBrowserOutput => _allBrowserOutput;
+  BrowserOutput get testBrowserOutput => _testBrowserOutput;
+
+  void resetTestBrowserOutput() {
+    _testBrowserOutput = new BrowserOutput();
+  }
 
   String toString();
+
   /** Starts the browser loading the given url */
   Future<bool> start(String url);
 }
 
 class Safari extends Browser {
   /**
    * The binary used to run safari - changing this can be nececcary for
    * testing or using non standard safari installation.
    */
   static const String binary = "/Applications/Safari.app/Contents/MacOS/Safari";
@@ skipping 332 matching lines @@
 }
 
 class Firefox extends Browser {
   static const String enablePopUp =
       'user_pref("dom.disable_open_during_load", false);';
   static const String disableDefaultCheck =
       'user_pref("browser.shell.checkDefaultBrowser", false);';
   static const String disableScriptTimeLimit =
       'user_pref("dom.max_script_run_time", 0);';
 
-  static string _binary = _getBinary();
+  static String _binary = _getBinary();
 
   Future _createPreferenceFile(var path) {
     var file = new File("${path.toString()}/user.js");
     var randomFile = file.openSync(mode: FileMode.WRITE);
     randomFile.writeStringSync(enablePopUp);
     randomFile.writeStringSync(disableDefaultCheck);
     randomFile.writeStringSync(disableScriptTimeLimit);
     randomFile.close();
   }
 
   // This is extracted to a function since we may need to support several
   // locations.
   static String _getWindowsBinary() {
     return "C:\\Program Files (x86)\\Mozilla Firefox\\firefox.exe";
   }
 
   static String _getBinary() {
     if (Platform.isWindows) return _getWindowsBinary();
     if (Platform.isLinux) return 'firefox';
   }
 
   Future<bool> start(String url) {
     _logEvent("Starting firefox browser on: $url");
     // Get the version and log that.
     return Process.run(_binary, ["--version"]).then((var versionResult) {
       if (versionResult.exitCode != 0) {
         _logEvent("Failed to firefox get version");
-        _logEvent("Make sure $binary is a valid program for running firefox");
+        _logEvent("Make sure $_binary is a valid program for running firefox");
         return new Future.value(false);
       }
       version = versionResult.stdout;
       _logEvent("Got version: $version");
 
       return new Directory('').createTemp().then((userDir) {
         _createPreferenceFile(userDir.path);
         _cleanup = () { userDir.deleteSync(recursive: true); };
         var args = ["-profile", "${userDir.path}",
                     "-no-remote", "-new-instance", url];
         return startBrowser(_binary, args);
 
       });
     }).catchError((e) {
-      _logEvent("Running $binary --version failed with $e");
+      _logEvent("Running $_binary --version failed with $e");
       return false;
     });
   }
 
   String toString() => "Firefox";
 }
 
 
 /**
  * Describes the current state of a browser used for testing.
@@ skipping 33 matching lines @@
   // Used for debugging, this is simply a unique identifier assigned to each
   // test.
   int id;
   static int _idCounter = 0;
 
   BrowserTest(this.url, this.doneCallback, this.timeout) {
     id = _idCounter++;
   }
 }
 
+/* Describes the output of running the test in a browser */
+class BrowserTestOutput {
+  final bool didTimeout;
+  final Duration delayUntilTestStarted;
+  final Duration duration;
+  final BrowserOutput browserOutput;
+  final String dom;
+
+  BrowserTestOutput(
+      this.delayUntilTestStarted, this.duration, this.dom,
+      this.browserOutput, {this.didTimeout: false});
+}
 
 /**
  * Encapsulates all the functionality for running tests in browsers.
  * The interface is rather simple. After starting the runner tests
  * are simply added to the queue and a the supplied callbacks are called
  * whenever a test completes.
  */
 class BrowserTestRunner {
   final Map globalConfiguration;
 
@@ skipping 110 matching lines @@
       if (status.currentTest.id != testId) {
         print("Expected test id ${status.currentTest.id} for"
               "${status.currentTest.url}");
         print("Got test id ${testId}");
         print("Last test id was ${status.lastTest.id} for "
               "${status.currentTest.url}");
         throw("This should never happen, wrong test id");
       }
       testCache[testId] = status.currentTest.url;
       Stopwatch watch = new Stopwatch()..start();
-      status.currentTest.doneCallback(output,
-                                      status.currentTest.delayUntilTestStarted,
-                                      status.currentTest.stopwatch.elapsed);
+
+      // Report that the test is finished now
+      var browserTestOutput = new BrowserTestOutput(
+          status.currentTest.delayUntilTestStarted,
+          status.currentTest.stopwatch.elapsed,
+          output,
+          status.browser.testBrowserOutput);
+      status.currentTest.doneCallback(browserTestOutput);
+
       watch.stop();
       status.lastTest = status.currentTest;
       status.currentTest = null;
     } else {
       print("\nThis is bad, should never happen, handleResult no test");
       print("URL: ${status.lastTest.url}");
       print(output);
       terminate().then((_) {
         exit(1);
       });
@@ skipping 11 matching lines @@
           status.currentTest.stopwatch.elapsed;
     }
   }
 
   void handleTimeout(BrowserTestingStatus status) {
     // We simply kill the browser and starts up a new one!
     // We could be smarter here, but it does not seems like it is worth it.
     status.timeout = true;
     timedOut.add(status.currentTest.url);
     var id = status.browser.id;
+
+    status.currentTest.stopwatch.stop();
     status.browser.close().then((_) {
+      // Wait until the browser is closed before reporting the test as timeout.
+      // This will enable us to capture stdout/stderr from the browser
+      // (which might provide us with information about what went wrong).
+      var browserTestOutput = new BrowserTestOutput(
+          status.currentTest.delayUntilTestStarted,
+          status.currentTest.stopwatch.elapsed,
+          'Dom could not be fetched, since the test timed out.',
+          status.browser.testBrowserOutput,
+          didTimeout: true);
+      status.currentTest.doneCallback(browserTestOutput);
+      status.currentTest = null;

[ricow1, 2013/10/18 14:00:42]

shouldn't we do this right away instead of waiting for the browser to close?

[kustermann, 2013/10/18 15:28:27]

I don't think so. We should not set the current test to 'null' before we
actually reported the result of the current test.

[And we want to wait for the browser to shutdown to capture more stdout/stderr
before reporting the result of the test].

+
       // We don't want to start a new browser if we are terminating.
       if (underTermination) return;
       var browser;
       var new_id = id;
       if (browserName == 'chromeOnAndroid') {
         browser = new AndroidChrome(adbDeviceMapping[id]);
       } else {
         browserStatus.remove(id);
         browser = getInstance();
         new_id = "BROWSER$browserIdCount";
@@ skipping 14 matching lines @@
         }
         if (success) {
           browserStatus[browser.id] = new BrowserTestingStatus(browser);
         } else {
           // TODO(ricow): Handle this better.
           print("This is bad, should never happen, could not start browser");
           exit(1);
         }
       });
     });
-    status.currentTest.stopwatch.stop();
-    status.currentTest.doneCallback("TIMEOUT",
-                                    status.currentTest.delayUntilTestStarted,
-                                    status.currentTest.stopwatch.elapsed);
-    status.currentTest = null;
   }
 
   BrowserTest getNextTest(String browserId) {
     if (testQueue.isEmpty) return null;
     var status = browserStatus[browserId];
     if (status == null) return null;
 
     // We are currently terminating this browser, don't start a new test.
     if (status.timeout) return null;
+
     BrowserTest test = testQueue.removeLast();
     if (status.currentTest == null) {
       status.currentTest = test;
     } else {
       // TODO(ricow): Handle this better.
       print("This is bad, should never happen, getNextTest all full");
       print("This happened for browser $browserId");
       print("Old test was: ${status.currentTest.url}");
       print("Timed out tests:");
       for (var v in timedOut) {
         print("  $v");
       }
       exit(1);
     }
 
     status.currentTest.timeoutTimer = createTimeoutTimer(test, status);
     status.currentTest.stopwatch = new Stopwatch()..start();
+
+    // Reset the test specific output information (stdout, stderr) on the
+    // browser since a new test is begin started.
+    status.browser.resetTestBrowserOutput();
+
     return test;
   }
 
   Timer createTimeoutTimer(BrowserTest test, BrowserTestingStatus status) {
     return new Timer(
         new Duration(seconds: test.timeout), () { handleTimeout(status); });
   }
 
   void queueTest(BrowserTest test) {
     testQueue.add(test);
@@ skipping 354 matching lines @@
     Dart test driver, number of tests: <div id="number"></div><br>
     Currently executing: <div id="currently_executing"></div><br>
     Unhandled error: <div id="unhandled_error"></div>
     <iframe id="embedded_iframe"></iframe>
   </body>
 </html>
 """;
     return driverContent;
   }
 }