Closed Bug 620991 Opened 14 years ago Closed 14 years ago

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

Categories

(Core Graveyard :: Plug-ins, defect)

Product:
Core Graveyard
Component:
Plug-ins
Platform:
x86
Windows 7
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED FIXED
Milestone:
mozilla2.0b10

People

(Reporter: ted, Assigned: roc)

References

(
URL
)

Details

(Keywords: assertion, intermittent-failure)

Attachments

(1 file, 1 obsolete file)

fix v2
(deleted), patch
Details | Diff | Splinter Review 
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
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...
This is the same assert I keep seeing as well. My crashes usually involve google voice, which uses flash.
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...
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.
FWIW, the real failure is in test_visibility.html.  test_windowed_invalidate.html is just a red herring here.
(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...
I couldn't reproduce this locally.

Andreas, any chance you can test this on a m-c tip build?
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.
> 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...
Attached patch fix (obsolete) (deleted) — — 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 on attachment 506271 [details] [diff] [review]
fix

r=me.  I'll land it and re-enable the test.
Attachment #506271 - Flags: review+
http://hg.mozilla.org/mozilla-central/rev/afe951130c65

I'll mark this as FIXED.  Please reopen if it happens again.
Status: NEW → RESOLVED
Closed: 14 years ago
Keywords: checkin-needed
Resolution: --- → FIXED
Whiteboard: [orange][needs landing] → [orange]
Target Milestone: --- → mozilla2.0b10
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 → ---
Attached patch fix v2 (deleted) — — Splinter Review 
Sorry!
Attachment #506271 - Attachment is obsolete: true
Whiteboard: [orange] → [orange][needs landing]
http://hg.mozilla.org/mozilla-central/rev/e1419349c6fa
Status: REOPENED → RESOLVED
Closed: 14 years ago → 14 years ago
Resolution: --- → FIXED
Whiteboard: [orange][needs landing] → [orange]
Whiteboard: [orange]
Product: Core → Core Graveyard
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: