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)
Tracking
()
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```
Comment hidden (Intermittent Failures Robot) |
![]() |
||
Updated•5 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 13•4 years ago
|
||
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?
Assignee | ||
Comment 14•4 years ago
|
||
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.
Assignee | ||
Comment 15•4 years ago
|
||
--> 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 calls
boom1`, 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.
Assignee | ||
Comment 16•4 years ago
|
||
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.
Comment 17•4 years ago
|
||
Thank you for taking a look!
Made Bug 1708332 for the failure I mentioned in Comment 13.
Assignee | ||
Comment 18•4 years ago
|
||
Updated•4 years ago
|
Assignee | ||
Comment 19•4 years ago
|
||
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.)
Comment hidden (Intermittent Failures Robot) |
Comment 21•4 years ago
|
||
Comment 22•4 years ago
|
||
bugherder |
Updated•4 years ago
|
Comment hidden (Intermittent Failures Robot) |
Description
•