feat: include test duration in timeout error messages

lib/runnable.js

@@ -67,6 +67,7 @@ Runnable.prototype.reset = function () {
   this.pending = false;
   delete this.state;
   delete this.err;
+  delete this._startTime;
 };
 
 /**
@@ -243,7 +244,11 @@ Runnable.prototype.resetTimeout = function () {
     if (self.timeout() === 0) {
       return;
     }
-    self.callback(self._timeoutError(ms));
+    var duration;
+    if (self._startTime) {
+      duration = new Date() - self._startTime;
+    }
+    self.callback(self._timeoutError(ms, duration));
     self.timedOut = true;
   }, ms);
 };
@@ -270,6 +275,7 @@ Runnable.prototype.globals = function (globals) {
 Runnable.prototype.run = function (fn) {
   var self = this;
   var start = new Date();
+  this._startTime = start;
   var ctx = this.ctx;
   var finished;
   var errorWasHandled = false;
@@ -305,7 +311,7 @@ Runnable.prototype.run = function (fn) {
     self.duration = new Date() - start;
     finished = true;
     if (!err && self.duration > ms && ms > 0) {
-      err = self._timeoutError(ms);
+      err = self._timeoutError(ms, self.duration);
     }
     fn(err);
   }
@@ -420,11 +426,15 @@ Runnable.prototype.run = function (fn) {
  * Instantiates a "timeout" error
  *
  * @param {number} ms - Timeout (in milliseconds)
+ * @param {number} [duration] - Actual duration (in milliseconds), if available
  * @returns {Error} a "timeout" error
  * @private
  */
-Runnable.prototype._timeoutError = function (ms) {
+Runnable.prototype._timeoutError = function (ms, duration) {
   let msg = `Timeout of ${ms}ms exceeded. For async tests and hooks, ensure "done()" is called; if returning a Promise, ensure it resolves.`;
+  if (typeof duration === "number" && duration > 0) {
+    msg += ` Test ran for ${duration}ms.`;
+  }
   if (this.file) {
     msg += " (" + this.file + ")";
   }

test/unit/runnable.spec.js

@@ -623,6 +623,46 @@ describe("Runnable(title, fn)", function () {
           });
         });
       });
+
+      it("should include duration in timeout error message when timeout fires", function (done) {
+        var runnable = new Runnable("foo", function (done) {
+          setTimeout(done, 50);
+        });
+        runnable.timeout(20);
+        runnable.run(function (err) {
+          expect(err, "to satisfy", { code: TIMEOUT, timeout: 20 });
+          expect(err.message, "to match", /Test ran for \d+ms/);
+          done();
+        });
+      });
+
+      it("should include duration in timeout error message when test finishes late", function (done) {
+        var runnable = new Runnable("foo", function (done) {
+          setTimeout(function () {
+            done();
+          }, 30);
+        });
+        runnable.timeout(10);
+        runnable.run(function (err) {
+          expect(err, "to satisfy", { code: TIMEOUT, timeout: 10 });
+          expect(err.message, "to match", /Test ran for \d+ms/);
+          done();
+        });
+      });
+
+      it("should include duration in timeout error message for promise-based tests", function (done) {
+        var runnable = new Runnable("foo", function () {
+          return new Promise(function (resolve) {
+            setTimeout(resolve, 30);
+          });
+        });
+        runnable.timeout(10);
+        runnable.run(function (err) {
+          expect(err, "to satisfy", { code: TIMEOUT, timeout: 10 });
+          expect(err.message, "to match", /Test ran for \d+ms/);
+          done();
+        });
+      });
     });
 
     describe("if async", function () {