Updating to loader.js 4.0.10 broke our tests

[tamzinblake]

Still fishing out details for a better bug report, but I figured I should mention sooner rather than later. Our tests started mysteriously being broken this morning, and it turns out it was because we had loader.js specified as "^4.0.0" and so it updated from 4.0.9 to 4.0.10 yesterday - reverting back to 4.0.9 fixed it (so now we have it specified as "4.0.9").

I'll post more details to reproduce as I find them.

[rwjblue]

Thanks for reporting! Staying tuned for more details...

[chriskrycho]

We had the exact same issue. I'll report further details as we figure them out, but I can confirm that pinning to 4.0.9 resolved it for us.

The specific error we were seeing (across a wide variety of tests, but primarily acceptance tests) was like this—I just grabbed one of the 34 tests which failed, out of 342 total:

 26) [PhantomJS 2.1] TestLoader Failures: mobile-web/tests/acceptance/vendor-search-test: could not be loaded
     Died on test #1 moduleLoadFailure@http://localhost:7357/assets/test-support.js:6468:15
require@http://localhost:7357/assets/test-loader.js:69:31
loadModules@http://localhost:7357/assets/test-loader.js:58:25
load@http://localhost:7357/assets/test-loader.js:89:35
http://localhost:7357/assets/test-support.js:6477:20: undefined is not a constructor (evaluating '(0, _mobileWebTestsHelpersModuleForAcceptance['default'])('Acceptance | vendor search')')

     http://localhost:7357/assets/tests.js:1486:60
     exports@http://localhost:7357/assets/vendor.js:131:37
     requireModule@http://localhost:7357/assets/vendor.js:30:25
     require@http://localhost:7357/assets/test-loader.js:67:16
     loadModules@http://localhost:7357/assets/test-loader.js:58:25
     load@http://localhost:7357/assets/test-loader.js:89:35
     http://localhost:7357/assets/test-support.js:6477:20

It also appears to have affected our Mirage (0.1.x) configuration, in that we saw errors like this:

Error: Ember Data Request GET /api/baskets/getorderdays returned a 404
Payload (text/html; charset=utf-8)
Not found: /api/baskets/getorderdays

(That one was coming from an integration test.)

References to Ember.assign in acceptance tests also reported undefined is not a constructor (evaluating 'Ember.assign(...)') (where ... is whatever assignment we tried to do with it).

[stefanpenner]

is there a reproduction?

[tamzinblake]

I wasn't able to track down any particularly useful info or a reproduction, but here's a relevant stack trace that probably is in no way helpful:

stack: >
15:46:43.734             TypeError: 'undefined' is not an object (evaluating 'initializer.name')
15:46:43.734         message: >
15:46:43.734             Died on test #1     at test (http://localhost:4201/assets/test-support.js:3259)
15:46:43.734                 at http://localhost:4201/assets/test-support.js:6463
15:46:43.734                 at http://localhost:4201/assets/test-loader.js:69
15:46:43.735                 at http://localhost:4201/assets/test-support.js:12295
15:46:43.735                 at forEach (http://localhost:4201/assets/vendor.js:453)
15:46:43.735                 at _loadSplitModules (http://localhost:4201/assets/test-support.js:12297)
15:46:43.735                 at http://localhost:4201/assets/test-loader.js:89
15:46:43.735                 at http://localhost:4201/assets/test-support.js:6476: 'undefined' is not an object (evaluating 'initializer.name')

[tamzinblake]

So it's basically not able to load any of our integration tests, but is trying to? I'm not having much luck digging into this, but we've got a lot of different stuff wired up here.

[tamzinblake]

Okay, we appear to have 2 different classes of errors. Some of our integration tests aren't loading at all:

Died on test #1     at Object.TestLoader.moduleLoadFailure (http://localhost:4201/assets/test-support.js:6461:11)
    at Object.TestLoader.require (http://localhost:4201/assets/test-loader.js:69:14)
    at http://localhost:4201/assets/test-support.js:12295:22
    at Array.forEach (native)
    at Object._loadSplitModules [as loadModules] (http://localhost:4201/assets/test-support.js:12294:18)
    at Function.TestLoader.load (http://localhost:4201/assets/test-loader.js:89:24)
    at http://localhost:4201/assets/test-support.js:6476:16: Cannot read property 'name' of undefined@ 0 ms
Source:     
TypeError: Cannot read property 'name' of undefined
    at http://localhost:4201/assets/vendor.js:176940:23
    at Array.forEach (native)
    at exports.default (http://localhost:4201/assets/vendor.js:176930:8)
    at Module.eval [as callback] (pagerduty/app.js:42:39)
    at Module.exports (http://localhost:4201/assets/vendor.js:2197:32)
    at Module.reify (http://localhost:4201/assets/vendor.js:2218:59)
    at Module.exports (http://localhost:4201/assets/vendor.js:2195:10)
    at Module.reify (http://localhost:4201/assets/vendor.js:2218:59)
    at Module.exports (http://localhost:4201/assets/vendor.js:2195:10)
    at requireModule (http://localhost:4201/assets/vendor.js:2096:18)

And then some of them seem to have modules that aren't loading correctly:

beforeEach failed on visiting /: (0 , _pagerdutyTestsHelpersStartApp.default) is not a function@ 0 ms
Source:     
TypeError: (0 , _pagerdutyTestsHelpersStartApp.default) is not a function
    at Object.beforeEach (http://localhost:4201/assets/tests.js:6354:67)
    at callHook (http://localhost:4201/assets/test-support.js:2805:20)
    at runHook (http://localhost:4201/assets/test-support.js:2798:5)
    at process (http://localhost:4201/assets/test-support.js:2565:24)
    at begin (http://localhost:4201/assets/test-support.js:2547:2)
    at http://localhost:4201/assets/test-support.js:2607:4
Died on test #2     at Module.callback (http://localhost:4201/assets/tests.js:6372:19)
    at Module.exports (http://localhost:4201/assets/vendor.js:2197:32)
    at requireModule (http://localhost:4201/assets/vendor.js:2096:18)
    at Object.TestLoader.require (http://localhost:4201/assets/test-loader.js:67:9)
    at http://localhost:4201/assets/test-support.js:12295:22
    at Array.forEach (native)
    at Object._loadSplitModules [as loadModules] (http://localhost:4201/assets/test-support.js:12294:18): visit is not defined@ 0 ms
Source:     
ReferenceError: visit is not defined
    at Object.<anonymous> (http://localhost:4201/assets/tests.js:6373:5)
    at runTest (http://localhost:4201/assets/test-support.js:2779:28)
    at Object.run (http://localhost:4201/assets/test-support.js:2764:4)
    at http://localhost:4201/assets/test-support.js:2906:11
    at process (http://localhost:4201/assets/test-support.js:2565:24)
    at begin (http://localhost:4201/assets/test-support.js:2547:2)
    at http://localhost:4201/assets/test-support.js:2607:4
afterEach failed on visiting /: andThen is not defined@ 24 ms
Source:     
ReferenceError: andThen is not defined
    at Object.afterEach (http://localhost:4201/assets/tests.js:6363:7)
    at callHook (http://localhost:4201/assets/test-support.js:2805:20)
    at runHook (http://localhost:4201/assets/test-support.js:2798:5)
    at process (http://localhost:4201/assets/test-support.js:2565:24)
    at begin (http://localhost:4201/assets/test-support.js:2547:2)
    at http://localhost:4201/assets/test-support.js:2607:4

I assume the latter has something to do with processing the default export of tests/helpers/start-app.js

Vaguely wondering if this is somehow a problem with having a complex dependency graph, just given the changes introduced between 4.0.9 and 4.0.10 - like maybe they're getting pruned in such a way that they can't actually get resolved in time?

[rwjblue]

I am guessing that some of the AMD callback args are not being populated (so they are undefined), you would need to confirm though...

[stefanpenner]

I suspect @kratiahuja fix may have uncovered an existing bug in reification?

Can someone share an app with the issue privately \w me or @rwjblue, would love to get to the bottom of this.

[kratiahuja]

@stefanpenner Let me know how I can help with this. I suspect my second PR may have uncovered a new bug causing this to fail. I suspect somewhere the flattening of dependencies is not happening as expected.

[stefanpenner]

@kratiahuja sounds good. Hopefully someone can share a reproduction so we can dig in further.

[kratiahuja]

@thomblake could you please share a reproduction of the issue so that we can dig into this?

[stefanpenner]

@chriskrycho ^^

[chriskrycho]

I'll see if I can reproduce minimally on Friday. Shipping some features and bug fixes takes priority tomorrow. Unfortunately, there was nothing obvious beyond what I posted initially to make the issue clear, so it's going to take so digging.

[tamzinblake]

I am in the hospital now but if I get out soon I'll see what I can come up with. On Jul 13, 2016 6:45 PM, "Chris Krycho" notifications@github.com wrote:

I'll see if I can reproduce minimally on Friday. Shipping some features and bug fixes takes priority tomorrow. Unfortunately, there was nothing obvious beyond what I posted initially to make the issue clear, so it's going to take so digging.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/ember-cli/loader.js/issues/87#issuecomment-232534910, or mute the thread https://github.com/notifications/unsubscribe/AADac2RcDWZHw8wxC3XwnKOkQKHDs8fTks5qVZTQgaJpZM4I8Jkp .

[stefanpenner]

I am in the hospital now but if I get out soon I'll see what I can come up with.

oh no! All the best sir.

[stefanpenner]

@chriskrycho if you can share the app privately maybe we can figure out quickly

[kratiahuja]

Bumping this again.

@chriskrycho @thomblake : could you guys provide us with a reproducible steps or a share the app privately?

[chriskrycho]

Might be able to next week. I'm off this week, and we've been pretty busy just trying to ship features (we just pinned to the previous release for now). Do ping again if I haven't followed up in a few weeks, though.

[kratiahuja]

Bumping this issue again.

@chriskrycho @thomblake : could guys help us reproduce this?

@stefanpenner: I think we should close this issue if there is no further reproduction.

[chriskrycho]

I’ll see if I can take a gander later this week. We’ve just been slammed with shipping.

[stefanpenner]

Will gladly reopen if a reproduction can be provided. Our attempts have not been able to replicate :(

[danwenzel]

Hey there, I'm on @thomblake's team. Sorry for the delay. I finally got a chance to dig into this, and the issue is definitely related to this change: https://github.com/ember-cli/loader.js/pull/86

In our case, it looks like the ember-cli-mirage module is somehow not being properly marked as isPending: false where it should be. So the module never properly loads, throwing an error, and we end of with undefined callback args.

If I change this line: https://github.com/kratiahuja/loader.js/blob/e2b7724eaa04c89c53fbcae255c49e171848c24d/lib/loader/loader.js#L231

if (pending && !mod.finalized && !mod.isPending) {

... to this:

if (pending && (mod.name === 'pagerduty/initializers/ember-cli-mirage' || (!mod.finalized && !mod.isPending))) {

... everything works

I hope this helps. I can dig into it more later this week.

[stefanpenner]

@danwenzel we really need a reproduction, a simple app that demonstrates this. I suspect it will be trivial to debug once that is provided.

We are also very eager to address this, but as it stands it isn't yet actionable, nor does it absolutely demonstrate a bug in loader, rather it is possible to mitigate the symptom by changing the loader. But without something were we can investigate the root cause, the bug could very well be elsewhere.

[krisselden]

@stefanpenner glimmer-syntax demonstrates this issue. it is not a bug in loader.js but it is a different but valid topological sort order, but I can't get glimmer-syntax to load with the updated loader.js.

[krisselden]

glimmer-syntax.pdf

[stefanpenner]

@krisselden oooo thanks for the example + diagram. Do you have cycles to look at this, if not is it blocking you. (e.g. should i stop what im doing now and investigate?)

[stefanpenner]

@krisselden do you have a branch of glimmer using this loader and failing? I suspect I know what the issue is then, but I would like to confirm.

[rwjblue]

@stefanpenner - I believe it is a branch of Ember (here is the one I have been reviewing), but I'm not sure that branch is updated with his latest changes.

[stefanpenner]

ya, i believe i know what is going on. I don't believe this to be a bug, but I have to run to meeting and haven't fully completed my response. I will finish when i return.

[danwenzel]

@stefanpenner: Did you ever get a chance to finish looking at this?

[stefanpenner]

@danwenzel yes, I don't believe this to be a bug in loader. There exist multiple possible orderings, the previous ordering was the result of a bug, and resulted in both an unexpected ordering (cycles that should have worked didn't, instead ones that shouldn't have did) and resulted in performance degradation.

In hindsight, it may have been prudent to do a major version bump. But typically we do not do that for legit bugfixes that change edge-case behavior.

[tamzinblake]

@stefanpenner Is there an explanation of how to avoid this? For now our workaround is to use an outdated version of loader.js, which doesn't seem like a permanent solution.

[krisselden]

@thomblake it happens when you have a cyclic reference between modules that have top level side effects that use dependencies. When you do this, your modules can only be loaded in one order despite the module graph having more than one topological sort.

[krisselden]

In the PDF I attached it was between parser and syntax, @stefanpenner in my case glimmer-syntax/lib/syntax was loading before glimmer-syntax/lib/parser but in the end I just refactored out the cycle.

I wish there was a linting tool.

[stefanpenner]

I wish there was a linting tool.

agreed

[tamzinblake]

I think my confusion is several levels removed from this discussion. I don't understand where in our (giant, monolithic) ember-cli app these cycles would be generated, or how to spot them. I'm not even entirely sure where loader.js is being called - it's just installed as part of our default ember-cli setup.

[chriskrycho]

@thomblake not sure if you ever got your side resolved; in the app itself, using https://github.com/zertosh/eslint-plugin-dependencies will highlight direct cycles in your application. Given the kind of issue going on here, it's unlikely to actually highlight the fix, as I don't think it will pick up indirect cycles. (This is still an issue for me, and I don't have time yet to figure out where in my stack this cycle is arising.)

[stefanpenner]

@thomblake / @chriskrycho I will gladly take some time to help you guys fix the issues. But as mentioned, I really need a reproduction. Most likely access to your app (maybe via a screenshare)

[tamzinblake]

@stefanpenner That would be really helpful! I think I might actually understand the stuff earlier in the thread now, but have no idea how to debug this issue. Maybe we could screenhero?

[broerse]

@stefanpenner You can reproduce this by cloning https://github.com/mharris717/ember-cli-pagination changing ember-cli-qunit to ^3.1.2 and run npm test. I would like to update ember-cli-pagination to the new qunit but am stuck on this bug for now.

[chriskrycho]

Okay, I'm coming back to this now and am going to try to figure out exactly where this is going awry in our app. (I finally have the time!) Will update here as I have more info.

[tamzinblake]

@chriskrycho Any luck?

[tamzinblake]

@chriskrycho Also, I see you recommended eslint-plugin-dependencies earlier - any advice on getting that set up so that it properly resolves dependencies in an ember-cli project?

[chriskrycho]

None so far, but I'm basically not doing anything else until this is fixed at this point. I'll certainly update once I have an answer here. Currently, something around our use of Mirage (we're still back on 0.1.14) seems to be involved, but I've gotten no further than that.

As for eslint-plugin-dependencies, I haven't looked at it again since that post. 😬

[tamzinblake]

It's still a bit mysterious to me, but I figured out a thing that seemed to help:

At the top of tests/helpers/start-app.js, I had

import Application from 'pagerduty/app';
import startMirage from 'pagerduty/tests/helpers/setup-mirage-for-integration';

Inside setup-mirage-for-integration I was calling

import mirageInitializer from 'pagerduty/initializers/ember-cli-mirage';

Meanwhile, pagerduty/app was also running all of the initializers. Knowing this maybe had something to do with the order in which dependencies were being resolved, I tried reversing the order of those two:

import startMirage from 'pagerduty/tests/helpers/setup-mirage-for-integration';
import Application from 'pagerduty/app';

And it worked

I debugged this by setting some breakpoints while running ember test --server - I had to disable try/catch and then set a breakpoint just above where the error was happening, and reload and then go up the call stack and set another breakpoint in some spot that was calling require(moduleName), and then reload and turn on 'break on caught exceptions' after the first time it stopped and then go forward without breakpoints, and then I could go through the call stack, particularly looking at the context around _reify calls.

I hope that helps, I still find it terribly confusing.

[chriskrycho]

That's extremely helpful, @thomblake; it has resolved my issue as well.

I will attempt to create a tiny reproduction of this issue early next week.

[tamzinblake]

@broerse I tried cloning your repo and debugging the same way, with no luck. It looked like it was failing in a different place though.

[tamzinblake]

@stefanpenner

In case this is still relevant to anyone, minimal-ish reproduction: https://github.com/PagerDuty/loader-js-test

I basically just created a new Ember 2.10 app, installed mirage, added the bits to start-app and destroy-app, and added an integration test that calls them.

At this point I'm pretty sure this is an ember-cli-mirage documentation issue more than anything