emberjs / ember.js

Ember.js - A JavaScript framework for creating ambitious web applications
https://emberjs.com
MIT License
22.45k stars 4.21k forks source link

Error after upgrading to Ember 2.4 #13071

Closed workmanw closed 8 years ago

workmanw commented 8 years ago

This error only occurs after the app has been active and running for a while, giving the user a chance to navigate between several different routes. It's very hard to reproduce, it seems to "just happen" after a while. We've been able to reproduce it a few times using our production build (ember.min.js), but never using a debug build (ember.debug.js).

Here is the stack:

 "Cannot read property '_lookupFactory' of undefined"

TypeError: Cannot read property '_lookupFactory' of undefined
    at i (https://qa-integration.batterii.com/assets/vendor-69da94618271be1c4338db3f0e942865.js:7:2712)
    at o (https://qa-integration.batterii.com/assets/vendor-69da94618271be1c4338db3f0e942865.js:7:2833)
    at Object.a [as default] (https://qa-integration.batterii.com/assets/vendor-69da94618271be1c4338db3f0e942865.js:7:2888)
    at Object.i [as subexpr] (https://qa-integration.batterii.com/assets/vendor-69da94618271be1c4338db3f0e942865.js:6:4717)
    at a (https://qa-integration.batterii.com/assets/vendor-69da94618271be1c4338db3f0e942865.js:15:16476)
    at i (https://qa-integration.batterii.com/assets/vendor-69da94618271be1c4338db3f0e942865.js:15:16302)
    at n (https://qa-integration.batterii.com/assets/vendor-69da94618271be1c4338db3f0e942865.js:15:16189)
    at Object.r [as acceptHash] (https://qa-integration.batterii.com/assets/vendor-69da94618271be1c4338db3f0e942865.js:15:16075)
    at n (https://qa-integration.batterii.com/assets/vendor-69da94618271be1c4338db3f0e942865.js:15:26102)
    at Object.a.inline (https://qa-integration.batterii.com/assets/vendor-69da94618271be1c4338db3f0e942865.js:15:26664)

That seems to point back to the lookup-helper. The few times I've been lucky enough to catch this at a breakpoint, I've observed that the minified owner parameter becomes undefined. The rest of the env looks correct. See:

image image

I know that's very little to go on. Short of coming up with an easy way to reproduce this, is there any additional information about the stack that might helpful in debugging this?

workmanw commented 8 years ago

What's even more odd is that you can see in the last screenshot, there is var s = "helper:" + e; on line 8786 ... but somehow on the very next line s is undefined. :confused: It's almost as if the stack is getting borked ... or the chrome debugger is just getting it wrong.

raido commented 8 years ago

I have seen something like this too. Happens rarely and i do not know how to reproduce. Also i am not sure if it is my app's problem or something else.

workmanw commented 8 years ago

@raido is your stack the same as mine (IE the failure is on _lookupFactory)? Are you on Ember 2.4.1? Have you seen this issue on prior versions of ember?

We upgraded from Ember 2.2 => Ember 2.4 and started seeing this issue pretty heavily in our server logs within a few days.

rlivsey commented 8 years ago

:+1: seen this myself and confused the heck out of me, from my bugsnag logs:

11779      if (validateLazyHelperName(name, owner, env.hooks.keywords)) {
11780        var helperName = 'helper:' + name;
11781        if (owner.hasRegistration(helperName, options)) {
11782          helper = owner._lookupFactory(helperName, options);
11783        }
11784      }
11785    }

As you say, how can owner be undefined on line 11782 if it's got past the owner.hasRegistration the line before?

Likewise only seen it on production when minified (above comes from sourcemaps).

Logs show we've only seen it on Chrome so far.

raido commented 8 years ago

@workmanw Yes, my error is also related too _lookupFactory and is see lookupHelper in the stacktrace.

Logs from production build, happened just now with v2.3.0

TypeError: Cannot read property '_lookupFactory' of undefined
    at o (vendor-6292d0672068025de3c6d57c1fb505d0.js:7)
    at Object.a [as default] (vendor-6292d0672068025de3c6d57c1fb505d0.js:7)
    at Object.r [as lookupHelper] (vendor-6292d0672068025de3c6d57c1fb505d0.js:6)
    at Object.D [as inline] (vendor-6292d0672068025de3c6d57c1fb505d0.js:16)
    at Object.i.inline (vendor-6292d0672068025de3c6d57c1fb505d0.js:16)
    at l.populateNodes (vendor-6292d0672068025de3c6d57c1fb505d0.js:16)
    at l.render (vendor-6292d0672068025de3c6d57c1fb505d0.js:16)
    at i (vendor-6292d0672068025de3c6d57c1fb505d0.js:16)
    at vendor-6292d0672068025de3c6d57c1fb505d0.js:16
    at s (vendor-6292d0672068025de3c6d57c1fb505d0.js:16)
jcbvm commented 8 years ago

I can confirm this issue on 2.4.2, seeing it sometimes in production, not seen in development yet. Can this be caused by the ember-inspector maybe?

For more info: never had this on 2.3.x and the stack is the same (_lookupFactory)

EDIT: I can confirm that this is not a ember-inspector issue, error occured while inspector was disabled.

gpoitch commented 8 years ago

Confirmed bug in 2.4.1 and 2.4.2. Happens only with minified js

workmanw commented 8 years ago

@jcbvm @gdub22 Have either of you been able to reproduce it consistently? I've tried and tried to find at least a consistent set of steps in our app with the hope of building an ember-twiddle, but I've had no luck.

This is completely anecdotal and probably a red herring, but it seems to happen while trying to render a helper which has an ancestor component rendered with the component helper ({{component componentName}}).

rlivsey commented 8 years ago

@workmanw Likewise not been able to reproduce consistently, we do use the {{component}} helper a lot throughout our app.

gpoitch commented 8 years ago

@workmanw not 100% consistently but I think I narrowed it down to a particular component which does happen to use the component helper in its own template.

ef4 commented 8 years ago

Uglify transpiles the function above to:

function n(e,t,r,n){
  var i=r.helpers[e];
  if(!i){
    var o=r.owner;
    if (a(e,o,r.hooks.keywords)){
      var s="helper:"+e;
      o.hasRegistration(s,n) && (i=o._lookupFactory(s,n));
    }
  }
  return i;
}

Notice that both property accesses on owner have been compiled down to a single line. My guess is that the crash actually happens on the first one, and the sourcemap fidelity is not high enough to distinguish them correctly.

Edited to add: Ah, but the crash is definitely for a _lookupFactory property, so my speculation must be wrong. Curiouser and curiouser.

workmanw commented 8 years ago

@ef4 Maybe ... but the few times I've caught this exception in the debugger, o (in your snippet) is undefined, but r.owner is a valid owner. In fact, I'm able to do r.owner.hasRegistration(s,n) && (r.owner._lookupFactory(s,n)); and get the class. Granted this is after Chrome has broken on a caught exception ... so the debugger could also be in a misleading state.

rlivsey commented 8 years ago

@ef4 yep it's definitely a strange one.

Could V8 be optimising it away for some reason? Who knows most about the dark arts of V8, @stefanpenner maybe?

wycats commented 8 years ago

If the line code that is crashing is:

o.hasRegistration(s,n) && (i=o._lookupFactory(s,n));

then:

  1. o.hasRegistration(s,n) has already returned a truthy value; this means
  2. o is neither null or undefined; therefore
  3. Cannot read property '_lookupFactory' of undefined is either wrong or a bug in v8

Am I missing something obvious?

wycats commented 8 years ago

For people who have reproduced this problem, what version of Chrome are you running? Have you reproduced it in Firefox, IE, or Safari?

workmanw commented 8 years ago

@wycats I don't see anything obvious you're missing. These are the same conclusions I arrived at. We have only seen this issue logged on Chrome latest (48). In my reproduction testing, I was using 48.0.2564.116. I personally did not try Firefox, IE or Safari, but I will try them out and report back.

EDIT: I cannot simplify the problem to the point of producing a twiddle. But if it would be helpful, I can queue up one or more failures paused at a breakpoint, and jump on a screenhero if someone wants to poke around in the chrome debugger. Sometimes I can reproduce it 3 times in a minute. Sometimes it takes 20 minutes or more.

workmanw commented 8 years ago

@wycats Alright. I spent the last hour trying Chrome, Safari and Firefox. I was able to reproduce it several times in Chrome and not at all in Safari and Firefox. I'm not sure this is conclusive, but it is certainly pointing more and more toward a Chrome specific issue.

wycats commented 8 years ago

This whole thing reminds me of http://yehudakatz.com/2010/01/02/the-craziest-fing-bug-ive-ever-seen/

raido commented 8 years ago

I have not been able to reproduce it either. For me it typically happens when app boots. Reloading app several times probably crash it, yet it is not consistent. It may crash 5 times in just minutes or take half an hour. I tested on latest Chrome.

stefanpenner commented 8 years ago

@workmanw I would recommend forcing that function to stay in specific modes, this may help us find out more about the issue. At which point we should also ping our v8 friends. But for that, a reproduction (even a full app) is likely going to be required.

To keep functions in specific modes, you can slowly disable parts of v8, and see if the bug stops. This will help us get closer to the root cause.

first I would just disable inlining, by running chromes v8 with it disabled: --nouse_inlining (my guess is this may be sufficient)

/Applications/Google\ Chrome\ Canary.app/Contents/MacOS/Google\ Chrome\ Canary --js-flags="--nouse_inlining" --user-data-dir=/tmp/foobar

On the flip side, try disabling crankshaft all together --crankshaft=false

/Applications/Google\ Chrome\ Canary.app/Contents/MacOS/Google\ Chrome\ Canary --js-flags="--crankshaft=false" --user-data-dir=/tmp/foobar
workmanw commented 8 years ago

@stefanpenner

I tested this using Chrome 48 (rather than canary). If you'd like me to try with Canary, I'd be happy to.

With --nouse_inlining I was not able to reproduce this issue. With --crankshaft=false I was able to reproduce this issue.

At which point we should also ping our v8 friends. But for that, a reproduction (even a full app) is likely going to be required.

I completely understand. I've spent about 4 hours trying to "work forwards" and build an Ember-twiddle that reproduces this. I just don't understand enough of what's going on to do that. So now I'm going to start "working backwards" using our app to simplify the reproduction by reducing the reproduction steps and ripping out as much out of our app as I can.

stefanpenner commented 8 years ago

With --nouse_inlining I was not able to reproduce this issue.

seems expected, so its most likely related to inlining bug of some kind.

With --crankshaft=false I was able to reproduce this issue.

this may be the wrong flag, i can't remember.

I completely understand. I've spent about 4 hours trying to "work forwards" and build an Ember-twiddle that reproduces this. I just don't understand enough of what's going on to do that. So now I'm going to start "working backwards" using our app to simplify the reproduction by reducing the reproduction steps and ripping out as much out of our app as I can.

@workmanw is it possible to share the app (or a URL to the app) as-is with steps to reproduce? The reality is, reproducing this in isolation may be tricky.

stefanpenner commented 8 years ago

A :sadpanda: work-around, is to force the function to exceed the max AST that can be inlined. This should allow you to :ship:

putting the following string in that function's body, should do the trick (right now, these limits/heuristics change overtime)

"Pork chop porchetta rump, bacon turducken filet mignon tri-tip drumstick picanha beef ribs sausage salami. Leberkas beef landjaeger bresaola, sausage meatloaf pastrami frankfurter ribeye jowl turducken drumstick flank. Pork loin shank tongue leberkas ham strip steak salami swine short ribs cupim. Strip steak sausage turkey tenderloin, alcatra turducken porchetta ribeye brisket spare ribs rump salami ground round tail frankfurter. Kielbasa cow porchetta, hamburger jowl salami turducken capicola beef. Corned beef meatloaf ball tip landjaeger shank pork belly. Short loin kielbasa pig tail, brisket cupim salami andouille hamburger sausage short ribs."
stefanpenner commented 8 years ago

@workmanw if you can also check in canary, that would be handy.

workmanw commented 8 years ago

@stefanpenner

putting the following string in that function, should do the trick (right now, these can change overtime)

Your knowledge of the internals never cease to amaze me.

@workmanw is it possible to share the app as-is with steps to reproduce?

Yea, I should be able to make that happen. If you give me a little bit I'll provision some credentials to one of our pre-production environments and get the data primed. I could probably get okay to share the source if need be, but would have to do that privately.

@workmanw if you can also check in canary, that would be handy.

Done. I checked canary "version 51.0.2673.0 canary (64-bit)" without either of the flags and unfortunately I could still reproduce it.

stefanpenner commented 8 years ago

I could probably get okay to share the source if need be, but would have to do that privately.

It would help me personally try and reduce the problem further, although no guarantees. I more or less would love to do the following:

With a app in-front of me (where I can change code + explore) discovering a proper work-around/reproduction might be possible.

workmanw commented 8 years ago

EDIT: The application linked below is using a build of ember which contains the workaround from PR #13118. It is no longer be valid for reproduction of this issue. If anyone is interested in reproducing this issue using our app, contact me and I could probably make that happen.


@stefanpenner So I did whittle down the reproduction by injecting some code into the page. Believe me, otherwise it would have been a nightmare.

This is still not 100% reproducible. If you follow these steps and it still hasn't occurred, try restarting chrome all together.

1) Visiting this URL: https://qa-integration.batterii.com/#/community/MTpDb21tdW5pdHksOTAwMQ/room/MTpSb29tLDE5NzQ2MzAwMQ/wall/MTpSb29tLDE5NzQ2MzAwMSxXYWxsLDEwMDAx

2) Login with email: emberdev@batterii.com and password: tomster1. That should deeplink you into a page that looks like this:

image

3) After logging in and landing on the above page, you'll need to refresh (so that you start clean from that page).

4) Open your chrome debugger and run the following in the console:


(function() {
var room = 'MTpSb29tLDE5NzQ2MzAwMQ',
    wall = 'MTpSb29tLDE5NzQ2MzAwMSxXYWxsLDEwMDAx',
    wallitem = 'MTpXYWxsSXRlbSwxOTg0NjMwMDQ';

function promiseTimer(ms) {
  return new Ember.RSVP.Promise(function(resolve) {
    Ember.run.later(resolve, ms);
  });
}

function timedTransition() {
  return BC.router.transitionTo.apply(BC.router, arguments).then(function() {
    return promiseTimer(800);
  });
}

function takeActions() {
  var downloadUrl = window.wallitemRecord.get('downloadUrl');
  window.open(downloadUrl);
  promiseTimer(1400).then(function() {
    return timedTransition('wall.wallitem', room, wall, wallitem);
  }).then(function() {
    return timedTransition('wall', room, wall);
  }).then(function() {
    return timedTransition('wall.wallitem', room, wall, wallitem);
  }).then(function() {
    return timedTransition('wall', room, wall);
  }).then(function() {
    return timedTransition('wall.wallitem', room, wall, wallitem);
  }).then(function() {
    return timedTransition('wall', room, wall);
  }).then(function() {
    return timedTransition('wall.wallitem', room, wall, wallitem);
  }).then(function() {
    return timedTransition('wall', room, wall);
  }).then(function() {
    return timedTransition('wall.wallitem', room, wall, wallitem);
  }).then(function() {
    return timedTransition('wall', room, wall);
  });
}

BC.store.findRecord('wallitem', wallitem).then(function(wallitem) { window.wallitemRecord = wallitem; });
$('<button id="crash-reproduce">Crash Reproduce</button>').appendTo('.top-right-nav');
$('#crash-reproduce').on('click', takeActions);
})();

5) Set Chrome Debugger to "Pause on Caught Exceptions".

6) The injected code should have added a button in the upper right corner. Click that button. First a new tab will open and trigger a file to be downloaded, then a modal dialog should open and close several times. That modal is actually "routable" so you should also observe the route changing. On the second or third open of the modal, you should hit the exception. If this doesn't occur, refresh the browser and try again (starting with step 4).

image


I'll work on getting you source code in the meantime. We run on Google App Engine so you will still have to connect to a cloud server, but I should be able to arrange it so you can run the client app locally (proxying to a cloud server).

Lastly, I'm on slack now and will be until about 4PM EST. I'd be happy to screenhero if need be. I'll also be available all day tomorrow.

stefanpenner commented 8 years ago

Awesome repro steps!

I'm running chores currently, but will try to investigate later today (or tomorrow morning).

workmanw commented 8 years ago

@stefanpenner Thanks a lot! I'll be online all day tomorrow and happy to help out if need be. You can find me in the emberjs slack. I also sent you an email about getting access to our source code (emailed your @gmail listed on your github account).

workmanw commented 8 years ago

@stefanpenner FYI I did slightly tweak the steps. I found that it was much more likely you would reproduce the problem if you use our app's "masonry mode" list. All that changed was the URL in step 1, the screenshot below step 2 and the code snippet in step 4.

sandstrom commented 8 years ago

In response to the question above, if this is v8/Chrome only: checked our logs, found 8 cases, all Chrome (49/48) on Windows (7 and 10). Unfortunately I don't have more data points.

raido commented 8 years ago

I have been trying to reproduce this but without a luck on Twiddle and locally. But it seems to be specific to helpers, because i have another app in production without helpers and it does not crash, take this with some salt.

I did some brute force tests by forcing application to navigate between routes back and forth and at times bug would occur after 3 transitions, throw the error and recover from it with next transition and after recovering never seemed to crash again.

Edit: I let it navigate through 7 routes for 300 times, with 50ms delay between transitions and nothing would break. Did 5 manual reloads after that and it crashed on boot when doing initial "index route" rendering where are some helpers in templates.

workmanw commented 8 years ago

I did some brute force tests by forcing application to navigate between routes back and forth and at times bug would occur after 3 transitions, throw the error and recover from it with next transition and after recovering never seemed to crash again.

This absolutely describes my experience.

In our case, we use window.open to trigger a file download and this action "seems to" help increase the likely hood of this issue happening (but it could be a red herring). For me, sometimes I get on a roll and it'll happen 10 out of 10 times after the 3rd or 4th transition. Other times, it won't happen once in half an hour.

raido commented 8 years ago

@workmanw I have bunch of "likely hood" type of things that "seem" to help reproduce it but in reality i have not been able to follow any of the "hints" application has given me. It seems completely random.

I tried to crash your application too by the reproduction steps given here, did not happen.

raido commented 8 years ago

@stefanpenner I tried adding some "pork chop" to function body, did not seem to help or i did something wrong.

Anyway, i think i have a way to make this happen more often. I have now confirmed, that it is always the same helper: which crashes it in my application. I'll keep digging.

So far, i managed to get some console logs out an when it crashes, not only the owner* is undefined but helperName also is undefined. So there more than one thing going missing.

@workmanw Some steps that helped me get my app crashing a lot more:

if (validateLazyHelperName(name, owner, env.hooks.keywords)) {
        var helperName = 'helper:' + name;
        console.log("Before", helperName, owner !== undefined, owner._lookupFactory !== undefined);
        if (owner.hasRegistration(helperName, options)) {
          console.log("After", helperName, owner !== undefined);
          console.log("After _lookupFactory", owner._lookupFactory !== undefined);
          helper = owner._lookupFactory(helperName, options);
        }
      }

Run ember s --prod Result of this for me is as follow, when it crashes:

Before helper:t true true
After undefined false
TypeError: Cannot read property '_lookupFactory' of undefined

As second console log runs, both helperName and owner are already "undefined" and obviously it crashes on "After _lookupFactory" console.log.

Edit: Keep in mind this helper:t is custom made not from ember-i18n.

typeoneerror commented 8 years ago

Sorry to +1 this, but not sure if I get subscribe to updates with just a "thumbs up emote".

Exact same error, only in production builds.

Chrome: 48.0.2564.116, 49.0.2623.87 MacOS: 10.9.5

raido commented 8 years ago

@stefanpenner with --nouse_inlining it does not seem to occur. I tried running with and without nouse_inlining couple of times and it never crashed when inlining was disabled. Running Chrome without flags i could get 5 out 7 reloads to crash with those console.logs in place from my previous comment. I still have to figure out how to make this reproducible on Twiddle or demo app.

2468ben commented 8 years ago

I've been seeing this since the start of February (2.3, then 2.4), OSX and Windows, Chrome only. Removing all custom Em.Helper.helpers and ember-truth-helpers stopped the errors from appearing (of course).

It's been a while since I ran into a bug that made me brush off my tinfoil hat. You are not alone. The truth is out there.

kategengler commented 8 years ago

Also seeing this in the error logs for EmberObserver.com. Chiming in because it might be useful since it's open source https://github.com/emberobserver/client

Also on Ember 2.4.1, seen on every route in the application, on Chrome or Chromium 48 on Windows 7, 8.1, 10, OS X and Ubuntu.

wycats commented 8 years ago

@typeoneerror fwiw I'm personally very happy to have people report that they experience the same bug while also providing environment details.

I'm not sure who exactly is supposed to be harmed by such reports :wink:

stefanpenner commented 8 years ago

Just opened a V8 bug, https://bugs.chromium.org/p/v8/issues/detail?id=4839.

Sorry I still haven't had any cycles to take a deeper look, hopefully soon.

krisselden commented 8 years ago

It was harder to reproduce for me than what was described but I was able to reproduce on a very recent Mac OS Chromium build Version 51.0.2671.4 (64-bit)

raido commented 8 years ago

I just saw this happening on a Twiddle with ember.prod.js build. Chrome 49.0.2623.87 (64-bit), OS X 10.11.3

Uncaught TypeError: Cannot read property '_lookupFactory' of undefined VM3158 ember.prod.js:11783

Reproduction still unclear, once i have steps for reproduction i will share the Twiddle here.

jakobkummerow commented 8 years ago

@raido It may help to run Chrome with --js-flags="--predictable", which turns off various features that are known to cause indeterminism (like anything involving background threads). Please do let me know when you find a good repro!

workmanw commented 8 years ago

:tada: Yay! I can see from our logs half a dozen or so people were able to reproduce this on various versions of chrome, including 51.

@krisselden I'm sorry about that. I think in my previous responses I had implied that it wasn't always reproducible, but I should have been explicit about that on the comment with the reproduction steps. Sometimes it just seems to not happen. There are still variables in play here I don't fully grasp. If I can't get it to easily happen after 2 or 3 attempts, restarting chrome can help.

@stefanpenner I have some cycles now and I've spent 6-8 hours trying to reproduce it in a twiddle. If you have any thoughts or hunches, I'd be happy to explore them. I just don't have enough domain knowledge about this problem.

raido commented 8 years ago

@workmanw @stefanpenner I have the same issue with knowledge about the whole problem that is going on here. My twiddle that used to crash often, now does it rarely and i have nothing changed except closed and opened Chrome couple of times (probably unrelated). It is really annoying.

@jakobkummerow I have not been able to crash my app with --predictable flag.

runspired commented 8 years ago

I've been trying to create a failing acceptance test here: https://github.com/runspired/bug-13071

bower_components is committed since ember.debug.js has been swapped for ember.prod.js. No luck so far in reproducing, but I'm on Chrome 47 which has no appeared above in any bug reports.

raido commented 8 years ago

@runspired I have tried that too with a Twiddle, it never crashed during tests but sometimes after completing tests and manually navigating around it would.

The Twiddle that i have been playing around with https://ember-twiddle.com/7fdf923d89ea37095cf3

Once i got it crash three times in row, like each transition ended with _lookupFactory message.

Edit: I managed to catch stackstraces of 3 crashes from the Twiddle on screencast, 2 of them are same, one is different. https://www.dropbox.com/s/51uwx6zo1scs7il/bug-13071.mp4?dl=1

krisselden commented 8 years ago

It is too hard for me to reliably reproduce this issue but my current suspect is this https://github.com/emberjs/ember.js/blob/cfed40154285501c19a60aef3c0f51c645c9d44d/packages/ember-runtime/lib/mixins/container_proxy.js#L115-L119 if anyone has an easier time reproducing, I would hand write the aliases and also not close over for the proxy target.

krisselden commented 8 years ago

@workmanw if I do a PR to avoid what I think is the problem can you test it out?