Eric Rahm [:erahm] Reporter
	Description • 8 years ago

> 2622 WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file layout/style/Loader.cpp, line 2157

This warning [1] shows up in the following test suites:

>    620 - desktop-test-linux64/debug-mochitest-devtools-chrome-3 dt3
>    516 - desktop-test-linux64/debug-mochitest-devtools-chrome-6 dt6
>    351 - desktop-test-linux64/debug-mochitest-devtools-chrome-1 dt1
>    190 - desktop-test-linux64/debug-mochitest-devtools-chrome-2 dt2
>    180 - desktop-test-linux64/debug-mochitest-devtools-chrome-8 dt8
>    176 - desktop-test-linux64/debug-mochitest-devtools-chrome-4 dt4
>    129 - desktop-test-linux64/debug-mochitest-browser-chrome-1 bc1
>    129 - desktop-test-linux64/debug-mochitest-browser-chrome-e10s-5 bc5
>     55 - desktop-test-linux64/debug-mochitest-devtools-chrome-10 dt10
>     53 - desktop-test-linux64/debug-mochitest-clipboard cl
>     52 - desktop-test-linux64/debug-mochitest-devtools-chrome-7 dt7
>     50 - desktop-test-linux64/debug-mochitest-clipboard-e10s cl
>     26 - desktop-test-linux64/debug-mochitest-devtools-chrome-5 dt5
>     21 - desktop-test-linux64/debug-mochitest-chrome-3 c3
>     14 - desktop-test-linux64/debug-mochitest-devtools-chrome-9 dt9
>     13 - desktop-test-linux64/debug-mochitest-chrome-2 c2
>     12 - desktop-test-linux64/debug-mochitest-chrome-1 c1
>      5 - desktop-test-linux64/debug-mochitest-browser-chrome-e10s-3 bc3
>      4 - desktop-test-linux64/debug-mochitest-browser-chrome-4 bc4
>      4 - desktop-test-linux64/debug-mochitest-browser-chrome-7 bc7
>      4 - desktop-test-linux64/debug-mochitest-browser-chrome-e10s-7 bc7
>      4 - desktop-test-linux64/debug-mochitest-browser-chrome-3 bc3
>      3 - desktop-test-linux64/debug-mochitest-browser-chrome-e10s-2 bc2
>      3 - desktop-test-linux64/debug-mochitest-browser-chrome-e10s-4 bc4
>      2 - desktop-test-linux64/debug-mochitest-browser-chrome-6 bc6
>      2 - desktop-test-linux64/debug-mochitest-browser-chrome-e10s-6 bc6
>      2 - desktop-test-linux64/debug-mochitest-browser-chrome-2 bc2
>      1 - desktop-test-linux64/debug-mochitest-a11y a11y
>      1 - desktop-test-linux64/debug-mochitest-browser-chrome-5 bc5

It shows up in 1009 tests. A few of the most prevalent:

>     28 - [e10s] browser/components/preferences/in-content/tests/browser_cookies_exceptions.js
>     28 -        browser/components/preferences/in-content/tests/browser_cookies_exceptions.js
>     18 -        devtools/client/inspector/markup/test/browser_markup_events_jquery_1.6.js
>     17 -        devtools/client/inspector/test/browser_inspector_select-last-selected.js
>     16 -        browser/components/preferences/in-content/tests/browser_subdialogs.js
>     16 -        devtools/client/inspector/markup/test/browser_markup_events_jquery_1.7.js
>     16 - [e10s] browser/components/preferences/in-content/tests/browser_subdialogs.js
>     15 -        devtools/client/inspector/markup/test/browser_markup_events_jquery_1.3.js
>     14 -        devtools/client/inspector/markup/test/browser_markup_events_jquery_1.4.js
>     13 -        devtools/client/inspector/markup/test/browser_markup_events2.js

[1] https://hg.mozilla.org/mozilla-central/annotate/62f79d676e0e/layout/style/Loader.cpp#l2157

	Eric Rahm [:erahm] Reporter
	Comment 1 • 8 years ago

