Closed Bug 1652531 Opened 4 years ago Closed 3 years ago

Intermittent Assertion failure: cache->PreservingWrapper(), at /builds/worker/checkouts/gecko/dom/bindings/DOMJSProxyHandler.cpp:85

Categories

(Core :: XPConnect, defect, P2)

Product:
Core
Component:
XPConnect
Type:
defect

Tracking

()

Status:
RESOLVED WORKSFORME
Tracking Flags:
Tracking Status
firefox89 --- affected

People

(Reporter: intermittent-bug-filer, Assigned: mccr8)

References

Details

(Keywords: assertion, intermittent-failure, Whiteboard: [stockwell unknown])

Attachments

(1 file, 2 obsolete files)

Log actual uses of lazy pref getter callbacks. DO NOT LAND
(deleted), patch
Details | Diff | Splinter Review

Filed by: abutkovits [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=309607648&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/IVdwZdMwQ_agUthB__QP0g/runs/0/artifacts/public/logs/live_backing.log

[task 2020-07-13T17:21:00.835Z] 17:21:00 INFO - TEST-START | browser/components/ssb/tests/browser/browser_ssb_open.js
[task 2020-07-13T17:21:00.839Z] 17:21:00 INFO - GECKO(8648) | [Child 9627: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (0x7f88286936f0) [pid = 9627] [serial = 1] [outer = (nil)] [url = https://example.org/browser/browser/components/ssb/tests/browser/empty_page.html]
[task 2020-07-13T17:21:00.839Z] 17:21:00 INFO - GECKO(8648) | [Child 9627: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0x7f880c16b400) [pid = 9627] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2020-07-13T17:21:00.839Z] 17:21:00 INFO - GECKO(8648) | [Child 9627: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0x7f8812646000) [pid = 9627] [serial = 3] [outer = (nil)] [url = https://example.org/browser/browser/components/ssb/tests/browser/empty_page.html]
[task 2020-07-13T17:21:00.894Z] 17:21:00 INFO - GECKO(8648) | [Child 9627, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-07-13T17:21:00.910Z] 17:21:00 INFO - GECKO(8648) | [Child 9649: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7f6d8e445c00 == 1 [pid = 9649] [id = {4840ec51-f012-4026-929f-fb1b1abaf41c}]
[task 2020-07-13T17:21:00.926Z] 17:21:00 INFO - GECKO(8648) | [Child 9627, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 4382
[task 2020-07-13T17:21:00.961Z] 17:21:00 INFO - GECKO(8648) | [Child 9649: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (0x7f6daa8936f0) [pid = 9649] [serial = 1] [outer = (nil)]
[task 2020-07-13T17:21:00.962Z] 17:21:00 INFO - GECKO(8648) | [Child 9649: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0x7f6d8e468400) [pid = 9649] [serial = 2] [outer = 0x7f6daa8936f0]
[task 2020-07-13T17:21:00.982Z] 17:21:00 INFO - GECKO(8648) | [Child 9706, Main Thread] WARNING: could not set real-time limit at process startup: file /builds/worker/checkouts/gecko/dom/ipc/ContentChild.cpp, line 1627
[task 2020-07-13T17:21:01.118Z] 17:21:01 INFO - GECKO(8648) | [Child 9649, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp, line 351
[task 2020-07-13T17:21:01.119Z] 17:21:01 INFO - GECKO(8648) | [Child 9649, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp, line 351
[task 2020-07-13T17:21:01.154Z] 17:21:01 INFO - GECKO(8648) | [Child 9649: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (0x7f6d94943000) [pid = 9649] [serial = 3] [outer = 0x7f6daa8936f0]
[task 2020-07-13T17:21:01.295Z] 17:21:01 INFO - GECKO(8648) | [Parent 8648, Main Thread] WARNING: '!mPresContext', file /builds/worker/checkouts/gecko/dom/events/UIEvent.cpp, line 137
[task 2020-07-13T17:21:01.423Z] 17:21:01 INFO - GECKO(8648) | [Parent 8648, Main Thread] WARNING: NS_ENSURE_TRUE(GetWrapper()) failed: file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSActor.cpp, line 92
[task 2020-07-13T17:21:01.499Z] 17:21:01 INFO - GECKO(8648) | [Child 9014: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f9e31eb1400 == 0 [pid = 9014] [id = {e077d202-f85b-4edf-9ec0-2f5affcfda45}] [url = about:blank]
[task 2020-07-13T17:21:01.539Z] 17:21:01 INFO - GECKO(8648) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmp6gVV9w.mozrunner/runtests_leaks_tab_pid9738.log
[task 2020-07-13T17:21:01.540Z] 17:21:01 INFO - GECKO(8648) | [9738, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 245
[task 2020-07-13T17:21:01.567Z] 17:21:01 INFO - GECKO(8648) | [Child 9014: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0x7f9e4e093350) [pid = 9014] [serial = 4] [outer = (nil)] [url = about:blank]
[task 2020-07-13T17:21:01.575Z] 17:21:01 INFO - GECKO(8648) | [Child 8912: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 26 (0x7f7f0cd49000) [pid = 8912] [serial = 66] [outer = (nil)] [url = https://example.com/browser/browser/components/ssb/tests/browser/site1/empty.html]
[task 2020-07-13T17:21:01.576Z] 17:21:01 INFO - GECKO(8648) | [Child 8912: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 25 (0x7f7f0cccfc00) [pid = 8912] [serial = 84] [outer = (nil)] [url = https://example.com/browser/browser/components/ssb/tests/browser/site1/bad.html]
[task 2020-07-13T17:21:01.578Z] 17:21:01 INFO - GECKO(8648) | [Child 8912: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 24 (0x7f7f070b5800) [pid = 8912] [serial = 76] [outer = (nil)] [url = https://example.com/browser/browser/components/ssb/tests/browser/site1/allhost.html]
[task 2020-07-13T17:21:01.580Z] 17:21:01 INFO - GECKO(8648) | [Child 8912: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 23 (0x7f7f0cd45c00) [pid = 8912] [serial = 90] [outer = (nil)] [url = about:blank]
[task 2020-07-13T17:21:01.580Z] 17:21:01 INFO - GECKO(8648) | [Child 8912: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 22 (0x7f7f057e9c00) [pid = 8912] [serial = 72] [outer = (nil)] [url = https://example.com/browser/browser/components/ssb/tests/browser/site1/allhost.html]
[task 2020-07-13T17:21:01.580Z] 17:21:01 INFO - GECKO(8648) | [Child 8912: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 21 (0x7f7f0cc92400) [pid = 8912] [serial = 77] [outer = (nil)] [url = https://example.com/browser/browser/components/ssb/tests/browser/site2/final.html]
[task 2020-07-13T17:21:01.580Z] 17:21:01 INFO - GECKO(8648) | [Child 8912: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 20 (0x7f7f0cccb000) [pid = 8912] [serial = 105] [outer = (nil)] [url = about:blank]
[task 2020-07-13T17:21:01.580Z] 17:21:01 INFO - GECKO(8648) | [Child 8912: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 19 (0x7f7f070bc000) [pid = 8912] [serial = 87] [outer = (nil)] [url = about:blank]
[task 2020-07-13T17:21:01.581Z] 17:21:01 INFO - GECKO(8648) | [Child 8912: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 18 (0x7f7f0cca0c00) [pid = 8912] [serial = 102] [outer = (nil)] [url = about:blank]
[task 2020-07-13T17:21:01.582Z] 17:21:01 INFO - GECKO(8648) | [Child 8912: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 17 (0x7f7f0cc97c00) [pid = 8912] [serial = 96] [outer = (nil)] [url = about:blank]
[task 2020-07-13T17:21:01.586Z] 17:21:01 INFO - GECKO(8648) | [Child 8912: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 16 (0x7f7f057eec00) [pid = 8912] [serial = 73] [outer = (nil)] [url = https://example.com/browser/browser/components/ssb/tests/browser/site1/final.html]
[task 2020-07-13T17:21:01.586Z] 17:21:01 INFO - GECKO(8648) | [Child 8912: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 15 (0x7f7f0cc9e400) [pid = 8912] [serial = 81] [outer = (nil)] [url = https://example.com/browser/browser/components/ssb/tests/browser/site1/final.html]
[task 2020-07-13T17:21:01.586Z] 17:21:01 INFO - GECKO(8648) | [Child 8912: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 14 (0x7f7f057e9000) [pid = 8912] [serial = 92] [outer = (nil)] [url = about:blank]
[task 2020-07-13T17:21:01.586Z] 17:21:01 INFO - GECKO(8648) | [Child 8912: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 13 (0x7f7f0cc9a000) [pid = 8912] [serial = 99] [outer = (nil)] [url = about:blank]
[task 2020-07-13T17:21:01.586Z] 17:21:01 INFO - GECKO(8648) | [Child 8912: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 12 (0x7f7f070c0000) [pid = 8912] [serial = 93] [outer = (nil)] [url = https://example.com/browser/browser/components/ssb/tests/browser/test_page.html#https://example.com/browser/browser/components/ssb/tests/browser/empty_page.html]
[task 2020-07-13T17:21:01.587Z] 17:21:01 INFO - GECKO(8648) | [Child 8912: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 11 (0x7f7f0cc9cc00) [pid = 8912] [serial = 80] [outer = (nil)] [url = https://example.com/browser/browser/components/ssb/tests/browser/site1/bad.html]
[task 2020-07-13T17:21:01.587Z] 17:21:01 INFO - GECKO(8648) | [Child 8912: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (0x7f7f0ccd2400) [pid = 8912] [serial = 89] [outer = (nil)] [url = about:blank]
[task 2020-07-13T17:21:01.687Z] 17:21:01 INFO - GECKO(8648) | Assertion failure: cache->PreservingWrapper(), at /builds/worker/checkouts/gecko/dom/bindings/DOMJSProxyHandler.cpp:85
[task 2020-07-13T17:21:01.694Z] 17:21:01 INFO - Initializing stack-fixing for the first stack frame, this may take a while...

Component: General → DOM: Bindings (WebIDL)
Product: Firefox → Core

It looks like this is happening in DOMProxyHandler::GetExpandoObject for HTMLDocument.

Some verify failures for browser/components/places/tests/browser/browser_toolbar_other_bookmarks.js

For non-verify, there are tons of failures in the test browser/components/ssb/tests/browser/browser_ssb_open.js

"ssb" appears to be "site specific browser".

Comment 0 also includes browser_ssb_open.js, so presumably that was related to this issue from the start.

The spike here might be related to the land in Bug 1596897.

Paul could you have a look over the frequent failures here and see if they're somehow connected to your recent land?
Fails on debug builds only, here's a recent log: https://treeherder.mozilla.org/logviewer?job_id=329237308&repo=autoland&lineNumber=69388
Thank you.

Flags: needinfo?(pbz)

Oh nevermind, mostly fails on browser/components/urlbar/tests/browser/browser_tabKeyBehavior.js so might be related to https://hg.mozilla.org/integration/autoland/rev/9f5e51b38c2c1f8878a02656c226792e8acfa90f, Bug 1678323.
Marco, please have a look over this. Thank you.

Flags: needinfo?(pbz) → needinfo?(mak)

the patch itself is trivial, it basically just sets the tabindex attribute on just created nodes. I'd rather think something is unhappy with the test, that is pretty much pressing Tab on the UI, focusing different buttons or content.

I don't know the reasons for which this assertion may fire, we need someone knowing the DOM bindings code to make hypothesis about what may activate this assertion. Andrew, any idea who may be a good person to help theorizing here?

Flags: needinfo?(continuation)

I actually see Preferences.cpp in the middle of the stack I wonder if my test change to browser.toolbars.keyboard_navigation is being handled in a closing window, or something similar:
https://searchfox.org/mozilla-central/rev/d537e47349944c0fbd0100bd52c30e493e748c2e/browser/base/content/browser.js#470-482

I'm testing a modified patch checking window.closed on Try.

The new version looks better, so it was likely just that listener trying to init objects in a closed window. My test basically uncovered a bug.

Flags: needinfo?(mak)
Flags: needinfo?(continuation)

The recent failure spike is caused by the changes that landed in Bug 1696253.
Mark, could you please take a look?
(Backfill range, see failures below the assertion caused by browser_HomePage_add_button.js)

Flags: needinfo?(mstriemer)
See Also: → https://bugzilla.mozilla.org/show_bug.cgi?id=1696253
Summary: Intermittent Assertion failure: cache->PreservingWrapper(), at /builds/worker/checkouts/gecko/dom/bindings/DOMJSProxyHandler.cpp:85 → Very frequent Assertion failure: cache->PreservingWrapper(), at /builds/worker/checkouts/gecko/dom/bindings/DOMJSProxyHandler.cpp:85

I'm trying to get a Pernosco trace for this crash. This is likely some kind of issue with DOM code that the front end change is triggering. I don't know what it could be, though. It looks like the patch in question was initially backed out for the same issue, but I don't see any reasoning in the bug for why it was relanded.

I was not able to reproduce in Pernosco.

Peter, any idea what could be going wrong here? I assume some weird chrome element has a bug in it or something but I don't know how we can narrow it down or what exactly might be the issue with said class.

Flags: needinfo?(peterv)

kmag took a look at this. The stacks indicate that this is happening inside a pref callback.

He had this to say:
"9 chances out of 10 it's this: https://searchfox.org/mozilla-central/rev/200bfc652c5128011e7725fc7c201eb125d453e7/browser/base/content/browser.js#590
We've run into cases like that where we don't unlink the weak reference to the callback after we unlink the document.
So that listener has to go and be replaced with something that explicitly unregisters itself."

The code Kris linked to is document.documentElement.toggleAttribute("proton", newValue); inside the lazy gProton setter.

Flags: needinfo?(peterv)

Gijs, do you have time to fix this? It looks like you added this preference getter callback in bug 1680069. Thanks.

Flags: needinfo?(gijskruitbosch+bugs)

Kris walked me through this a bit, so I think I could look at it. Looks like this is related to the bug where I've been ignoring a needinfo for about a year....

Flags: needinfo?(gijskruitbosch+bugs)
See Also: → https://bugzilla.mozilla.org/show_bug.cgi?id=1543537
Assignee: nobody → continuation
Depends on: 1699614

The rate seems to have fallen off, though it hasn't gone away entirely.

For instance, there's a failure in the very push that merged my patch in bug 1699614 to m-c: https://treeherder.mozilla.org/logviewer?job_id=333819791&repo=mozilla-central&lineNumber=17249

That one seems to be while running browser/components/places/tests/browser/browser_toolbar_other_bookmarks.js. I do see that browser/base/content/browser-places.js has a similar pattern with a lazy preference getter for SHOW_OTHER_BOOKMARKS with a callback that accesses doc, so maybe that's the issue. Hopefully the failure rate will fall to a more reasonable level. Ideally I'll be able to reproduce the issue locally and then investigate bug 1543537 so we don't need to do these weird workarounds.

Flags: needinfo?(mstriemer)
Whiteboard: [stockwell disable-recommended] → [stockwell needswork]

This is really a cycle collector issue, though one that can be worked around by changing the way lazy pref callbacks are written as I did in bug 1699614. Bug 1543537 should fix the underlying issue, though it is bit of a risky change so we'll see how easy that is to land.

Component: DOM: Bindings (WebIDL) → XPCOM
Component: XPCOM → XPConnect

Failures decreased considerably since March 20th.

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended]
Summary: Very frequent Assertion failure: cache->PreservingWrapper(), at /builds/worker/checkouts/gecko/dom/bindings/DOMJSProxyHandler.cpp:85 → Intermittent Assertion failure: cache->PreservingWrapper(), at /builds/worker/checkouts/gecko/dom/bindings/DOMJSProxyHandler.cpp:85

This is still happening somewhat frequently. It looks like the most common culprit is browser/components/places/tests/browser/browser_toolbar_other_bookmarks.js

Probably the next step would be to add some kind of logging for the lazy preference getter when it gets a callback argument, then run it on that test and try to figure out what is the source of it.

The idea here is that you apply this patch, run a test that has seen many failures, then look for the lazy preference getter and apply a work around by using a weak reference to the document in question.

There are 19 total failures in the last 7 days on

task 2021-04-05T05:08:44.066Z] 05:08:44 INFO - TEST-START | browser/components/places/tests/browser/browser_toolbar_other_bookmarks.js
[task 2021-04-05T05:08:44.096Z] 05:08:44 INFO - GECKO(5392) | [Child 9916, Main Thread] WARNING: Scrolled rect smaller than scrollport?: file /builds/worker/checkouts/gecko/layout/generic/nsGfxScrollFrame.cpp:7067
[task 2021-04-05T05:08:44.135Z] 05:08:44 INFO - GECKO(5392) | [Parent 3524: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 2154857d000 == 13 [pid = 3524] [id = 141]
[task 2021-04-05T05:08:44.135Z] 05:08:44 INFO - GECKO(5392) | [Parent 3524: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 62 (2154adc6e40) [pid = 3524] [serial = 394] [outer = 0]
[task 2021-04-05T05:08:44.135Z] 05:08:44 INFO - GECKO(5392) | [Parent 3524: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 63 (2154b5d0800) [pid = 3524] [serial = 395] [outer = 2154adc6e40]
[task 2021-04-05T05:08:44.153Z] 05:08:44 INFO - GECKO(5392) | [Parent 3524, Main Thread] WARNING: NS_ENSURE_TRUE(uri) failed: file /builds/worker/checkouts/gecko/caps/BasePrincipal.cpp:1327
[task 2021-04-05T05:08:44.153Z] 05:08:44 INFO - GECKO(5392) | [Parent 3524, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4235
[task 2021-04-05T05:08:44.355Z] 05:08:44 INFO - GECKO(5392) | [Parent 3524: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 21551945000 == 14 [pid = 3524] [id = 142]
[task 2021-04-05T05:08:44.355Z] 05:08:44 INFO - GECKO(5392) | [Parent 3524: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 64 (2154b04eac0) [pid = 3524] [serial = 396] [outer = 0]
[task 2021-04-05T05:08:44.396Z] 05:08:44 INFO - GECKO(5392) | Warning: asking to enable_gpu_markers but no supporting extension was found
[task 2021-04-05T05:08:44.401Z] 05:08:44 INFO - GECKO(5392) | [Child 9256: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 10d58041c00 == 3 [pid = 9256] [id = 62]
[task 2021-04-05T05:08:44.401Z] 05:08:44 INFO - GECKO(5392) | [Child 9256: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 5 (10d60f17ac0) [pid = 9256] [serial = 146] [outer = 0]
[task 2021-04-05T05:08:44.401Z] 05:08:44 INFO - GECKO(5392) | [Child 9256: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 6 (10d5e7a1c00) [pid = 9256] [serial = 147] [outer = 10d60f17ac0]
[task 2021-04-05T05:08:44.486Z] 05:08:44 INFO - GECKO(5392) | [Parent 3524, Main Thread] WARNING: NS_ENSURE_TRUE(presShell) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4233
[task 2021-04-05T05:08:44.505Z] 05:08:44 INFO - GECKO(5392) | [Parent 3524: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 65 (2154c3bdc00) [pid = 3524] [serial = 397] [outer = 2154b04eac0]
[task 2021-04-05T05:08:44.669Z] 05:08:44 INFO - GECKO(5392) | [Parent 3524, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1591
[task 2021-04-05T05:08:44.842Z] 05:08:44 INFO - GECKO(5392) | [Child 9256: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 7 (10d5ec65c00) [pid = 9256] [serial = 148] [outer = 10d60f17ac0]
[task 2021-04-05T05:08:44.852Z] 05:08:44 INFO - GECKO(5392) | [Child 9916, Main Thread] WARNING: Scrolled rect smaller than scrollport?: file /builds/worker/checkouts/gecko/layout/generic/nsGfxScrollFrame.cpp:7064
[task 2021-04-05T05:08:44.902Z] 05:08:44 INFO - GECKO(5392) | [Child 9256: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 10d58042c00 == 2 [pid = 9256] [id = 60] [url = about:blank]
[task 2021-04-05T05:08:44.902Z] 05:08:44 INFO - GECKO(5392) | [Child 9256: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 10d5803f000 == 1 [pid = 9256] [id = 61] [url = about:blank]
[task 2021-04-05T05:08:44.960Z] 05:08:44 INFO - GECKO(5392) | [Child 9256: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 6 (10d58053e40) [pid = 9256] [serial = 144] [outer = 0] [url = about:blank]
[task 2021-04-05T05:08:44.960Z] 05:08:44 INFO - GECKO(5392) | [Child 9256: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 5 (10d60f173c0) [pid = 9256] [serial = 142] [outer = 0] [url = about:blank]
[task 2021-04-05T05:08:45.020Z] 05:08:45 INFO - GECKO(5392) | [GPU 2112, Compositor] WARNING: Possibly dropping task posted to updater thread: file /builds/worker/checkouts/gecko/gfx/layers/apz/src/APZUpdater.cpp:370
[task 2021-04-05T05:08:46.665Z] 05:08:46 INFO - GECKO(5392) | Assertion failure: cache->PreservingWrapper(), at /builds/worker/checkouts/gecko/dom/bindings/DOMJSProxyHandler.cpp:90
[task 2021-04-05T05:08:46.665Z] 05:08:46 INFO - GECKO(5392) | #01: mozilla::dom::HTMLDocument_Binding::DOMProxyHandler::get(JSContext*, JS::Handle<JSObject >, JS::Handle<JS::Value>, JS::Handle<JS::PropertyKey>, JS::MutableHandle<JS::Value>) const [s3:gecko-generated-sources:ffea961421280aed373ae24db50d9b22656064c6fb65681b8d1f20ebb0da346cf17e865e896e6484cbd3074d19ed87db91d84c60ec31c3e525f33647b3df8a34/dom/bindings/HTMLDocumentBinding.cpp::724]
[task 2021-04-05T05:08:46.666Z] 05:08:46 INFO - GECKO(5392) | #02: static js::Proxy::getInternal(JSContext, JS::Handle<JSObject >, JS::Handle<JS::Value>, JS::Handle<JS::PropertyKey>, JS::MutableHandle<JS::Value>) [js/src/proxy/Proxy.cpp:471]
[task 2021-04-05T05:08:46.666Z] 05:08:46 INFO - GECKO(5392) | #03: static js::Proxy::get(JSContext, JS::Handle<JSObject >, JS::Handle<JS::Value>, JS::Handle<JS::PropertyKey>, JS::MutableHandle<JS::Value>) [js/src/proxy/Proxy.cpp:479]
[task 2021-04-05T05:08:46.667Z] 05:08:46 INFO - GECKO(5392) | #04: js::GetProperty(JSContext, JS::Handle<JSObject >, JS::Handle<JS::Value>, js::PropertyName, JS::MutableHandle<JS::Value>) [js/src/vm/ObjectOperations-inl.h:123]
[task 2021-04-05T05:08:46.667Z] 05:08:46 INFO - GECKO(5392) | #05: js::GetProperty(JSContext*, JS::Handle<JS::Value>, JS::Handle<js::PropertyName >, JS::MutableHandle<JS::Value>) [js/src/vm/Interpreter.cpp:4559]
[task 2021-04-05T05:08:46.667Z] 05:08:46 INFO - GECKO(5392) | #06: Interpret(JSContext, js::RunState&) [js/src/vm/Interpreter.cpp:2935]
[task 2021-04-05T05:08:46.667Z] 05:08:46 INFO - GECKO(5392) | #07: js::RunScript(JSContext*, js::RunState&) [js/src/vm/Interpreter.cpp:405]
[task 2021-04-05T05:08:46.667Z] 05:08:46 INFO - GECKO(5392) | #08: js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [js/src/vm/Interpreter.cpp:552]
[task 2021-04-05T05:08:46.667Z] 05:08:46 INFO - GECKO(5392) | #09: InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) [js/src/vm/Interpreter.cpp:580]
[task 2021-04-05T05:08:46.667Z] 05:08:46 INFO - GECKO(5392) | #10: js::jit::DoCallFallback(JSContext*, js::jit::BaselineFrame*, js::jit::ICCall_Fallback*, unsigned int, JS::Value*, JS::MutableHandle<JS::Value>) [js/src/jit/BaselineIC.cpp:1841]
[task 2021-04-05T05:08:46.667Z] 05:08:46 INFO - GECKO(5392) | #11: ??? (???:???)
[task 2021-04-05T05:08:46.931Z] 05:08:46 INFO - GECKO(5392) | Exiting due to channel error.
[task 2021-04-05T05:08:46.931Z] 05:08:46 INFO - GECKO(5392) | [GPU 2112, Compositor] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:532
[task 2021-04-05T05:08:46.931Z] 05:08:46 INFO - GECKO(5392) | [GPU 2112, Main Thread] WARNING: Shutting down GPU process early due to a crash!: file /builds/worker/checkouts/gecko/gfx/ipc/GPUParent.cpp:600
[task 2021-04-05T05:08:47.018Z] 05:08:47 INFO - GECKO(5392) | [GPU 2112, Compositor] WARNING: I
[task 2021-04-05T05:08:47.043Z] 05:08:47 INFO - TEST-INFO | Main app process: exit 1
[task 2021-04-05T05:08:47.044Z] 05:08:47 ERROR - TEST-UNEXPECTED-FAIL | ShutdownLeaks | process() called before end of test suite
[task 2021-04-05T05:08:47.044Z] 05:08:47 INFO - TEST-INFO | Confirming we saw 317 DOCSHELL created and 294 destroyed log strings.
[task 2021-04-05T05:08:47.045Z] 05:08:47 INFO - TEST-INFO | Confirming we saw 842 DOMWINDOW created and 752 destroyed log strings.
[task 2021-04-05T05:08:47.045Z] 05:08:47 INFO - Buffered messages logged at 05:08:44
[task 2021-04-05T05:08:47.046Z] 05:08:47 INFO - Entering test bound setup
[task 2021-04-05T05:08:47.046Z] 05:08:47 INFO - Leaving test bound setup
[task 2021-04-05T05:08:47.046Z] 05:08:47 INFO - Entering test bound testShowingOtherBookmarksInToolbar
[task 2021-04-05T05:08:47.047Z] 05:08:47 INFO - Check the initial state of the Other Bookmarks folder.
[task 2021-04-05T05:08:47.047Z] 05:08:47 INFO - TEST-PASS | browser/components/places/tests/browser/browser_toolbar_other_bookmarks.js | Shouldn't have an Other Bookmarks button. -
[task 2021-04-05T05:08:47.050Z] 05:08:47 INFO - Buffered messages logged at 05:08:45
[task 2021-04-05T05:08:47.050Z] 05:08:47 INFO - Check visibility of an empty Other Bookmarks folder.
[task 2021-04-05T05:08:47.051Z] 05:08:47 INFO - Test whether or not the 'Other Bookmarks' folder is visible.
[task 2021-04-05T05:08:47.051Z] 05:08:47 INFO - TEST-PASS | browser/components/places/tests/browser/browser_toolbar_other_bookmarks.js | Other Bookmarks folder "hidden" state should be true. -

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

I'll try to find some time to look into what is going wrong with browser_toolbar_other_bookmarks.js, as that was the most frequent failure when I checked before.

The idea here is that you apply this patch, run a test that has seen many failures, then look for the lazy preference getter and apply a work around by using a weak reference to the document in question.
This new version only logs when we actually use the pref callback, which reduces the noise.
Attachment #9212840 - Attachment is obsolete: true
Attachment #9213602 - Attachment is obsolete: true
Depends on: 1703083

I think my patches in bug 1703083 will fix the browser_toolbar_other_bookmarks.js failures.

Severity: normal → S3
status-firefox89: --- → affected
Priority: -- → P2

No failures since bug 1703083 landed. There's probably no need to backport these fixes because the crashes will only happen if you flip certain prefs at a bad time, and presumably users aren't flipping prefs very often.

Every failure since the previous comment has been on comm-central, which I've now fixed in bug 1712045. I guess you might want to close the bug?

Resolving per comment 94.

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: