Closed Bug 1691192 Opened 5 years ago Closed 4 years ago

Intermittent layout/generic/crashtests/471360.html | assertion count 1 is more than expected 0 assertions from ASSERTION: Unexpected layers id in AllocPAPZParent; dropping message...: 'Error', file gfx/layers/ipc/ContentCompositorBridgeParent.cpp:177

Categories

(Core :: Layout, defect, P5)

defect

Tracking

()

RESOLVED FIXED
90 Branch
Tracking Status
firefox-esr78 --- unaffected
firefox88 --- wontfix
firefox89 --- wontfix
firefox90 --- fixed

People

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

References

Details

(Keywords: assertion, intermittent-failure)

Attachments

(1 file)

Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=329090924&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/EEnqP_ZqScWrOTcxGASdXw/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/EEnqP_ZqScWrOTcxGASdXw/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1


[task 2021-02-06T10:35:46.164Z] 10:35:46     INFO - REFTEST TEST-START | layout/generic/crashtests/471360.html
[task 2021-02-06T10:35:46.165Z] 10:35:46     INFO - REFTEST TEST-LOAD | file:///builds/worker/workspace/build/tests/reftest/tests/layout/generic/crashtests/471360.html | 2405 / 3887 (61%)
[task 2021-02-06T10:35:46.226Z] 10:35:46     INFO - [Parent 1440, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111 (NS_ERROR_NOT_AVAILABLE): file /builds/worker/checkouts/gecko/startupcache/StartupCacheUtils.cpp:153
[task 2021-02-06T10:35:46.226Z] 10:35:46     INFO - JavaScript error: resource://specialpowers/AppTestDelegateParent.jsm, line 10: NS_ERROR_NOT_AVAILABLE:
[task 2021-02-06T10:35:46.227Z] 10:35:46     INFO - [Parent 1440, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111 (NS_ERROR_NOT_AVAILABLE): file /builds/worker/checkouts/gecko/startupcache/StartupCacheUtils.cpp:153
[task 2021-02-06T10:35:46.227Z] 10:35:46     INFO - JavaScript error: resource://specialpowers/AppTestDelegateParent.jsm, line 10: NS_ERROR_NOT_AVAILABLE:
[task 2021-02-06T10:35:46.277Z] 10:35:46     INFO - [Child 4497, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012 (NS_ERROR_FILE_NOT_FOUND): file /builds/worker/checkouts/gecko/layout/style/Loader.cpp:1993
[task 2021-02-06T10:35:46.346Z] 10:35:46     INFO - [Child 4522, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012 (NS_ERROR_FILE_NOT_FOUND): file /builds/worker/checkouts/gecko/layout/style/Loader.cpp:1993
[task 2021-02-06T10:35:46.465Z] 10:35:46     INFO - [Parent 1440, Main Thread] WARNING: 'aOwner->IsDiscarded()', file /builds/worker/workspace/obj-build/dist/include/mozilla/dom/SyncedContextInlines.h:32
[task 2021-02-06T10:35:46.469Z] 10:35:46     INFO - [Parent 1440, Main Thread] WARNING: Received `load` event on unbridged BrowserParent!: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:3978
[task 2021-02-06T10:35:46.469Z] 10:35:46     INFO - [Parent 1440, Main Thread] WARNING: Received `load` event on unbridged BrowserParent!: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:3978
[task 2021-02-06T10:35:46.474Z] 10:35:46     INFO - [Child 4547, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/ipc/ContentChild.cpp:4060
[task 2021-02-06T10:35:46.496Z] 10:35:46     INFO - [Parent 1440, Main Thread] WARNING: 'aOwner->IsDiscarded()', file /builds/worker/workspace/obj-build/dist/include/mozilla/dom/SyncedContextInlines.h:32
[task 2021-02-06T10:35:46.496Z] 10:35:46     INFO - [Child 4522, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/ipc/ContentChild.cpp:4060
[task 2021-02-06T10:35:46.512Z] 10:35:46     INFO - [Parent 1440, Main Thread] WARNING: Received `load` event on unbridged BrowserParent!: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:3978
[task 2021-02-06T10:35:46.514Z] 10:35:46     INFO - [Parent 1440, Main Thread] WARNING: Received `load` event on unbridged BrowserParent!: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:3978
[task 2021-02-06T10:35:46.515Z] 10:35:46     INFO - [Parent 1440, Main Thread] WARNING: Received `load` event on unbridged BrowserParent!: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:3978
[task 2021-02-06T10:35:46.522Z] 10:35:46     INFO - [Child 4547, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012 (NS_ERROR_FILE_NOT_FOUND): file /builds/worker/checkouts/gecko/layout/style/Loader.cpp:1993
[task 2021-02-06T10:35:46.553Z] 10:35:46     INFO - [Child 1695, Main Thread] WARNING: 'aFrameContext.IsNullOrDiscarded()', file /builds/worker/checkouts/gecko/dom/ipc/WindowGlobalChild.cpp:416
[task 2021-02-06T10:35:46.584Z] 10:35:46     INFO - ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-06T10:35:46.585Z] 10:35:46     INFO - ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-06T10:35:46.589Z] 10:35:46     INFO - [Child 4522, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:512
[task 2021-02-06T10:35:46.589Z] 10:35:46     INFO - ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-06T10:35:46.590Z] 10:35:46     INFO - [Child 4497, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:512
[task 2021-02-06T10:35:46.611Z] 10:35:46     INFO - ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-06T10:35:46.612Z] 10:35:46     INFO - ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-06T10:35:46.612Z] 10:35:46     INFO - ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost

task 2021-02-06T10:37:30.572Z] 10:37:30     INFO - REFTEST TEST-PASS | layout/generic/crashtests/471360.html | (LOAD ONLY)
[task 2021-02-06T10:37:30.573Z] 10:37:30     INFO - REFTEST TEST-END | layout/generic/crashtests/471360.html
[task 2021-02-06T10:37:30.669Z] 10:37:30     INFO - [Child 8384, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:619
[task 2021-02-06T10:37:30.729Z] 10:37:30     INFO - [Child 8331, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/ipc/ContentChild.cpp:4060
[task 2021-02-06T10:37:30.731Z] 10:37:30     INFO - [Child 8331, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/ipc/ContentChild.cpp:4060
[task 2021-02-06T10:37:30.757Z] 10:37:30     INFO - [Child 8331, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/ipc/ContentChild.cpp:4060
[task 2021-02-06T10:37:30.779Z] 10:37:30     INFO - [Child 8331, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/ipc/ContentChild.cpp:4060
[task 2021-02-06T10:37:30.799Z] 10:37:30     INFO - [Child 8311, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3365
[task 2021-02-06T10:37:30.820Z] 10:37:30     INFO - ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpEHslxY.mozrunner/runreftest_leaks_tab_pid8426.log
[task 2021-02-06T10:37:30.828Z] 10:37:30     INFO - ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-06T10:37:30.847Z] 10:37:30     INFO - ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-06T10:37:30.850Z] 10:37:30     INFO - ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-06T10:37:30.851Z] 10:37:30     INFO - ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-06T10:37:30.852Z] 10:37:30     INFO - [Child 8331, Main Thread] WARNING: MsgDropped in ContentChild: file /builds/worker/checkouts/gecko/dom/ipc/ContentChild.cpp:2165
[task 2021-02-06T10:37:30.879Z] 10:37:30     INFO - [8426, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:251
[task 2021-02-06T10:37:30.935Z] 10:37:30     INFO - [Parent 1440, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111 (NS_ERROR_NOT_AVAILABLE): file /builds/worker/checkouts/gecko/startupcache/StartupCacheUtils.cpp:153
[task 2021-02-06T10:37:30.937Z] 10:37:30     INFO - JavaScript error: resource://specialpowers/AppTestDelegateParent.jsm, line 10: NS_ERROR_NOT_AVAILABLE:
[task 2021-02-06T10:37:30.938Z] 10:37:30     INFO - [Parent 1440, Main Thread] WARNING: Ancestor context is no longer current: file /builds/worker/checkouts/gecko/docshell/base/CanonicalBrowsingContext.cpp:1087
[task 2021-02-06T10:37:30.939Z] 10:37:30     INFO - [Parent 1440, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111 (NS_ERROR_NOT_AVAILABLE): file /builds/worker/checkouts/gecko/startupcache/StartupCacheUtils.cpp:153
[task 2021-02-06T10:37:30.946Z] 10:37:30     INFO - JavaScript error: resource://specialpowers/AppTestDelegateParent.jsm, line 10: NS_ERROR_NOT_AVAILABLE:
[task 2021-02-06T10:37:30.967Z] 10:37:30     INFO - [Parent 1440, Main Thread] WARNING: Received `load` event on unbridged BrowserParent!: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:3978
[task 2021-02-06T10:37:30.970Z] 10:37:30     INFO - REFTEST TEST-UNEXPECTED-FAIL | layout/generic/crashtests/471360.html | assertion count 1 is more than expected 0 assertions```
Summary: Intermittent layout/generic/crashtests/471360.html | assertion count 1 is more than expected 0 assertions → Intermittent layout/generic/crashtests/471360.html | assertion count 1 is more than expected 0 assertions from ASSERTION: should have done initial reflow by now: 'mDidInitialize', file /builds/worker/checkouts/gecko/layout/base/PresShell.cpp:3530

Daniel, this is happening on mochitest plain jobs as well: https://treeherder.mozilla.org/logviewer?job_id=338081176&repo=mozilla-central&lineNumber=2017

Should we open a new bug for these or modify this bug's summary to include them?

Flags: needinfo?(dholbert)

I assume "this is happening" you're referring to the "should have done initial reflow" assertion -- is that right? If so: yes, let's use a new bug for the other test where this has been seen. Thanks!

Also: I think this bug actually may have the wrong assertion-text in its description. In the log from comment 0 here and also the log linked in comment 3 (and I assume the others - those are just the instances that I've looked at), it looks to me like the actual assertion-failure during this test is quite different:

###!!! ASSERTION: Unexpected layers id in AllocPAPZParent; dropping message...: 'Error', file /builds/worker/checkouts/gecko/gfx/layers/ipc/ContentCompositorBridgeParent.cpp:177

More context with backtrace:

[task 2021-02-06T10:36:35.370Z] 10:36:35     INFO - [Parent 1440, Compositor] ###!!! ASSERTION: Unexpected layers id in AllocPAPZParent; dropping message...: 'Error', file /builds/worker/checkouts/gecko/gfx/layers/ipc/ContentCompositorBridgeParent.cpp:177
[task 2021-02-06T10:36:35.370Z] 10:36:35     INFO - #01: mozilla::layers::PCompositorBridgeParent::OnMessageReceived(IPC::Message const&) [s3:gecko-generated-sources:5765aca2662654c050d4929e2906b6efbc52e7c849c5590a2f32347ddad06fb092b9d643ac7699855729702ee87f2f619594dacf5cd6a30c7cf3cbc4ba9e3c75/ipc/ipdl/PCompositorBridgeParent.cpp::1078]
[task 2021-02-06T10:36:35.371Z] 10:36:35     INFO - #02: mozilla::layers::PCompositorManagerParent::OnMessageReceived(IPC::Message const&) [s3:gecko-generated-sources:465f788c5c2153f2808bde1001998ab167eaff20dd748295e96a4079a3456cfd1a822dbe432109311fce0091cc1cbeee521673d1eb10a143fbb293f855779e0e/ipc/ipdl/PCompositorManagerParent.cpp::205]
[task 2021-02-06T10:36:35.372Z] 10:36:35     INFO - #03: mozilla::ipc::MessageChannel::DispatchAsyncMessage(mozilla::ipc::ActorLifecycleProxy*, IPC::Message const&) [ipc/glue/MessageChannel.cpp:2154]
[task 2021-02-06T10:36:35.372Z] 10:36:35     INFO - #04: mozilla::ipc::MessageChannel::DispatchMessage(IPC::Message&&) [ipc/glue/MessageChannel.cpp:2080]
[task 2021-02-06T10:36:35.373Z] 10:36:35     INFO - #05: mozilla::ipc::MessageChannel::RunMessage(mozilla::ipc::MessageChannel::MessageTask&) [ipc/glue/MessageChannel.cpp:1925]
[task 2021-02-06T10:36:35.373Z] 10:36:35     INFO - #06: mozilla::ipc::MessageChannel::MessageTask::Run() [ipc/glue/MessageChannel.cpp:1958]
[task 2021-02-06T10:36:35.378Z] 10:36:35     INFO - #07: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1153]
[task 2021-02-06T10:36:35.379Z] 10:36:35     INFO - #08: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/threads/nsThreadUtils.cpp:548]
[task 2021-02-06T10:36:35.379Z] 10:36:35     INFO - #09: mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:303]
[task 2021-02-06T10:36:35.380Z] 10:36:35     INFO - #10: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:335]
[task 2021-02-06T10:36:35.381Z] 10:36:35     INFO - #11: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:311]
[task 2021-02-06T10:36:35.381Z] 10:36:35     INFO - #12: nsThread::ThreadFunc(void*) [xpcom/threads/nsThread.cpp:393]
[task 2021-02-06T10:36:35.483Z] 10:36:35     INFO - #13: _pt_root [nsprpub/pr/src/pthreads/ptthread.c:204]
[task 2021-02-06T10:36:35.486Z] 10:36:35     INFO -  fix-stacks: error: failed to read symbols file `/builds/worker/workspace/build/symbols/libpthread.so.0/10063CBC74776C265F7DB3F1F380A3DA0/libpthread.so.0.sym` for `/lib/x86_64-linux-gnu/libpthread.so.0`
[task 2021-02-06T10:36:35.487Z] 10:36:35     INFO -  fix-stacks: note: this is expected and harmless for system libraries on debug automation runs
[task 2021-02-06T10:36:35.488Z] 10:36:35     INFO -  fix-stacks: No such file or directory (os error 2)
[task 2021-02-06T10:36:35.489Z] 10:36:35     INFO - #14: ??? [/lib/x86_64-linux-gnu/libpthread.so.0 + 0x76db]
[task 2021-02-06T10:36:35.491Z] 10:36:35     INFO - #15: clone [/lib/x86_64-linux-gnu/libc.so.6 + 0x121a3f]
[task 2021-02-06T10:36:35.491Z] 10:36:35     INFO - #16: ??? (???:???)

Both logs do also have one instance of ASSERTION: should have done initial reflow by now: 'mDidInitialize' somewhere in the log, but it's during a different test (436900-2.html) and it seems to be an expected-fail there. (That test is annotated as having 0 to 1 assertions, with this being the occasional-assertion, I assume).

So I don't think this bug is really about that "should have done initial reflow" assertion at all.

Flags: needinfo?(dholbert)

--> Adjusting bug summary to reflect the correct assertion text, per comment 14. (Please correct me if I'm missing something, though.)

Also: I'm not sure if this is related, but it's interesting -- in both of the failure logs that I linked in comment 14, the logging includes an interesting note that suggests this test was the slowest test and took over a minute (104 seconds in one case, 74 seconds in the other):

The log from comment 0 has:

REFTEST INFO | Slowest test took 104371ms (file:///builds/worker/workspace/build/tests/reftest/tests/layout/generic/crashtests/471360.html)

The log from comment 3 has:

REFTEST INFO | Slowest test took 74131ms (file:///builds/worker/workspace/build/tests/reftest/tests/layout/generic/crashtests/471360.html)

It looks like the test does some sort of repeated self-editing (boom1 calls boom2, which calls boom3, which callsboom1`, all via seetTimeouts)
Link to test source: https://searchfox.org/mozilla-central/source/layout/generic/crashtests/471360.html

We probably should place an upper-bound on the amount of cycling here, or else the test can keep running for an indefinite amount of time, due to the fact that the test harness waits for paints to stabilize.

Summary: Intermittent layout/generic/crashtests/471360.html | assertion count 1 is more than expected 0 assertions from ASSERTION: should have done initial reflow by now: 'mDidInitialize', file /builds/worker/checkouts/gecko/layout/base/PresShell.cpp:3530 → Intermittent layout/generic/crashtests/471360.html | assertion count 1 is more than expected 0 assertions from ASSERTION: Unexpected layers id in AllocPAPZParent; dropping message...: 'Error', file gfx/layers/ipc/ContentCompositorBridgeParent.cpp:177
Depends on: 471360

Also fwiw, it looks like we have several other intermittent-failure bugs with the same Unexpected layers id in AllocPAPZParent assertion failure: bug 1676017 and bug 1655640, at least.

Thank you for taking a look!
Made Bug 1708332 for the failure I mentioned in Comment 13.

Assignee: nobody → dholbert
Status: NEW → ASSIGNED

Note, this particular test also seems to be causing a "load failed: timed out waiting for pending paint count to reach zero" failure on aarch64 (per bug 1700634), which makes sense for reasons discussed in comment 15 here. Sample log:
https://treeherder.mozilla.org/logviewer?job_id=338238518&repo=mozilla-central&lineNumber=25300

The attached patch (putting an upper-bound on the cycling) should address that, as well as the "slowest test" issue noted here. I'm not sure if it'll fix the assertion-failure as well (the thing that this bug is really focusing on), but it seems like it might. (And we can reopen this after the patch lands if it doesn't.)

Pushed by dholbert@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/f0ad5df7104d Give crashtest 471360.html an upper-bound on its looping so that it doesn't cycle forever and block the harness from proceeding. r=mats
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → 90 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: