Merge pull request #693 from nathanboktae/wait-for-details

Better log messages for waitFor.timeout events

@@ -437,7 +437,7 @@ Emitted when a navigation step has been started.
 ``step.timeout``
 ~~~~~~~~~~~~~~~~
 
-**Arguments:** ``None``
+**Arguments:** ``[step, timeout]``
 
 Emitted when a navigation step has been executed.
 
@@ -483,9 +483,11 @@ Emitted when a ``Casper.wait()`` operation starts.
 ``waitFor.timeout``
 ~~~~~~~~~~~~~~~~~~~
 
-**Arguments:** ``None``
+**Arguments:** ``[timeout, details]``
+
+Emitted when the execution time of a ``Casper.wait*()`` operation has exceeded the value of ``timeout``.
 
-Emitted when the execution time of a ``Casper.wait*()`` operation has exceeded the value of ``Casper.options.stepTimeout``.
+``deatils`` is a property bag describing what was being waited on. For example, if ``waitForSelector`` timed out, ``details`` will have a ``selector`` string property that was the selector that did not show up in time.
 
 
 .. index:: filters

@@ -1943,7 +1943,7 @@ You can also write the same thing like this::
 ``waitFor()``
 -------------------------------------------------------------------------------
 
-**Signature:** ``waitFor(Function testFx[, Function then, Function onTimeout, Number timeout])``
+**Signature:** ``waitFor(Function testFx[, Function then, Function onTimeout, Number timeout, Object details])``
 
 Waits until a function returns true to process any next step.
 
@@ -1977,6 +1977,9 @@ Example using the ``onTimeout`` callback::
 
     casper.run();
 
+``details`` is a property bag of various information that will be passed to the ``waitFor.timeout`` event, if it is emitted.
+This can be used for better error messages or to conditionally ignore some timeout events.
+
 .. _casper_waitforpopup:
 
 .. index:: Popups, New window, window.open, Tabs

@@ -122,7 +122,7 @@ var Casper = function Casper(options) {
         retryTimeout:        20,
         waitTimeout:         5000,
         clipRect : null,
-        viewportSize : null,
+        viewportSize : null
     };
     // options
     this.options = utils.mergeObjects(this.defaults, options);
@@ -1504,7 +1504,7 @@ Casper.prototype.runStep = function runStep(step) {
         var stepTimeoutCheckInterval = setInterval(function _check(self, start, stepNum) {
             if (new Date().getTime() - start > self.options.stepTimeout) {
                 if (getCurrentSuiteId(self) === stepNum) {
-                    self.emit('step.timeout');
+                    self.emit('step.timeout', stepNum, self.options.onStepTimeout);
                     if (utils.isFunction(self.options.onStepTimeout)) {
                         self.options.onStepTimeout.call(self, self.options.stepTimeout, stepNum);
                     }
@@ -2003,12 +2003,14 @@ Casper.prototype.waitDone = function waitDone() {
  * @param  Function  then       The next step to perform (optional)
  * @param  Function  onTimeout  A callback function to call on timeout (optional)
  * @param  Number    timeout    The max amount of time to wait, in milliseconds (optional)
+ * @param  Object    details    A property bag of information about the condition being waited on (optional)
  * @return Casper
  */
-Casper.prototype.waitFor = function waitFor(testFx, then, onTimeout, timeout) {
+Casper.prototype.waitFor = function waitFor(testFx, then, onTimeout, timeout, details) {
     "use strict";
     this.checkStarted();
-    timeout = timeout ? timeout : this.options.waitTimeout;
+    timeout = timeout || this.options.waitTimeout;
+    details = details || { testFx: testFx };
     if (!utils.isFunction(testFx)) {
         throw new CasperError("waitFor() needs a test function");
     }
@@ -2019,7 +2021,7 @@ Casper.prototype.waitFor = function waitFor(testFx, then, onTimeout, timeout) {
         this.waitStart();
         var start = new Date().getTime();
         var condition = false;
-        var interval = setInterval(function _check(self, testFx, timeout, onTimeout) {
+        var interval = setInterval(function _check(self) {
             /*jshint maxstatements:20*/
             if ((new Date().getTime() - start < timeout) && !condition) {
                 condition = testFx.call(self, self);
@@ -2029,13 +2031,13 @@ Casper.prototype.waitFor = function waitFor(testFx, then, onTimeout, timeout) {
             if (!condition) {
                 self.log("Casper.waitFor() timeout", "warning");
                 var onWaitTimeout = onTimeout ? onTimeout : self.options.onWaitTimeout;
-                self.emit('waitFor.timeout', timeout, onWaitTimeout);
+                self.emit('waitFor.timeout', timeout, details);
                 clearInterval(interval); // refs #383
                 if (!utils.isFunction(onWaitTimeout)) {
                     throw new CasperError('Invalid timeout function');
                 }
                 try {
-                    return onWaitTimeout.call(self, timeout);
+                    return onWaitTimeout.call(self, timeout, details);
                 } catch (error) {
                     self.emit('waitFor.timeout.error', error);
                 } finally {
@@ -2047,7 +2049,7 @@ Casper.prototype.waitFor = function waitFor(testFx, then, onTimeout, timeout) {
             if (then) {
                 self.then(then);
             }
-        }, this.options.retryTimeout, this, testFx, timeout, onTimeout);
+        }, this.options.retryTimeout, this);
         this.waiters.push(interval);
     });
 };
@@ -2071,7 +2073,7 @@ Casper.prototype.waitForPopup = function waitForPopup(urlPattern, then, onTimeou
         } catch (e) {
             return false;
         }
-    }, then, onTimeout, timeout);
+    }, then, onTimeout, timeout, { popup: urlPattern });
 };
 
 /**
@@ -2090,7 +2092,7 @@ Casper.prototype.waitForResource = function waitForResource(test, then, onTimeou
     timeout = timeout ? timeout : this.options.waitTimeout;
     return this.waitFor(function _check() {
         return this.resourceExists(test);
-    }, then, onTimeout, timeout);
+    }, then, onTimeout, timeout, { resource: test });
 };
 
 /**
@@ -2112,7 +2114,7 @@ Casper.prototype.waitForUrl = function waitForUrl(url, then, onTimeout, timeout)
             return url.test(this.getCurrentUrl());
         }
         throw new CasperError('invalid url argument');
-    }, then, onTimeout, timeout);
+    }, then, onTimeout, timeout, { url: url });
 };
 
 /**
@@ -2131,7 +2133,7 @@ Casper.prototype.waitForSelector = function waitForSelector(selector, then, onTi
     timeout = timeout ? timeout : this.options.waitTimeout;
     return this.waitFor(function _check() {
         return this.exists(selector);
-    }, then, onTimeout, timeout);
+    }, then, onTimeout, timeout, { selector: selector });
 };
 
 /**
@@ -2153,7 +2155,7 @@ Casper.prototype.waitForText = function(pattern, then, onTimeout, timeout) {
             return pattern.test(content);
         }
         return content.indexOf(pattern) !== -1;
-    }, then, onTimeout, timeout);
+    }, then, onTimeout, timeout, { text: pattern });
 };
 
 /**
@@ -2173,7 +2175,7 @@ Casper.prototype.waitForSelectorTextChange = function(selector, then, onTimeout,
     var currentSelectorText = this.fetchText(selector);
     return this.waitFor(function _check() {
         return currentSelectorText !== this.fetchText(selector);
-    }, then, onTimeout, timeout);
+    }, then, onTimeout, timeout, { selectorTextChange: selector });
 };
 
 /**
@@ -2192,7 +2194,10 @@ Casper.prototype.waitWhileSelector = function waitWhileSelector(selector, then,
     timeout = timeout ? timeout : this.options.waitTimeout;
     return this.waitFor(function _check() {
         return !this.exists(selector);
-    }, then, onTimeout, timeout);
+    }, then, onTimeout, timeout, {
+        selector: selector,
+        waitWhile: true
+    });
 };
 
 /**
@@ -2211,7 +2216,7 @@ Casper.prototype.waitUntilVisible = function waitUntilVisible(selector, then, on
     timeout = timeout ? timeout : this.options.waitTimeout;
     return this.waitFor(function _check() {
         return this.visible(selector);
-    }, then, onTimeout, timeout);
+    }, then, onTimeout, timeout, { visible: selector });
 };
 
 /**
@@ -2230,7 +2235,10 @@ Casper.prototype.waitWhileVisible = function waitWhileVisible(selector, then, on
     timeout = timeout ? timeout : this.options.waitTimeout;
     return this.waitFor(function _check() {
         return !this.visible(selector);
-    }, then, onTimeout, timeout);
+    }, then, onTimeout, timeout, {
+        visible: selector,
+        waitWhile: true
+    });
 };
 
 /**

@@ -164,15 +164,6 @@ var Tester = function Tester(casper, options) {
         }
     });
 
-    // casper events
-    this.casper.on('error', function onCasperError(msg, backtrace) {
-        self.processPhantomError(msg, backtrace);
-    });
-
-    this.casper.on('waitFor.timeout', function onWaitForTimeout(timeout) {
-        this.warn(f('wait timeout of %dms reached', timeout));
-    });
-
     function errorHandler(error, backtrace) {
         self.casper.unwait();
         if (error instanceof Error) {
@@ -196,6 +187,11 @@ var Tester = function Tester(casper, options) {
         self.done();
     }
 
+    // casper events
+    this.casper.on('error', function onCasperError(msg, backtrace) {
+        self.processPhantomError(msg, backtrace);
+    });
+
     [
         'wait.error',
         'waitFor.timeout.error',
@@ -227,8 +223,34 @@ var Tester = function Tester(casper, options) {
         throw new TimedOutError(f("Timeout occured (%dms)", timeout));
     };
 
-    this.casper.options.onWaitTimeout = function test_onWaitTimeout(timeout) {
-        throw new TimedOutError(f("Wait timeout occured (%dms)", timeout));
+    this.casper.options.onWaitTimeout = function test_onWaitTimeout(timeout, details) {
+        /*jshint maxcomplexity:10*/
+        var message = f("Wait timeout occured (%dms)", timeout);
+        details = details || {};
+
+        if (details.selector) {
+            message = f(details.waitWhile ? '"%s" never went away in %dms' : '"%s" still did not exist in %dms', details.selector, timeout);
+        }
+        else if (details.visible) {
+            message = f(details.waitWhile ? '"%s" never disappeared in %dms' : '"%s" never appeared in %dms', details.visible, timeout);
+        }
+        else if (details.url || details.resource) {
+            message = f('%s did not load in %dms', details.url || details.resource, timeout);
+        }
+        else if (details.popup) {
+            message = f('%s did not pop up in %dms', details.popup, timeout);
+        }
+        else if (details.text) {
+            message = f('"%s" did not appear in the page in %dms', details.text, timeout);
+        }
+        else if (details.selectorTextChange) {
+            message = f('"%s" did not have a text change in %dms', details.selectorTextChange, timeout);
+        }
+        else if (utils.isFunction(details.testFx)) {
+            message = f('"%s" did not evaluate to something truthy in %dms', details.testFx.toString(), timeout);
+        }
+
+        errorHandlerAndDone(new TimedOutError(message));
     };
 };
 
@@ -857,7 +879,7 @@ Tester.prototype.assertInstanceOf = function assertInstanceOf(subject, construct
         standard: f('Subject is instance of: "%s"', constructor.name),
         values: {
             subject: subject,
-            constructorName: constructor.name,
+            constructorName: constructor.name
         }
     });
 };

@@ -64,8 +64,9 @@ class CasperExecTestBase(unittest.TestCase):
         if not what:
             raise AssertionError('Empty lookup')
         if isinstance(what, (list, tuple)):
+            output = self.runCommand(cmd, **kwargs)
             for entry in what:
-                self.assertIn(entry, self.runCommand(cmd, **kwargs))
+                self.assertIn(entry, output)
         else:
             self.assertIn(what, self.runCommand(cmd))
 
@@ -287,6 +288,21 @@ class TestCommandOutputTest(CasperExecTestBase):
         ], failing=True)
 
     @timeout(20)
