449809 - Properties on Javascript objects occasionally disappear

Status: RESOLVED WORKSFORME

(Core :: JavaScript Engine, defect)

Description

[Steve Dunham]

User-Agent:       Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.5; en-US; rv:1.9.0.1) Gecko/2008070206 Firefox/3.0.1
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.1) Gecko/2008070208 Firefox/3.0.1

Since Firefox 3 came out we've been been getting sporadic exceptions in our GWT application that indicate that properties had become "null" or disappeared during the course of execution of our code.  (N.B. the value in the prototype was "null".)

The most telling case is the following code (generated by GWT):

function $missingElement(this$static){
  var el, msg;
  el = createDiv();
  this$static.element = el;
  msg = 'FF3: Created missing element ' + el + ' ' + this$static.element;
  log_0(msg, $Error(new Error_0(), msg));
  return this$static.element;
}

Which logs the error "FF3: Created missing element [object HTMLDivElement] null"

this$static is a javascript object with a prototype whose value for the "element" property is null.  This particular method is called after we've already detected the problem.

There are cases where we've fetched a non-null value from this$static.element, and later, in the same thread of execution, it returns null.

My best guess, not knowing Firefox internals, is that the hash table on the object is getting into some weird state.

Reproducible: Sometimes

Steps to Reproduce:
We're seeing this one a daily basis while testing our GWT-based javascript application, but we can't reproduce it on demand.  I've been unable to construct a repeatable test case.



This has happened on multiple platforms OSX/PPC, OSX/Intel, WindowsXP, and in 3.0 and 3.0.1 versions of Firefox.

The application this occurs in is a rather large (2.4MB, 80kloc), single-page ajax application. The code paths that this happen in are successfully executed thousands of times - so this issue is non-deterministic.

We've seen a couple of cases with other properties on other objects, but they are much more rare.

Comment 1

[Steve Dunham]

Is it possible that the "property cache" is causing this?  

Two other code fragments that demonstrate the issue:

  function C_e(b,a){if(b.f===null){b.f=u_e(new t_e());}b.f.Ab(a);}

threw a "b.f is null" exception.  (note that u_e() returns its argument) and


function addClickListener_7(listener){
  if (this.clickListeners_0 === null) {
    this.clickListeners_0 = $ClickListenerCollection(new ClickListenerCollection());
  }
  this.clickListeners_0.add_3(listener);
}

threw a "this.clickListeners_0 is null" exception ($ClickListenerCollection() is an initializer which returns its argument.)

Comment 2

[Andreas Sterbenz]

I'm seeing the same issue.

Comment 3

[Steve Dunham]

I saw another instance today at a different location:

   JavaScript TypeError exception: this.widget_0 is null

occurred in this code:

  function isAttached(){
    if (this.widget_0 !== null) {
      return this.widget_0.isAttached();
    }
    return false;
  }

Comment 4

[Steve Dunham]

Attachment: Test case - load index.html, wait for "elem is null" exception

