Nested setTimeout inside a setInterval isn't cleared properly

[unleashy]

• FakeTimers version: 7.1.2
• Environment: Latest Chrome on Windows 10 or Node.js 14 on Windows 10

I have a nested setTimeout inside a setInterval, with the timeout being cleared based on an event. Whilst trying to test this behaviour like this:

clock.tick(INTERVAL_MS);
clock.clearTimeout(timeoutId);
clock.tick(TIMEOUT_MS);
// ... check timeout is not called ...

It works just fine the first time. But if you repeat this same code twice, it's like the clearTimeout does not actually clear the timeout and it's immediately called. I put up a reproduction in codesandbox (linked below) that prints "timeout" inside the timeout and then exercises it. I'm not sure if I'm doing anything wrong, but the timeout should not be called, right?

I also did the same thing without faketimers, just the browser's native intervals and timeouts, and it works perfectly, so this leads to me to think it's a bug within faketimers.

What did you expect to happen?

"timeout" should not be printed on the console.

What actually happens

"timeout" is printed once on the console.

How to reproduce

1. Go to https://dopve.csb.app/
2. Open devtools console
3. Click on the "Test" button
4. "timeout" will be printed once

Code can be found at https://codesandbox.io/s/intelligent-hooks-dopve?file=/src/index.js

Thank you!

[fatso83]

Hi, I spent waaaay to much time trying to debug this ... Essentially, this is user error; please post stuff like this to StackOverflow and tag it with sinon next time, so the bigger community can help answer your questions 😄

The problem is that you have tricked yourself (and me 😸 ) with comments. When it says

// "timeout" is logged to the console by now

this is not what is really happening. Embedding lots of debug statements prior to this shows this quite clearly. What really happens is that you see the result of the second setTimeout.

I modified your example to add lots of logging: https://codesandbox.io/s/nervous-wood-5o3nc Btw, I had to make a dedicated log statement, as console.log would actually not print objects as they were at the time of logging, but as they were when looking at them later. So that is the reason for serializing the objects.

So this is what is happening:

1. You create an interval at time 0 that will run at 10000, 20000, 30000, etc (or the closest fit after ticking past these)
2. You tick the clock by 10000
3. This creates a setTimeout to schedule a log statement with "timeout"
4. You clear the timeout
5. You tick it by 1000. nothing happens (correct). The time is now 11000 (not 10000, which your logic dictates)
6. You tick the clock by 10000. This is where the funny stuff happens
7. The clock.tick triggers the interval timer to run at time 20000, creating a new setTimeout to run at 21000
8. The clock ticks on until it finishes at 21000, which then runs the scheduled setTimeout
9. You then clear the setTimeout (which has already run!)
10. Confusion arises 😄

[unleashy]

Thank you! I am REALLY sorry for causing a long debugging session, I genuinely thought this was a bug in the library and not user error 🙈 But, well, whilst your explanation makes sense, is that really how fake-timers should work? To me it is not intuitive, at all, that the second setTimeout would be scheduled to run at 21000 because the outer setInterval is scheduled to run at 20000, if the outer setInterval only runs at 21000 because of some delay. Like, I expected setTimeout to use the “current” time and then add to it, so really the setTimeout would run at 22000.

Either way thank you again for taking the time ❤

[fatso83]

When you tick the clock, fake timers will ensure that the timers are scheduled to run at the times they are supposed to run, not when the tick is "finished". After all, that would make the most sense, if compared to how things work on a "real" timeline: the executions would be spread out according to when they were scheduled.

Not sure I get what you mean here, though:

Like, I expected setTimeout to use the “current” time and then add to it, so really the setTimeout would run at 22000.

setTimeout does use the current time of when it is scheduled. The setInterval that schedules it runs every 10000 millis, so when you use tick to move from time A to time B it will stop at points inbetween to fire the timers that are set to run in that time interval. So when moving from 11000 to 21000 it will hit timers that have been scheduled to run at 20000 (which adds additional timers that is set to run at 21000) and then runs the timers at 21000 when it gets there.

I guess that you think of "current time" as the initial time + the time given to tick, but clock.tick does not "jump" to a given time and runs all timers that have passed their scheduled executions. That would make it impossible to get behaviour that would be similar to the real world.

Example:

function recursiveTimer(){
    console.log(Date.now());
    setTimeout(recursiveTimer, 1000);
}

recursiveTimer();

In real life, this would normally print millis since the Epoch every second. If you stub the time in @sinonjs/fake-timers and do clock.tick(10000) you will see that this is also what happens. If, instead, it was like it seems like you suggested, that we tick the clock by 10000 and then schedule all the timers that have passed, it would only print once! So that's why it works as it does 😄

[unleashy]

Ah I see, I get it now. Thank you so much for all the help!! ❤