Bisection points to:

https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=1c1d78ab773ca5bce52238fc2155c0eabc626e0c&tochange=54e0b3c264e59bfb4a1d943558d56512502e7339

Which is bug 1187335, lets move this over to service workers. Tom can you take a look?

	Tom Tung [:tt, :ttung]
	Comment 2 • 8 years ago

Sure, I would like to take a look at this bug.

	Tom Tung [:tt, :ttung]
	Comment 3 • 8 years ago

Hi Eric,

I don't think those warning messages are related to bug 1187335 or service workers. 

I rollback the code to the changeset (313122:1c1d78ab773c) before bug 1187335 was landing and pushed it to try [1]. I found out that the warning have already existed in raw log of dt3 and dt6 [2] [3]. It used to be |WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /home/worker/workspace/build/src/layout/style/Loader.cpp, line 2139| and it became |line 2157| after the patches for bug 1187335 was landed.

I tried to log the error message in try [4] because I cannot reproduce it in local. I found out
that the warning happens because the failures return from |channel->AsyncOpen2| [5], which doesn't seem to be related to bug 1187335.

[1] https://treeherder.mozilla.org/#/jobs?repo=try&revision=dee277015b03&selectedJob=27949732
[2] https://public-artifacts.taskcluster.net/W10qkcRARjuhu_kzKifYjA/0/public/logs/live_backing.log
[3] https://public-artifacts.taskcluster.net/fKULbCthQueJe83S5ckfOQ/0/public/logs/live_backing.log
[4] https://treeherder.mozilla.org/#/jobs?repo=try&revision=f29ced23a4a1&selectedJob=27946994
[5] http://searchfox.org/mozilla-central/source/layout/style/Loader.cpp#1730

	Tom Tung [:tt, :ttung]
	Comment 4 • 8 years ago

I compared the warning numbers for Loader.cpp line 2139/2157 among the raw log of linux64-debug for dt1 dt2 dt3 dt4 dt6 dt8 in both the changeset [1] which landed my patches and the changeset [2] before landed my patches in m-c. The both total warning numbers for Loader.cpp line 2139/2157 are 401. So there are no different between them. 

[1] https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&revision=176aff980979bf588baed78c2824571a6a7f2b96
[2] https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&revision=e6e733f522a584cddd27ec255d801983a9f9051e

	Eric Rahm [:erahm] Reporter
	Comment 5 • 8 years ago

It appears you win the prize for touching layout/style/loader.cpp last in cset 126d0c86f8ee4288ded7fc349e79d5e9bde0152e. Bisector got confused by the line changes, sorry for the confusion!

	Eric Rahm [:erahm] Reporter
	Comment 6 • 8 years ago

Further semi-manual bisection points to:

https://hg.mozilla.org/integration/fx-team/pushloghtml?fromchange=2f9e69c982f1e67887a1834b36ff0af4ababb3af&tochange=3db372da6fe108ddb0727003447f22c2483fb86d

That looks like a checkin-needed push, so there's several bugs combined making it harder to bisect further.

> ryanvm@gmail.com Fri Jul 15 21:14:29 2016 +0000
> 	3db372da6fe1	Edouard Oger — Bug 677372 - Send Tab/Page/Link to device. r=markh, a=KWierso
> 	53236b4393f2	Edouard Oger — Bug 1244597 - Show notification on incoming tab. r=markh
> 	9125083b8dfe	Thom Chiovoloni — Bug 1268912 - Use unicode apostrophe for client.name2 in sync properties, working around issues with sync tests. r=markh
> 	f249501590e6	Jan Odvarko — Bug 1259819 - HTML Sidebar component. r=pbro
> 	e0e3108d38d8	Lin Clark — Bug 1285053 - New console frontend: use variables view link for object inspection. r=bgrins
> 	c49f826bb58e	Nicolas Chevobbe — Bug 1286700 - Reps: Fix function import in text-node.js. r=Honza
> 	25d022b355be	Jason Laster — Bug 1286390 - Add sourceMapURL to source actor form. r=jlongster

