Repository: sinonjs/fake-timers
Pull request #325 (2020-05-17 10:52:04)

Add stack trace to code recursively scheduling timers
#### Purpose (TL;DR) - mandatory
<!--
> give a concise (one or two short sentences) description of what problem is being solved by this PR
>
> Example: Fix issue #123456 by re-structuring the colour selection conditional in method `paintBlue`
-->
Fix issue #230 by using stack information for jobs and timers to provide more context when an infinite loop error is thrown.

<!--
#### Background (Problem in detail)  - optional
-->
<!--
> When relevant, give a more thorough description of what the problem the PR is trying to solve. Examples of good topics for this section are:
> * Link to an existing GitHub issue describing the problem
> * Describing the problem in greater detail than the TL;DR section above
> * How you discovered the issue if it's not already described as an issue on GitHub
> * Discussion of different approaches to solving this problem and why you chose your proposed solution
-->



#### Solution  - optional

<!--
> When contributing code (and not just fixing typos, documentation and configuration), please describe why/how your solution works. This helps reviewers spot any mistakes in the implementation.
>
> Example:
> "This solution works by adding a `paintBlue()` method"
> Then your reviewer might spot a mistake in the implementation, if `paintBlue()` uses the colour red.
-->

This solution works by adding a `stack` property to jobs and tasks. This data can then be used, if an infinite loop is detected, to set the stack of the thrown `infiniteLoopError`.


##### Example stack trace from test run
```
Error: Aborting after running 5 timers, assuming an infinite loop!
Timeout - recursiveCreateTimerTimeout
      at recursiveCreateTimer (test/fake-timers-test.js:4668)
      at recursiveCreateTimerTimeout (test/fake-timers-test.js:4669)
      at callTimer (src/fake-timers-src.js:441)
      at Object.next (src/fake-timers-src.js:1039)
      at src/fake-timers-src.js:1128
```

