test_windowed_invalidate.html runs after mochitest shutdown, trips assertion / JS_Assert

RESOLVED FIXED in mozilla2.0b10

Status

()

defect
RESOLVED FIXED
9 years ago
7 years ago

People

(Reporter: ted, Assigned: roc)

Tracking

({assertion, intermittent-failure})

Trunk
mozilla2.0b10
x86
Windows 7
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

()

Attachments

(1 attachment, 1 obsolete attachment)

From the log in the URL:
555 INFO TEST-START | /tests/modules/plugin/test/test_windowed_invalidate.html
556 INFO TEST-END | /tests/modules/plugin/test/test_windowed_invalidate.html | finished in 30ms
557 INFO TEST-START | Shutdown
558 INFO Passed: 494
559 INFO Failed: 0
560 INFO Todo:   0
561 INFO SimpleTest FINISHED
562 INFO TEST-PASS | /tests/modules/plugin/test/test_windowed_invalidate.html | Plugin became invisible again.
++DOMWINDOW == 36 (0C7E0B20) [serial = 190] [outer = 090C40A8]
WARNING: getting z level of unregistered window: file e:/builds/moz2_slave/cen-w32-dbg/build/xpfe/appshell/src/nsWindowMediator.cpp, line 606
WARNING: getting z level of unregistered window: file e:/builds/moz2_slave/cen-w32-dbg/build/xpfe/appshell/src/nsWindowMediator.cpp, line 606
WARNING: NS_ENSURE_SUCCESS(rv, 0) failed with result 0x8000FFFF: file e:/builds/moz2_slave/cen-w32-dbg/build/content/base/src/nsContentUtils.cpp, line 2899
WARNING: NS_ENSURE_TRUE(pusher.Push(aBoundElement)) failed: file e:/builds/moz2_slave/cen-w32-dbg/build/content/xbl/src/nsXBLProtoImplMethod.cpp, line 327
--DOCSHELL 088ADF70 == 6
WARNING: NS_ENSURE_SUCCESS(rv, 0) failed with result 0x8000FFFF: file e:/builds/moz2_slave/cen-w32-dbg/build/content/base/src/nsContentUtils.cpp, line 2899
WARNING: NS_ENSURE_TRUE(pusher.Push(aBoundElement)) failed: file e:/builds/moz2_slave/cen-w32-dbg/build/content/xbl/src/nsXBLProtoImplMethod.cpp, line 327
WARNING: NS_ENSURE_SUCCESS(rv, 0) failed with result 0x8000FFFF: file e:/builds/moz2_slave/cen-w32-dbg/build/content/base/src/nsContentUtils.cpp, line 2899
WARNING: NS_ENSURE_TRUE(pusher.Push(aBoundElement)) failed: file e:/builds/moz2_slave/cen-w32-dbg/build/content/xbl/src/nsXBLProtoImplMethod.cpp, line 327
WARNING: NS_ENSURE_SUCCESS(rv, 0) failed with result 0x8000FFFF: file e:/builds/moz2_slave/cen-w32-dbg/build/content/base/src/nsContentUtils.cpp, line 2899
WARNING: NS_ENSURE_TRUE(pusher.Push(aBoundElement)) failed: file e:/builds/moz2_slave/cen-w32-dbg/build/content/xbl/src/nsXBLProtoImplMethod.cpp, line 327
WARNING: NS_ENSURE_SUCCESS(rv, 0) failed with result 0x8000FFFF: file e:/builds/moz2_slave/cen-w32-dbg/build/content/base/src/nsContentUtils.cpp, line 2899
WARNING: NS_ENSURE_TRUE(pusher.Push(aBoundElement)) failed: file e:/builds/moz2_slave/cen-w32-dbg/build/content/xbl/src/nsXBLProtoImplMethod.cpp, line 327
--DOCSHELL 0470ED00 == 5
WARNING: NS_ENSURE_SUCCESS(rv, 0) failed with result 0x8000FFFF: file e:/builds/moz2_slave/cen-w32-dbg/build/content/base/src/nsContentUtils.cpp, line 2899
WARNING: NS_ENSURE_TRUE(pusher.Push(aBoundElement)) failed: file e:/builds/moz2_slave/cen-w32-dbg/build/content/xbl/src/nsXBLProtoImplMethod.cpp, line 327
WARNING: NS_ENSURE_SUCCESS(rv, 0) failed with result 0x8000FFFF: file e:/builds/moz2_slave/cen-w32-dbg/build/content/base/src/nsContentUtils.cpp, line 2899
WARNING: NS_ENSURE_TRUE(pusher.Push(aBoundElement)) failed: file e:/builds/moz2_slave/cen-w32-dbg/build/content/xbl/src/nsXBLProtoImplMethod.cpp, line 327
###!!! ASSERTION: XPConnect is being called on a scope without a 'Components' property!  (stack and details follow): 'Error', file e:/builds/moz2_slave/cen-w32-dbg/build/js/src/xpconnect/src/xpcwrappednativescope.cpp, line 781
And the object whose scope lacks a 'Components' property is:
[ useless stack elided ]

object 0E19E968
class 6E2D3188 Object
flags: none
properties:
    enumerate "run": slot 0
proto <Object at 0B57C820>
parent <Window object at 0B57C7D0>
slots:
   0 = <unnamed function (http://mochi.test:8888/tests/SimpleTest/SimpleTest.js:520) at 0E19E9A0 (JSFunction at 0E159230)>

Assertion failure: obj->containsSlot(slot), at e:/builds/moz2_slave/cen-w32-dbg/build/js/src/jsinterp.cpp:5311

(the stack from the JS_Assert doesn't seem all that interesting.)

I don't really know if this is a bug in the test, the harness, or the JS engine, honestly.
Keywords: assertion
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)

Comment 73

9 years ago
In the logs, we see:

551 INFO TEST-PASS | /tests/modules/plugin/test/test_visibility.html | Plugin should not be visible.
552 INFO TEST-PASS | /tests/modules/plugin/test/test_visibility.html | Plugin should not have painted. (expected 0 independent paints, expected 0 logged paints, got 0 actual paints)
553 INFO TEST-PASS | /tests/modules/plugin/test/test_visibility.html | Plugin should now be visible.
554 INFO TEST-PASS | /tests/modules/plugin/test/test_visibility.html | Plugin should have painted once. (expected 1 independent paints, expected 2 logged paints, got 2 actual paints)
555 INFO TEST-PASS | /tests/modules/plugin/test/test_visibility.html | Plugin should now be visible.
556 INFO TEST-PASS | /tests/modules/plugin/test/test_visibility.html | Plugin should have painted once. (expected 1 independent paints, expected 2 logged paints, got 2 actual paints)
557 INFO TEST-PASS | /tests/modules/plugin/test/test_visibility.html | Plugin should still be visible.
558 INFO TEST-PASS | /tests/modules/plugin/test/test_visibility.html | Plugin should have painted twice. (expected 2 independent paints, expected 4 logged paints, got 4 actual paints)
559 INFO TEST-PASS | /tests/modules/plugin/test/test_visibility.html | Plugin should still be visible.
560 INFO TEST-PASS | /tests/modules/plugin/test/test_visibility.html | Plugin should have painted twice. (expected 2 independent paints, expected 4 logged paints, got 4 actual paints)
561 INFO TEST-PASS | /tests/modules/plugin/test/test_visibility.html | Plugin became invisible again.
562 INFO TEST-PASS | /tests/modules/plugin/test/test_visibility.html | Plugin became invisible again.
563 INFO TEST-PASS | /tests/modules/plugin/test/test_visibility.html | Plugin became invisible again.
564 INFO TEST-PASS | /tests/modules/plugin/test/test_visibility.html | Plugin became invisible again.
565 INFO TEST-PASS | /tests/modules/plugin/test/test_visibility.html | Plugin became invisible again.
566 INFO TEST-END | /tests/modules/plugin/test/test_visibility.html | finished in 1196ms
567 INFO TEST-START | /tests/modules/plugin/test/test_windowed_invalidate.html
568 INFO TEST-PASS | /tests/modules/plugin/test/test_windowed_invalidate.html | Plugin became invisible again.
569 INFO TEST-END | /tests/modules/plugin/test/test_windowed_invalidate.html | finished in 78ms

The interesting thing here are the five "Plugin became invisible again" messages.  Here is the code which is responsible to make sure that we won't see five of those messages:

<http://mxr.mozilla.org/mozilla-central/source/modules/plugin/test/mochitest/test_visibility.html?force=1#81>

In other words, it seems that the clearInterval call is failing to clear the interval every time it's being called, until the finish's timeout kicks in and "finishes" the test, which leaves the interval running in the background.

Now, why the interval keeps running after the page unload is another story in itself, but we should debug to see why the failure is happening...

Comment 74

9 years ago
This is the same assert I keep seeing as well. My crashes usually involve google voice, which uses flash.
Comment hidden (Legacy TBPL/Treeherder Robot)

Comment 76

9 years ago
This might have some significance, since the test plugin is involved in this case.  I'm building on Windows right now to run the test under the debugger to see what happens in nsGlobalWindow::ClearInterval...

Comment 77

9 years ago
We think what happens here is that we do JS_ClearScope and then try to run a function that was previously compiled as compile-and-go against that cleared object, and it reaches into non-existing slots. If you can break on this that would be great. I am not currently able to reproduce this with TM tip.

Comment 78

9 years ago
FWIW, the real failure is in test_visibility.html.  test_windowed_invalidate.html is just a red herring here.

Comment 79

9 years ago
(In reply to comment #77)
> We think what happens here is that we do JS_ClearScope and then try to run a
> function that was previously compiled as compile-and-go against that cleared
> object, and it reaches into non-existing slots. If you can break on this that
> would be great.

That makes a lot of sense...

> I am not currently able to reproduce this with TM tip.

Can you try m-c tip too?  I'm building, and I can run the test under a profiler, but I'd have to ping you on IRC because I wouldn't have any idea how to debug this...

Comment 80

9 years ago
I couldn't reproduce this locally.

Andreas, any chance you can test this on a m-c tip build?
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Disabled test_visibility.html on Windows in http://hg.mozilla.org/mozilla-central/rev/1ceb49844869 - if nothing else, maybe it'll let us see that the leak has nothing to do with this.
Comment hidden (Legacy TBPL/Treeherder Robot)
> In other words, it seems that the clearInterval call is failing to clear

The relevant thing there looks to be this part of the log:

557 INFO TEST-PASS | /tests/modules/plugin/test/test_visibility.html | Plugin
should still be visible.
559 INFO TEST-PASS | /tests/modules/plugin/test/test_visibility.html | Plugin
should still be visible.

That message only happens in part3().  So part3() is running twice, and setting up the interval twice, and clobbering the interval id of the first interval the second time.  Then of course the first interval never gets cleared.

And the reason part3() runs twice is this, presumably:

553 INFO TEST-PASS | /tests/modules/plugin/test/test_visibility.html | Plugin
should now be visible.
555 INFO TEST-PASS | /tests/modules/plugin/test/test_visibility.html | Plugin
should now be visible.

which means part2() is running twice.  

I have no idea how part2 manages to run twice, though...
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Posted patch fix (obsolete) — Splinter Review
This should fix it.

We can run part2 twice because of async plugin painting. We might get asked to paint the plugin multiple times and each one will trigger the didPaint callback off a timer, so we can trigger multiple calls to part2 before the first part2 callback has had a chance to run.
Assignee: nobody → roc
Keywords: checkin-needed
Whiteboard: [orange] → [orange][needs landing]
We need a review here.
You should also reënable the test.  (See comment 102.)

Comment 114

9 years ago
Comment on attachment 506271 [details] [diff] [review]
fix

r=me.  I'll land it and re-enable the test.
Attachment #506271 - Flags: review+

Comment 115

9 years ago
http://hg.mozilla.org/mozilla-central/rev/afe951130c65

I'll mark this as FIXED.  Please reopen if it happens again.
Status: NEW → RESOLVED
Last Resolved: 9 years ago
Keywords: checkin-needed
Resolution: --- → FIXED
Whiteboard: [orange][needs landing] → [orange]
Target Milestone: --- → mozilla2.0b10

Comment 116

9 years ago
Backed out the patch because of test failure:

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1295844756.1295845443.2174.gz
96801 INFO TEST-START | /tests/modules/plugin/test/test_visibility.html
96802 ERROR TEST-UNEXPECTED-FAIL | /tests/modules/plugin/test/test_visibility.html | [SimpleTest/SimpleTest.js, window.onerror] An error occurred - didPaint is not defined at http://mochi.test:8888/tests/modules/plugin/test/test_visibility.html:93

http://hg.mozilla.org/mozilla-central/rev/064c6937f64e
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Posted patch fix v2Splinter Review
Sorry!
Attachment #506271 - Attachment is obsolete: true
Whiteboard: [orange] → [orange][needs landing]

Comment 118

8 years ago
http://hg.mozilla.org/mozilla-central/rev/e1419349c6fa
Status: REOPENED → RESOLVED
Last Resolved: 9 years ago8 years ago
Resolution: --- → FIXED
Whiteboard: [orange][needs landing] → [orange]
Whiteboard: [orange]
You need to log in before you can comment on or make changes to this bug.