This seems a bit more legit for the good/bad transition:

> $ log_spam report --repo fx-team 2f9e69c982f1Using cached data
> Reading cache from fx-team-2f9e69c982f1-linux64/results.json
> Top 40 Warnings
> ===============
>  22908 WARNING: No inner window available!: file dom/base/nsGlobalWindow.cpp, line 10026
>   3711 WARNING: 'NS_FAILED(rv)', file dom/url/URL.cpp, line 228
>   3560 WARNING: Please do not use mouseenter/leave events in chrome. They are slower than mouseover/out!: '!nsContentUtils::IsChromeDoc(d)', file dom/events/EventListenerManager.cpp, line 398
>   2271 WARNING: Failed to retarget HTML data delivery to the parser thread.: file parser/html/nsHtml5StreamParser.cpp, line 967
>   1875 WARNING: NS_ENSURE_TRUE(ParseTypeAttribute(type, &version)) failed: file dom/base/nsScriptLoader.cpp, line 1287
>   1870 WARNING: A control runnable was posted to a worker that is already shutting down!: file dom/workers/WorkerPrivate.cpp, line 2496
>   1752 WARNING: NS_ENSURE_SUCCESS(status, status) failed with result 0x805303F4: file netwerk/protocol/http/nsCORSListenerProxy.cpp, line 553
>   1677 WARNING: data callback fires before cubeb_stream_start() is called: file dom/media/AudioStream.cpp, line 597
>   1372 WARNING: 'NS_FAILED(res)', file editor/libeditor/EditorBase.cpp, line 663
>   1225 WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x8007000E: file dom/xul/nsXULPrototypeCache.cpp, line 323
>   1165 WARNING: NS_ENSURE_TRUE(maybeContext) failed: file xpcom/threads/nsThread.cpp, line 921
>   1109 WARNING: NS_ENSURE_TRUE(content && aRange) failed: file editor/txtsvc/nsFilteredContentIterator.cpp, line 239
>   1101 WARNING: Silently denied access to property (void 0): Access to privileged JS object not permitted (@(null):0:0): file js/xpconnect/wrappers/XrayWrapper.cpp, line 214
>   1077 WARNING: NS_ENSURE_TRUE(startupCache) failed: file dom/xbl/nsXBLDocumentInfo.cpp, line 265
>   1077 WARNING: NS_ENSURE_TRUE(startupCache) failed: file dom/xbl/nsXBLDocumentInfo.cpp, line 198
>   1042 WARNING: attempt to modify an immutable nsStandardURL: file netwerk/base/nsStandardURL.cpp, line 1424
>   1025 WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file netwerk/base/nsNetUtilInlines.h, line 180
>   1024 WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file netwerk/base/nsIOService.cpp, line 781

vs

> $ log_spam report --repo fx-team 3db372da6fe1
> Using cached data
> Reading cache from fx-team-3db372da6fe1-linux64/results.json
> Top 40 Warnings
> ===============
>  22908 WARNING: No inner window available!: file dom/base/nsGlobalWindow.cpp, line 10026
>   3871 WARNING: 'NS_FAILED(rv)', file dom/url/URL.cpp, line 228
>   3773 WARNING: Please do not use mouseenter/leave events in chrome. They are slower than mouseover/out!: '!nsContentUtils::IsChromeDoc(d)', file dom/events/EventListenerManager.cpp, line 398
>   2316 WARNING: Failed to retarget HTML data delivery to the parser thread.: file parser/html/nsHtml5StreamParser.cpp, line 967
>   1876 WARNING: NS_ENSURE_TRUE(ParseTypeAttribute(type, &version)) failed: file dom/base/nsScriptLoader.cpp, line 1287
>   1809 WARNING: A control runnable was posted to a worker that is already shutting down!: file dom/workers/WorkerPrivate.cpp, line 2496
>   1734 WARNING: NS_ENSURE_SUCCESS(status, status) failed with result 0x805303F4: file netwerk/protocol/http/nsCORSListenerProxy.cpp, line 553
>   1672 WARNING: data callback fires before cubeb_stream_start() is called: file dom/media/AudioStream.cpp, line 597
> !!!   1369 WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file layout/style/Loader.cpp, line 2164
>   1368 WARNING: 'NS_FAILED(res)', file editor/libeditor/EditorBase.cpp, line 663
>   1317 WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x8007000E: file dom/xul/nsXULPrototypeCache.cpp, line 323
>   1179 WARNING: NS_ENSURE_TRUE(maybeContext) failed: file xpcom/threads/nsThread.cpp, line 921
>   1162 WARNING: attempt to modify an immutable nsStandardURL: file netwerk/base/nsStandardURL.cpp, line 1424
>   1152 WARNING: Silently denied access to property (void 0): Access to privileged JS object not permitted (@(null):0:0): file js/xpconnect/wrappers/XrayWrapper.cpp, line 214
>   1109 WARNING: NS_ENSURE_TRUE(content && aRange) failed: file editor/txtsvc/nsFilteredContentIterator.cpp, line 239
>   1079 WARNING: NS_ENSURE_TRUE(startupCache) failed: file dom/xbl/nsXBLDocumentInfo.cpp, line 198
>   1079 WARNING: NS_ENSURE_TRUE(startupCache) failed: file dom/xbl/nsXBLDocumentInfo.cpp, line 265
>   1039 WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file netwerk/base/nsNetUtilInlines.h, line 180
>   1038 WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file netwerk/base/nsIOService.cpp, line 781

	:Gijs (he/him)
	Comment 7 • 8 years ago

AFAICT the linked NS_ENSURE_SUCCESS basically points to LoadSheet failing, though 0x80520012 is NS_ERROR_FILE_NOT_FOUND, and so it sounds like we're somehow requesting stylesheets that don't exist? I... wonder why anybody would be doing that. I also don't know why that would trigger log spam - feels like warning in stderr for a non-existant stylesheet (certainly in this obfuscated way) is not very helpful. Dan, can you check if my diagnosis is correct, and if so can we move this to somewhere in Layout-land to get the warnings to go away, or something? :-)

I'd also be happy to fix some/all of the tests to not trigger them, but it seems they're relatively spread-out when it comes to individual tests, so that might be a long slog, and I also expect some of the devtools tests might be intentionally checking what happens [with devtools] if a site requests a stylesheet that doesn't exist. Just guessing there, though - it would help if we knew which sheets were triggering this.

	Daniel Holbert [:dholbert]
	Comment 8 • 8 years ago

Your diagnosis sounds likely-correct.  We might need to add/enable some more logging here, to figure out which stylesheet load is failing.

Given that this is most spammy in devtools tests (comment 0), I'm guessing the recent spike must have been from bug 1259819 (the only obviously-devtools-related change in comment 6).  Perhaps that bug's changes accidentally added a bogus stylesheet reference?

	Daniel Holbert [:dholbert]
	Comment 9 • 8 years ago

(Er, at second glance, I guess there are some other devtools changes in that push, too.  However, it does look like the error coincides with "inspector" toolboxes appearing, which makes me still suspect bug 1259819.)

Can anyone reproduce this locally? (E.g. when running ./mach mochitest devtools/client/animationinspector )

I cannot (on my local linux64 machine, same architecture as the one where the failures were reported).  I do see *some* NS_ENSURE_*** failures, but nothing from Loader.cpp.  However, I do see the following 3 errors whenever an inspector panel is opened:
{
Chrome file doesn't exist: /scratch/work/builds/mozilla-inbound/obj/dist/bin/browser/chrome/devtools/content/inspector/markup/markup.css
Chrome file doesn't exist: /scratch/work/builds/mozilla-inbound/obj/dist/bin/browser/chrome/devtools/content/sourceeditor/codemirror/addon/dialog/dialog.css
Chrome file doesn't exist: /scratch/work/builds/mozilla-inbound/obj/dist/bin/browser/chrome/devtools/content/sourceeditor/codemirror/addon/dialog/dialog.css
}

