ReactiveX / ReactiveX/rxjs

Delay causes fast loop of TimeoutOverflowWarning

Open
#5,238 4 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
TypeScript
Stars
31.7k
Forks
3k
PR merge metrics
No merged PRs in 30d

Description

Bug Report

Current Behavior

If a delay is running while the system's clock is changed it affects the delay of notifications.

In the extreme case where the system's date goes back in time by more than 2^31 ms (~25 days) it gets stuck in a fast loop printing the message below ~1000 times/sec.

(node:26164) TimeoutOverflowWarning: 157852823770 does not fit into a 32-bit signed integer.

By overriding setInterval with:

let realSetInterval = setInterval;
global.setInterval = (cb, time,...args) => {
  if (time > 4294967296){
    let stack = new Error().stack
    console.log(time, stack )
    process.exit()
  }
  return realSetInterval(cb, time,...args);
}

I got the following stack trace:

Error
    at global.setInterval (/home/ubuntu/backend/generac.js:17:17)
    at AsyncAction.requestAsyncId (/home/ubuntu/backend/node_modules/rxjs/internal/scheduler/AsyncAction.js:44:16)
    at AsyncAction.schedule (/home/ubuntu/backend/node_modules/rxjs/internal/scheduler/AsyncAction.js:39:35)
    at AsyncAction.DelaySubscriber.dispatch [as work] (/home/ubuntu/backend/node_modules/rxjs/internal/operators/delay.js:59:18)
    at AsyncAction._execute (/home/ubuntu/backend/node_modules/rxjs/internal/scheduler/AsyncAction.js:71:18)
    at AsyncAction.execute (/home/ubuntu/backend/node_modules/rxjs/internal/scheduler/AsyncAction.js:59:26)
    at AsyncScheduler.flush (/home/ubuntu/backend/node_modules/rxjs/internal/scheduler/AsyncScheduler.js:52:32)
    at listOnTimeout (internal/timers.js:531:17)
    at processTimers (internal/timers.js:475:7)

Reproduction

Steps:

  1. Set computer's date 1 year in the future.
  2. Execute the script below
  3. After "Set Clock back now" is logged, but before "You were too late", set the computer's date to today.
  4. "You were too late" is not logged, and the TimeoutOverflowWarning will be repeatedly logged to the console.
let rx = require('rxjs');
let op = require('rxjs/operators')

setInterval(() => {
  console.log("Set clock back now");
  rx.of(1).pipe(op.delay(5000)).subscribe(() => console.log("You were too late, try again"));

}, 10000)

Expected behavior
Delays between notifications should not be impacted by clock time of the system.

Environment

  • Runtime: Node 12.13.1, Linux ARM
  • RxJS version: tested on 6.5.3, but reviewed code between 5.x and master which all appear to have same issue

Possible Solution

Related to #5232.

Delay mixes logic to handle offsetting start to an absolute time, and logic to delay individual notifications. Does it make sense to separate the two features into separate operators?

Analysis

When the of emits the value the notification is added to DelaySubscriber's this.queue. The DelayMessage includes the absolute time the notification is scheduled to be emitted, and dispatch is scheduled for execution in this.delay.
https://github.com/ReactiveX/rxjs/blob/41888efcd1f34de2ee1eda0bd778d4fe0ab4263e/src/internal/operators/delay.ts#L132)

The scheduler's clock is then set backwards in time before Dispatch is executed.

Dispatch is called after this.delay elapses. It emits any notifications scheduled to be emitted before scheduler.now.

https://github.com/ReactiveX/rxjs/blob/41888efcd1f34de2ee1eda0bd778d4fe0ab4263e/src/internal/operators/delay.ts#L99

Since scheduler.now() is now significantly in the past, queue[0].time is in the future, so nothing is emitted. Since the queue is not empty, dispatch calculates the delay until the next notification to emit.

https://github.com/ReactiveX/rxjs/blob/41888efcd1f34de2ee1eda0bd778d4fe0ab4263e/src/internal/operators/delay.ts#L104

The delay ultimately is passed to setInterval where the delay is validated to be less than TIMEOUT_MAX, which is 2 ** 31 - 1ms, which is less than 25 days.

https://github.com/nodejs/node/blob/1fab8a92974ce555adca39baada1d199b4952fd7/lib/internal/timers.js#L160

Since queue[0] was scheduled "in the future" and not emitted, the delay was a large positive number significantly larger than TIMEOUT_MAX. Node's behavior in the case of a duration overflow is to set the duration to 1ms.

Dispatch is then called 1ms later, and the process repeats since queue[0] since hasn't been emitted, and is still far enough in the future to exceed TIMEOUT_MAX.

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start with src/internal/operators/delay.ts, especially the queue and dispatch paths identified in the report, then inspect the related AsyncAction scheduler calls. Run the provided clock-change reproduction under the reported Node environment and verify that the delayed notification is emitted without repeated TimeoutOverflowWarning messages after the clock moves backward.

Written by the indexing model from the issue text.

Assessment

Tech stack
javascript, typescript
Domain
api
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.