Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Infinite loop in timers in Node 11 #23935

Closed
jcubic opened this issue Oct 28, 2018 · 3 comments
Closed

Infinite loop in timers in Node 11 #23935

jcubic opened this issue Oct 28, 2018 · 3 comments
Labels
duplicate Issues and PRs that are duplicates of other issues or PRs. timers Issues and PRs related to the timers subsystem / setImmediate, setInterval, setTimeout.

Comments

@jcubic
Copy link
Contributor

jcubic commented Oct 28, 2018

  • Version: v11.0.0
  • Platform: Linux jcubic 4.18.13-100.fc27.x86_64 deps: update openssl to 1.0.1j #1 SMP Wed Oct 10 18:34:01 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
  • Subsystem: timers

I have jest test that was working in Node 10 and it's broken in Node 11, I've reported the issue to jest framework but this may be issue with Node 11, I don't see much breaking changes to setTimeout in Changelog. Only the one that execute tick after each timer.

the problem is probably with setTimeout function, after code run successfully (it sometimes don't give output) when I run in debug mode

node --inspect-brk ./node_modules/jest/bin/jest.js --runInBand \
  --coverage --testMatch '**/__tests__/*.spec.js'
``

and when I pause when script stack (in Chrome, when it stuck) it point to timers.js file:

It created infinite loop in those 2 functions:

```js
function processTimers(now) {
  debug('process timer lists %d', now);
  nextExpiry = Infinity;

  let list;
  let ranAtLeastOneList = false;
  while (list = queue.peek()) {
    if (list.expiry > now) {
      nextExpiry = list.expiry;
      return refCount > 0 ? nextExpiry : -nextExpiry;
    }
    if (ranAtLeastOneList)
      runNextTicks();
    else
      ranAtLeastOneList = true;
    listOnTimeout(list, now);
  }
  return 0;
}

function listOnTimeout(list, now) {
  const msecs = list.msecs;

  debug('timeout callback %d', msecs);

  var diff, timer;
  let ranAtLeastOneTimer = false;
  while (timer = L.peek(list)) {
    diff = now - timer._idleStart;

    // Check if this loop iteration is too early for the next timer.
    // This happens if there are more timers scheduled for later in the list.
    if (diff < msecs) {
      list.expiry = timer._idleStart + msecs;
      list.id = timerListId++;
      queue.percolateDown(1);
      debug('%d list wait because diff is %d', msecs, diff);
      return;
    }

    if (ranAtLeastOneTimer)
      runNextTicks();
    else
      ranAtLeastOneTimer = true;

    // The actual logic for when a timeout happens.
    L.remove(timer);

    const asyncId = timer[async_id_symbol];

    if (!timer._onTimeout) {
      if (timer[kRefed])
        refCount--;
      timer[kRefed] = null;

      if (destroyHooksExist() && !timer._destroyed) {
        emitDestroy(asyncId);
        timer._destroyed = true;
      }
      continue;
    }

    emitBefore(asyncId, timer[trigger_async_id_symbol]);

    let start;
    if (timer._repeat)
      start = getLibuvNow();

    try {
      const args = timer._timerArgs;
      if (!args)
        timer._onTimeout();
      else
        Reflect.apply(timer._onTimeout, timer, args);
    } finally {
      if (timer._repeat && timer._idleTimeout !== -1) {
        timer._idleTimeout = timer._repeat;
        if (start === undefined)
          start = getLibuvNow();
        insert(timer, timer[kRefed], start);
      } else {
        if (timer[kRefed])
          refCount--;
        timer[kRefed] = null;

        if (destroyHooksExist() && !timer._destroyed) {
          emitDestroy(timer[async_id_symbol]);
          timer._destroyed = true;
        }
      }
    }

    emitAfter(asyncId);
  }

  // If `L.peek(list)` returned nothing, the list was either empty or we have
  // called all of the timer timeouts.
  // As such, we can remove the list from the object map and the PriorityQueue.
  debug('%d list empty', msecs);

  // The current list may have been removed and recreated since the reference
  // to `list` was created. Make sure they're the same instance of the list
  // before destroying.
  if (list === lists[msecs]) {
    delete lists[msecs];
    queue.shift();
  }
}

The problem is that the script is not ending. it keep processing event that it should finish. And node inspector don't give async stack trace I only see two functions processTimers and listOnTimeout.

I've tried to debug setTimeout function to see why it's freezing I've put this code in jest test:

global.global_timers = {};
(function(setTimeout) {
    var counter = 0;
    global.setTimeout = function(fn, timer) {
        var c = counter++;
        global.global_timers[c] = new Error().stack;
        return setTimeout(function() {
            delete global.global_timers[c];
            fn();
        }, timer);
    };
})(setTimeout);

but when I pause in Inspector setTimeout is original function and there are no global_timers variable.

@richardlau
Copy link
Member

See #23921 and #23860. Should be fixed by #23870.

@richardlau richardlau added duplicate Issues and PRs that are duplicates of other issues or PRs. timers Issues and PRs related to the timers subsystem / setImmediate, setInterval, setTimeout. v11.x labels Oct 28, 2018
@jcubic jcubic closed this as completed Oct 28, 2018
@mareksrom
Copy link

This issue is not fully solved, infinite loop in timers can still occur in some cases...

@mareksrom
Copy link

please see PR #24318

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
duplicate Issues and PRs that are duplicates of other issues or PRs. timers Issues and PRs related to the timers subsystem / setImmediate, setInterval, setTimeout.
Projects
None yet
Development

No branches or pull requests

3 participants