Perhaps this NS_ENSURE_SUCCESS logging has evolved into those ^^ errors somehow?  And/or maybe they're symptoms of the same underlying problem and they just manifest with different logging depending on the machine? Seems like perhaps we should investigate & address these more-precise stylesheet load problems, and then maybe that'll fix this NS_ENSURE_SUCCESS logspam as a side-effect.

	Daniel Holbert [:dholbert]
	Comment 10 • 8 years ago

I spun off bug 1305476 for the "Chrome file doesn't exist" logging that I mentioned in comment 9.

It seems reasonably likely that that's the cause of this bug's Loader.cpp file-not-found errors, but I guess we'll see.

	Daniel Holbert [:dholbert]
	Comment 11 • 8 years ago

(The bug I spun off ended up actually being fixed in bug 1305568.)

erahm, could you perhaps run your diagnostic again, to see if this has improved significantly?

I did a quit spot-check comparison, though I'm not sure whether I'm looking at the right thing.  I compared Linux64 debug "mochitest-devtools-chrome-3" logs from the push with the fix vs. its parent push, and I'm seeing a decrease of about half (though I'm not seeing anywhere near the numbers you reported in comment 0).

Specifically: here's a dt3 log from bug 1305568's push (MAYBE-GOOD):
 https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=bf002e13d807&selectedJob=4067315
 https://public-artifacts.taskcluster.net/HJ5oYfCjRKKZeDSDs_Ck6g/0/public/logs/live_backing.log
That one has 27 intances of "style/Loader.cpp".

And here's a dt3 log from the previous push (BAD):
 https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=23c3dc155f73&selectedJob=4063751
 https://public-artifacts.taskcluster.net/DT_F_nf7THC0q2rcX8vFrg/0/public/logs/live_backing.log
That has 56 instances of "style/Loader.cpp"

	Eric Rahm [:erahm] Reporter
	Comment 12 • 8 years ago

There's about 1700 less (now below my normal threshold for complaining). It looks like devtools is still the top offender.

> 876 WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file layout/style/Loader.cpp, line 2156

This warning [1] shows up in the following test suites:

>    182 - desktop-test-linux64/debug-mochitest-devtools-chrome-4 dt4
>    129 - desktop-test-linux64/debug-mochitest-browser-chrome-e10s-1 bc1
>    129 - desktop-test-linux64/debug-mochitest-browser-chrome-6 bc6
>    107 - desktop-test-linux64/debug-mochitest-devtools-chrome-2 dt2
>     89 - desktop-test-linux64/debug-mochitest-devtools-chrome-9 dt9
>     42 - desktop-test-linux64/debug-mochitest-devtools-chrome-5 dt5
>     22 - desktop-test-linux64/debug-mochitest-devtools-chrome-3 dt3
>     22 - desktop-test-linux64/debug-mochitest-chrome-3 c3
>     19 - desktop-test-linux64/debug-mochitest-devtools-chrome-1 dt1
>     17 - desktop-test-linux64/debug-mochitest-clipboard-e10s cl
>     17 - desktop-test-linux64/debug-mochitest-clipboard cl
>     14 - desktop-test-linux64/debug-mochitest-chrome-2 c2
>     14 - desktop-test-linux64/debug-mochitest-devtools-chrome-10 dt10
>     11 - desktop-test-linux64/debug-mochitest-chrome-1 c1
>     11 - desktop-test-linux64/debug-mochitest-devtools-chrome-6 dt6
>     11 - desktop-test-linux64/debug-mochitest-devtools-chrome-7 dt7
>      4 - desktop-test-linux64/debug-mochitest-browser-chrome-4 bc4
>      4 - desktop-test-linux64/debug-mochitest-devtools-chrome-8 dt8
>      4 - desktop-test-linux64/debug-mochitest-browser-chrome-7 bc7
>      4 - desktop-test-linux64/debug-mochitest-browser-chrome-e10s-7 bc7
>      3 - desktop-test-linux64/debug-mochitest-browser-chrome-2 bc2
>      3 - desktop-test-linux64/debug-mochitest-browser-chrome-e10s-2 bc2
>      3 - desktop-test-linux64/debug-mochitest-browser-chrome-e10s-4 bc4
>      3 - desktop-test-linux64/debug-mochitest-browser-chrome-e10s-3 bc3
>      2 - desktop-test-linux64/debug-mochitest-browser-chrome-1 bc1
>      1 - desktop-test-linux64/debug-mochitest-a11y a11y
>      1 - desktop-test-linux64/debug-mochitest-browser-chrome-e10s-5 bc5
>      1 - desktop-test-linux64/debug-mochitest-browser-chrome-5 bc5

