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

Fix race condition with clearing Onyx and the SyncQueue #220

Merged
merged 23 commits into from
Jan 12, 2023
Merged
Show file tree
Hide file tree
Changes from 17 commits
Commits
Show all changes
23 commits
Select commit Hold shift + click to select a range
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
13 changes: 12 additions & 1 deletion lib/Onyx.js
Original file line number Diff line number Diff line change
Expand Up @@ -1050,6 +1050,13 @@ function clear(keysToPreserve = []) {
const keyValuesToReset = [];
const defaultKeys = _.keys(defaultKeyStates);

// Get all the values for the keys that need to be preserved. These key/value pairs will be set
// in Onyx after the database is cleared().
const keyValuesToPreserve = _.reduce(keysToPreserve, (finalArray, keyToPreserve) => {
finalArray.push([keyToPreserve, cache.getValue(keyToPreserve)]);
return finalArray;
}, []);

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Instead of using _.reduce it's simpler to just use _.map

const keyValuesToPreserve = _.map(keysToPreserve, key => [key, cache.getValue(key)]);

We remap every key we want to preserve to a key-value pair, in the end we still end up with the same list of key-value pairs

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agreed, makes things much easier to read.

// The only keys that should not be cleared are:
// 1. Anything specifically passed in keysToPreserve (because some keys like language preferences, offline
// status, or activeClients need to remain in Onyx even when signed out)
Expand Down Expand Up @@ -1102,7 +1109,11 @@ function clear(keysToPreserve = []) {
notifyCollectionSubscribersOnNextTick(key, value);
});

return Storage.multiSet(keyValuesToReset);
// Call clear() and make sure that the default key/values and the key/values from the parameter
// are preserved in storage. This makes sure to always leave storage in a state that contains
// all the default values and any additional values that we want to remain after the database is cleared.
return Storage.clear()
.then(() => Storage.multiSet(defaultKeyValuePairs.concat(keyValuesToPreserve)));
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why do we use .concat instead of spreading (like we do with props)?

Storage.multiSet([...defaultKeyValuePairs, ...keyValuesToPreserve])

both .concat and spreading result in a new array

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I try to stay away from using the spread operator on code that needs to be super performant. Babel will transpile to something that's pretty slow. It's probably not really necessary here, but it's the habit I've been in.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This might be true for objects, if some of the keys are destructed and the rest are ...rest, but for Arrays, babel works like this

Code

const arr3 = [...arr1, ...arr2];

Transpiled

var arr3 = [].concat(arr1, arr2);

You can check that out in the live https://babeljs.io/repl though I think babel stopped transpiling the spread operator as it is supported natively by all alive browsers: https://caniuse.com/?search=spread%20operator

I think if we tell webpack/babel to ignore IE11 it would just stop transpiling the spread operator

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, that would be great to stop transpiling it altogether. We are not interested in supporting IE11. I didn't know that about arrays. I'll go ahead and switch this to a spread operator.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, that would be great to stop transpiling it altogether. We are not interested in supporting IE11. I didn't know that about arrays. I'll go ahead and switch this to a spread operator.

Here's a small PR regarding that: #226

});
}

Expand Down
8 changes: 8 additions & 0 deletions lib/SyncQueue.js
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,14 @@ export default class SyncQueue {
this.run = run;
}

/**
* Stop the queue from being processed and clear out any existing tasks
*/
abort() {
this.queue = [];
this.isProcessing = false;
}

