Summary:
I believe I discovered why our tests intermittently fail, why those
failures cause a cascade of failures, and how to fix it.
The bug is subtle and it's helpful to get a quick refresher on how various
parts of our testing system work:
First a deeper dive into how Promises work:
1. Upon creating a new Promise, the "executor" block (the one that gets
passed `resolve` and `reject`), gets synchronously run.
2. You eventually call `resolve()`.
3. The minute you call `resolve()`, Bluebird's `async.js` queues up
whatever's downstream (the next `then` block)
4. The queue gets processed on every "tick".
5. Once the "tick" happens, our queue processes and downstream `then`
blocks get run.
6. If any more Promises come in before the "tick", they get added to the
queue. Nothing gets processed until the "tick" happens.
The important takeaway here is this "tick" in step 4. This "tick" is the
core of what makes Promises asynchronous. By default, Bluebird in our
Node-like environment uses `setImmediate` as the underlying
implementation.
Our test environment is different. We do NOT use `setImmediate` in our test
environment.
We use Bluebird's `Promise.setScheduler` API to implement our own "tick". This
gives us much greater control over when Promises advance. Node's `setImmediate`
puts you at the whim of the underlying event loop.
Before today, our test "tick" implementation used `setTimeout` and
`advanceClock` triggered by `process.nextTick`.
Let me also quickly explain `setTimeout` in our test environment.
We globally override `setTimeout` in our test environment to not be based on
actual time at all. There are places in our code where we wait for several
hundred miliseconds, or have timeouts places. Instead of "sleeping" some amount
of time and hoping for the best, we gain absolute control over "time". "Time"
is just an integer value that only moves forward when you manually call
`advanceClock()` and pass it a certain number of "milliseconds".
At the beginning of each test, we reset time back to zero, we record
setTimeouts that come in, and as advanceClock gets called, we know if we need
to run any of the setTimeout callbacks.
Back to the Promise "tick" implementation. Before today, our testing "tick"
implementation relied our our stubbed `setTimeout` and our control of time.
This almost always works fine. Unfortunately tests would sometimes
intermittently fail, and furthermore cause a cascade of failures down the road.
We've been plauged with this for as long as I can remember. I think I finally
found how all of this comes together to cause these intermittent failures and
how to fix it.
The issue arises from a test like the one in query-subscription-pool-spec. We
have tests here (and subtly in other yet unknown places) that go
something like this:
```
it("TEST A", () => {
Foo.add(new Thing())
expect(Foo._things.length).toBe(1)
})
it("TEST B", () => {
expect(true).toBe(true)
})
```
At the surface this test looks straightforward. The problem is that
`Foo.add` may down the line call something like `trigger()`, which may
have listeners setup, which might try and asynchronously do all kinds of
things (like read the fs or read/write to the database).
The biggest issue with this is that the test 'finishes' immediately after
that `expect` block and immediately moves onto the next test. If `Foo.add`
is asynchronous, by the time whatever downstream effects of `Foo.add` take
place we may be in a completely different test. Furthremore if those
downstream function errors, those errors will be raised, but Jasmine will
catch them in the wrong test sending you down a rabbit hole of dispair.
It gets worse.
At the start of each test, we reset our `setTimeout` stub time back to
zero. This is problematic when combined with the last issue.
Suppose `Foo.add` ends up queuing a downstream Promsie. Before today, that
downstream Promise used `setTimeout(0)` to trigger the `then` block.
Suppose TEST A finishes before `process.nextTick` in our custom scheduler
can call `advanceClock` and run the downstream Promise.
Once Test B starts, it will reset our `setTimeout` stub time back to zero.
`process.nextTick` comes back after Test B has started and calls
`advanceClock` like it's supposed to.
Unfortunately, because our stub time has been reset, advanceClock will NOT
find the original callback function that would have resolved `Foo.add`'s
downstream Promise!!!
This means that Bluebird is now stuck waiting for a "tick" that will never
come anymore.
Since Bluebird thinks it's waiting for a "tick", all future Promises will
get queued, but never called (see Step 6 of the Promise description
above).
This is why once one test fails, downstream ones never complete and
Jasmine times out.
The failure is intermittent because `process.nextTick` is racing agianst a
test finishing, the next one starting, and how many and how far downstream
promises are setup.
Okay. So how do we fix this? First I tried to simply not reset the time back to
zero again in our stubbed time-override. This doesn't work because it simply
exposes the diasterous consequences of downstream Promises resolving after a
test has completed. When a test completes we cleanup objects, unmount React
components. Those downstream promises and timeouts come back and throw all
kinds of errors like: "can't read property x of undefined" and "can't find a
match for component X".
The fix that works the best is to simply MAKE PROMISES FULLY SYCNRHONOUS.
Now if you look at our custom Promise Test Scheduler in time-override,
you'll see that it immediately and sychronously calls the function. This
means that all downstream promises will run BEFORE the test ends.
Note that this is designed as a safeguard. The best way to make a more
robust test is to declare that your funtion body is asynchronous. If you
call a method that has downstream effects, it's your responsibility to
wait for them to finish. I would consider the test example above a very,
very subtle bug. Unfortunately it's so subtle that it's unreasonable to
expect that we'll always catch them. Making everything in our testing
environment synchronous ensures that test setup and cleanup happen when we
intuitively expect them to.
Addendum:
The full Promise call chain looks something like this:
-> `Promise::_resolveCallback`
-> `Promise::_fulfill`
-> `Promise::_async.settlePromises`
-> `AsyncSettlePromises`
-> `Async::_queueTick`
-> CHECK `Async::_isTickUsed`
-> `Async::_schedule`
-> `TimeOverride.scheduler`
-> `setTimeout`
-> `process.nextTick`
-> `advanceClock`
-> `Async::_drainQueues`
-> `Async::_drainQueue`
-> `THEN BLOCK RUNS`
-> `Maybe more things get added to queue`
-> `Async::_reset`
-> `Async::_queueTick` works again.
Test Plan: They now work
Reviewers: halla, mark, spang, juan, jackie
Reviewed By: juan, jackie
Differential Revision: https://phab.nylas.com/D3538
More spec fixes
replace process.nextTick with setTimeout(fn, 0) for specs
Also added an unspy in the afterEach
Temporarily disable specs
fix(spec): start fixing specs
Summary:
This is the WIP fix to our spec runner.
Several tests have been completely commented out that will require
substantially more work to fix. These have been added to our sprint
backlog.
Other tests have been fixed to update to new APIs or to deal with genuine
bugs that were introduced without our knowing!
The most common non-trivial change relates to observing the `NylasAPI` and
`NylasAPIRequest`. We used to observe the arguments to `makeRequest`.
Unfortunately `NylasAPIRequest.run` is argumentless. Instead you can do:
`NylasAPIRequest.prototype.run.mostRecentCall.object.options` to get the
`options` passed into the object. the `.object` property grabs the context
of the spy when it was last called.
Fixing these tests uncovered several concerning issues with our test
runner. I spent a while tracking down why our participant-text-field-spec
was failling every so often. I chose that spec because it was the first
spec to likely fail, thereby requiring looking at the least number of
preceding files. I tried binary searching, turning on and off, several
files beforehand only to realize that the failure rate was not determined
by a particular preceding test, but rather the existing and quantity of
preceding tests, AND the number of console.log statements I had. There is
some processor-dependent race condition going on that needs further
investigation.
I also discovered an issue with the file-download-spec. We were getting
errors about it accessing a file, which was very suspicious given the code
stubs out all fs access. This was caused due to a spec that called an
async function outside ot a `waitsForPromise` block or a `waitsFor` block.
The test completed, the spies were cleaned up, but the downstream async
chain was still running. By the time the async chain finished the runner
was already working on the next spec and the spies had been restored
(causing the real fs access to run).
Juan had an idea to kill the specs once one fails to prevent cascading
failures. I'll implement this in the next diff update
Test Plan: npm test
Reviewers: juan, halla, jackie
Differential Revision: https://phab.nylas.com/D3501
Disable other specs
Disable more broken specs
All specs turned off till passing state
Use async-safe versions of spec functions
Add async test spec
Remove unused package code
Remove canary spec
Decaffination replaces someString[index..-1] with
someString.slice(index, -1 + 1), which is bizzare. This commit changes those
instances to someString.slice(index).
Test Plan: Lots of tests, mostly updated to enzyme. Not many new ones.
Reviewers: evan, juan, jackie
Reviewed By: juan, jackie
Subscribers: juan
Differential Revision: https://phab.nylas.com/D3374
Dramatically clean up and simply the spec bootup process.
Converting spec bootup system to es6 from coffee.
Converted old `jasmine-helper`, `spec-helper`, and `spec-suite` to a new
`n1-spec-runner` file.
Each of these old files had tons and tons of code related to various parts
of the spec bootup and running process.
Each of those parts have been extracted into individual files