It shows up in 636 tests. A few of the most prevalent:

>     28 - [e10s] browser/components/preferences/in-content/tests/browser_cookies_exceptions.js
>     28 -        browser/components/preferences/in-content/tests/browser_cookies_exceptions.js
>     16 - [e10s] browser/components/preferences/in-content/tests/browser_subdialogs.js
>     16 -        browser/components/preferences/in-content/tests/browser_subdialogs.js
>     12 -        browser/components/preferences/in-content/tests/browser_privacypane_4.js
>     12 - [e10s] browser/components/preferences/in-content/tests/browser_privacypane_4.js
>     10 - [e10s] browser/components/preferences/in-content/tests/browser_security.js
>     10 -        browser/components/preferences/in-content/tests/browser_security.js
>      7 - [e10s] browser/components/preferences/in-content/tests/browser_privacypane_1.js
>      7 -        browser/components/preferences/in-content/tests/browser_privacypane_8.js

[1] https://hg.mozilla.org/integration/autoland/annotate/bf002e13d807/layout/style/Loader.cpp#l2156

	:Gijs (he/him)
	Comment 13 • 8 years ago

Needinfo me to look at the prefs case, I suspect that there's a dead thing there too that needs its references removing.

Otherwise, Dan, can we have a followup to remove the warning and add another that warns only if the URL is chrome:// or resource:// or something, and includes the broken URL?

	Daniel Holbert [:dholbert]
	Comment 14 • 8 years ago

(In reply to :Gijs Kruitbosch from comment #13)
> Needinfo me to look at the prefs case, I suspect that there's a dead thing
> there too that needs its references removing.

To get you started -- I see the following logged repeatedly, when I run browser_cookies_exceptions.js locally:
Chrome file doesn't exist: /scratch/work/builds/mozilla-inbound/obj/dist/bin/chrome/toolkit/content/mozapps/preferences/preferences.css

I expect that's the problem there.

> Otherwise, Dan, can we have a followup to remove the warning and add another
> that warns only if the URL is chrome:// or resource:// or something, and
> includes the broken URL?

I don't know enough about this warning to be sure whether that would be appropriate -- and I can't reproduce it locally (I'm getting "Chrome file doesn't exist" instead, as noted above), so I can't really investigate further.  So, I'm not sure it merits removing.  In this case, it was spammy, but it was giving us a hint about a legitimate issue.

Also, re "warns only if the URL is chrome:// or resource:// or something, and includes the broken URL?":  right now, it looks like we are perhaps only warning in that case -- and the logging that I'm getting locally *does* include the (resolved-to-actual-path) broken URL.

Perhaps it would be worth investigating why we're seeing different versions of this logging on the server vs. locally, though -- I'll file a followup on that, though it doesn't seem important enough for me to prioritize above other things at the moment.

	Daniel Holbert [:dholbert]
	Comment 15 • 8 years ago

(I spun off bug 1306055 to figure out why we're logging differently on the TreeHerder machines vs. my local machine.  Once Gijs has sorted out the bogus preferences.css reference [either here or in a dependent bug], I'd say we can call this bug FIXED.)

	:Gijs (he/him)
	Comment 16 • 8 years ago

Marking this bug FIXED per comment #15.