From b18a86cec779552b0d4098689f012c5a648723c9 Mon Sep 17 00:00:00 2001 From: Flarnie Marchan Date: Fri, 25 May 2018 15:38:38 -0700 Subject: [PATCH 01/13] Initial failing unit test for error handling in schedule **what is the change?:** see title **why make this change?:** Adding tests for the error handling behavior we are about to add. This test is failing, which gives us the chance to make it pass. Wrote skeletons of some other tests to add. Unit testing this way is really hacky, and I'm also adding to the fixture to test this in the real browser environment. **test plan:** Ran new test, saw it fail! --- .../src/__tests__/ReactScheduler-test.js | 66 ++++++++++++++++++- 1 file changed, 65 insertions(+), 1 deletion(-) diff --git a/packages/react-scheduler/src/__tests__/ReactScheduler-test.js b/packages/react-scheduler/src/__tests__/ReactScheduler-test.js index 88c49289fdeee..e017f24f8b106 100644 --- a/packages/react-scheduler/src/__tests__/ReactScheduler-test.js +++ b/packages/react-scheduler/src/__tests__/ReactScheduler-test.js @@ -20,6 +20,8 @@ describe('ReactScheduler', () => { let rAFCallbacks = []; let postMessageCallback; let postMessageEvents = []; + let postMessageErrors = []; + let catchPostMessageErrors = false; function runPostMessageCallbacks(config: FrameTimeoutConfigType) { let timeLeftInFrame = 0; @@ -31,7 +33,17 @@ describe('ReactScheduler', () => { currentTime = startOfLatestFrame + frameSize - timeLeftInFrame; if (postMessageCallback) { while (postMessageEvents.length) { - postMessageCallback(postMessageEvents.shift()); + if (catchPostMessageErrors) { + // catch errors for testing error handling + try { + postMessageCallback(postMessageEvents.shift()); + } catch (e) { + postMessageErrors.push(e); + } + } else { + // we are not expecting errors + postMessageCallback(postMessageEvents.shift()); + } } } } @@ -64,6 +76,7 @@ describe('ReactScheduler', () => { const originalAddEventListener = global.addEventListener; postMessageCallback = null; postMessageEvents = []; + postMessageErrors = []; global.addEventListener = function(eventName, callback, useCapture) { if (eventName === 'message') { postMessageCallback = callback; @@ -361,5 +374,56 @@ describe('ReactScheduler', () => { }); }); + describe('when callbacks throw errors', () => { + describe('when some callbacks throw', () => { + it('still calls all callbacks within same frame', () => { + const {scheduleWork, cancelScheduledWork} = ReactScheduler; + const callbackLog = []; + const callbackA = jest.fn(() => callbackLog.push('A')); + const callbackB = jest.fn(() => { + callbackLog.push('B'); + throw new Error('B error'); + }); + const callbackC = jest.fn(() => callbackLog.push('C')); + const callbackD = jest.fn(() => { + callbackLog.push('D'); + throw new Error('D error'); + }); + const callbackE = jest.fn(() => callbackLog.push('E')); + scheduleWork(callbackA); + scheduleWork(callbackB); + scheduleWork(callbackC); + scheduleWork(callbackD); + scheduleWork(callbackE); + // Initially doesn't call anything + expect(callbackLog).toEqual([]); + catchPostMessageErrors = true; + advanceOneFrame({timeLeftInFrame: 15}); + // calls all callbacks + expect(callbackLog).toEqual(['A', 'B', 'C', 'D', 'E']); + // errors should still get thrown + expect(postMessageErrors.length).toBe(2); + expect(postMessageErrors[0].message).toBe('B error'); + expect(postMessageErrors[1].message).toBe('D error'); + }); + }); + describe('when all scheduled callbacks throw', () => { + it('still calls all callbacks within same frame', () => { + // TODO + // calls all callbacks + // does not catch errors + // errors happen at right time + }); + }); + describe('when callbacks throw over multiple frames', () => { + it('still calls all callbacks within same frame', () => { + // TODO + // calls all callbacks + // does not catch errors + // errors happen at right time + }); + }); + }); + // TODO: test 'now' }); From 16972dea5f2c96b50c917f83b25bdd38cb253140 Mon Sep 17 00:00:00 2001 From: Flarnie Marchan Date: Sat, 26 May 2018 14:14:19 -0700 Subject: [PATCH 02/13] Add fixture for testing error handling in scheduler **what is the change?:** Added a fixture which does the following - logs in the console to show what happens when you use `requestAnimationFrame` to schedule a series of callbacks and some of them throw errors. Then does the same actions with the `scheduler` and verifies that it behaves in a similar way. Hard to really verify the errors get thrown at the proper time without looking at the console. **why make this change?:** We want the most authentic, accurate test of how errors are handled in the scheduler. That's what this fixture should be. **test plan:** Manually verified that this test does what I expect - right now it's failing but follow up commits will fix that. --- fixtures/schedule/index.html | 93 ++++++++++++++++++++++++++++++++++++ 1 file changed, 93 insertions(+) diff --git a/fixtures/schedule/index.html b/fixtures/schedule/index.html index 24fd26aee95f2..59faafcc167d9 100644 --- a/fixtures/schedule/index.html +++ b/fixtures/schedule/index.html @@ -69,6 +69,11 @@

Tests:

Actual:
+
  • +

    When some callbacks throw errors, still calls them all within the same frame

    +

    IMPORTANT: Open the console when you run this! Inspect the logs there!

    + +
    • @@ -134,6 +139,9 @@

    Tests:

    // test 4 [ ], + // test 5 + [ + ], ]; const expectedResults = [ @@ -182,6 +190,10 @@

    Tests:

    'cbD called with argument of {"didTimeout":false}', 'frame 3 started... we stop counting now.', ], + // test 5 + [ + // ... TODO + ], ]; function runTestOne() { // Test 1 @@ -287,6 +299,87 @@

    Tests:

    displayTestResult(4); checkTestResult(4); }); + +} + +// Error handling + +function runTestFive() { + // Test 5 + // When some callbacks throw errors, still calls them all within the same frame + const cbA = (x) => { + console.log('cbA called with argument of ' + JSON.stringify(x)); + } + const cbB = (x) => { + console.log('cbB called with argument of ' + JSON.stringify(x)); + console.log('cbB is about to throw an error!'); + throw new Error('error B'); + } + const cbC = (x) => { + console.log('cbC called with argument of ' + JSON.stringify(x)); + } + const cbD = (x) => { + console.log('cbD called with argument of ' + JSON.stringify(x)); + console.log('cbD is about to throw an error!'); + throw new Error('error D'); + } + const cbE = (x) => { + console.log('cbE called with argument of ' + JSON.stringify(x)); + console.log('This was the last callback! ------------------'); + } + + console.log('We are aiming to roughly emulate the way ' + + '`requestAnimationFrame` handles errors from callbacks.'); + + console.log('about to run the simulation of what it should look like...:'); + + requestAnimationFrame(() => { + console.log('frame 1 started'); + requestAnimationFrame(() => { + console.log('frame 2 started'); + requestAnimationFrame(() => { + console.log('frame 3 started... we stop counting now.'); + console.log('about to wait a moment and start this again but ' + + 'with the scheduler instead of requestAnimationFrame'); + setTimeout(runSchedulerCode, 1000); + }); + }); + }); + requestAnimationFrame(cbA); + console.log('scheduled cbA'); + requestAnimationFrame(cbB); // will throw error + console.log('scheduled cbB'); + requestAnimationFrame(cbC); + console.log('scheduled cbC'); + requestAnimationFrame(cbD); // will throw error + console.log('scheduled cbD'); + requestAnimationFrame(cbE); + console.log('scheduled cbE'); + + + function runSchedulerCode() { + console.log('-------------------------------------------------------------'); + console.log('now lets see what it looks like using the scheduler...:'); + requestAnimationFrame(() => { + console.log('frame 1 started'); + requestAnimationFrame(() => { + console.log('frame 2 started'); + requestAnimationFrame(() => { + console.log('frame 3 started... we stop counting now.'); + }); + }); + }); + scheduleWork(cbA); + console.log('scheduled cbA'); + scheduleWork(cbB); // will throw error + console.log('scheduled cbB'); + scheduleWork(cbC); + console.log('scheduled cbC'); + scheduleWork(cbD); // will throw error + console.log('scheduled cbD'); + scheduleWork(cbE); + console.log('scheduled cbE'); + }; } From 0ac6e11d7d394fe1910a77d8db57c7cf6eef6de4 Mon Sep 17 00:00:00 2001 From: Flarnie Marchan Date: Mon, 28 May 2018 10:33:38 -0700 Subject: [PATCH 03/13] Handle errors in scheduler **what is the change?:** We set a flag before calling any callback, and then use a 'try/finally' block to wrap it. Note that we *do not* catch the error, if one is thrown. But, we only unset the flag after the callback successfully finishes. If we reach the 'finally' block and the flag was not unset, then it means an error was thrown. In that case we start a new postMessage callback, to finish calling any other pending callbacks if there is time. **why make this change?:** We need to make sure that an error thrown from one callback doesn't stop other callbacks from firing, but we also don't want to catch or swallow the error because we want engineers to still be able to log and debug errors. **test plan:** New tests added are passing, and we verified that they fail without this change. --- .../react-scheduler/src/ReactScheduler.js | 26 ++++++++++++++++--- 1 file changed, 22 insertions(+), 4 deletions(-) diff --git a/packages/react-scheduler/src/ReactScheduler.js b/packages/react-scheduler/src/ReactScheduler.js index ddcfa17a5663c..bfae5a263392e 100644 --- a/packages/react-scheduler/src/ReactScheduler.js +++ b/packages/react-scheduler/src/ReactScheduler.js @@ -129,6 +129,26 @@ if (!ExecutionEnvironment.canUseDOM) { }, }; + /** + * Handles the case where a callback errors: + * - don't catch the error, because this changes debugging behavior + * - do start a new postMessage callback, to call any remaining callbacks, + * - but only if there is an error, so there is not extra overhead. + */ + const callSafely = function(callback, arg) { + let finishedCalling = false; + try { + callback(arg); + finishedCalling = true; + } finally { + if (!finishedCalling) { + // an error must have been thrown + isIdleScheduled = true; + window.postMessage(messageKey, '*'); + } + } + }; + /** * Checks for timed out callbacks, runs them, and then checks again to see if * any more have timed out. @@ -163,8 +183,7 @@ if (!ExecutionEnvironment.canUseDOM) { // it has timed out! // call it const callback = currentCallbackConfig.scheduledCallback; - // TODO: error handling - callback(frameDeadlineObject); + callSafely(callback, frameDeadlineObject); // remove it from linked list cancelScheduledWork(currentCallbackConfig); } else { @@ -218,8 +237,7 @@ if (!ExecutionEnvironment.canUseDOM) { } frameDeadlineObject.didTimeout = false; const latestCallback = latestCallbackConfig.scheduledCallback; - // TODO: before using this outside of React we need to add error handling - latestCallback(frameDeadlineObject); + callSafely(latestCallback, frameDeadlineObject); currentTime = now(); } if (headOfPendingCallbacksLinkedList !== null) { From be9bda6776bd5fda8ee0194c0a497d93004ad44d Mon Sep 17 00:00:00 2001 From: Flarnie Marchan Date: Mon, 28 May 2018 10:33:50 -0700 Subject: [PATCH 04/13] Add more tests for error handling in scheduler **what is the change?:** Added tests for more situations where error handling may come up. **why make this change?:** To get additional protection against this being broken in the future. **test plan:** Ran new tests and verified that they fail when error handling fails. --- .../src/__tests__/ReactScheduler-test.js | 215 ++++++++++++++++-- 1 file changed, 202 insertions(+), 13 deletions(-) diff --git a/packages/react-scheduler/src/__tests__/ReactScheduler-test.js b/packages/react-scheduler/src/__tests__/ReactScheduler-test.js index e017f24f8b106..3dc5b98f522a4 100644 --- a/packages/react-scheduler/src/__tests__/ReactScheduler-test.js +++ b/packages/react-scheduler/src/__tests__/ReactScheduler-test.js @@ -293,8 +293,6 @@ describe('ReactScheduler', () => { describe('when there is some time left in the frame', () => { it('calls timed out callbacks and then any more pending callbacks, defers others if time runs out', () => { - // TODO first call timed out callbacks - // then any non-timed out callbacks if there is time const {scheduleWork} = ReactScheduler; startOfLatestFrame = 1000000000000; currentTime = startOfLatestFrame - 10; @@ -376,8 +374,22 @@ describe('ReactScheduler', () => { describe('when callbacks throw errors', () => { describe('when some callbacks throw', () => { + /** + * + + + * | rAF postMessage | + * | | + * | +---------------------+ | + * | | paint/layout | cbA() cbB() cbC() cbD() cbE() | + * | +---------------------+ ^ ^ | + * | | | | + * + | | + + * + + + * throw errors + * + * + */ it('still calls all callbacks within same frame', () => { - const {scheduleWork, cancelScheduledWork} = ReactScheduler; + const {scheduleWork} = ReactScheduler; const callbackLog = []; const callbackA = jest.fn(() => callbackLog.push('A')); const callbackB = jest.fn(() => { @@ -402,25 +414,202 @@ describe('ReactScheduler', () => { // calls all callbacks expect(callbackLog).toEqual(['A', 'B', 'C', 'D', 'E']); // errors should still get thrown - expect(postMessageErrors.length).toBe(2); - expect(postMessageErrors[0].message).toBe('B error'); - expect(postMessageErrors[1].message).toBe('D error'); + const postMessageErrorMessages = postMessageErrors.map(e => e.message); + expect(postMessageErrorMessages).toEqual(['B error', 'D error']); + catchPostMessageErrors = false; }); }); describe('when all scheduled callbacks throw', () => { + /** + * + + + * | rAF postMessage | + * | | + * | +---------------------+ | + * | | paint/layout | cbA() cbB() cbC() cbD() cbE() | + * | +---------------------+ ^ ^ ^ ^ ^ | + * | | | | | | | + * + | | | | | + + * | + + + + + * + all callbacks throw errors + * + * + */ it('still calls all callbacks within same frame', () => { - // TODO + const {scheduleWork} = ReactScheduler; + const callbackLog = []; + const callbackA = jest.fn(() => { + callbackLog.push('A'); + throw new Error('A error'); + }); + const callbackB = jest.fn(() => { + callbackLog.push('B'); + throw new Error('B error'); + }); + const callbackC = jest.fn(() => { + callbackLog.push('C'); + throw new Error('C error'); + }); + const callbackD = jest.fn(() => { + callbackLog.push('D'); + throw new Error('D error'); + }); + const callbackE = jest.fn(() => { + callbackLog.push('E'); + throw new Error('E error'); + }); + scheduleWork(callbackA); + scheduleWork(callbackB); + scheduleWork(callbackC); + scheduleWork(callbackD); + scheduleWork(callbackE); + // Initially doesn't call anything + expect(callbackLog).toEqual([]); + catchPostMessageErrors = true; + advanceOneFrame({timeLeftInFrame: 15}); // calls all callbacks - // does not catch errors - // errors happen at right time + expect(callbackLog).toEqual(['A', 'B', 'C', 'D', 'E']); + // errors should still get thrown + const postMessageErrorMessages = postMessageErrors.map(e => e.message); + expect(postMessageErrorMessages).toEqual([ + 'A error', + 'B error', + 'C error', + 'D error', + 'E error', + ]); + catchPostMessageErrors = false; }); }); describe('when callbacks throw over multiple frames', () => { + /** + * + * **Detail View of Frame 1** + * + * + + + * | rAF postMessage | + * | | + * | +---------------------+ | + * | | paint/layout | cbA() cbB() | ... Frame 2 + * | +---------------------+ ^ ^ | + * | | | | + * + + | + + * errors | + * + + * takes long time + * and pushes rest of + * callbacks into + * next frame -> + * + * + * + * **Overview of frames 1-4** + * + * + * + + + + + + * | | | | | + * | +--+ | +--+ | +--+ | +--+ | + * | +--+ A,B+-> +--+ C,D+-> +--+ E,F+-> +--+ G | + * + ^ + ^ + ^ + + + * | | | + * error error error + * + * + */ it('still calls all callbacks within same frame', () => { - // TODO - // calls all callbacks - // does not catch errors - // errors happen at right time + const {scheduleWork} = ReactScheduler; + startOfLatestFrame = 1000000000000; + currentTime = startOfLatestFrame - 10; + catchPostMessageErrors = true; + const callbackLog = []; + const callbackA = jest.fn(() => { + callbackLog.push('A'); + throw new Error('A error'); + }); + const callbackB = jest.fn(() => { + callbackLog.push('B'); + // time passes, causing us to run out of idle time + currentTime += 25; + }); + const callbackC = jest.fn(() => { + callbackLog.push('C'); + throw new Error('C error'); + }); + const callbackD = jest.fn(() => { + callbackLog.push('D'); + // time passes, causing us to run out of idle time + currentTime += 25; + }); + const callbackE = jest.fn(() => { + callbackLog.push('E'); + throw new Error('E error'); + }); + const callbackF = jest.fn(() => { + callbackLog.push('F'); + // time passes, causing us to run out of idle time + currentTime += 25; + }); + const callbackG = jest.fn(() => callbackLog.push('G')); + + scheduleWork(callbackA); + scheduleWork(callbackB); + scheduleWork(callbackC); + scheduleWork(callbackD); + scheduleWork(callbackE); + scheduleWork(callbackF); + scheduleWork(callbackG); + + // does nothing initially + expect(callbackLog).toEqual([]); + + // frame 1; + // callback A runs and throws, callback B takes up rest of frame + advanceOneFrame({timeLeftInFrame: 15}); // runs rAF and postMessage callbacks + + // calls A and B + expect(callbackLog).toEqual(['A', 'B']); + // error was thrown from A + let postMessageErrorMessages = postMessageErrors.map(e => e.message); + expect(postMessageErrorMessages).toEqual(['A error']); + + // frame 2; + // callback C runs and throws, callback D takes up rest of frame + advanceOneFrame({timeLeftInFrame: 15}); // runs rAF and postMessage callbacks + + // calls C and D + expect(callbackLog).toEqual(['A', 'B', 'C', 'D']); + // error was thrown from A + postMessageErrorMessages = postMessageErrors.map(e => e.message); + expect(postMessageErrorMessages).toEqual(['A error', 'C error']); + + // frame 3; + // callback E runs and throws, callback F takes up rest of frame + advanceOneFrame({timeLeftInFrame: 15}); // runs rAF and postMessage callbacks + + // calls E and F + expect(callbackLog).toEqual(['A', 'B', 'C', 'D', 'E', 'F']); + // error was thrown from A + postMessageErrorMessages = postMessageErrors.map(e => e.message); + expect(postMessageErrorMessages).toEqual([ + 'A error', + 'C error', + 'E error', + ]); + + // frame 4; + // callback G runs and it's the last one + advanceOneFrame({timeLeftInFrame: 15}); // runs rAF and postMessage callbacks + + // calls G + expect(callbackLog).toEqual(['A', 'B', 'C', 'D', 'E', 'F', 'G']); + // error was thrown from A + postMessageErrorMessages = postMessageErrors.map(e => e.message); + expect(postMessageErrorMessages).toEqual([ + 'A error', + 'C error', + 'E error', + ]); + + catchPostMessageErrors = true; }); }); }); From 0dde6a1c6d73d5db1bc4c1f08d5504efc5863ce0 Mon Sep 17 00:00:00 2001 From: Flarnie Marchan Date: Tue, 29 May 2018 13:22:08 -0700 Subject: [PATCH 05/13] callSafely -> callUnsafely --- packages/react-scheduler/src/ReactScheduler.js | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/packages/react-scheduler/src/ReactScheduler.js b/packages/react-scheduler/src/ReactScheduler.js index bfae5a263392e..bb4016a4a811d 100644 --- a/packages/react-scheduler/src/ReactScheduler.js +++ b/packages/react-scheduler/src/ReactScheduler.js @@ -135,7 +135,7 @@ if (!ExecutionEnvironment.canUseDOM) { * - do start a new postMessage callback, to call any remaining callbacks, * - but only if there is an error, so there is not extra overhead. */ - const callSafely = function(callback, arg) { + const callUnsafely = function(callback, arg) { let finishedCalling = false; try { callback(arg); @@ -183,7 +183,7 @@ if (!ExecutionEnvironment.canUseDOM) { // it has timed out! // call it const callback = currentCallbackConfig.scheduledCallback; - callSafely(callback, frameDeadlineObject); + callUnsafely(callback, frameDeadlineObject); // remove it from linked list cancelScheduledWork(currentCallbackConfig); } else { @@ -237,7 +237,7 @@ if (!ExecutionEnvironment.canUseDOM) { } frameDeadlineObject.didTimeout = false; const latestCallback = latestCallbackConfig.scheduledCallback; - callSafely(latestCallback, frameDeadlineObject); + callUnsafely(latestCallback, frameDeadlineObject); currentTime = now(); } if (headOfPendingCallbacksLinkedList !== null) { From 0743201e07b28dba2f4c830d6d14faa3a4b1e020 Mon Sep 17 00:00:00 2001 From: Flarnie Marchan Date: Tue, 29 May 2018 14:44:18 -0700 Subject: [PATCH 06/13] Fix bugs with error handling in schedule **what is the change?:** - ensure that we properly remove the callback from the linked list, even if it throws an error and is timed out. - ensure that you can call 'cancelScheduledWork' more than once and it is idempotent. **why make this change?:** To fix bugs :) **test plan:** Existing tests pass, and we'll add more tests in a follow up commit. --- .../react-scheduler/src/ReactScheduler.js | 64 +++++++++++-------- 1 file changed, 39 insertions(+), 25 deletions(-) diff --git a/packages/react-scheduler/src/ReactScheduler.js b/packages/react-scheduler/src/ReactScheduler.js index bb4016a4a811d..4f15b589208b3 100644 --- a/packages/react-scheduler/src/ReactScheduler.js +++ b/packages/react-scheduler/src/ReactScheduler.js @@ -37,6 +37,7 @@ type CallbackConfigType = {| timeoutTime: number, next: CallbackConfigType | null, // creating a linked list prev: CallbackConfigType | null, // creating a linked list + cancelled: boolean, |}; export type CallbackIdType = CallbackConfigType; @@ -135,12 +136,16 @@ if (!ExecutionEnvironment.canUseDOM) { * - do start a new postMessage callback, to call any remaining callbacks, * - but only if there is an error, so there is not extra overhead. */ - const callUnsafely = function(callback, arg) { + const callUnsafely = function(callbackConfig: CallbackConfigType, arg: Deadline) { + const callback = callbackConfig.scheduledCallback; let finishedCalling = false; try { callback(arg); finishedCalling = true; } finally { + // always remove it from linked list + cancelScheduledWork(callbackConfig); + if (!finishedCalling) { // an error must have been thrown isIdleScheduled = true; @@ -172,31 +177,42 @@ if (!ExecutionEnvironment.canUseDOM) { // We know that none of them have timed out yet. return; } - nextSoonestTimeoutTime = -1; // we will reset it below - - // keep checking until we don't find any more timed out callbacks - frameDeadlineObject.didTimeout = true; + // NOTE: we intentionally wait to update the nextSoonestTimeoutTime until + // after successfully calling any timed out callbacks. + // If a timed out callback throws an error, we could get stuck in a state + // where the nextSoonestTimeoutTime was set wrong. + let updatedNextSoonestTimeoutTime = -1; // we will update nextSoonestTimeoutTime below + const timedOutCallbacks = []; + + // iterate once to find timed out callbacks and find nextSoonestTimeoutTime let currentCallbackConfig = headOfPendingCallbacksLinkedList; while (currentCallbackConfig !== null) { const timeoutTime = currentCallbackConfig.timeoutTime; if (timeoutTime !== -1 && timeoutTime <= currentTime) { // it has timed out! - // call it - const callback = currentCallbackConfig.scheduledCallback; - callUnsafely(callback, frameDeadlineObject); - // remove it from linked list - cancelScheduledWork(currentCallbackConfig); + timedOutCallbacks.push(currentCallbackConfig); } else { if ( timeoutTime !== -1 && - (nextSoonestTimeoutTime === -1 || - timeoutTime < nextSoonestTimeoutTime) + (updatedNextSoonestTimeoutTime === -1 || + timeoutTime < updatedNextSoonestTimeoutTime) ) { - nextSoonestTimeoutTime = timeoutTime; + updatedNextSoonestTimeoutTime = timeoutTime; } } currentCallbackConfig = currentCallbackConfig.next; } + + if (timedOutCallbacks.length > 0) { + frameDeadlineObject.didTimeout = true; + for (let i = 0, len = timedOutCallbacks.length; i < len; i++) { + callUnsafely(timedOutCallbacks[i], frameDeadlineObject); + } + } + + // NOTE: we intentionally wait to update the nextSoonestTimeoutTime until + // after successfully calling any timed out callbacks. + nextSoonestTimeoutTime = updatedNextSoonestTimeoutTime; }; // We use the postMessage trick to defer idle work until after the repaint. @@ -225,19 +241,9 @@ if (!ExecutionEnvironment.canUseDOM) { headOfPendingCallbacksLinkedList !== null ) { const latestCallbackConfig = headOfPendingCallbacksLinkedList; - // move head of list to next callback - headOfPendingCallbacksLinkedList = latestCallbackConfig.next; - if (headOfPendingCallbacksLinkedList !== null) { - headOfPendingCallbacksLinkedList.prev = null; - } else { - // if headOfPendingCallbacksLinkedList is null, - // then the list must be empty. - // make sure we set the tail to null as well. - tailOfPendingCallbacksLinkedList = null; - } frameDeadlineObject.didTimeout = false; - const latestCallback = latestCallbackConfig.scheduledCallback; - callUnsafely(latestCallback, frameDeadlineObject); + // callUnsafely will remove it from the head of the linked list + callUnsafely(latestCallbackConfig, frameDeadlineObject); currentTime = now(); } if (headOfPendingCallbacksLinkedList !== null) { @@ -303,6 +309,7 @@ if (!ExecutionEnvironment.canUseDOM) { timeoutTime, prev: null, next: null, + cancelled: false, }; if (headOfPendingCallbacksLinkedList === null) { // Make this callback the head and tail of our list @@ -333,6 +340,13 @@ if (!ExecutionEnvironment.canUseDOM) { cancelScheduledWork = function( callbackConfig: CallbackIdType /* CallbackConfigType */, ) { + if (callbackConfig.cancelled === true) { + return; + } + + // cancelScheduledWork should be idempotent, a no-op after first call. + callbackConfig.cancelled = true; + /** * There are four possible cases: * - Head/nodeToRemove/Tail -> null From 0212f826c2d9543c48122bf6431c00100819efac Mon Sep 17 00:00:00 2001 From: Flarnie Marchan Date: Tue, 29 May 2018 15:34:55 -0700 Subject: [PATCH 07/13] Unit tests for error handling with timed out callbacks **what is the change?:** More unit tests, to cover behavior which we missed; error handling of timed out callbacks. **why make this change?:** To protect the future!~ **test plan:** Run the new tests. --- .../src/__tests__/ReactScheduler-test.js | 107 ++++++++++++++++++ 1 file changed, 107 insertions(+) diff --git a/packages/react-scheduler/src/__tests__/ReactScheduler-test.js b/packages/react-scheduler/src/__tests__/ReactScheduler-test.js index 3dc5b98f522a4..f1a9ccddbf8c2 100644 --- a/packages/react-scheduler/src/__tests__/ReactScheduler-test.js +++ b/packages/react-scheduler/src/__tests__/ReactScheduler-test.js @@ -418,6 +418,52 @@ describe('ReactScheduler', () => { expect(postMessageErrorMessages).toEqual(['B error', 'D error']); catchPostMessageErrors = false; }); + + /** + * timed out + * + + +--+ + * + rAF postMessage | | | + + * | | | | | + * | +---------------------+ v v v | + * | | paint/layout | cbA() cbB() cbC() cbD() cbE() | + * | +---------------------+ ^ ^ | + * | | | | + * + | | + + * + + + * throw errors + * + * + */ + it('and with some timed out callbacks, still calls all callbacks within same frame', () => { + const {scheduleWork} = ReactScheduler; + const callbackLog = []; + const callbackA = jest.fn(() => { + callbackLog.push('A'); + throw new Error('A error'); + }); + const callbackB = jest.fn(() => callbackLog.push('B')); + const callbackC = jest.fn(() => callbackLog.push('C')); + const callbackD = jest.fn(() => { + callbackLog.push('D'); + throw new Error('D error'); + }); + const callbackE = jest.fn(() => callbackLog.push('E')); + scheduleWork(callbackA); + scheduleWork(callbackB); + scheduleWork(callbackC, {timeout: 2}); // times out fast + scheduleWork(callbackD, {timeout: 2}); // times out fast + scheduleWork(callbackE, {timeout: 2}); // times out fast + // Initially doesn't call anything + expect(callbackLog).toEqual([]); + catchPostMessageErrors = true; + advanceOneFrame({timeLeftInFrame: 15}); + // calls all callbacks; calls timed out ones first + expect(callbackLog).toEqual(['C', 'D', 'E', 'A', 'B']); + // errors should still get thrown + const postMessageErrorMessages = postMessageErrors.map(e => e.message); + expect(postMessageErrorMessages).toEqual(['D error', 'A error']); + catchPostMessageErrors = false; + }); }); describe('when all scheduled callbacks throw', () => { /** @@ -479,6 +525,67 @@ describe('ReactScheduler', () => { ]); catchPostMessageErrors = false; }); + + /** + * postMessage + * + + + * | rAF all callbacks time out | + * | | + * | +---------------------+ | + * | | paint/layout | cbA() cbB() cbC() cbD() cbE() | + * | +---------------------+ ^ ^ ^ ^ ^ | + * | | | | | | | + * + | | | | | + + * | + + + + + * + all callbacks throw errors + * + * + */ + it('and with all timed out callbacks, still calls all callbacks within same frame', () => { + const {scheduleWork} = ReactScheduler; + const callbackLog = []; + const callbackA = jest.fn(() => { + callbackLog.push('A'); + throw new Error('A error'); + }); + const callbackB = jest.fn(() => { + callbackLog.push('B'); + throw new Error('B error'); + }); + const callbackC = jest.fn(() => { + callbackLog.push('C'); + throw new Error('C error'); + }); + const callbackD = jest.fn(() => { + callbackLog.push('D'); + throw new Error('D error'); + }); + const callbackE = jest.fn(() => { + callbackLog.push('E'); + throw new Error('E error'); + }); + scheduleWork(callbackA, {timeout: 2}); // times out fast + scheduleWork(callbackB, {timeout: 2}); // times out fast + scheduleWork(callbackC, {timeout: 2}); // times out fast + scheduleWork(callbackD, {timeout: 2}); // times out fast + scheduleWork(callbackE, {timeout: 2}); // times out fast + // Initially doesn't call anything + expect(callbackLog).toEqual([]); + catchPostMessageErrors = true; + advanceOneFrame({timeLeftInFrame: 15}); + // calls all callbacks + expect(callbackLog).toEqual(['A', 'B', 'C', 'D', 'E']); + // errors should still get thrown + const postMessageErrorMessages = postMessageErrors.map(e => e.message); + expect(postMessageErrorMessages).toEqual([ + 'A error', + 'B error', + 'C error', + 'D error', + 'E error', + ]); + catchPostMessageErrors = false; + }); }); describe('when callbacks throw over multiple frames', () => { /** From 102d7c6f39d43504c966c8dab6986fba548259e6 Mon Sep 17 00:00:00 2001 From: Flarnie Marchan Date: Tue, 29 May 2018 16:01:30 -0700 Subject: [PATCH 08/13] Adds fixture to test timed out callbacks with scheduler **what is the change?:** See title In the other error handling fixture we compare 'scheduleWork' error handling to 'requestAnimationFrame' and try to get as close as possible. There is no 'timing out' feature with 'requestAnimationFrame' but effectively the 'timing out' feature changes the order in which things are called. So we just changed the order in the 'requestAnimationFrame' version and that works well for illustrating the behavior we expect in the 'scheduleWork' test. **why make this change?:** We need more test coverage of timed out callbacks. **test plan:** Executed the fixture manually in Firefox and Chrome. Results looked good. --- fixtures/schedule/index.html | 83 ++++++++++++++++++++++++++++++++++++ 1 file changed, 83 insertions(+) diff --git a/fixtures/schedule/index.html b/fixtures/schedule/index.html index 59faafcc167d9..f2a6073086455 100644 --- a/fixtures/schedule/index.html +++ b/fixtures/schedule/index.html @@ -74,6 +74,11 @@

    Tests:

    IMPORTANT: Open the console when you run this! Inspect the logs there!

    +
  • +

    When some callbacks throw errors and some also time out, still calls them all within the same frame

    +

    IMPORTANT: Open the console when you run this! Inspect the logs there!

    + +
    • @@ -381,6 +386,84 @@

    Tests:

    console.log('scheduled cbE'); }; } + +function runTestSix() { + // Test 6 + // When some callbacks throw errors, still calls them all within the same frame + const cbA = (x) => { + console.log('cbA called with argument of ' + JSON.stringify(x)); + console.log('cbA is about to throw an error!'); + throw new Error('error A'); + } + const cbB = (x) => { + console.log('cbB called with argument of ' + JSON.stringify(x)); + } + const cbC = (x) => { + console.log('cbC called with argument of ' + JSON.stringify(x)); + } + const cbD = (x) => { + console.log('cbD called with argument of ' + JSON.stringify(x)); + console.log('cbD is about to throw an error!'); + throw new Error('error D'); + } + const cbE = (x) => { + console.log('cbE called with argument of ' + JSON.stringify(x)); + console.log('This was the last callback! ------------------'); + } + + console.log('We are aiming to roughly emulate the way ' + + '`requestAnimationFrame` handles errors from callbacks.'); + + console.log('about to run the simulation of what it should look like...:'); + + requestAnimationFrame(() => { + console.log('frame 1 started'); + requestAnimationFrame(() => { + console.log('frame 2 started'); + requestAnimationFrame(() => { + console.log('frame 3 started... we stop counting now.'); + console.log('about to wait a moment and start this again but ' + + 'with the scheduler instead of requestAnimationFrame'); + setTimeout(runSchedulerCode, 1000); + }); + }); + }); + requestAnimationFrame(cbC); + console.log('scheduled cbC first; simulating timing out'); + requestAnimationFrame(cbD); // will throw error + console.log('scheduled cbD first; simulating timing out'); + requestAnimationFrame(cbE); + console.log('scheduled cbE first; simulating timing out'); + requestAnimationFrame(cbA); + console.log('scheduled cbA'); // will throw error + requestAnimationFrame(cbB); + console.log('scheduled cbB'); + + + function runSchedulerCode() { + console.log('-------------------------------------------------------------'); + console.log('now lets see what it looks like using the scheduler...:'); + requestAnimationFrame(() => { + console.log('frame 1 started'); + requestAnimationFrame(() => { + console.log('frame 2 started'); + requestAnimationFrame(() => { + console.log('frame 3 started... we stop counting now.'); + }); + }); + }); + scheduleWork(cbA); + console.log('scheduled cbA'); + scheduleWork(cbB); // will throw error + console.log('scheduled cbB'); + scheduleWork(cbC, {timeout: 1}); + console.log('scheduled cbC'); + scheduleWork(cbD, {timeout: 1}); // will throw error + console.log('scheduled cbD'); + scheduleWork(cbE, {timeout: 1}); + console.log('scheduled cbE'); + }; +} From 5c0742a91c5643f0a0f0ebd411d290d96bd06ed2 Mon Sep 17 00:00:00 2001 From: Flarnie Marchan Date: Tue, 29 May 2018 17:59:55 -0700 Subject: [PATCH 09/13] fix rebase problems --- packages/react-scheduler/src/ReactScheduler.js | 2 ++ 1 file changed, 2 insertions(+) diff --git a/packages/react-scheduler/src/ReactScheduler.js b/packages/react-scheduler/src/ReactScheduler.js index 4f15b589208b3..aab7c1f30659a 100644 --- a/packages/react-scheduler/src/ReactScheduler.js +++ b/packages/react-scheduler/src/ReactScheduler.js @@ -86,6 +86,7 @@ if (!ExecutionEnvironment.canUseDOM) { timeoutTime: 0, next: null, prev: null, + cancelled: false, }; const timeoutId = localSetTimeout(() => { callback({ @@ -96,6 +97,7 @@ if (!ExecutionEnvironment.canUseDOM) { }); }); timeoutIds.set(callback, timeoutId); + callbackConfig.cancelled = true; return callbackConfig; }; cancelScheduledWork = function(callbackId: CallbackIdType) { From 8759d56a3cef87b30c70a12575a5e352d7999452 Mon Sep 17 00:00:00 2001 From: Flarnie Marchan Date: Tue, 29 May 2018 18:08:44 -0700 Subject: [PATCH 10/13] make fixture compensate for chrome JS speed --- fixtures/schedule/index.html | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/fixtures/schedule/index.html b/fixtures/schedule/index.html index f2a6073086455..d5b243a3c2f84 100644 --- a/fixtures/schedule/index.html +++ b/fixtures/schedule/index.html @@ -293,7 +293,7 @@

    Tests:

    updateTestResult(4, 'scheduled cbA'); scheduleWork(cbB, {timeout: 100}); // times out later updateTestResult(4, 'scheduled cbB'); - scheduleWork(cbC, {timeout: 2}); // will time out fast + scheduleWork(cbC, {timeout: 1}); // will time out fast updateTestResult(4, 'scheduled cbC'); scheduleWork(cbD); // won't time out updateTestResult(4, 'scheduled cbD'); From 534a48890a9e81bf66a0c9b58f2c0eb5cfbcd043 Mon Sep 17 00:00:00 2001 From: Flarnie Marchan Date: Wed, 30 May 2018 10:03:18 -0700 Subject: [PATCH 11/13] ran prettier --- packages/react-scheduler/src/ReactScheduler.js | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/packages/react-scheduler/src/ReactScheduler.js b/packages/react-scheduler/src/ReactScheduler.js index aab7c1f30659a..339aca7f8cdcd 100644 --- a/packages/react-scheduler/src/ReactScheduler.js +++ b/packages/react-scheduler/src/ReactScheduler.js @@ -138,7 +138,10 @@ if (!ExecutionEnvironment.canUseDOM) { * - do start a new postMessage callback, to call any remaining callbacks, * - but only if there is an error, so there is not extra overhead. */ - const callUnsafely = function(callbackConfig: CallbackConfigType, arg: Deadline) { + const callUnsafely = function( + callbackConfig: CallbackConfigType, + arg: Deadline, + ) { const callback = callbackConfig.scheduledCallback; let finishedCalling = false; try { From 1ae920a9e7603d8a0b2bbe4d10e10c868e6ad100 Mon Sep 17 00:00:00 2001 From: Flarnie Marchan Date: Wed, 30 May 2018 13:21:45 -0700 Subject: [PATCH 12/13] Remove 'cancelled' flag on callbackConfig in scheduler, add test **what is the change?:** - Instead of using a 'cancelled' flag on the callbackConfig, it's easier to just check the state of the callbackConfig inside 'cancelScheduledWork' to determine if it's already been cancelled. That way we don't have to remember to set the 'cancelled' flag every time we call a callback or cancel it. One less thing to remember. - We added a test for calling 'cancelScheduledWork' more than once, which would have failed before. Thanks @acdlite for suggesting this in code review. :) **why make this change?:** To increase stability of the schedule module, increase test coverage. **test plan:** Existing tests pass and we added a new test to cover this behavior. --- .../react-scheduler/src/ReactScheduler.js | 16 +++++++------- .../src/__tests__/ReactScheduler-test.js | 22 +++++++++++++++++++ 2 files changed, 30 insertions(+), 8 deletions(-) diff --git a/packages/react-scheduler/src/ReactScheduler.js b/packages/react-scheduler/src/ReactScheduler.js index 339aca7f8cdcd..cd21d1c3fcd00 100644 --- a/packages/react-scheduler/src/ReactScheduler.js +++ b/packages/react-scheduler/src/ReactScheduler.js @@ -37,7 +37,6 @@ type CallbackConfigType = {| timeoutTime: number, next: CallbackConfigType | null, // creating a linked list prev: CallbackConfigType | null, // creating a linked list - cancelled: boolean, |}; export type CallbackIdType = CallbackConfigType; @@ -86,7 +85,6 @@ if (!ExecutionEnvironment.canUseDOM) { timeoutTime: 0, next: null, prev: null, - cancelled: false, }; const timeoutId = localSetTimeout(() => { callback({ @@ -97,7 +95,6 @@ if (!ExecutionEnvironment.canUseDOM) { }); }); timeoutIds.set(callback, timeoutId); - callbackConfig.cancelled = true; return callbackConfig; }; cancelScheduledWork = function(callbackId: CallbackIdType) { @@ -314,7 +311,6 @@ if (!ExecutionEnvironment.canUseDOM) { timeoutTime, prev: null, next: null, - cancelled: false, }; if (headOfPendingCallbacksLinkedList === null) { // Make this callback the head and tail of our list @@ -345,13 +341,15 @@ if (!ExecutionEnvironment.canUseDOM) { cancelScheduledWork = function( callbackConfig: CallbackIdType /* CallbackConfigType */, ) { - if (callbackConfig.cancelled === true) { + if ( + callbackConfig.prev === null && + headOfPendingCallbacksLinkedList !== callbackConfig + ) { + // this callbackConfig has already been cancelled. + // cancelScheduledWork should be idempotent, a no-op after first call. return; } - // cancelScheduledWork should be idempotent, a no-op after first call. - callbackConfig.cancelled = true; - /** * There are four possible cases: * - Head/nodeToRemove/Tail -> null @@ -368,6 +366,8 @@ if (!ExecutionEnvironment.canUseDOM) { */ const next = callbackConfig.next; const prev = callbackConfig.prev; + callbackConfig.next = null; + callbackConfig.prev = null; if (next !== null) { // we have a next diff --git a/packages/react-scheduler/src/__tests__/ReactScheduler-test.js b/packages/react-scheduler/src/__tests__/ReactScheduler-test.js index f1a9ccddbf8c2..a5f81ba93148e 100644 --- a/packages/react-scheduler/src/__tests__/ReactScheduler-test.js +++ b/packages/react-scheduler/src/__tests__/ReactScheduler-test.js @@ -351,6 +351,28 @@ describe('ReactScheduler', () => { }); describe('with multiple callbacks', () => { + it('when called more than once', () => { + const {scheduleWork, cancelScheduledWork} = ReactScheduler; + const callbackLog = []; + let callbackBId; + const callbackA = jest.fn(() => callbackLog.push('A')); + const callbackB = jest.fn(() => callbackLog.push('B')); + const callbackC = jest.fn(() => callbackLog.push('C')); + scheduleWork(callbackA); + const callbackId = scheduleWork(callbackB); + scheduleWork(callbackC); + cancelScheduledWork(callbackId); + cancelScheduledWork(callbackId); + cancelScheduledWork(callbackId); + // Initially doesn't call anything + expect(callbackLog).toEqual([]); + advanceOneFrame({timeLeftInFrame: 15}); + + // Should still call A and C + expect(callbackLog).toEqual(['A', 'C']); + expect(callbackB).toHaveBeenCalledTimes(0); + }); + it('when one callback cancels the next one', () => { const {scheduleWork, cancelScheduledWork} = ReactScheduler; const callbackLog = []; From a7b13aa8a4fd48251b864359a2a396b814198a2e Mon Sep 17 00:00:00 2001 From: Flarnie Marchan Date: Wed, 30 May 2018 13:46:32 -0700 Subject: [PATCH 13/13] fix typo --- packages/react-scheduler/src/__tests__/ReactScheduler-test.js | 1 - 1 file changed, 1 deletion(-) diff --git a/packages/react-scheduler/src/__tests__/ReactScheduler-test.js b/packages/react-scheduler/src/__tests__/ReactScheduler-test.js index a5f81ba93148e..7cc6a9f279332 100644 --- a/packages/react-scheduler/src/__tests__/ReactScheduler-test.js +++ b/packages/react-scheduler/src/__tests__/ReactScheduler-test.js @@ -354,7 +354,6 @@ describe('ReactScheduler', () => { it('when called more than once', () => { const {scheduleWork, cancelScheduledWork} = ReactScheduler; const callbackLog = []; - let callbackBId; const callbackA = jest.fn(() => callbackLog.push('A')); const callbackB = jest.fn(() => callbackLog.push('B')); const callbackC = jest.fn(() => callbackLog.push('C'));