From 1f7512eb4a74ba94eb0a0ecd939278438e2faa34 Mon Sep 17 00:00:00 2001 From: Chris Thoburn Date: Thu, 26 Jul 2018 17:15:35 -0700 Subject: [PATCH] [FEAT] TrackableRequests for when async leakage is detected improve waiter erroring improve trace infra and add tests only run waiter tests in dev --- addon/-legacy-private/system/store.js | 82 ++++- addon/-private/system/store/common.js | 5 +- addon/-record-data-private/system/store.js | 82 ++++- tests/integration/store-test.js | 46 ++- tests/unit/store/async-leak-test.js | 359 +++++++++++++++++++++ 5 files changed, 555 insertions(+), 19 deletions(-) create mode 100644 tests/unit/store/async-leak-test.js diff --git a/addon/-legacy-private/system/store.js b/addon/-legacy-private/system/store.js index ae75e920ac8..daee35d9e21 100644 --- a/addon/-legacy-private/system/store.js +++ b/addon/-legacy-private/system/store.js @@ -220,9 +220,48 @@ Store = Service.extend({ this._serializerCache = Object.create(null); if (DEBUG) { - this.__asyncRequestCount = 0; + if (this._shouldTrackAsyncRequests === undefined) { + this._shouldTrackAsyncRequests = true; + } + if (this._generateStackTracesForTrackedRequests === undefined) { + this._generateStackTracesForTrackedRequests = false; + } + + this._trackedAsyncRequests = []; + this._trackAsyncRequestStart = label => { + let trace = + 'set `store._generateStackTracesForTrackedRequests = true;` to get a detailed trace for where this request originated'; + + if (this._generateStackTracesForTrackedRequests) { + try { + throw new Error(`EmberData TrackedRequest: ${label}`); + } catch (e) { + trace = e; + } + } + + let token = Object.freeze({ + label, + trace, + }); + + this._trackedAsyncRequests.push(token); + return token; + }; + this._trackAsyncRequestEnd = token => { + let index = this._trackedAsyncRequests.indexOf(token); + + if (index !== -1) { + this._trackedAsyncRequests.splice(index, 1); + } + }; + this.__asyncWaiter = () => { - return this.__asyncRequestCount === 0; + let shouldTrack = this._shouldTrackAsyncRequests; + let tracked = this._trackedAsyncRequests; + let isSettled = tracked.length === 0; + + return shouldTrack !== true || isSettled; }; Ember.Test.registerWaiter(this.__asyncWaiter); @@ -833,6 +872,24 @@ Store = Service.extend({ options, }; + if (DEBUG) { + if (this._generateStackTracesForTrackedRequests === true) { + let trace; + + try { + throw new Error(`Trace Origin for scheduled fetch for ${modelName}:${id}.`); + } catch (e) { + trace = e; + } + + // enable folks to discover the origin of this findRecord call when + // debugging. Ideally we would have a tracked queue for requests with + // labels or local IDs that could be used to merge this trace with + // the trace made available when we detect an async leak + pendingFetchItem.trace = trace; + } + } + let promise = resolver.promise; internalModel.loadingData(promise); @@ -2840,6 +2897,27 @@ Store = Service.extend({ if (DEBUG) { Ember.Test.unregisterWaiter(this.__asyncWaiter); + let shouldTrack = this._shouldTrackAsyncRequests; + let tracked = this._trackedAsyncRequests; + let isSettled = tracked.length === 0; + + if (!isSettled) { + if (shouldTrack) { + throw new Error( + 'Async Request leaks detected. Add a breakpoint here and set `store._generateStackTracesForTrackedRequests = true;`to inspect traces for leak origins:\n\t - ' + + tracked.map(o => o.label).join('\n\t - ') + ); + } else { + warn( + 'Async Request leaks detected. Add a breakpoint here and set `store._generateStackTracesForTrackedRequests = true;`to inspect traces for leak origins:\n\t - ' + + tracked.map(o => o.label).join('\n\t - '), + false, + { + id: 'ds.async.leak.detected', + } + ); + } + } } }, diff --git a/addon/-private/system/store/common.js b/addon/-private/system/store/common.js index ac56b0a8797..7eb81f77f18 100644 --- a/addon/-private/system/store/common.js +++ b/addon/-private/system/store/common.js @@ -34,14 +34,15 @@ export function _objectIsAlive(object) { } export function guardDestroyedStore(promise, store, label) { + let token; if (DEBUG) { - store.__asyncRequestCount++; + token = store._trackAsyncRequestStart(label); } let wrapperPromise = resolve(promise, label).then(v => promise); return _guard(wrapperPromise, () => { if (DEBUG) { - store.__asyncRequestCount--; + store._trackAsyncRequestEnd(token); } return _objectIsAlive(store); }); diff --git a/addon/-record-data-private/system/store.js b/addon/-record-data-private/system/store.js index afd1e347b81..5a5f11e19bf 100644 --- a/addon/-record-data-private/system/store.js +++ b/addon/-record-data-private/system/store.js @@ -226,9 +226,48 @@ Store = Service.extend({ this.modelDataWrapper = new ModelDataWrapper(this); if (DEBUG) { - this.__asyncRequestCount = 0; + if (this._shouldTrackAsyncRequests === undefined) { + this._shouldTrackAsyncRequests = true; + } + if (this._generateStackTracesForTrackedRequests === undefined) { + this._generateStackTracesForTrackedRequests = false; + } + + this._trackedAsyncRequests = []; + this._trackAsyncRequestStart = label => { + let trace = + 'set `store._generateStackTracesForTrackedRequests = true;` to get a detailed trace for where this request originated'; + + if (this._generateStackTracesForTrackedRequests) { + try { + throw new Error(`EmberData TrackedRequest: ${label}`); + } catch (e) { + trace = e; + } + } + + let token = Object.freeze({ + label, + trace, + }); + + this._trackedAsyncRequests.push(token); + return token; + }; + this._trackAsyncRequestEnd = token => { + let index = this._trackedAsyncRequests.indexOf(token); + + if (index !== -1) { + this._trackedAsyncRequests.splice(index, 1); + } + }; + this.__asyncWaiter = () => { - return this.__asyncRequestCount === 0; + let shouldTrack = this._shouldTrackAsyncRequests; + let tracked = this._trackedAsyncRequests; + let isSettled = tracked.length === 0; + + return shouldTrack !== true || isSettled; }; Ember.Test.registerWaiter(this.__asyncWaiter); @@ -842,6 +881,24 @@ Store = Service.extend({ options, }; + if (DEBUG) { + if (this._generateStackTracesForTrackedRequests === true) { + let trace; + + try { + throw new Error(`Trace Origin for scheduled fetch for ${modelName}:${id}.`); + } catch (e) { + trace = e; + } + + // enable folks to discover the origin of this findRecord call when + // debugging. Ideally we would have a tracked queue for requests with + // labels or local IDs that could be used to merge this trace with + // the trace made available when we detect an async leak + pendingFetchItem.trace = trace; + } + } + let promise = resolver.promise; internalModel.loadingData(promise); @@ -3060,6 +3117,27 @@ Store = Service.extend({ if (DEBUG) { Ember.Test.unregisterWaiter(this.__asyncWaiter); + let shouldTrack = this._shouldTrackAsyncRequests; + let tracked = this._trackedAsyncRequests; + let isSettled = tracked.length === 0; + + if (!isSettled) { + if (shouldTrack) { + throw new Error( + 'Async Request leaks detected. Add a breakpoint here and set `store._generateStackTracesForTrackedRequests = true;`to inspect traces for leak origins:\n\t - ' + + tracked.map(o => o.label).join('\n\t - ') + ); + } else { + warn( + 'Async Request leaks detected. Add a breakpoint here and set `store._generateStackTracesForTrackedRequests = true;`to inspect traces for leak origins:\n\t - ' + + tracked.map(o => o.label).join('\n\t - '), + false, + { + id: 'ds.async.leak.detected', + } + ); + } + } } }, diff --git a/tests/integration/store-test.js b/tests/integration/store-test.js index 175bf80c4da..4a28891e420 100644 --- a/tests/integration/store-test.js +++ b/tests/integration/store-test.js @@ -1,4 +1,4 @@ -import RSVP, { Promise as EmberPromise, resolve } from 'rsvp'; +import RSVP, { Promise, resolve } from 'rsvp'; import { run, next } from '@ember/runloop'; import setupStore from 'dummy/tests/helpers/store'; @@ -76,7 +76,7 @@ test("destroying record during find doesn't cause error", function(assert) { let TestAdapter = DS.Adapter.extend({ findRecord(store, type, id, snapshot) { - return new EmberPromise((resolve, reject) => { + return new Promise((resolve, reject) => { next(() => { store.unloadAll(type.modelName); reject(); @@ -93,31 +93,51 @@ test("destroying record during find doesn't cause error", function(assert) { return run(() => store.findRecord(type, id).then(done, done)); }); -test('find calls do not resolve when the store is destroyed', function(assert) { - assert.expect(0); +test('find calls do not resolve when the store is destroyed', async function(assert) { + assert.expect(2); let done = assert.async(); - + let next; + let nextPromise = new Promise(resolve => { + next = resolve; + }); let TestAdapter = DS.Adapter.extend({ - findRecord(store, type, id, snapshot) { - store.destroy(); - resolve(null); + findRecord() { + next(); + nextPromise = new Promise(resolve => { + next = resolve; + }).then(() => { + return { + data: { type: 'car', id: '1' }, + }; + }); + return nextPromise; }, }); initializeStore(TestAdapter); - let type = 'car'; - let id = 1; - store.push = function() { assert('The test should have destroyed the store by now', store.get('isDestroyed')); throw new Error("We shouldn't be pushing data into the store when it is destroyed"); }; + store.findRecord('car', '1'); + + await nextPromise; + + assert.throws(() => { + run(() => store.destroy()); + }, /Async Request leaks detected/); - run(() => store.findRecord(type, id)); + next(); + await nextPromise; - setTimeout(() => done(), 500); + // ensure we allow the internal store promises + // to flush, potentially pushing data into the store + setTimeout(() => { + assert.ok(true, 'We made it to the end'); + done(); + }, 0); }); test('destroying the store correctly cleans everything up', function(assert) { diff --git a/tests/unit/store/async-leak-test.js b/tests/unit/store/async-leak-test.js new file mode 100644 index 00000000000..2701ab6e05d --- /dev/null +++ b/tests/unit/store/async-leak-test.js @@ -0,0 +1,359 @@ +import { module } from 'qunit'; +import JSONAPIAdapter from 'ember-data/adapters/json-api'; +import JSONAPISerializer from 'ember-data/serializers/json-api'; +import { setupTest } from 'ember-qunit'; +import Store from 'ember-data/store'; +import Model from 'ember-data/model'; +import { Promise } from 'rsvp'; +import { attr } from '@ember-decorators/data'; +import { run } from '@ember/runloop'; +import { testInDebug as test } from '../../helpers/test-in-debug'; + +class Person extends Model { + @attr + name; +} + +module('unit/store async-waiter and leak detection', function(hooks) { + let store; + setupTest(hooks); + + hooks.beforeEach(function() { + let { owner } = this; + owner.register('service:store', Store); + owner.register('model:person', Person); + owner.register( + 'serializer:application', + JSONAPISerializer.extend({ + normalizeResponse(_, __, jsonApiPayload) { + return jsonApiPayload; + }, + }) + ); + store = owner.lookup('service:store'); + }); + + test('the waiter properly waits for pending requests', async function(assert) { + let stepResolve; + let stepPromise = new Promise(resolveStep => { + stepResolve = resolveStep; + }); + this.owner.register( + 'adapter:application', + JSONAPIAdapter.extend({ + findRecord() { + return new Promise(resolve => { + stepResolve(); + + setTimeout(() => { + resolve({ data: { type: 'person', id: '1' } }); + }, 50); // intentionally longer than the 10ms polling interval of `wait()` + }); + }, + }) + ); + + let request = store.findRecord('person', '1'); + let waiter = store.__asyncWaiter; + + assert.equal( + waiter(), + true, + 'We return true when no requests have been initiated yet (pending queue flush is async)' + ); + + await stepPromise; + + assert.equal(waiter(), false, 'We return false to keep waiting while requests are pending'); + + await request; + + assert.equal(waiter(), true, 'We return true to end waiting when no requests are pending'); + }); + + test('waiter can be turned off', async function(assert) { + let stepResolve; + let stepPromise = new Promise(resolveStep => { + stepResolve = resolveStep; + }); + this.owner.register( + 'adapter:application', + JSONAPIAdapter.extend({ + findRecord() { + return new Promise(resolve => { + stepResolve(); + + setTimeout(() => { + resolve({ data: { type: 'person', id: '1' } }); + }, 50); // intentionally longer than the 10ms polling interval of `wait()` + }); + }, + }) + ); + + // turn off the waiter + store._shouldTrackAsyncRequests = false; + + let request = store.findRecord('person', '1'); + let waiter = store.__asyncWaiter; + + assert.equal( + waiter(), + true, + 'We return true when no requests have been initiated yet (pending queue flush is async)' + ); + + await stepPromise; + + assert.equal( + store._trackedAsyncRequests.length, + 1, + 'We return true even though a request is pending' + ); + assert.equal(waiter(), true, 'We return true even though a request is pending'); + + await request; + + assert.equal(waiter(), true, 'We return true to end waiting when no requests are pending'); + }); + + test('waiter works even when the adapter rejects', async function(assert) { + assert.expect(4); + let stepResolve; + let stepPromise = new Promise(resolveStep => { + stepResolve = resolveStep; + }); + this.owner.register( + 'adapter:application', + JSONAPIAdapter.extend({ + findRecord() { + return new Promise((resolve, reject) => { + stepResolve(); + + setTimeout(() => { + reject({ errors: [] }); + }, 50); // intentionally longer than the 10ms polling interval of `wait()` + }); + }, + }) + ); + + let request = store.findRecord('person', '1'); + let waiter = store.__asyncWaiter; + + assert.equal( + waiter(), + true, + 'We return true when no requests have been initiated yet (pending queue flush is async)' + ); + + await stepPromise; + + assert.equal(waiter(), false, 'We return false to keep waiting while requests are pending'); + + await request.catch(e => { + assert.ok(true, 'promise was rejected'); + }); + + assert.equal(waiter(), true, 'We return true to end waiting when no requests are pending'); + }); + + test('waiter works even when the adapter throws', async function(assert) { + assert.expect(4); + let waiter = store.__asyncWaiter; + this.owner.register( + 'adapter:application', + JSONAPIAdapter.extend({ + findRecord() { + assert.equal( + waiter(), + false, + 'We return false to keep waiting while requests are pending' + ); + throw new Error('Invalid Request!'); + }, + }) + ); + + let request = store.findRecord('person', '1'); + + assert.equal( + waiter(), + true, + 'We return true when no requests have been initiated yet (pending queue flush is async)' + ); + + await request.catch(e => { + assert.ok(true, 'promise was rejected'); + }); + + assert.equal(waiter(), true, 'We return true to end waiting when no requests are pending'); + }); + + test('when the store is torn down too early, we throw an error', async function(assert) { + let next; + let stepPromise = new Promise(resolveStep => { + next = resolveStep; + }); + this.owner.register( + 'adapter:application', + JSONAPIAdapter.extend({ + findRecord() { + next(); + stepPromise = new Promise(resolveStep => { + next = resolveStep; + }).then(() => { + return { data: { type: 'person', id: '1' } }; + }); + return stepPromise; + }, + }) + ); + + store.findRecord('person', '1'); + let waiter = store.__asyncWaiter; + + assert.equal( + waiter(), + true, + 'We return true when no requests have been initiated yet (pending queue flush is async)' + ); + + await stepPromise; + + assert.equal(waiter(), false, 'We return false to keep waiting while requests are pending'); + + assert.throws(() => { + run(() => { + store.destroy(); + }); + }, /Async Request leaks detected/); + assert.equal(waiter(), false, 'We return false because we still have a pending request'); + + // make the waiter complete + run(() => next()); + assert.equal(store._trackedAsyncRequests.length, 0, 'Our pending request is cleaned up'); + assert.equal(waiter(), true, 'We return true because the waiter is cleared'); + }); + + test('when the store is torn down too early, but the waiter behavior is turned off, we emit a warning', async function(assert) { + let next; + let stepPromise = new Promise(resolveStep => { + next = resolveStep; + }); + this.owner.register( + 'adapter:application', + JSONAPIAdapter.extend({ + findRecord() { + next(); + stepPromise = new Promise(resolveStep => { + next = resolveStep; + }).then(() => { + return { data: { type: 'person', id: '1' } }; + }); + return stepPromise; + }, + }) + ); + + // turn off the waiter + store._shouldTrackAsyncRequests = false; + + store.findRecord('person', '1'); + let waiter = store.__asyncWaiter; + + assert.equal(store._trackedAsyncRequests.length, 0, 'We have no requests yet'); + assert.equal( + waiter(), + true, + 'We return true when no requests have been initiated yet (pending queue flush is async)' + ); + + await stepPromise; + + assert.equal(store._trackedAsyncRequests.length, 1, 'We have a pending request'); + assert.equal(waiter(), true, 'We return true because the waiter is turned off'); + assert.expectWarning(() => { + run(() => { + store.destroy(); + }); + }, /Async Request leaks detected/); + + assert.equal(waiter(), true, 'We return true because the waiter is turned off'); + + // make the waiter complete + run(() => next()); + assert.equal(store._trackedAsyncRequests.length, 0, 'Our pending request is cleaned up'); + assert.equal(waiter(), true, 'We return true because the waiter is cleared'); + }); + + test('when configured, pending requests have useful stack traces', async function(assert) { + let stepResolve; + let stepPromise = new Promise(resolveStep => { + stepResolve = resolveStep; + }); + let fakeId = 1; + this.owner.register( + 'adapter:application', + JSONAPIAdapter.extend({ + findRecord() { + return new Promise(resolve => { + stepResolve(); + + setTimeout(() => { + resolve({ data: { type: 'person', id: `${fakeId++}` } }); + }, 50); // intentionally longer than the 10ms polling interval of `wait()` + }); + }, + }) + ); + let request = store.findRecord('person', '1'); + let waiter = store.__asyncWaiter; + + assert.equal( + waiter(), + true, + 'We return true when no requests have been initiated yet (pending queue flush is async)' + ); + + await stepPromise; + + assert.equal(waiter(), false, 'We return false to keep waiting while requests are pending'); + assert.equal( + store._trackedAsyncRequests[0].trace, + 'set `store._generateStackTracesForTrackedRequests = true;` to get a detailed trace for where this request originated', + 'We provide a useful default message in place of a trace' + ); + + await request; + + assert.equal(waiter(), true, 'We return true to end waiting when no requests are pending'); + + store._generateStackTracesForTrackedRequests = true; + request = store.findRecord('person', '2'); + + assert.equal( + waiter(), + true, + 'We return true when no requests have been initiated yet (pending queue flush is async)' + ); + + await stepPromise; + + assert.equal(waiter(), false, 'We return false to keep waiting while requests are pending'); + /* + TODO this just traces back to the `flushPendingFetches`, + we should do something similar to capture where the fetch was scheduled + from. + */ + assert.equal( + store._trackedAsyncRequests[0].trace.message, + "EmberData TrackedRequest: DS: Handle Adapter#findRecord of 'person' with id: '2'", + 'We captured a trace' + ); + + await request; + + assert.equal(waiter(), true, 'We return true to end waiting when no requests are pending'); + }); +});