process() {
if (this.isProcessing || this.queue.length === 0) {
return;
Expand Down
12 changes: 9 additions & 3 deletions lib/storage/WebStorage.js
Original file line number Diff line number Diff line change
@@ -1,3 +1,8 @@
/**
* This file is here to wrap LocalForage with a layer that provides data-changed events like the ones that exist
* when using LocalStorage APIs in the browser. These events are great because multiple tabs can listen for when
* data changes and then stay up-to-date with everything happening in Onyx.
*/
import _ from 'underscore';
import Storage from './providers/LocalForage';

Expand Down Expand Up @@ -27,10 +32,11 @@ const webStorage = {
.then(() => raiseStorageSyncEvent(key));

// If we just call Storage.clear other tabs will have no idea which keys were available previously
// so that they can call keysChanged for them. That's why we iterate and remove keys one by one
// so that they can call keysChanged for them. That's why we iterate over every key and raise a storage sync
// event for each one
this.clear = () => Storage.getAllKeys()
.then(keys => _.map(keys, key => this.removeItem(key)))
.then(tasks => Promise.all(tasks));
.then(allKeys => _.each(allKeys, raiseStorageSyncEvent))
.then(() => Storage.clear());

// This listener will only be triggered by events coming from other tabs
global.addEventListener('storage', (event) => {
Expand Down
2 changes: 1 addition & 1 deletion lib/storage/providers/AsyncStorage.js
Original file line number Diff line number Diff line change
Expand Up @@ -74,7 +74,7 @@ const provider = {
removeItem: AsyncStorage.removeItem,

/**
* Clear absolutely everything from storage
* Clear everything from storage
* @returns {Promise<void>}
*/
clear: AsyncStorage.clear,
Expand Down
7 changes: 5 additions & 2 deletions lib/storage/providers/LocalForage.js
Original file line number Diff line number Diff line change
Expand Up @@ -75,10 +75,13 @@ const provider = {
},

/**
* Clear absolutely everything from storage
* Clear everything from storage and also stops the SyncQueue from adding anything more to storage
* @returns {Promise<void>}
*/
clear: localforage.clear,
clear() {
this.setItemQueue.abort();
return localforage.clear();
},

/**
* Returns all keys available in storage
Expand Down
25 changes: 1 addition & 24 deletions tests/unit/onyxClearNativeStorageTest.js
Original file line number Diff line number Diff line change
Expand Up @@ -43,28 +43,6 @@ describe('Set data while storage is clearing', () => {
return Onyx.clear();
});

it('should persist the value of Onyx.merge when called between the cache and storage clearing', () => {
expect.assertions(3);

// Given that Onyx is completely clear
// When Onyx.clear() is called
Onyx.clear();

// When merge is called between the cache and storage clearing, on a key with a default key state
Onyx.merge(ONYX_KEYS.DEFAULT_KEY, MERGED_VALUE);
return waitForPromisesToResolve()
.then(() => {
// Then the value in Onyx, the cache, and the storage is the merged value
expect(onyxValue).toBe(MERGED_VALUE);
const cachedValue = cache.getValue(ONYX_KEYS.DEFAULT_KEY);
expect(cachedValue).toBe(MERGED_VALUE);

// Use parseInt to convert the string value from the storage mock back to an integer
return Storage.getItem(ONYX_KEYS.DEFAULT_KEY)
.then(storedValue => expect(parseInt(storedValue, 10)).toBe(MERGED_VALUE));
});
});

it('should replace the value of Onyx.set with the default key state in the cache', () => {
expect.assertions(3);

Expand Down Expand Up @@ -120,8 +98,7 @@ describe('Set data while storage is clearing', () => {
.then(() => {
// Then the value of the preserved key is also still set in both the cache and storage
expect(regularKeyOnyxValue).toBe(SET_VALUE);
const regularKeyCachedValue = cache.getValue(ONYX_KEYS.REGULAR_KEY);
expect(regularKeyCachedValue).toBe(SET_VALUE);
expect(cache.getValue(ONYX_KEYS.REGULAR_KEY)).toBe(SET_VALUE);
return Storage.getItem(ONYX_KEYS.REGULAR_KEY)
.then(storedValue => expect(parseInt(storedValue, 10)).toBe(SET_VALUE));
});
Expand Down
20 changes: 0 additions & 20 deletions tests/unit/onyxClearWebStorageTest.js
Original file line number Diff line number Diff line change
Expand Up @@ -50,26 +50,6 @@ describe('Set data while storage is clearing', () => {
return Onyx.clear();
});

it('should persist the value of Onyx.merge when called between the cache and storage clearing', () => {
Copy link
Collaborator Author

@tgolen tgolen Jan 5, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@neil-marcellini I saw you added these tests, and as far as I can tell, they are no longer necessary because the behavior of clear() has been changed. Can you please take a look at this and make sure that I am not introducing regressions that I'm not aware of?

Basically, the way I read this is that the problem only happened because we were done something like this:

Onyx.clear();
Onyx.set(keyValuesToPreserve);

My PR here changes this behavior so that no one should ever be doing that anymore. It should now become:

Onyx.clear(keysToPreserve);

So that's why I think it's OK to remove these tests since they no longer test a valid use case.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These tests make sure that the following flow works for keys with a default key state, like the session.

  1. Sign out the user with Onyx.clear()
  2. Sign in a new user (before Onyx.clear finishes), and merge new data on the session key
  3. Ensure that Onyx.clear doesn't set a default key state on the session key and wipe out the value saved in step 2.

I think it might still be valuable to test calling Onyx.clear() and then Onyx.merge on a key with a default state.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

OK, thanks! My point is that this...

Sign in a new user (before Onyx.clear finishes),

...isn't possible to do. Onyx.clear() takes less that 200ms to complete now on an account with 4000 reports, as well as we are no longer optimistically redirecting to the sign-on page. We are waiting until Onyx.clear() is finished before the redirect happens.

If there is a valid use case of calling clear -> merge, I could see having a test, but I don't know if any time that would ever be a valid case. Do you have a specific one in mind? If that does exist in the code, it should be rewritten like I showed above.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Onyx.clear() takes less that 200ms to complete now on an account with 4000 reports,

Ah ok nice. If that's the case for all platforms then I agree that we don't need this test any more 👍.

we are no longer optimistically redirecting to the sign-on page. We are waiting until Onyx.clear() is finished before the redirect happens.

I don't think we are based on the code here. As soon as the session key is cleared we are signed out, and that can happen before Onyx finishes clearing.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As soon as the session key is cleared we are signed out, and that can happen before Onyx finishes clearing.

Ah yes, you're technically right. However, the session key is removed at the same time as all other keys now (because it is once again using LocalForage.clear() under the hood rather than using a multiSet() or multiRemove()).

expect.assertions(3);

// Given that Onyx is completely clear
// When Onyx.clear() is called
Onyx.clear();

// When merge is called between the cache and storage clearing, on a key with a default key state
Onyx.merge(ONYX_KEYS.DEFAULT_KEY, MERGED_VALUE);
return waitForPromisesToResolve()
.then(() => {
// Then the value in Onyx, the cache, and the storage is the merged value
expect(onyxValue).toBe(MERGED_VALUE);
const cachedValue = cache.getValue(ONYX_KEYS.DEFAULT_KEY);
expect(cachedValue).toBe(MERGED_VALUE);
const storedValue = Storage.getItem(ONYX_KEYS.DEFAULT_KEY);
return expect(storedValue).resolves.toBe(MERGED_VALUE);
});
});

it('should replace the value of Onyx.set with the default key state in the cache', () => {
expect.assertions(3);

Expand Down
8 changes: 2 additions & 6 deletions tests/unit/onyxMultiMergeWebStorageTest.js
Original file line number Diff line number Diff line change
Expand Up @@ -141,12 +141,8 @@ describe('Onyx.mergeCollection() amd WebStorage', () => {
});

it('setItem() and multiMerge()', () => {
// When Onyx is cleared, since it uses multiSet() to clear out all the values, the keys will remain with null for all the values
expect(localforageMock.storageMap).toEqual({
test_1: null,
test_2: null,
test_3: null,
});
// Onyx should be empty after clear() is called
expect(localforageMock.storageMap).toEqual({});

// Given no previous data and several calls to setItem and call to mergeCollection to update a given key

Expand Down
19 changes: 19 additions & 0 deletions tests/unit/storage/providers/LocalForageProviderTest.js
Original file line number Diff line number Diff line change
Expand Up @@ -104,4 +104,23 @@ describe('storage/providers/LocalForage', () => {
});
});
});

it('clear', () => {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@kidroca - @tgolen asked me to help with implementing a test like what you described here - just want to double-check check I'm capturing this right since I'm a bit new to jest and it's "fake time"...

Copy link
Contributor

@kidroca kidroca Jan 5, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Almost there.
What you've got right now won't resolve the promise after 1000ms
Also setItemTimedOut should be a function - right now it's just the result of a setTimeout() call - a numeric ID
(Probably the reason for the TypeError: callback is not a function errors)

I think you just need to change the mock like so:

// Given an implementation of setItem that resolves after 1000ms
localForage.setItem = jest.fn(() => new Promise(
  (resolve) =>  setTimeout(resolve, 1000))
);
  1. setItem should return a promise
  2. we make the returned promise resolve after 1000ms - it would only resolve after we advance timers

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah hm... in actuality, we want to measure how many times the promise is resolved then, right? But there's no other way to do that other than having a callback get called when the promise resolves?

So my thought was to do something like this instead:

    it('clear', () => {
        // Use fake timers, so we can manipulate time at our will for this test.
        jest.useFakeTimers();

        // Given a mocked implementation of setItem that calls a callback function after 1000ms
        const callback = jest.fn();
        localforage.setItem = jest.fn(() => new Promise(resolve => setTimeout(resolve, 1000)).then(callback));

        // When we call setItem 5 times, but then call clear after only 1000ms
        for (let i = 0; i < 5; i++) {
            StorageProvider.setItem(`key${i}`, `value${i}`);
        }

        // We should not have called the mocked callback for setItem yet because we have not advanced the timer.
        expect(callback).not.toHaveBeenCalled();

        jest.advanceTimersByTime(1000);
        StorageProvider.clear();
        jest.advanceTimersByTime(4000);

        // The mocked callback for setItem should only have been called once since all other calls were aborted when we called clear()
        expect(callback).toHaveBeenCalledTimes(1);
    });

However I'm seeing that's not quite working as I would expect 🤔

Error: expect(jest.fn()).toHaveBeenCalledTimes(expected)

Expected number of calls: 1
Received number of calls: 0

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Also, I noticed you had the comment here noting that "fake timers cause promises to hang" - wonder if that might be the same reason for the issue I'm seeing?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(Btw, just tested this again using real timers and I don't see this problem. So I do have a suspicion this is somehow related to FakeTimers)

Copy link
Contributor

@kidroca kidroca Jan 6, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah hm... in actuality, we want to measure how many times the promise is resolved then, right?

I guess it might look like that from a certain point of view, but it's not necessary

If we make 5 StorageProvider.setItem calls they should be queued (this is what we test)
This should immediately call localForage.setItem (our mock) 1 time
then wait for the returned promise to resolve in order to move to the next item in the queue
In our test the queue would be emptied so then next 4 calls to localForage.setItem shouldn't happen

Also, I noticed you had the comment here noting that "fake timers cause promises to hang" - wonder if that might be the same reason for the issue I'm seeing?

I'm can't remember what lead me to that conclusion...
Maybe we can try and update jest

This might also need calls to waitForPromisesToResolve

(Btw, just tested this again using real timers and I don't see this problem. So I do have a suspicion this is somehow related to FakeTimers)

I'm not sure how you test this with real timers, but if you don't wait for the timers to expire the test should appear as passing successfully


There's an alternative way to test this without using timers

const task = createDeferredTask();

localforage.setItem = jest.fn()
   . mockReturnValue(Promise.resolve()) // default value
   . mockReturnValueOnce(task.promise) // first call

for (let i = 0; i < 5; i++) {
  StorageProvider.setItem(`key${i}`, `value${i}`);
}

// at this point `localForage.setItem` should be called once, but we control when it resolves 
// and we keep it unresolved 

// this should queue any calls that follow, so we don't expect more than 1 `localForage.setItem` call
StorageProvider.clear();

// we simulate the 1st setItem resolves after we called clear
task.resolve()

return waitForPromisesToResolve().then(() => {
  expect(localForage.setItem).toHaveBeenCalledTimes(1);
})

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hm, yes I do see some issues with Jest's fake timers and Promises being reported by others like here and here.

Although I can't quite wrap my head around your alternative way... is there a way to demonstrate the "before" case (i.e. clear() doesn't call abort and thus setItem is called 5 times?)

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

is there a way to demonstrate the "before" case (i.e. clear() doesn't call abort and thus setItem is called 5 times?)

Running this test against the pre-PR code should produce exactly that error
expected setItem to be called 1 time but it was called 5 times

I can't quite wrap my head around your alternative way

  1. We create a promise which we programmatically control when to resolve
  2. We configure localforage.setItem to return this promise the first time it's called and to otherwise return resolved promises
  3. We make 5 StorageProvider.setItem calls
  4. This adds 5 items to the queue and starts executing the first localForage.setItem
  5. This simulates the 1st localForage.setItem taking a random time.
  6. The important bit is we call StorageProvider.clear() while the first localForage.setItem isn't completed yet (and the queue is not empty, because the queue would only go to the next item after the 1st completes)
  7. We call StorageProvider.clear() and only then we resolve the first localForage.setItem call
  8. waitForPromisesToResolve() makes jest wait for any promises (even promises returned as the result of a promise) to resolve
    9.If StorageProvider.clear() does not abort the queue, more localForage.setItem would be executed because StorageProvider.setItem works like this
    • StorageProvider.setItem (5th call)
      • Queue -> push -> process ->
        • return promise for 5th call
          • return promise for 4th call
            • return promise for 3th call
              • return promise for nth call

So the promise of the 5th call waits the promise of the 4th call and only then calls localForage.setItem and the promise of the 4th call waits the promise of the 3rd and so on

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, amazing explanation - thanks for taking the time to explain that to me I appreciate it! Okay, let's go with this then since it doesn't require us to update jest in this PR.

// Use fake timers, so we can manipulate time at our will for this test.
jest.useFakeTimers();

// Given an implementation of setItem that resolves after 1000ms
localforage.setItem = jest.fn(() => new Promise(resolve => setTimeout(resolve, 1000)));

// When we call setItem 5 times, but then call clear after only 1000ms
for (let i = 0; i < 5; i++) {
StorageProvider.setItem(`key${i}`, `value${i}`);
}
jest.advanceTimersByTime(1000);
StorageProvider.clear();
jest.advanceTimersByTime(4000);

// Then setItem should only have been called once since all other calls were aborted when we called clear()
expect(localforage.setItem).toHaveBeenCalledTimes(1);
});
});