This will eventually trigger the issue, the amount of time it takes appears to be non-deterministic. (I've had it happen on iteration 83, on iteration 525, or get though 5000+ iterations without triggering the issue.)

Comment 5

[Steve Dunham]

Attachment: Test case - load index.html, wait for "elem is null" exception

Updated test case to draw fewer icons, shorten delay - hopefully it fails a little faster now.

Comment 6

[alancurtis]

I'm seeing the same problem as described above.  Here is one of the many times this has failed:

JS Code snippet:

function $Image_1(this$static, url, left, top, width, height){
28628 $clinit_505();
28629 this$static.state = $Image$ClippedState(new Image
$ClippedState(), this$static, url, left, top, width, height);
28630 this$static.element['className'] = 'gwt-Image';
28631 return this$static;
28632}

In Firebug, inspecting this$static, everything looks fine, with
'className' assigned "" going into $Image_1().  The resulting error
generated is " this$static.element is null". 

This problem does not occur in the Chrome browser, nor in IE 8 (beta).  (IE 7 has other problems that are not relevant here).  

My application has a bit of animation in it, and lots of images being drawn, moved, and removed.  The same type of error is occurring on several execution paths, with a common theme being that the element being reported as null was not null earlier in the stack, and that the element was not written to in the code execution path between a check for (not null) and when the null exception was encountered.  

My current workaround is a big try-catch around the code where the errors are coming from, and this appears to be working.  I'm still getting reported errors but it's not killing further JS execution on the page.

Comment 7

[alancurtis]

Another instance:

image.element is null

function $Image$ClippedState(this$static, image, url, left, top, width, height){
28715 var tmp, clippedImgHtml, style;
28716 this$static.width_0 = width;
28717 this$static.height_0 = height;
28718 $replaceElement_0(image, (tmp = $doc.createElement('span') , (tmp.innerHTML = (style = 'width: ' + width + 'px; height: ' + height + 'px; background: url(' + url + ') no-repeat ' + (-left + 'px ') + (-top + 'px') , clippedImgHtml = "<img src='" + $moduleBase + "clear.cache.gif' style='" + style + "' border='0'>" , clippedImgHtml) || '' , undefined) , $getFirstChildElement(tmp)));
28719 sinkEvents(image.element, 131197 | (image.element.__eventBits || 0));
28720 addCommand(new Image$ClippedState$1());
28721 return this$static;
28722}

Callstack is:
$Image$ClippedState(com.google.gwt.user.client.ui.Image$ClippedState@3 width_0=40 height_0=40 $H=3 typeId$=0, <img src="http://localhost:8080/myapp/com.myapp.Main/clear.cache.gif" style="background: transparent url(http://localhost:8080/myapp/com.myapp.Main/1B01A4FC23A25346F03AA64AAAC056CC.cache.png) no-repeat scroll -3180px -40px; width: 40px; height: 40px; -moz-background-clip: -moz-initial; -moz-background-origin: -moz-initial; -moz-background-inline-policy: -moz-initial;" border="0"> element=img typeId$=300 attached=false, "http://localhost:8080/myapp/com.myapp.Main/1B01A4FC23A25346F03AA64AAAC056CC.cache.png", 3180, 40, 40, 40)1C538BE3...ache.html (line 28727)
$Image_0(<img src="http://localhost:8080/myapp/com.myapp.Main/clear.cache.gif" style="background: transparent url(http://localhost:8080/myapp/com.myapp.Main/1B01A4FC23A25346F03AA64AAAC056CC.cache.png) no-repeat scroll -3180px -40px; width: 40px; height: 40px; -moz-background-clip: -moz-initial; -moz-background-origin: -moz-initial; -moz-background-inline-policy: -moz-initial;" border="0"> element=img typeId$=300 attached=false, "http://localhost:8080/myapp/com.myapp.Main/1B01A4FC23A25346F03AA64AAAC056CC.cache.png", 3180, 40, 40, 40)1C538BE3...ache.html (line 28650)
$createImage(com.google.gwt.user.client.ui.impl.ClippedImagePrototype@4)1C538BE3...ache.html (line 29447)
$showNextFrameOrientation(<div class="myAppPanel debugBorder" style="overflow: hidden; width: 40px; height: 40px;"></div>)1C538BE3...ache.html (line 35377)
animationUpdated_5(0.043654206298248566)1C538BE3...ache.html (line 30620)
$onUpdate_0(com.myapp.client.view.animation.LinearMovement@5 listeners=[], 0.043654206298248566)1C538BE3...ache.html (line 34957)
onUpdate_5(0.043654206298248566)1C538BE3...ache.html (line 34993)
$update_2(com.myapp.client.view.animation.LinearMovement@5 listeners=[], 1223580036386)1C538BE3...ache.html (line 7357)
updateAnimations()1C538BE3...ache.html (line 7404)
run_7()1C538BE3...ache.html (line 22583)
$fireImpl(com.google.gwt.animation.client.Animation$1@6 isRepeating=false timerId=549894 $H=6 typeId$=247)1C538BE3...ache.html (line 1436)
fire()1C538BE3...ache.html (line 1474)
createTimeout()()

Comment 8

[Steve Dunham]

The test case that I attached usually takes a while to fail - on the order of a half hour.  It usually fails with an "elem is null" exception and the iteration that it fails in varies wildly.  On various runs, it has failed in iterations: 13344, 90561, 48048, 155891, 37, 10016, 88718, and 19892.

Comment 9

[Jim Blandy :jimb]

I've reproduced this a few times live, but ran to 300k iterations in Xvfb (memory-only X server, no interference from user input) under varying amounts of processor load without problems.  So I can confirm the bug, but not reproduce it yet.  I have some more ideas I'll try tomorrow.

Comment 10

[Al Billings [:abillings - ex-MoCo]]

Jim, any updates on this during the last couple of weeks?

Comment 11

[Jim Blandy :jimb]

Unfortunately, I haven't had much success making this more reliably reproducible.  Running it on an artificial frame buffer (no disturbance from mouse or keyboard) doesn't help.  I've tried running it under Chronicle (http://code.google.com/p/chronicle-recorder/), but Chronicle disturbs Mozilla's execution, such that it doesn't run at all; I wasn't able to understand valgrind + Chronicle enough to fix that.  (It's also not clear that a Chronicle log for a program that runs for 30 minutes in real time would fit on my disk, so using Chronicle would have to go along with a quicker reproduction recipe.)

My current best guess is that one of the support threads is writing somewhere it shouldn't; with some random changes to the timeouts, I let it run to 600k iterations overnight without encountering the bug.

Next step will be trying Helgrind, the valgrind thread race condition detector.

Comment 12

[Jesse Ruderman]

Have you tried triggering garbage collection at different times?  Or using gczeal?

Comment 13

[Jason Orendorff [:jorendorff]]

Another thing to try is setting a breakpoint in js_ReportIsNullOrUndefined (where that error is reported) and checking the JSObject in various ways.  Dumping the object with js_DumpObject is a nice start.

The test case can probably be boiled down a little more.  It would be nice to get it all in a single page.

Comment 14

[bufflike film dude]

Are there possibly other instances of this issue logged, but not related, in bugzilla?

Comment 15

[Jim Blandy :jimb]

Sayrer says to try the tip of valgrind SVN: drd, and new helgrind.

Comment 16

[Ray Ryan]

We've been running Steve's sample app against FireFox 3.5 beta 3 and the mystery nulls are not happening. 

If anyone knows what change might have fixed this, any chance of picking it up in 3.0.10, presuming there will be such a thing?

Comment 17

[Jim Blandy :jimb]

Unfortunately, we don't know what fixed it.  I found it very hard to reproduce to begin with.

Comment 18

[Johnny Stenback (:jst)]

Ray, any chance you guys could find out a time frame when this was fixed, knowing a specific date (which you can find if you're able to reproduce this by testing nightly trunk builds to isolate when the fix went in). Seems like we're having a hard time to reproduce this, and w/o that, it'll be extremely hard to know what fixed this so we can consider backporting the fix etc.

Comment 19

[Ray Ryan]

The earliest reference I find is on 22 April 2009, where someone reported:

I built Firefox on Linux from the latest source (aka Firefox 3.5) and ran the testcase.

I haven't been able to find an actual version number or svn url yet, that info might be lost.

Comment 20

[alancurtis]

The last version that I can see from my log files where the error *is* occurring is firefox/3.0.13 if that's any help.  I haven't seen it with 3.5 or above.

Comment 21

[Johnny Stenback (:jst)]

The best think I can think of to do here to track down when this problem showed up is to find a nightly build (available for download at ftp://ftp.mozilla.org/pub/firefox/nightly/2009/) from back before this was first seen and then do a binary search using builds from that date range to find out when this was fixed. Depending on how easy it is to reproduce this for those who can reproduce this, this could be fairly fast, or it could take a while to do. But that's the best I've got.

Comment 22

[Jim Blandy :jimb]

I have not been able to reproduce this problem at all, so I'm going to mark this WORKSFORME.  If anyone is able to reproduce it using the current sources, please re-open this bug.