tests: Fix frontend tests (#4188), ugly work around for "Pad never loaded" (#4200)

* remote_runner.js: fix drain call (cf.
https://github.com/caolan/async/blob/master/CHANGELOG.md#breaking-changes)

* dont wait 30 seconds after remote_runner.js returned

* timeout frontend tests after 9.5 minutes to prevent travis from silently stop them

* log when not all tests finished

* prevent killTimeout to happen after last test

* log server messages to console

* remote_runner will take some time to setup sl, so this second is not necessary

* dont write to global mocha variable

* mochas `test end` event is not called when a before/beforeEach-hooks
failed, so we should only use pass/fail/pending-hooks for logging.
also some cruft removed

* pass test in `pending`-event handler

* remove some more cruft in tests/frontend/runner.js

* frontend tests: clarify why stats.tests and total differ

* move killTimeout to pass/fail/pending instead of `test end` to guarantee that it is run

* delete killTimeout on test end to prevent misleading log message

* unused variable

* fix regex

* unlikely edge case

* ensure `allowed test duration exceeded` message is printed for the last runner

* get rid of jquery.iframe.js, currently no support for IE<9

* retry up to 3 times when pad could not be loaded

* Call the logging code in stopSauce in a callback for `browser.quit()`.
This should fix cases like
https://app.saucelabs.com/tests/cb8225375d274cbcbb091309f5466cfd
Travis received all the logs and remote_runner.js exits, but there never
is a DELETE command for webdriver.

.travis.yml

@@ -33,6 +33,8 @@ jobs:
     - if: fork = false
       name: "Test the Frontend"
       install:
+        #FIXME
+        - "sed 's/\"loglevel\": \"INFO\",/\"loglevel\": \"WARN\",/g' settings.json.template > settings.json"
         - "tests/frontend/travis/sauce_tunnel.sh"
         - "bin/installDeps.sh"
         - "export GIT_HASH=$(git rev-parse --verify --short HEAD)"

tests/frontend/helper.js

@@ -1,11 +1,9 @@
 var helper = {};
 
 (function(){
-  var $iframeContainer, $iframe, jsLibraries = {};
+  var $iframe, jsLibraries = {};
 
   helper.init = function(cb){
-    $iframeContainer = $("#iframe-container");
-
     $.get('/static/js/jquery.js').done(function(code){
       // make sure we don't override existing jquery
       jsLibraries["jquery"] = "if(typeof $ === 'undefined') {\n" + code + "\n}";
@@ -90,6 +88,11 @@ var helper = {};
   }
   helper.evtType = evtType;
 
+  // @todo needs fixing asap
+  // newPad occasionally timeouts, might be a problem with ready/onload code during page setup
+  // This ensures that tests run regardless of this problem
+  helper.retry = 0
+
   helper.newPad = function(cb, padName){
     //build opts object
     var opts = {clearCookies: true}
@@ -109,6 +112,9 @@ var helper = {};
       helper.clearSessionCookies();
     }
 
+    // needed for retry
+    let origPadName = padName;
+
     if(!padName)
       padName = "FRONTEND_TEST_" + helper.randomString(20);
     $iframe = $("<iframe src='/p/" + padName + (encodedParams || '') + "'></iframe>");
@@ -116,32 +122,36 @@ var helper = {};
     //clean up inner iframe references
     helper.padChrome$ = helper.padOuter$ = helper.padInner$ = null;
 
-    //clean up iframes properly to prevent IE from memoryleaking
+    //remove old iframe
-    $iframeContainer.find("iframe").purgeFrame().done(function(){
+    $("#iframe-container iframe").remove();
-      $iframeContainer.append($iframe);
+    //set new iframe
-      $iframe.one('load', function(){
+    $("#iframe-container").append($iframe);
-        helper.padChrome$ = getFrameJQuery(                $('#iframe-container iframe'));
+    $iframe.one('load', function(){
-        if (opts.clearCookies) {
+      helper.padChrome$ = getFrameJQuery($('#iframe-container iframe'));
-          helper.clearPadPrefCookie();
+      if (opts.clearCookies) {
-        }
+        helper.clearPadPrefCookie();
-        if (opts.padPrefs) {
+      }
-          helper.setPadPrefCookie(opts.padPrefs);
+      if (opts.padPrefs) {
-        }
+        helper.setPadPrefCookie(opts.padPrefs);
-        helper.waitFor(function(){
+      }
-          return !$iframe.contents().find("#editorloadingbox").is(":visible");
+      helper.waitFor(function(){
-        }, 50000).done(function(){
+        return !$iframe.contents().find("#editorloadingbox").is(":visible");
-          helper.padOuter$  = getFrameJQuery(helper.padChrome$('iframe[name="ace_outer"]'));
+      }, 10000).done(function(){
-          helper.padInner$  = getFrameJQuery( helper.padOuter$('iframe[name="ace_inner"]'));
+        helper.padOuter$  = getFrameJQuery(helper.padChrome$('iframe[name="ace_outer"]'));
+        helper.padInner$  = getFrameJQuery( helper.padOuter$('iframe[name="ace_inner"]'));
 
-          //disable all animations, this makes tests faster and easier
+        //disable all animations, this makes tests faster and easier
-          helper.padChrome$.fx.off = true;
+        helper.padChrome$.fx.off = true;
-          helper.padOuter$.fx.off = true;
+        helper.padOuter$.fx.off = true;
-          helper.padInner$.fx.off = true;
+        helper.padInner$.fx.off = true;
 
-          opts.cb();
+        opts.cb();
-        }).fail(function(){
+      }).fail(function(){
+        if (helper.retry > 3) {
           throw new Error("Pad never loaded");
-        });
+        }
+        helper.retry++;
+        helper.newPad(cb,origPadName);
       });
     });
 

tests/frontend/index.html

@@ -18,7 +18,6 @@
     <script src="lib/expect.js"></script>
 
     <script src="lib/sendkeys.js"></script>    
-    <script src="lib/jquery.iframe.js"></script>  
     <script src="helper.js"></script>
     
     <script src="specs_list.js"></script>

tests/frontend/lib/jquery.iframe.js

@@ -1,40 +0,0 @@
-//copied from http://stackoverflow.com/questions/8407946/is-it-possible-to-use-iframes-in-ie-without-memory-leaks
-(function($) {
-    $.fn.purgeFrame = function() {
-        var deferred;
-        var browser = bowser;
-
-        if (browser.msie && parseFloat(browser.version, 10) < 9) {
-            deferred = purge(this);
-        } else {
-            this.remove();
-            deferred = $.Deferred();
-            deferred.resolve();
-        }
-
-        return deferred;
-    };
-
-    function purge($frame) {
-        var sem = $frame.length
-          , deferred = $.Deferred();
-
-        $frame.load(function() {
-            var frame = this;
-            frame.contentWindow.document.innerHTML = '';
-
-            sem -= 1;
-            if (sem <= 0) {
-                $frame.remove();
-                deferred.resolve();
-            }
-        });
-        $frame.attr('src', 'about:blank');
-
-        if ($frame.length === 0) {
-            deferred.resolve();
-        }
-
-        return deferred.promise();
-    }
-})(jQuery);

tests/frontend/runner.js

@@ -21,19 +21,15 @@ $(function(){
   }
 
   function CustomRunner(runner) {
-    var self = this
+    var stats = { suites: 0, tests: 0, passes: 0, pending: 0, failures: 0 };
-      , stats = this.stats = { suites: 0, tests: 0, passes: 0, pending: 0, failures: 0 }
-      , failures = this.failures = [];
 
     if (!runner) return;
-    this.runner = runner;
 
     runner.on('start', function(){
       stats.start = new Date;
     });
 
     runner.on('suite', function(suite){
-      stats.suites = stats.suites || 0;
       suite.root || stats.suites++;
       if (suite.root) return;
       append(suite.title);
@@ -50,31 +46,23 @@ $(function(){
     });
 
     // Scroll down test display after each test
-    mocha = $('#mocha')[0];
+    let mochaEl = $('#mocha')[0];
     runner.on('test', function(){
-      mocha.scrollTop = mocha.scrollHeight;
+      mochaEl.scrollTop = mochaEl.scrollHeight;
     });
 
+    // max time a test is allowed to run
+    // TODO this should be lowered once timeslider_revision.js is faster
     var killTimeout;
-    runner.on('test end', function(test){
+    runner.on('test end', function(){
-      stats.tests = stats.tests || 0;
       stats.tests++;
-      if ('passed' == test.state) {
+    });
-        append("->","[green]PASSED[clear] :", test.title," ",test.duration,"ms");
-      } else if (test.pending) {
-        append("->","[yellow]PENDING[clear]:", test.title);
-      } else {
-        append("->","[red]FAILED[clear] :", test.title, stringifyException(test.err));
-      }
 
+    runner.on('pass', function(test){
       if(killTimeout) clearTimeout(killTimeout);
       killTimeout = setTimeout(function(){
         append("FINISHED - [red]no test started since 3 minutes, tests stopped[clear]");
       }, 60000 * 3);
-    });
-
-    runner.on('pass', function(test){
-      stats.passes = stats.passes || 0;
 
       var medium = test.slow() / 2;
       test.speed = test.duration > test.slow()
@@ -84,22 +72,28 @@ $(function(){
           : 'fast';
 
       stats.passes++;
+      append("->","[green]PASSED[clear] :", test.title," ",test.duration,"ms");
     });
 
     runner.on('fail', function(test, err){
-      stats.failures = stats.failures || 0;
+      if(killTimeout) clearTimeout(killTimeout);
+      killTimeout = setTimeout(function(){
+        append("FINISHED - [red]no test started since 3 minutes, tests stopped[clear]");
+      }, 60000 * 3);
+
       stats.failures++;
       test.err = err;
-      failures.push(test);
+      append("->","[red]FAILED[clear] :", test.title, stringifyException(test.err));
     });
 
-    runner.on('end', function(){
+    runner.on('pending', function(test){
-      stats.end = new Date;
+      if(killTimeout) clearTimeout(killTimeout);
-      stats.duration = new Date - stats.start;
+      killTimeout = setTimeout(function(){
-    });
+        append("FINISHED - [red]no test started since 3 minutes, tests stopped[clear]");
+      }, 60000 * 3);
 
-    runner.on('pending', function(){
       stats.pending++;
+      append("->","[yellow]PENDING[clear]:", test.title);
     });
 
     var $console = $("#console");
@@ -133,11 +127,19 @@ $(function(){
 
       var total = runner.total;
       runner.on('end', function(){
-        if(stats.tests >= total){
+        stats.end = new Date;
-          var minutes = Math.floor(stats.duration / 1000 / 60);
+        stats.duration = stats.end - stats.start;
-          var seconds = Math.round((stats.duration / 1000) % 60);
+        var minutes = Math.floor(stats.duration / 1000 / 60);
-
+        var seconds = Math.round((stats.duration / 1000) % 60) // chrome < 57 does not like this .toString().padStart("2","0");
-          append("FINISHED -", stats.passes, "tests passed,", stats.failures, "tests failed, duration: " + minutes + ":" + seconds);
+        if(stats.tests === total){
+          append("FINISHED -", stats.passes, "tests passed,", stats.failures, "tests failed,", stats.pending," pending, duration: " + minutes + ":" + seconds);
+        } else if (stats.tests > total) {
+          append("FINISHED - but more tests than planned returned", stats.passes, "tests passed,", stats.failures, "tests failed,", stats.pending," pending, duration: " + minutes + ":" + seconds);
+          append(total,"tests, but",stats.tests,"returned. There is probably a problem with your async code or error handling, see https://github.com/mochajs/mocha/issues/1327");
+        }
+        else {
+          append("FINISHED - but not all tests returned", stats.passes, "tests passed,", stats.failures, "tests failed,", stats.pending, "tests pending, duration: " + minutes + ":" + seconds);
+          append(total,"tests, but only",stats.tests,"returned. Check for failed before/beforeEach-hooks (no `test end` is called for them and subsequent tests of the same suite are skipped), see https://github.com/mochajs/mocha/pull/1043");
         }
       });
   }

tests/frontend/travis/remote_runner.js

@@ -25,35 +25,41 @@ var sauceTestWorker = async.queue(function (testSettings, callback) {
       console.log("Remote sauce test '" + name + "' started! " + url);
 
       //tear down the test excecution
-      var stopSauce = function(success){
+      var stopSauce = function(success,timesup){
-        getStatusInterval && clearInterval(getStatusInterval);
+        clearInterval(getStatusInterval);
         clearTimeout(timeout);
 
-        browser.quit();
+        browser.quit(function(){
+          if(!success){
+            allTestsPassed = false;
+          }
 
-        if(!success){
+          // if stopSauce is called via timeout (in contrast to via getStatusInterval) than the log of up to the last
-          allTestsPassed = false;
+          // five seconds may not be available here. It's an error anyway, so don't care about it.
-        }
+          var testResult = knownConsoleText.replace(/\[red\]/g,'\x1B[31m').replace(/\[yellow\]/g,'\x1B[33m')
+                           .replace(/\[green\]/g,'\x1B[32m').replace(/\[clear\]/g, '\x1B[39m');
+          testResult = testResult.split("\\n").map(function(line){
+            return "[" + testSettings.browserName + " " + testSettings.platform + (testSettings.version === "" ? '' : (" " + testSettings.version)) + "] " + line;
+          }).join("\n");
 
-        var testResult = knownConsoleText.replace(/\[red\]/g,'\x1B[31m').replace(/\[yellow\]/g,'\x1B[33m')
+          console.log(testResult);
-                         .replace(/\[green\]/g,'\x1B[32m').replace(/\[clear\]/g, '\x1B[39m');
+          if (timesup) {
-        testResult = testResult.split("\\n").map(function(line){
+            console.log("[" + testSettings.browserName + " " + testSettings.platform + (testSettings.version === "" ? '' : (" " + testSettings.version)) + "] allowed test duration exceeded");
-          return "[" + testSettings.browserName + " " + testSettings.platform + (testSettings.version === "" ? '' : (" " + testSettings.version)) + "] " + line;
+          }
-        }).join("\n");
+          console.log("Remote sauce test '" + name + "' finished! " + url);
 
-        console.log(testResult);
+          callback();
-        console.log("Remote sauce test '" + name + "' finished! " + url);
+        });
-
-        callback();
       }
 
       /**
-       * timeout for the case the test hangs
+       * timeout if a test hangs or the job exceeds 9.5 minutes
+       * It's necessary because if travis kills the saucelabs session due to inactivity, we don't get any output
        * @todo this should be configured in testSettings, see https://wiki.saucelabs.com/display/DOCS/Test+Configuration+Options#TestConfigurationOptions-Timeouts
        */
       var timeout = setTimeout(function(){
-        stopSauce(false);
+        stopSauce(false,true);
-      }, 1200000 * 10);
+      }, 570000); // travis timeout is 10 minutes, set this to a slightly lower value
 
       var knownConsoleText = "";
       var getStatusInterval = setInterval(function(){
@@ -64,11 +70,13 @@ var sauceTestWorker = async.queue(function (testSettings, callback) {
           knownConsoleText = consoleText;
 
           if(knownConsoleText.indexOf("FINISHED") > 0){
-            let match = knownConsoleText.match(/FINISHED - ([0-9]+) tests passed, ([0-9]+) tests failed/);
+            let match = knownConsoleText.match(/FINISHED.*([0-9]+) tests passed, ([0-9]+) tests failed/);
-            if (match[2] && match[2] == 0){
+            // finished without failures
+            if (match[2] && match[2] == '0'){
               stopSauce(true);
-            }
+
-            else {
+            // finished but some tests did not return or some tests failed
+            } else {
               stopSauce(false);
             }
           }
@@ -128,8 +136,6 @@ sauceTestWorker.push({
   , 'version'        : '78.0'
 });
 
-sauceTestWorker.drain = function() {
+sauceTestWorker.drain(function() {
-  setTimeout(function(){
+  process.exit(allTestsPassed ? 0 : 1);
-    process.exit(allTestsPassed ? 0 : 1);
+});
-  }, 3000);
-}

tests/frontend/travis/runner.sh

@@ -16,7 +16,7 @@ cd "${MY_DIR}/../../../"
 # This is possible because the "install" section of .travis.yml already contains
 # a call to bin/installDeps.sh
 echo "Running Etherpad directly, assuming bin/installDeps.sh has already been run"
-node node_modules/ep_etherpad-lite/node/server.js "${@}" > /dev/null &
+node node_modules/ep_etherpad-lite/node/server.js "${@}" &
 
 echo "Now I will try for 15 seconds to connect to Etherpad on http://localhost:9001"
 
@@ -30,9 +30,6 @@ echo "Now I will try for 15 seconds to connect to Etherpad on http://localhost:9
 
 echo "Successfully connected to Etherpad on http://localhost:9001"
 
-# just in case, let's wait for another second before going on
-sleep 1
-
 # On the Travis VM, remote_runner.js is found at
 # /home/travis/build/ether/[secure]/tests/frontend/travis/remote_runner.js
 # which is the same directory that contains this script.
@@ -46,8 +43,6 @@ echo "Now starting the remote runner"
 node remote_runner.js
 exit_code=$?
 
-kill $!
 kill $(cat /tmp/sauce.pid)
-sleep 30
 
 exit $exit_code