codecov[bot]: # [Codecov](https://codecov.io/gh/sinonjs/fake-timers/pull/325?src=pr&el=h1) Report
> Merging [#325](https://codecov.io/gh/sinonjs/fake-timers/pull/325?src=pr&el=desc) into [master](https://codecov.io/gh/sinonjs/fake-timers/commit/2ebd23c01130c9a525b4424e899aef24bb19c4bb&el=desc) will **increase** coverage by `0.07%`.
> The diff coverage is `100.00%`.

[![Impacted file tree graph](https://codecov.io/gh/sinonjs/fake-timers/pull/325/graphs/tree.svg?width=650&height=150&src=pr&token=YubuW6TySz)](https://codecov.io/gh/sinonjs/fake-timers/pull/325?src=pr&el=tree)

```diff
@@            Coverage Diff             @@
##           master     #325      +/-   ##
==========================================
+ Coverage   93.11%   93.18%   +0.07%     
==========================================
  Files           1        1              
  Lines         552      558       +6     
==========================================
+ Hits          514      520       +6     
  Misses         38       38              
```

| Flag | Coverage Δ | |
|---|---|---|
| #unit | `93.18% <100.00%> (+0.07%)` | :arrow_up: |

| [Impacted Files](https://codecov.io/gh/sinonjs/fake-timers/pull/325?src=pr&el=tree) | Coverage Δ | |
|---|---|---|
| [src/fake-timers-src.js](https://codecov.io/gh/sinonjs/fake-timers/pull/325/diff?src=pr&el=tree#diff-c3JjL2Zha2UtdGltZXJzLXNyYy5qcw==) | `93.18% <100.00%> (+0.07%)` | :arrow_up: |

------

[Continue to review full report at Codecov](https://codecov.io/gh/sinonjs/fake-timers/pull/325?src=pr&el=continue).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/sinonjs/fake-timers/pull/325?src=pr&el=footer). Last update [2ebd23c...9a92f55](https://codecov.io/gh/sinonjs/fake-timers/pull/325?src=pr&el=lastupdated). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments).

SimenB: Could we just keep track of the last scheduled timer instead of all scheduled timers? Not sure how much that matters
SimenB: Another though, this is mostly meant to catch timers added while running timers. Could we add some flag internally that's set to `true` whenever we run timers, and only collect these at that time? 
alistairjcbrown: @SimenB Thanks for the feedback!
I've updated to set an error object on the job instead of getting the error stack. The second commit adds in a `isNearInfiniteLimit` flag which is used to decide whether to attach an error object to the job. Jobs from the job before we hit the limit will have an error property populated, which is then used if we need to create an InfiniteLoopError. What do you think?


fatso83: no time (parental leave) at the moment to look at PRs, sorry.
benjamingr: Also:

>  What do you think?

The actual implementation logic lgtm
alistairjcbrown: @benjamingr Awesome, thanks for the feedback! I'll take a run through it tomorrow night 👍 
alistairjcbrown: @benjamingr 

> Dealing with a non-writeable stack property

Using `defineProperty` wrapped in `try`/`catch` as suggested - TIL about non-writeable stacks 👍 

> calculating the slice size automatically

Doing this by running through the stack line by line, checking the line matches `at target.X ` (where `X` may be `(anonymous function)` or `<computed>`) or `at Object.Y` (where `Y` is a clock method).

> Tests that check a larger chunk of the stack (so we're sure this doesn't break)

Apologies, I wasn't 100% sure on what this was asking, so I've added more tests to cover `requestAnimationFrame`, `setImmediate`, `setInterval`, `requestIdleCallback`,  `nextTick`.

If this was referring to checking more of the stack trace itself, the tests are checking that we're getting the expected method at the top of the stack - but we can't check the filename as it'll be `__puppeteer_evaluation_script__` on headless. Do you want more of the stack trace checked?
benjamingr: Hey, I wanted to merge and it looks like there is a merge conflict - can you please take a look?

Patch:
diff --git a/src/fake-timers-src.js b/src/fake-timers-src.js
index c969a85..858ef6b 100644
--- a/src/fake-timers-src.js
+++ b/src/fake-timers-src.js
@@ -67,6 +67,18 @@ function withGlobal(_global) {
     var NativeDate = _global.Date;
     var uniqueTimerId = 1;
 
+    var isNearInfiniteLimit = false;
+
+    function checkIsNearInfiniteLimit(clock, i) {
+        if (clock.loopLimit && i === clock.loopLimit - 1) {
+            isNearInfiniteLimit = true;
+        }
+    }
+
+    function resetIsNearInfiniteLimit() {
+        isNearInfiniteLimit = false;
+    }
+
     function isNumberFinite(num) {
         if (Number.isFinite) {
             return Number.isFinite(num);
@@ -143,6 +155,64 @@ function withGlobal(_global) {
         throw new TypeError("now should be milliseconds since UNIX epoch");
     }
 
+    function getInfiniteLoopError(clock, job) {
+        var infiniteLoopError = new Error(
+            "Aborting after running " +
+                clock.loopLimit +
+                " timers, assuming an infinite loop!"
+        );
+        var computedTargetPattern = /\s+at target\.[<|(].*?[>|)]\s+/;
+        var clockMethodPattern = new RegExp(
+            "\\s+at Object\\.(?:" + Object.keys(clock).join("|") + ")\\s+"
+        );
+
+        var matchedLineIndex = -1;
+        job.error.stack.split("\n").some(function(line, i) {
+            // If we've matched a computed target line (e.g. setTimeout) then we
+            // don't need to look any further. Return true to stop iterating.
+            var matchedComputedTarget = line.match(computedTargetPattern);
+            if (matchedComputedTarget) {
+                matchedLineIndex = i;
+                return true;
+            }
+
+            // If we've matched a clock method line, then there may still be
+            // others further down the trace. Return false to keep iterating.
+            var matchedClockMethod = line.match(clockMethodPattern);
+            if (matchedClockMethod) {
+                matchedLineIndex = i;
+                return false;
+            }
+
+            // If we haven't matched anything on this line, but we matched
+            // previously and set the matched line index, then we can stop.
+            // If we haven't matched previously, then we should keep iterating.
+            return matchedLineIndex >= 0;
+        });
+
+        var stack =
+            infiniteLoopError +
+            "\n" +
+            (job.type || "Microtask") +
+            " - " +
+            (job.func.name || "anonymous") +
+            "\n" +
+            job.error.stack
+                .split("\n")
+                .slice(matchedLineIndex + 1)
+                .join("\n");
+
+        try {
+            Object.defineProperty(infiniteLoopError, "stack", {
+                value: stack
+            });
+        } catch (e) {
+            // noop
+        }
+
+        return infiniteLoopError;
+    }
+
     function inRange(from, to, timer) {
         return timer && timer.callAt >= from && timer.callAt <= to;
     }
@@ -251,14 +321,13 @@ function withGlobal(_global) {
         for (var i = 0; i < clock.jobs.length; i++) {
             var job = clock.jobs[i];
             job.func.apply(null, job.args);
+
+            checkIsNearInfiniteLimit(clock, i);
             if (clock.loopLimit && i > clock.loopLimit) {
-                throw new Error(
-                    "Aborting after running " +
-                        clock.loopLimit +
-                        " timers, assuming an infinite loop!"
-                );
+                throw getInfiniteLoopError(clock, job);
             }
         }
+        resetIsNearInfiniteLimit();
         clock.jobs = [];
     }
 
@@ -267,6 +336,10 @@ function withGlobal(_global) {
             throw new Error("Callback must be provided to timer calls");
         }
 
+        if (isNearInfiniteLimit) {
+            timer.error = new Error();
+        }
+
         timer.type = timer.immediate ? "Immediate" : "Timeout";
 
         if (timer.hasOwnProperty("delay")) {
@@ -772,7 +845,8 @@ function withGlobal(_global) {
         clock.nextTick = function nextTick(func) {
             return enqueueJob(clock, {
                 func: func,
-                args: Array.prototype.slice.call(arguments, 1)
+                args: Array.prototype.slice.call(arguments, 1),
+                error: isNearInfiniteLimit ? new Error() : null
             });
         };
 
@@ -1067,22 +1141,22 @@ function withGlobal(_global) {
             runJobs(clock);
             for (i = 0; i < clock.loopLimit; i++) {
                 if (!clock.timers) {
+                    resetIsNearInfiniteLimit();
                     return clock.now;
                 }
 
                 numTimers = keys(clock.timers).length;
                 if (numTimers === 0) {
+                    resetIsNearInfiniteLimit();
                     return clock.now;
                 }
 
                 clock.next();
+                checkIsNearInfiniteLimit(clock, i);
             }
 
-            throw new Error(
-                "Aborting after running " +
-                    clock.loopLimit +
-                    " timers, assuming an infinite loop!"
-            );
+            var excessJob = firstTimer(clock);
+            throw getInfiniteLoopError(clock, excessJob);
         };
 
         clock.runToFrame = function runToFrame() {
@@ -1099,6 +1173,7 @@ function withGlobal(_global) {
                                 var numTimers;
                                 if (i < clock.loopLimit) {
                                     if (!clock.timers) {
+                                        resetIsNearInfiniteLimit();
                                         resolve(clock.now);
                                         return;
                                     }
@@ -1106,6 +1181,7 @@ function withGlobal(_global) {
                                     numTimers = Object.keys(clock.timers)
                                         .length;
                                     if (numTimers === 0) {
+                                        resetIsNearInfiniteLimit();
                                         resolve(clock.now);
                                         return;
                                     }
@@ -1115,16 +1191,12 @@ function withGlobal(_global) {
                                     i++;
 
                                     doRun();
+                                    checkIsNearInfiniteLimit(clock, i);
                                     return;
                                 }
 
-                                reject(
-                                    new Error(
-                                        "Aborting after running " +
-                                            clock.loopLimit +
-                                            " timers, assuming an infinite loop!"
-                                    )
-                                );
+                                var excessJob = firstTimer(clock);
+                                reject(getInfiniteLoopError(clock, excessJob));
                             } catch (e) {
                                 reject(e);
                             }


Test patch:
diff --git a/test/fake-timers-test.js b/test/fake-timers-test.js
index b5820d5..087991f 100644
--- a/test/fake-timers-test.js
+++ b/test/fake-timers-test.js
@@ -4622,3 +4622,345 @@ describe("#187 - Support timeout.refresh in node environments", function() {
         clock.uninstall();
     });
 });
+
+describe("loop limit stack trace", function() {
+    var test,
+        expectedMessage =
+            "Aborting after running 5 timers, assuming an infinite loop!";
+
+    beforeEach(function() {
+        test = this;
+        this.clock = FakeTimers.install({ loopLimit: 5 });
+    });
+
+    afterEach(function() {
+        this.clock.uninstall();
+    });
+
+    describe("queueMicrotask", function() {
+        beforeEach(function() {
+            function recursiveQueueMicroTask() {
+                test.clock.queueMicrotask(recursiveQueueMicroTask);
+            }
+            recursiveQueueMicroTask();
+        });
+
+        it("provides a stack trace for running microtasks", function() {
+            var caughtError = false;
+
+            try {
+                test.clock.runMicrotasks();
+            } catch (err) {
+                caughtError = true;
+                assert.equals(err.message, expectedMessage);
+                assert.equals(
+                    new RegExp(
+                        "Error: " +
+                            expectedMessage +
+                            "\\s+Microtask - recursiveQueueMicroTask\\s+at recursiveQueueMicroTask\\s"
+                    ).test(err.stack),
+                    true
+                );
+            }
+            assert.equals(caughtError, true);
+        });
+    });
+
+    describe("nextTick", function() {
+        beforeEach(function() {
+            function recursiveQueueMicroTask() {
+                test.clock.nextTick(recursiveQueueMicroTask);
+            }
+            recursiveQueueMicroTask();
+        });
+
+        it("provides a stack trace for running microtasks", function() {
+            var caughtError = false;
+
+            try {
+                test.clock.runMicrotasks();
+            } catch (err) {
+                caughtError = true;
+                assert.equals(err.message, expectedMessage);
+                assert.equals(
+                    new RegExp(
+                        "Error: " +
+                            expectedMessage +
+                            "\\s+Microtask - recursiveQueueMicroTask\\s+at recursiveQueueMicroTask\\s"
+                    ).test(err.stack),
+                    true
+                );
+            }
+            assert.equals(caughtError, true);
+        });
+    });
+
+    describe("setTimeout", function() {
+        beforeEach(function() {
+            function recursiveCreateTimer() {
+                setTimeout(function recursiveCreateTimerTimeout() {
+                    recursiveCreateTimer();
+                }, 10);
+            }
+            recursiveCreateTimer();
+        });
+
+        it("provides a stack trace for running all async", function() {
+            var catchSpy = sinon.spy();
+
+            return test.clock
+                .runAllAsync()
+                .catch(catchSpy)
+                .then(function() {
+                    assert(catchSpy.calledOnce);
+                    var err = catchSpy.firstCall.args[0];
+                    assert.equals(err.message, expectedMessage);
+                    assert.equals(
+                        new RegExp(
+                            "Error: " +
+                                expectedMessage +
+                                "\\s+Timeout - recursiveCreateTimerTimeout\\s+at recursiveCreateTimer\\s"
+                        ).test(err.stack),
+                        true
+                    );
+                });
+        });
+
+        it("provides a stack trace for running all sync", function() {
+            var caughtError = false;
+
+            try {
+                test.clock.runAll();
+            } catch (err) {
+                caughtError = true;
+                assert.equals(err.message, expectedMessage);
+                assert.equals(
+                    new RegExp(
+                        "Error: " +
+                            expectedMessage +
+                            "\\s+Timeout - recursiveCreateTimerTimeout\\s+at recursiveCreateTimer\\s"
+                    ).test(err.stack),
+                    true
+                );
+            }
+            assert.equals(caughtError, true);
+        });
+    });
+
+    describe("requestIdleCallback", function() {
+        beforeEach(function() {
+            function recursiveCreateTimer() {
+                test.clock.requestIdleCallback(
+                    function recursiveCreateTimerTimeout() {
+                        recursiveCreateTimer();
+                    },
+                    10
+                );
+            }
+            recursiveCreateTimer();
+        });
+
+        it("provides a stack trace for running all async", function() {
+            var catchSpy = sinon.spy();
+
+            return test.clock
+                .runAllAsync()
+                .catch(catchSpy)
+                .then(function() {
+                    assert(catchSpy.calledOnce);
+                    var err = catchSpy.firstCall.args[0];
+                    assert.equals(err.message, expectedMessage);
+                    assert.equals(
+                        new RegExp(
+                            "Error: " +
+                                expectedMessage +
+                                "\\s+Timeout - recursiveCreateTimerTimeout\\s+at recursiveCreateTimer\\s"
+                        ).test(err.stack),
+                        true
+                    );
+                });
+        });
+
+        it("provides a stack trace for running all sync", function() {
+            var caughtError = false;
+
+            try {
+                test.clock.runAll();
+            } catch (err) {
+                caughtError = true;
+                assert.equals(err.message, expectedMessage);
+                assert.equals(
+                    new RegExp(
+                        "Error: " +
+                            expectedMessage +
+                            "\\s+Timeout - recursiveCreateTimerTimeout\\s+at recursiveCreateTimer\\s"
+                    ).test(err.stack),
+                    true
+                );
+            }
+            assert.equals(caughtError, true);
+        });
+    });
+
+    describe("setInterval", function() {
+        beforeEach(function() {
+            function recursiveCreateTimer() {
+                setInterval(function recursiveCreateTimerTimeout() {
+                    recursiveCreateTimer();
+                }, 10);
+            }
+            recursiveCreateTimer();
+        });
+
+        it("provides a stack trace for running all async", function() {
+            var catchSpy = sinon.spy();
+
+            return test.clock
+                .runAllAsync()
+                .catch(catchSpy)
+                .then(function() {
+                    assert(catchSpy.calledOnce);
+                    var err = catchSpy.firstCall.args[0];
+                    assert.equals(err.message, expectedMessage);
+                    assert.equals(
+                        new RegExp(
+                            "Error: " +
+                                expectedMessage +
+                                "\\s+Interval - recursiveCreateTimerTimeout\\s+at recursiveCreateTimer\\s"
+                        ).test(err.stack),
+                        true
+                    );
+                });
+        });
+
+        it("provides a stack trace for running all sync", function() {
+            var caughtError = false;
+
+            try {
+                test.clock.runAll();
+            } catch (err) {
+                caughtError = true;
+                assert.equals(err.message, expectedMessage);
+                assert.equals(
+                    new RegExp(
+                        "Error: " +
+                            expectedMessage +
+                            "\\s+Interval - recursiveCreateTimerTimeout\\s+at recursiveCreateTimer\\s"
+                    ).test(err.stack),
+                    true
+                );
+            }
+            assert.equals(caughtError, true);
+        });
+    });
+
+    describe("setImmediate", function() {
+        beforeEach(function() {
+            if (!setImmediatePresent) {
+                this.skip();
+            }
+
+            function recursiveCreateTimer() {
+                setImmediate(function recursiveCreateTimerTimeout() {
+                    recursiveCreateTimer();
+                });
+            }
+            recursiveCreateTimer();
+        });
+
+        it("provides a stack trace for running all async", function() {
+            var catchSpy = sinon.spy();
+
+            return test.clock
+                .runAllAsync()
+                .catch(catchSpy)
+                .then(function() {
+                    assert(catchSpy.calledOnce);
+                    var err = catchSpy.firstCall.args[0];
+                    assert.equals(err.message, expectedMessage);
+                    assert.equals(
+                        new RegExp(
+                            "Error: " +
+                                expectedMessage +
+                                "\\s+Immediate - recursiveCreateTimerTimeout\\s+at recursiveCreateTimer\\s"
+                        ).test(err.stack),
+                        true
+                    );
+                });
+        });
+
+        it("provides a stack trace for running all sync", function() {
+            var caughtError = false;
+
+            try {
+                test.clock.runAll();
+            } catch (err) {
+                caughtError = true;
+                assert.equals(err.message, expectedMessage);
+                assert.equals(
+                    new RegExp(
+                        "Error: " +
+                            expectedMessage +
+                            "\\s+Immediate - recursiveCreateTimerTimeout\\s+at recursiveCreateTimer\\s"
+                    ).test(err.stack),
+                    true
+                );
+            }
+            assert.equals(caughtError, true);
+        });
+    });
+
+    describe("requestAnimationFrame", function() {
+        beforeEach(function() {
+            function recursiveCreateTimer() {
+                test.clock.requestAnimationFrame(
+                    function recursiveCreateTimerTimeout() {
+                        recursiveCreateTimer();
+                    }
+                );
+            }
+            recursiveCreateTimer();
+        });
+
+        it("provides a stack trace for running all async", function() {
+            var catchSpy = sinon.spy();
+
+            return test.clock
+                .runAllAsync()
+                .catch(catchSpy)
+                .then(function() {
+                    assert(catchSpy.calledOnce);
+                    var err = catchSpy.firstCall.args[0];
+                    assert.equals(err.message, expectedMessage);
+                    assert.equals(
+                        new RegExp(
+                            "Error: " +
+                                expectedMessage +
+                                "\\s+AnimationFrame - recursiveCreateTimerTimeout\\s+at recursiveCreateTimer\\s"
+                        ).test(err.stack),
+                        true
+                    );
+                });
+        });
+
+        it("provides a stack trace for running all sync", function() {
+            var caughtError = false;
+
+            try {
+                test.clock.runAll();
+            } catch (err) {
+                caughtError = true;
+                assert.equals(err.message, expectedMessage);
+                assert.equals(
+                    new RegExp(
+                        "Error: " +
+                            expectedMessage +
+                            "\\s+AnimationFrame - recursiveCreateTimerTimeout\\s+at recursiveCreateTimer\\s"
+                    ).test(err.stack),
+                    true
+                );
+            }
+            assert.equals(caughtError, true);
+        });
+    });
+});