+    def test_waitFor_timeout(self):
+        # using begin()
+        script_path = os.path.join(TEST_ROOT, 'tester', 'waitFor_timeout.js')
+        self.assertCommandOutputContains('test ' + script_path, [
+            '"p.nonexistent" still did not exist in',
+            '"#encoded" did not have a text change in',
+            '"p[style]" never appeared in',
+            '/github\.com/ did not load in',
+            '/foobar/ did not pop up in',
+            '"Lorem ipsum" did not appear in the page in',
+            'return false',
+            'did not evaluate to something truthy in'
+        ], failing=True)
+
+    @timeout(20)
     def test_dubious_test(self):
         script_path = os.path.join(TEST_ROOT, 'tester', 'dubious.js')
         self.assertCommandOutputContains('test ' + script_path, [

+/*global casper*/
+/*jshint strict:false*/
+
+casper.options.waitTimeout = 500;
+
+casper.test.begin('waitForSelector fails with expected message', 1, function(test) {
+    casper.start('../site/waitFor.html');
+
+    casper.waitForSelector('p.nonexistent', function() {
+        throw new Error('waitForSelector found something it should not have');
+    });
+
+    casper.run(function() {
+        test.done();
+    });
+});
+
+casper.test.begin('waitWhileSelector fails with expected message', 1, function(test) {
+    casper.start('../site/waitFor.html');
+
+    casper.waitForSelector('#encoded');
+
+    casper.waitWhileSelector('#encoded', function() {
+        throw new Error('waitWhileSelector thought something got removed when it did not');
+    });
+
+    casper.run(function() {
+        test.done();
+    });
+});
+
+casper.test.begin('waitForSelectorTextChange fails with expected message', 1, function(test) {
+    casper.start('../site/waitFor.html');
+
+    casper.waitForSelectorTextChange('#encoded', function() {
+        throw new Error('waitForSelectorTextChange thought text changed when it did not');
+    });
+
+    casper.run(function() {
+        test.done();
+    });
+});
+
+casper.test.begin('waitUntilVisible fails with expected message', 1, function(test) {
+    casper.start('../site/waitFor.html');
+
+    casper.waitUntilVisible('p[style]', function() {
+        throw new Error('waitUntilVisible falsely identified a hidden paragraph');
+    });
+
+    casper.run(function() {
+        test.done();
+    });
+});
+
+casper.test.begin('waitWhileVisible fails with expected message', 1, function(test) {
+    casper.start('../site/waitFor.html');
+
+    casper.waitWhileVisible('img', function() {
+        throw new Error('waitWhileVisible thought something disappeared when it did not');
+    });
+
+    casper.run(function() {
+        test.done();
+    });
+});
+
+casper.test.begin('waitForUrl fails with expected message', 1, function(test) {
+    casper.start('../site/waitFor.html');
+
+    casper.waitForUrl(/github\.com/, function() {
+        throw new Error('waitForUrl thought we actually navigated to GitHub');
+    });
+
+    casper.run(function() {
+        test.done();
+    });
+});
+
+casper.test.begin('waitForPopup fails with expected message', 1, function(test) {
+    casper.start('../site/waitFor.html');
+
+    casper.waitForPopup(/foobar/, function() {
+        throw new Error('waitForPopup found something it should not have');
+    });
+
+    casper.run(function() {
+        test.done();
+    });
+});
+
+casper.test.begin('waitForText fails with expected message', 1, function(test) {
+    casper.start('../site/waitFor.html');
+
+    casper.waitForText("Lorem ipsum", function() {
+        throw new Error('waitForText found something it should not have');
+    });
+
+    casper.run(function() {
+        test.done();
+    });
+});
+
+casper.test.begin('waitFor fails with expected message', 1, function(test) {
+    casper.start('../site/waitFor.html');
+
+    casper.waitFor(function() {
+      return false
+    }, function() {
+        throw new Error('waitFor fasely succeeded');
+    });
+
+    casper.run(function() {
+        test.done();
+    });
+});
\ No newline at end of file