Spurious assertion error when the callback to setInterval lasts longer than the interval

[andreubotella]

Attacler/Bart reported on Discord that an AssertionError was being thrown while they were stress-testing their code. It seems to happen spuriously, but their stress test seemed to hit it every time.

const MET = setInterval(() => {
    // console.log("RET", worker.RET);
    if (worker.RET <= 0) {
        removeWorkers(executeId);
        events.emit("return_" + executeId, {
            errors: ["Maximum execution time passed!"],
            logs: [],
            error: true,
        });
        spawnWorkers(1);
    }
    worker.RET -= 0.1;
}, 100);

events.on("return_" + executeId, (data: MessageEvent) => {
    console.log("RETURN", executeId);
    if (MET != undefined) clearInterval(MET);
    console.log(data);
    res(data);

    setTimeout(() => {
        removeWorkers(executeId);
    }, 250);
    spawnWorkers(1);
});

error: Uncaught (in promise) AssertionError: Assertion failed.
            if (MET != undefined) clearInterval(MET);
                                  ^
    at assert (deno:extensions/timers/01_timers.js:22:13)
    at setGlobalTimeout (deno:extensions/timers/01_timers.js:332:5)
    at setOrClearGlobalTimeout (deno:extensions/timers/01_timers.js:376:7)
    at unschedule (deno:extensions/timers/01_timers.js:425:9)
    at clearTimer (deno:extensions/timers/01_timers.js:547:5)
    at clearInterval (deno:extensions/timers/01_timers.js:564:5)
    at file:///mnt/abc2f9c2-fcf1-457f-94e4-be464a8e61ea/Connectplatform/Deno%20Connect/helpers/workers.ts:233:35
    at EventEmitter.emit (https://deno.land/x/[email protected]/mod.ts:166:7)
    at Worker.worker.onmessage (file:///mnt/abc2f9c2-fcf1-457f-94e4-be464a8e61ea/Connectplatform/Deno%20Connect/helpers/workers.ts:110:28)
    at Worker.wrappedHandler (deno:runtime/js/01_web_util.js:26:37)

Since the failed assertion makes sure that the timeout is not lesser than zero, and changing the interval to 4000ms solved the problem, it seems to be caused by the callback taking longer to run than the interval.

[lucacasonato]

For reference the entire setTimeout code is so complicated because back when we implemented setTimeout for the first time, tokios timers were not ordered so we couldn't do a direct setTimeout -> tokio::time::sleep . The timers are now ordered, so we should now be able to get rid of the entire complexity for timers and do a direct setTimeout -> async op_timers_sleep (using tokio::time::sleep) mapping.

We would need to figure out how to be able to cancel this ongoing timer, but overall I think this should greatly simplify 01_timers.js and likely fix this bug.

[BartTactick]

This is true, however its not that breaking for my application so for me it does not have a big prio

[halfmatthalfcat]

I believe this might be causing the same issue I'm seeing right now with rxjs under heavy load:

error: Uncaught (in promise) AssertionError: Assertion failed.
    at assert (deno:ext/timers/01_timers.js:40:13)
    at setGlobalTimeout (deno:ext/timers/01_timers.js:349:5)
    at setOrClearGlobalTimeout (deno:ext/timers/01_timers.js:393:7)
    at unschedule (deno:ext/timers/01_timers.js:442:9)
    at clearTimer (deno:ext/timers/01_timers.js:564:5)
    at clearInterval (deno:ext/timers/01_timers.js:581:5)
    at r.recycleAsyncId (https://cdn.esm.sh/v53/[email protected]/deno/operators.js:4:10920)
    at r._unsubscribe (https://cdn.esm.sh/v53/[email protected]/deno/operators.js:4:11535)
    at r.e.unsubscribe (https://cdn.esm.sh/v53/[email protected]/deno/operators.js:4:639)
    at r.e.unsubscribe (https://cdn.esm.sh/v53/[email protected]/deno/operators.js:4:761)

[andreubotella]

Just having the setInterval callback take longer –even significantly longer– than the interval isn't enough to reproduce this bug. But I've found a reproducible test case:

Deno.test(async function clearTimeoutAfterNextTimerIsDue1() {
  const promise = deferred();

  setTimeout(() => {
    promise.resolve();
  }, 300);

  const interval = setInterval(() => {
    Deno.sleepSync(400);
    // Both the interval and the timeout's due times are now in the past.
    clearTimeout(interval);
  }, 100);

  await promise;
});

The bug is due to an interaction between various timers that happens when calling clearTimeout() or clearInterval() on the first timer that is currently scheduled to run, when the first and second timers scheduled are now in the past. Since in the current timers implementation, an interval's next callback is scheduled before the current one runs, this is easier to come across when cancelling the current interval, but you can also run into this in other cases:

Deno.test(async function clearTimeoutAfterNextTimerIsDue2() {
  const promise = deferred();

  const timeout1 = setTimeout(() => {}, 100);

  setTimeout(() => {
    promise.resolve();
  }, 200);

  Deno.sleepSync(300);
  // Both of the timeouts' due times are now in the past.
  clearTimeout(timeout1);

  await promise;
});

This issue will be fixed in the rewrite of timers I'm doing in #12862.