[BUG] setTimeout fires incorrectly when using chrome debug

[Thomas101]

Hey,

I've found an issue that means when you're running on an iOS device and debugging in chrome setTimeouts can fire in the wrong order. If you place the following code block into a fresh app and run it you should get the error...

  componentDidMount:function() {
    this.runTest()
  },

  test:function(cb) {
    var aFired = false
    var bFired = false
    var aExpected = new Date().getTime()+130
    var bExpected = new Date().getTime()+500
    console.log('Schedule A to fire @' + aExpected)
    console.log('Schedule B to fire @' + bExpected)

    var a = setTimeout(() => {
      var now = new Date().getTime()
      console.log('A fired', now, now - aExpected)
      aFired = true
      if (bFired) { console.log('ERROR: b fired early'); return;
      }
      if (aFired && bFired) { cb() }
    }, 130)
    var b = setTimeout(() => {
      var now = new Date().getTime()
      console.log('B fired', now, now - bExpected)
      bFired = true
      if (!aFired) { console.log('ERROR: A not fired'); return;
      }
      if (aFired && bFired) { cb() }
    }, 500)
  },
  runTest:function() {
    this.test(() => {
      setTimeout(() => {
        this.runTest()
      }, 500)
    })
  },

On the console you'll get something like...

index.ios.js:25 Schedule A to fire @1448977966848
index.ios.js:26 Schedule B to fire @1448977967218
index.ios.js:30 A fired 1448977966754 -94
index.ios.js:38 B fired 1448977966755 -463
index.ios.js:25 Schedule A to fire @1448977966902
index.ios.js:26 Schedule B to fire @1448977967272
index.ios.js:30 A fired 1448977966806 -96
index.ios.js:38 B fired 1448977966806 -466
index.ios.js:25 Schedule A to fire @1448977966951
index.ios.js:26 Schedule B to fire @1448977967321
index.ios.js:30 A fired 1448977966835 -116
index.ios.js:38 B fired 1448977966835 -486


index.ios.js:25 Schedule A to fire @1448977966983
index.ios.js:26 Schedule B to fire @1448977967353
index.ios.js:38 B fired 1448977966871 -482
index.ios.js:40 ERROR: A not fired
index.ios.js:30 A fired 1448977966871 -112
index.ios.js:32 ERROR: b fired early

... with the first 3 firing correctly and the last one incorrectly. I believe this bug is also what is causing issue #1693 as one of the setTimeout functions sometimes fires early in touchableHandleResponderGrant

[facebook-github-bot]

Hey Thomas101, thanks for reporting this issue!

React Native, as you've probably heard, is getting really popular and truth is we're getting a bit overwhelmed by the activity surrounding it. There are just too many issues for us to manage properly.

• If this is a feature request or a bug that you would like to be fixed by the team, please report it on Product Pains. It has a ranking feature that lets us focus on the most important issues the community is experiencing.
• If you don't know how to do something or not sure whether some behavior is expected or a bug, please ask on StackOverflow with the tag react-native or for more real time interactions, ask on Discord in the #react-native channel.
• We welcome clear issues and PRs that are ready for in-depth discussion; thank you for your contributions!

[christopherdro]

@Thomas101 Try taking a look at https://facebook.github.io/react-native/docs/timers.html#timermixin at the last paragraph:
We strongly discourage using the global setTimeout(...) and recommend instead that you use this.setTimeout(...)

[Thomas101]

Thanks @christopherdro, we've been using that wherever possible but some of the built in react functionality uses plain old settimeout which is where the bug raised its head initially

[ide]

@Thomas101 Thanks for your detailed investigation and write-up. RN should implement timers correctly. In fact if I'm reading your code and logs correctly, it looks like the timeout arg is ignored as events A and B run at almost the same time. cc @sahrens

[Thomas101]

Those were the logs that came out, you should get similar results if you run it yourself. This is purely speculation as I haven't looked at the implementation, but as it only happenens when running the chrome debugger and using the device, did wonder if it could be a time drift issue between my Mac and ipad?

[satya164]

@christopherdro Also not possible to use it when using the ES6 class syntax. Need to manually cleanup ofc.

[sahrens]

Not sure who owns timers these days - maybe @tadeuzagallo or @nicklockwood ? Also cc @dmmiller because we want to be consistent on iOS and android.

[aleclarson]

I've experienced this while "Debug in Chrome" is active. setTimeout fires very early.

Has it been confirmed that TimerMixin avoids this issue?

I thought TimerMixin only helps with cleanup in componentWillUnmount?

[Thomas101]

Hi @aleclarson using the TimerMixin still has the same problem as this uses setTimeout behind the scenes.

[aleclarson]

Who works on the debugger-proxy packager endpoint? Is there a hack related to setTimeout that involves accounting for socket latency? I can't imagine how else setTimeout could be acting so strangely.

[PaulBGD]

Go vote for this issue so that the developers can see that it's important: https://productpains.com/post/react-native/settimeout-fires-incorrectly-when-using-chrome-debug/

[sahrens]

I don't know much about our chrome integration or why it would cause a difference in timer behavior - @frantic or @tadeuzagallo?