510489 - mochitest-browser-chrome causes millions of ASSERTIONS "XPConnect is being called on a scope without a 'Components' property!"

Status: RESOLVED WORKSFORME

(Testing :: Code Coverage, defect)

Description

[Murali Nandigama [:murali]]

Dave Townsend was investigating XPINSTALL code coverage issues and tried to 'bunzip2' the mochitest-browser-chrome.log.bz2 file.

He got the following error

I'm trying to look at one of the logs from this run however it appears
to be corrupt. I get the following:

lambda:logs dave$ bunzip2 -v mochitest-browser-chrome.log.bz2
   mochitest-browser-chrome.log.bz2:
bunzip2: Compressed file ends unexpectedly;
        perhaps it is corrupted?  *Possible* reason follows.
bunzip2: No such file or directory
        Input file = mochitest-browser-chrome.log.bz2, output file =
mochitest-browser-chrome.log

It is possible that the compressed file(s) have become corrupted.
You can use the -tvv option to test integrity of such files.

You can use the `bzip2recover' program to attempt to recover
data from undamaged sections of corrupted files.

bunzip2: Deleting output file mochitest-browser-chrome.log, if it exists. 


When I tried it on winXP 32 bit with WinRAR, I got the following error after 100% unrar activity.

!   C:\Documents and Settings\mnandigama\Local Settings\Temp\Rar$DI00.531\mochitest-browser-chrome.log.bz2: Unexpected end of archive


This is by far the biggest log file in the full packet. 

Please help.

Comment 1

[Nick Thomas [:nthomas] (UTC+12)]

Buildbot terminated the mochitest-browser-chrome part of the run when it got no output after 43200 seconds. IIRC the process list had fix-linux-stack.pl running, so this looks like fallout from bug 385248.

Comment 2

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

fix-linux-stack.pl should be running the entire time the test is running.  I don't think the fact that it's running says that it's the source of the problem.

Comment 3

[Armen [:armenzg]]

This happened in the run of:
- Tue Aug 11 21:56:42 2009
- Sat Aug 15 03:02:01 2009

I assume this can be tried to be fixed/tracked down by doing local runs, right?

Who could take ownership of it?

Comment 4

[Murali Nandigama [:murali]]

Armen, I presume the question is directed to team members of RE team. Some one who runs it on the RE setup only can reproduce it to validate the scenario.

Comment 5

[Nick Thomas [:nthomas] (UTC+12)]

The sequence of problems is
* mochitest-browser-chrome log is corrupted, because
* buildbot aborted the mochitest-browser-chrome after it failed to complete within 12 hours, because
* there are more than 2 million instances of
!!! ASSERTION: XPConnect is being called on a scope without a 'Components' property!: 'Error', file /builds/moz2_slave/mozilla-central-linux-codecoverage/build/js/src/xpconnect/src/xpcwrappednativescope.cpp, line 786
in the bzip2recover'd log, which is several GB in size when uncompressed.

The way to solve the problem is to prevent the ASSERTIONS, and so avoid many many calls to fix-linux-stack.pl. No idea if this is a problem in the Firefox code, or code-coverage, or both, but I note that we hit approximately 175 of these ASSERTIONS if you run mochitest-browser-chrome on a regular linux debug build.

Comment 6

[Nick Thomas [:nthomas] (UTC+12)]

Attachment: The first 4.5M of log output (compressed)

The first 5 log fragments from bzip2recover. There are 1023 XPConnect assertions in here, plus 13 other miscellaneous ones.

Comment 7

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

According to bug 372581 comment 84 this is not specific to codecoverage, and probably blocks enabling unit tests on debug builds.

Comment 8

[Serge Gautherie (:sgautherie)]

Fwiw, see
https://bugzilla.mozilla.org/buglist.cgi?query_format=advanced&short_desc_type=allwordssubstr&short_desc=XPConnect+is+being+called&resolution=---&cmdtype=doit

Comment 9

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

http://hg.mozilla.org/users/dbaron_mozilla.com/patches/raw-file/56363c473a65/no-components-dump-stack is a patch that will add more information (the JS stack, which is critical for diagnosing what's going on with this assertion) to the logs.

Could somebody who's seeing millions of assertions here do a run with that patch and attach a reasonable subset of the log so we can see what their cause is?  (I'm seeing 117 of these assertions on a full mochitest-browser-chrome run, and from various causes.  So a "reasonable subset" should include at least a few hundred just so we can see which is causing the large number; probably around 1000 is best.)

Comment 10

[Murali Nandigama [:murali]]

I'm on it

Comment 11

[Murali Nandigama [:murali]]

dbaron, your patch failed to apply on the trunk

mnandigama@murali-desktop:~/src$ hg import ../no-components-dump-stack 
applying ../no-components-dump-stack
patching file js/src/xpconnect/src/xpcwrappednativescope.cpp
Hunk #1 FAILED at 774
1 out of 1 hunk FAILED -- saving rejects to file js/src/xpconnect/src/xpcwrappednativescope.cpp.rej
abort: patch failed to apply

Comment 12

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Just hand-edit in the one line right below that NS_ERROR, then.

Comment 13

[Murali Nandigama [:murali]]

Attachment: This is a tar.bz2 ball of the mochitest-browser-chrome STDOUT

tar.bz2 file

Comment 14

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Attachment: unique stacks in attachment 398813

Here's the output of:

grep "\(XPConnect is being\|^<function \|^file \)" browserchromelog.log | tr '\n\a' ' \n' | sort | uniq -c


unfortunately, the vast majority of the assertions (197118 of 197255) have no stack printed.  I'm not sure why that would happen.

However, all of the assertions with no stack printed are during shutdown of the tests, and the only useful information printed (other than the stack to the assertions) is a JavaScript error.  I'll attach the bit that repeats in the next attachment.

Comment 15

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Attachment: the part that repeats

Here's the part that repeats 98553 times (although I think the stacks change for the last few repetitions):  two assertions and then a JS error.


Near the end of these repetitions, there are two other messages I noticed that *could* be related:

************************************************************
* Call to xpconnect wrapped JSObject produced this error:  *
[Exception... "'[JavaScript Error: "this.outputStream is null" {file: "file:///home/mnandigama/mozcentral-dbg/dist/bin/components/GPSDGeolocationProvider.js" line: 226}]' when calling method: [nsIGeolocationProvider::shutdown]"  nsresult: "0x80570021 (NS_ERROR_XPC_JAVASCRIPT_ERROR_WITH_DETAILS)"  location: "<unknown>"  data: yes]
************************************************************

************************************************************
* Call to xpconnect wrapped JSObject produced this error:  *
[Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIObserverService.removeObserver]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: file:///home/mnandigama/mozcentral-dbg/dist/bin/components/NetworkGeolocationProvider.js :: anonymous :: line 375"  data: no]
************************************************************

Comment 16

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

(In reply to comment #14)
> stack printed.  I'm not sure why that would happen.

Actually, I do know:  there's no JS on the stack at the time, so there's nothing to print.

Comment 17

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

The console service uses XPCOM proxies, though, so the assertions seem likely to be related to that error message, and perhaps to some unbalanced calls here:
http://mxr.mozilla.org/mozilla-central/search?string=registerlistener

Comment 18

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

What command line did you use to run the tests?

Comment 19

[Murali Nandigama [:murali]]

make mochitest-browser-chrome from the OBJDIR

Comment 20

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Attachment: debugging patch

This adds sufficient debugging information to debug these assertions based on the output.  (The dumping-the-object part is the most useful, but I think the JS stack has turned out to be useful in one warning.)

Comment 21

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Attachment: debugging patch part 2: dump filename and line number

As the reviewer of http://hg.mozilla.org/mozilla-central/rev/fb3a90e23a98 , I claim you're a good reviewer for this as well.  This should eliminate most of the guesswork from the analysis I've been doing with the above patch, though I still need to get a new set of mochitest logs with it.

Comment 22

[Blake Kaplan (:mrbkap) (inactive)]

Comment on attachment 492731 [details] [diff] [review]
debugging patch

I wonder if xpc_DumpJSStack might work as well or better.

Comment 23

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Attachment: debugging patch

Revised per your suggestion, and also to loop over proxies since there are a bunch of assertions in some of the mochitest-plain tests that require such a loop.

Comment 24

[Blake Kaplan (:mrbkap) (inactive)]

Comment on attachment 492902 [details] [diff] [review]
debugging patch

>diff --git a/js/src/xpconnect/src/xpcwrappednativescope.cpp b/js/src/xpconnect/src/xpcwrappednativescope.cpp
>+    while (p->isProxy()) {

Nit: while( instead of while ( and brace on the next line.

>+        p = p->getProxyPrivate().toObjectOrNull();
>+        if(!p)
>+            break;
>+        printf("which is a proxy for:\n");
>+        js_DumpObject(p);

Non-nit: you probalby |while (p->isWrapper()) { ... same body ... }| instead of isProxy.

r=me with those addressed.

Comment 25

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Landed the debugging patches:
http://hg.mozilla.org/mozilla-central/rev/64a2a3834927
http://hg.mozilla.org/mozilla-central/rev/e71b310f0484

Comment 26

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

And I relanded the part of the debugging patch that I previously had to revert:
http://hg.mozilla.org/mozilla-central/rev/bc2fda9a8b32

Comment 27

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

(I believe what made it safe to reland was
http://hg.mozilla.org/mozilla-central/rev/9f34bdaf1495 .)

Comment 28

[Phil Ringnalda (:philor)]

I believe bug 631447 says it wasn't very safe: a suite-aborting infinite loop of assertions and stacks ending in a 50MB log that was too much for anyone to bother looking at for two weeks, with the extra bonus on OS X of failing to kill httpd.js so that it not only aborts mochitest-browser-chrome, but also kills mochitest-ipcplugins.

Comment 29

[Ryan VanderMeulen [:RyanVM]]

This assertion is long gone.