Closed Bug 1638455 Opened 5 years ago Closed 4 years ago

Intermittent Assertion failure: IsCanceled() (Subclass Cancel() didn't set IsCanceled()!), at /builds/worker/checkouts/gecko/dom/workers/WorkerRunnable.cpp:245

Categories

(Core :: DOM: Workers, defect, P5)

defect

Tracking

()

RESOLVED INCOMPLETE

People

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

References

Details

(Keywords: assertion, intermittent-failure)

Attachments

(1 obsolete file)

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


[task 2020-05-15T20:32:51.631Z] 20:32:51 INFO - TEST-START | devtools/shared/resources/tests/browser_target_list_processes.js
[task 2020-05-15T20:32:51.797Z] 20:32:51 INFO - GECKO(3316) | [Child 2472: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 015BB400 == 0 [pid = 2472] [id = {566f51f1-0de3-4e37-aa3c-7950808a2e14}] [url = about:blank]
[task 2020-05-15T20:32:52.012Z] 20:32:52 INFO - GECKO(3316) | [Child 2472: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (01568EF0) [pid = 2472] [serial = 1] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:52.012Z] 20:32:52 INFO - GECKO(3316) | [Child 2472: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (072DE400) [pid = 2472] [serial = 3] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:52.012Z] 20:32:52 INFO - GECKO(3316) | [Child 2472: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (072DA800) [pid = 2472] [serial = 2] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:52.027Z] 20:32:52 INFO - GECKO(3316) | [Child 2472, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-05-15T20:32:52.054Z] 20:32:52 INFO - GECKO(3316) | [Child 1244: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 00BAFC00 == 1 [pid = 1244] [id = {c13de6d0-ab92-4929-b36d-d105c0775536}]
[task 2020-05-15T20:32:52.054Z] 20:32:52 INFO - GECKO(3316) | [Child 1244, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 855
[task 2020-05-15T20:32:52.055Z] 20:32:52 INFO - GECKO(3316) | [Child 1244: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (00B68DE0) [pid = 1244] [serial = 1] [outer = 00000000]
[task 2020-05-15T20:32:52.055Z] 20:32:52 INFO - GECKO(3316) | [Child 1244: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (066C0400) [pid = 1244] [serial = 2] [outer = 00B68DE0]
[task 2020-05-15T20:32:52.115Z] 20:32:52 INFO - GECKO(3316) | [Parent 3288, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2020-05-15T20:32:52.122Z] 20:32:52 INFO - GECKO(3316) | [Child 1244, Main Thread] WARNING: 'NS_FAILED(GetAccentColor(unused))', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 482
[task 2020-05-15T20:32:52.342Z] 20:32:52 INFO - GECKO(3316) | [Child 920: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 08AAFC00 == 3 [pid = 920] [id = {61fcf074-6988-4707-b234-832f23353a01}] [url = https://example.com/browser/devtools/shared/resources/tests/fission_iframe.html]
[task 2020-05-15T20:32:52.342Z] 20:32:52 INFO - GECKO(3316) | [Child 920: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 13 (06BC5800) [pid = 920] [serial = 9] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:52.342Z] 20:32:52 INFO - GECKO(3316) | [Child 920: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 12 (06BC3400) [pid = 920] [serial = 13] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:52.342Z] 20:32:52 INFO - GECKO(3316) | [Child 920: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 11 (08AA4400) [pid = 920] [serial = 7] [outer = 00000000] [url = http://localhost:50595/test_page_errors.html]
[task 2020-05-15T20:32:52.343Z] 20:32:52 INFO - GECKO(3316) | [Child 920: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 06BC4C00 == 2 [pid = 920] [id = {fe921d04-b986-4387-ac32-97279ce9a1c2}] [url = https://example.com/browser/devtools/shared/resources/tests//fission_document.html]
[task 2020-05-15T20:32:52.343Z] 20:32:52 INFO - GECKO(3316) | [Child 920: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 00EAF000 == 1 [pid = 920] [id = {43813580-6d95-4ba6-85c3-2d4acb5167f1}] [url = about:blank]
[task 2020-05-15T20:32:52.343Z] 20:32:52 INFO - GECKO(3316) | [Child 920: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 00EAF800 == 0 [pid = 920] [id = {a97c4c4f-b8e0-4c0e-a89c-1967175467ba}] [url = about:blank]
[task 2020-05-15T20:32:52.344Z] 20:32:52 INFO - GECKO(3316) | [Child 5128: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (06CDFC00) [pid = 5128] [serial = 2] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:52.344Z] 20:32:52 INFO - GECKO(3316) | [Child 5128: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (06CE4000) [pid = 5128] [serial = 3] [outer = 00000000] [url = data:text/html,Document Events]
[task 2020-05-15T20:32:52.479Z] 20:32:52 INFO - GECKO(3316) | [Child 920: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (06BDFBD0) [pid = 920] [serial = 10] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:52.479Z] 20:32:52 INFO - GECKO(3316) | [Child 920: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 9 (06BDFAC0) [pid = 920] [serial = 20] [outer = 00000000] [url = https://example.com/browser/devtools/shared/resources/tests/fission_iframe.html]
[task 2020-05-15T20:32:52.519Z] 20:32:52 INFO - GECKO(3316) | [Child 5128: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (01068EF0) [pid = 5128] [serial = 1] [outer = 00000000] [url = data:text/html,Document Events]
[task 2020-05-15T20:32:52.861Z] 20:32:52 INFO - GECKO(3316) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to c:\users\task_1589571848\appdata\local\temp\tmplxhpud.mozrunner\runtests_leaks_tab_pid4724.log
[task 2020-05-15T20:32:52.861Z] 20:32:52 INFO - GECKO(3316) | [4724, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 224
[task 2020-05-15T20:32:52.956Z] 20:32:52 INFO - GECKO(3316) | [Child 920, Main Thread] WARNING: A runnable was posted to a worker that is already shutting down!: file /builds/worker/checkouts/gecko/dom/workers/WorkerPrivate.cpp, line 1433
[task 2020-05-15T20:32:52.957Z] 20:32:52 INFO - GECKO(3316) | [Child 920, Main Thread] WARNING: Failed to dispatch offline status change event!: file /builds/worker/checkouts/gecko/dom/workers/WorkerPrivate.cpp, line 1916
[task 2020-05-15T20:32:52.957Z] 20:32:52 INFO - GECKO(3316) | [Child 920, Worker Launcher] WARNING: '!lock->is<Terminated>()', file /builds/worker/checkouts/gecko/dom/workers/remoteworkers/RemoteWorkerChild.cpp, line 280
[task 2020-05-15T20:32:52.960Z] 20:32:52 INFO - GECKO(3316) | [Child 920, DOM Worker] WARNING: failed to post proxy release event, leaking!: file /builds/worker/checkouts/gecko/xpcom/threads/nsProxyRelease.h, line 78
[task 2020-05-15T20:32:52.963Z] 20:32:52 INFO - GECKO(3316) | Assertion failure: IsCanceled() (Subclass Cancel() didn't set IsCanceled()!), at /builds/worker/checkouts/gecko/dom/workers/WorkerRunnable.cpp:245
[task 2020-05-15T20:32:52.963Z] 20:32:52 INFO - GECKO(3316) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-05-15T20:32:52.970Z] 20:32:52 INFO - GECKO(3316) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-05-15T20:32:52.985Z] 20:32:52 INFO - GECKO(3316) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-05-15T20:32:52.986Z] 20:32:52 INFO - GECKO(3316) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-05-15T20:32:53.001Z] 20:32:53 INFO - GECKO(3316) | [Parent 3288, Main Thread] WARNING: '!contentParent', file /builds/worker/checkouts/gecko/dom/ipc/ContentProcessManager.cpp, line 101
[task 2020-05-15T20:32:53.002Z] 20:32:53 INFO - GECKO(3316) | [Parent 3288, Main Thread] WARNING: 'mProgress != Progress::ShutdownCompleted', file /builds/worker/checkouts/gecko/dom/serviceworkers/ServiceWorkerShutdownState.cpp, line 57
[task 2020-05-15T20:32:53.002Z] 20:32:53 INFO - GECKO(3316) | [Parent 3288, IPDL Background] WARNING: 'aOwner->mState == RemoteWorkerController::eTerminated', file /builds/worker/checkouts/gecko/dom/workers/remoteworkers/RemoteWorkerController.cpp, line 404
[task 2020-05-15T20:32:53.003Z] 20:32:53 INFO - GECKO(3316) | [Parent 3288, IPDL Background] WARNING: 'aResult.IsReject()', file /builds/worker/checkouts/gecko/dom/workers/remoteworkers/RemoteWorkerControllerParent.cpp, line 108
[task 2020-05-15T20:32:53.066Z] 20:32:53 INFO - GECKO(3316) | [Parent 3288, Main Thread] WARNING: 'mProgress != Progress::ShutdownCompleted', file /builds/worker/checkouts/gecko/dom/serviceworkers/ServiceWorkerShutdownState.cpp, line 57
[task 2020-05-15T20:32:53.109Z] 20:32:53 INFO - GECKO(3316) | #01: mozilla::dom::WorkerPrivate::ProcessAllControlRunnablesLocked() [dom/workers/WorkerPrivate.cpp:3517]
[task 2020-05-15T20:32:53.109Z] 20:32:53 INFO - GECKO(3316) | #02: mozilla::dom::WorkerPrivate::OnProcessNextEvent() [dom/workers/WorkerPrivate.cpp:3040]
[task 2020-05-15T20:32:53.110Z] 20:32:53 INFO - GECKO(3316) | #03: mozilla::dom::WorkerThread::Observer::OnProcessNextEvent(nsIThreadInternal*, bool) [dom/workers/WorkerThread.cpp:370]
[task 2020-05-15T20:32:53.110Z] 20:32:53 INFO - GECKO(3316) | #04: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1116]
[task 2020-05-15T20:32:53.111Z] 20:32:53 INFO - GECKO(3316) | #05: NS_ProcessPendingEvents(nsIThread*, unsigned int) [xpcom/threads/nsThreadUtils.cpp:449]
[task 2020-05-15T20:32:53.111Z] 20:32:53 INFO - GECKO(3316) | #06: mozilla::dom::WorkerPrivate::ClearMainEventQueue(mozilla::dom::WorkerPrivate::WorkerRanOrNot) [dom/workers/WorkerPrivate.cpp:3560]
[task 2020-05-15T20:32:53.112Z] 20:32:53 INFO - GECKO(3316) | #07: mozilla::dom::WorkerPrivate::NotifyInternal(mozilla::dom::WorkerStatus) [dom/workers/WorkerPrivate.cpp:4377]
[task 2020-05-15T20:32:53.112Z] 20:32:53 INFO - GECKO(3316) | #08: mozilla::dom::anonymous namespace'::NotifyRunnable::WorkerRun(JSContext*, mozilla::dom::WorkerPrivate*) [dom/workers/WorkerPrivate.cpp:442] [task 2020-05-15T20:32:53.113Z] 20:32:53 INFO - GECKO(3316) | #09: mozilla::dom::WorkerRunnable::Run() [dom/workers/WorkerRunnable.cpp:370] [task 2020-05-15T20:32:53.113Z] 20:32:53 INFO - GECKO(3316) | #10: mozilla::dom::WorkerPrivate::ProcessAllControlRunnablesLocked() [dom/workers/WorkerPrivate.cpp:3517] [task 2020-05-15T20:32:53.114Z] 20:32:53 INFO - GECKO(3316) | #11: mozilla::dom::WorkerPrivate::DoRunLoop(JSContext*) [dom/workers/WorkerPrivate.cpp:2873] [task 2020-05-15T20:32:53.115Z] 20:32:53 INFO - GECKO(3316) | #12: mozilla::dom::workerinternals::anonymous namespace'::WorkerThreadPrimaryRunnable::Run() [dom/workers/RuntimeService.cpp:2270]
[task 2020-05-15T20:32:53.115Z] 20:32:53 INFO - GECKO(3316) | #13: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1213]
[task 2020-05-15T20:32:53.115Z] 20:32:53 INFO - GECKO(3316) | #14: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/threads/nsThreadUtils.cpp:501]
[task 2020-05-15T20:32:53.116Z] 20:32:53 INFO - GECKO(3316) | #15: mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:302]
[task 2020-05-15T20:32:53.116Z] 20:32:53 INFO - GECKO(3316) | #16: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:315]
[task 2020-05-15T20:32:53.116Z] 20:32:53 INFO - GECKO(3316) | #17: MessageLoop::RunHandler() [ipc/chromium/src/base/message_loop.cc:309]
[task 2020-05-15T20:32:53.117Z] 20:32:53 INFO - GECKO(3316) | #18: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:291]
[task 2020-05-15T20:32:53.117Z] 20:32:53 INFO - GECKO(3316) | #19: static nsThread::ThreadFunc(void*) [xpcom/threads/nsThread.cpp:446]
[task 2020-05-15T20:32:53.601Z] 20:32:53 INFO - GECKO(3316) | #20: _PR_NativeRunThread(void*) [nsprpub/pr/src/threads/combined/pruthr.c:399]
[task 2020-05-15T20:32:53.602Z] 20:32:53 INFO - GECKO(3316) | #21: pr_root(void*) [nsprpub/pr/src/md/windows/w95thred.c:139]
[task 2020-05-15T20:32:53.602Z] 20:32:53 INFO - fix-stacks error: failed to read breakpad symbols dir Z:\task_1589571848\build\symbols\ucrtbase.DLL for Z:\task_1589571848\build\application\firefox\ucrtbase.DLL
[task 2020-05-15T20:32:53.602Z] 20:32:53 INFO - fix-stacks note: this is expected and harmless for system libraries on debug automation runs
[task 2020-05-15T20:32:53.603Z] 20:32:53 INFO - GECKO(3316) | #22: o____lc_collate_cp_func [Z:\task_1589571848\build\application\firefox\ucrtbase.DLL + 0x3e16f]
[task 2020-05-15T20:32:53.603Z] 20:32:53 INFO - GECKO(3316) | #23: BaseThreadInitThunk [C:\windows\system32\kernel32.dll + 0x4ef3c]
[task 2020-05-15T20:32:53.604Z] 20:32:53 INFO - GECKO(3316) | #24: RtlInitializeExceptionChain [C:\windows\SYSTEM32\ntdll.dll + 0x63618]
[task 2020-05-15T20:32:53.604Z] 20:32:53 INFO - GECKO(3316) | #25: RtlInitializeExceptionChain [C:\windows\SYSTEM32\ntdll.dll + 0x635eb]
[task 2020-05-15T20:32:53.605Z] 20:32:53 INFO - GECKO(3316) | [Parent 3288, Main Thread] WARNING: Not resolving response because actor is dead.: file /builds/worker/workspace/obj-build/ipc/ipdl/PContentParent.cpp, line 11856
[task 2020-05-15T20:32:53.606Z] 20:32:53 INFO - GECKO(3316) | [Child 3484: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 016B7000 == 0 [pid = 3484] [id = {5bb202c0-874e-43e5-8d95-97e5625f1787}] [url = about:blank]
[task 2020-05-15T20:32:53.606Z] 20:32:53 INFO - GECKO(3316) | [Child 4724: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 00ABA800 == 1 [pid = 4724] [id = {231ba899-be62-4b2e-b6bb-11a8a9f24c25}]
[task 2020-05-15T20:32:53.607Z] 20:32:53 INFO - GECKO(3316) | [Child 4724, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 855
[task 2020-05-15T20:32:53.607Z] 20:32:53 INFO - GECKO(3316) | [Child 3484: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (01668EF0) [pid = 3484] [serial = 1] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:53.608Z] 20:32:53 INFO - GECKO(3316) | [Child 3484: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (074C3400) [pid = 3484] [serial = 2] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:53.609Z] 20:32:53 INFO - GECKO(3316) | [Child 4724: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (00A68EF0) [pid = 4724] [serial = 1] [outer = 00000000]
[task 2020-05-15T20:32:53.609Z] 20:32:53 INFO - GECKO(3316) | [Child 4724: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (067DBC00) [pid = 4724] [serial = 2] [outer = 00A68EF0]
[task 2020-05-15T20:32:53.610Z] 20:32:53 INFO - GECKO(3316) | [Child 3484, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-05-15T20:32:53.610Z] 20:32:53 INFO - GECKO(3316) | [Child 4620: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (070E5800) [pid = 4620] [serial = 10] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:53.611Z] 20:32:53 INFO - GECKO(3316) | [Child 4620: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (070E6000) [pid = 4620] [serial = 3] [outer = 00000000] [url = data:text/html,Console Messages]
[task 2020-05-15T20:32:53.611Z] 20:32:53 INFO - GECKO(3316) | [Child 4620: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (0D403000) [pid = 4620] [serial = 8] [outer = 00000000] [url = data:text/html,Root Node tests]
[task 2020-05-15T20:32:53.612Z] 20:32:53 INFO - GECKO(3316) | [Child 4724, Main Thread] WARNING: 'NS_FAILED(GetAccentColor(unused))', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 482
[task 2020-05-15T20:32:53.612Z] 20:32:53 INFO - GECKO(3316) | [Child 4448: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (06BD9800) [pid = 4448] [serial = 2] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:53.613Z] 20:32:53 INFO - GECKO(3316) | [Child 5128: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (06CEB400) [pid = 5128] [serial = 4] [outer = 00000000] [url = data:text/html,Document Events]
[task 2020-05-15T20:32:53.613Z] 20:32:53 INFO - GECKO(3316) | [Child 3640: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 9 (029D3400) [pid = 3640] [serial = 5] [outer = 00000000] [url = data:text/html,<div id=div1>]
[task 2020-05-15T20:32:53.613Z] 20:32:53 INFO - GECKO(3316) | [Child 3640: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 8 (029CF000) [pid = 3640] [serial = 4] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:53.614Z] 20:32:53 INFO - GECKO(3316) | [Child 3640: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 7 (029DBC00) [pid = 3640] [serial = 9] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:53.614Z] 20:32:53 INFO - GECKO(3316) | [Child 3640: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 6 (029D0400) [pid = 3640] [serial = 6] [outer = 00000000] [url = data:text/html,<div id=div1>]
[task 2020-05-15T20:32:53.614Z] 20:32:53 INFO - GECKO(3316) | [Child 4620: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0BF17790) [pid = 4620] [serial = 9] [outer = 00000000] [url = http://example.com/document-builder.sjs?html=com]
[task 2020-05-15T20:32:53.615Z] 20:32:53 INFO - GECKO(3316) | [Child 4620: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0D401400) [pid = 4620] [serial = 11] [outer = 00000000] [url = http://example.com/document-builder.sjs?html=com]
[task 2020-05-15T20:32:53.615Z] 20:32:53 INFO - GECKO(3316) | [Child 4620, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/netwerk/base/nsNetUtil.cpp, line 2295
[task 2020-05-15T20:32:53.615Z] 20:32:53 INFO - GECKO(3316) | [Child 4620, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/caps/ContentPrincipal.cpp, line 398
[task 2020-05-15T20:32:53.616Z] 20:32:53 INFO - GECKO(3316) | [Child 4620, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/caps/ContentPrincipal.cpp, line 423
[task 2020-05-15T20:32:53.616Z] 20:32:53 INFO - GECKO(3316) | [Child 4620, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-05-15T20:32:53.635Z] 20:32:53 INFO - GECKO(3316) | [Child 2076: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (01568DE0) [pid = 2076] [serial = 1] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:53.635Z] 20:32:53 INFO - GECKO(3316) | [Child 2076: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (073C0800) [pid = 2076] [serial = 2] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:53.665Z] 20:32:53 INFO - GECKO(3316) | [Child 2076, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-05-15T20:32:53.721Z] 20:32:53 INFO - GECKO(3316) | [[Child 4448: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (00D68EF0) [pid = 4448] [serial = 1] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:53.721Z] 20:32:53 INFO - GECKO(3316) | Child 5128, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.[Child 4448: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (06BDD400) [pid = 4448] [serial = 3] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:53.721Z] 20:32:53 INFO - GECKO(3316) | cpp, line 3359
[task 2020-05-15T20:32:53.738Z] 20:32:53 INFO - GECKO(3316) | [Child 4448, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-05-15T20:32:53.774Z] 20:32:53 INFO - GECKO(3316) | [Child 4724: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (067E0400) [pid = 4724] [serial = 3] [outer = 00A68EF0]
[task 2020-05-15T20:32:53.869Z] 20:32:53 INFO - GECKO(3316) | [Child 3640: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 5 (01268DE0) [pid = 3640] [serial = 1] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:53.869Z] 20:32:53 INFO - GECKO(3316) | [Child 3640: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (02920020) [pid = 3640] [serial = 3] [outer = 00000000] [url = data:text/html,<div id=div3>]
[task 2020-05-15T20:32:53.870Z] 20:32:53 INFO - GECKO(3316) | [Child 3640: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (029208A0) [pid = 3640] [serial = 8] [outer = 00000000] [url = http://example.net/document-builder.sjs?html=net]
[task 2020-05-15T20:32:53.870Z] 20:32:53 INFO - GECKO(3316) | [Child 3640: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (029D9800) [pid = 3640] [serial = 7] [outer = 00000000] [url = data:text/html,<div id=div3>]
[task 2020-05-15T20:32:53.870Z] 20:32:53 INFO - GECKO(3316) | [Child 3640: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (029CC400) [pid = 3640] [serial = 2] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:53.871Z] 20:32:53 INFO - GECKO(3316) | [Child 3640: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0BBDE000) [pid = 3640] [serial = 10] [outer = 00000000] [url = http://example.net/document-builder.sjs?html=net]
[task 2020-05-15T20:32:53.871Z] 20:32:53 INFO - GECKO(3316) | [Child 3640, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/netwerk/base/nsNetUtil.cpp, line 2295
[task 2020-05-15T20:32:53.871Z] 20:32:53 INFO - GECKO(3316) | [Child 3640, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/caps/ContentPrincipal.cpp, line 398
[task 2020-05-15T20:32:53.871Z] 20:32:53 INFO - GECKO(3316) | [Child 3640, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/caps/ContentPrincipal.cpp, line 423
[task 2020-05-15T20:32:53.892Z] 20:32:53 INFO - GECKO(3316) | console.warn: "Listener for event 'process' did not return a promise."
[task 2020-05-15T20:32:53.892Z] 20:32:53 INFO - GECKO(3316) | console.warn: "Listener for event 'process' did not return a promise."
[task 2020-05-15T20:32:53.895Z] 20:32:53 INFO - GECKO(3316) | [Child 3640, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-05-15T20:32:53.990Z] 20:32:53 INFO - GECKO(3316) | [Parent 3288, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 475
[task 2020-05-15T20:32:54.068Z] 20:32:54 INFO - GECKO(3316) | MEMORY STAT | vsize 858MB | vsizeMaxContiguous 364MB | residentFast 293MB | heapAllocated 129MB
[task 2020-05-15T20:32:54.068Z] 20:32:54 INFO - TEST-OK | devtools/shared/resources/tests/browser_target_list_processes.js | took 2435ms
[task 2020-05-15T20:32:54.135Z] 20:32:54 INFO - checking window state
[task 2020-05-15T20:32:54.136Z] 20:32:54 INFO - GECKO(3316) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to c:\users\task_1589571848\appdata\local\temp\tmplxhpud.mozrunner\runtests_leaks_tab_pid3696.log
[task 2020-05-15T20:32:54.139Z] 20:32:54 INFO - GECKO(3316) | [3696, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 224
[task 2020-05-15T20:32:54.158Z] 20:32:54 INFO - GECKO(3316) | [Child 4724: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 00ABA800 == 0 [pid = 4724] [id = {231ba899-be62-4b2e-b6bb-11a8a9f24c25}] [url = data:text/html;charset=utf-8,%3Cdiv%20id%3D%22test%22%3E%3C%2Fdiv%3E]
[task 2020-05-15T20:32:54.178Z] 20:32:54 INFO - TEST-START | devtools/shared/resources/tests/browser_target_list_switchToTarget.js
[task 2020-05-15T20:32:54.193Z] 20:32:54 INFO - GECKO(3316) | [Parent 3288, Main Thread] WARNING: NS_ENSURE_TRUE(GetWrapper()) failed: file /builds/worker/checkouts/gecko/dom/ipc/JSActor.cpp, line 90
[task 2020-05-15T20:32:54.273Z] 20:32:54 INFO - GECKO(3316) | [Child 4724: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (00A68EF0) [pid = 4724] [serial = 1] [outer = 00000000] [url = data:text/html;charset=utf-8,%3Cdiv%20id%3D%22test%22%3E%3C%2Fdiv%3E]
[task 2020-05-15T20:32:54.273Z] 20:32:54 INFO - GECKO(3316) | [Child 4724: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (067DBC00) [pid = 4724] [serial = 2] [outer = 00000000] [url = about:blank]
[task 2020-05-15T20:32:54.274Z] 20:32:54 INFO - GECKO(3316) | [Child 4724: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (067E0400) [pid = 4724] [serial = 3] [outer = 00000000] [url = data:text/html;charset=utf-8,%3Cdiv%20id%3D%22test%22%3E%3C%2Fdiv%3E]
[task 2020-05-15T20:32:54.274Z] 20:32:54 INFO - GECKO(3316) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to c:\users\task_1589571848\appdata\local\temp\tmplxhpud.mozrunner\runtests_leaks_tab_pid1032.log
[task 2020-05-15T20:32:54.274Z] 20:32:54 INFO - GECKO(3316) | [1032, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 224
[task 2020-05-15T20:32:54.293Z] 20:32:54 INFO - GECKO(3316) | [Child 4724, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-05-15T20:32:54.340Z] 20:32:54 INFO - GECKO(3316) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to c:\users\task_1589571848\appdata\local\temp\tmplxhpud.mozrunner\runtests_leaks_tab_pid4156.log
[task 2020-05-15T20:32:54.340Z] 20:32:54 INFO - GECKO(3316) | [4156, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 224
[task 2020-05-15T20:32:54.361Z] 20:32:54 INFO - GECKO(3316) | [Child 3696: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 015B5C00 == 1 [pid = 3696] [id = {e26a1139-9f1a-48ed-91aa-af8e8f5f9979}]
[task 2020-05-15T20:32:54.362Z] 20:32:54 INFO - GECKO(3316) | [Child 3696, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 855
[task 2020-05-15T20:32:54.362Z] 20:32:54 INFO - GECKO(3316) | [Child 3696: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (01568DE0) [pid = 3696] [serial = 1] [outer = 00000000]
[task 2020-05-15T20:32:54.363Z] 20:32:54 INFO - GECKO(3316) | [Child 3696: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (076C8400) [pid = 3696] [serial = 2] [outer = 01568DE0]
[task 2020-05-15T20:32:54.426Z] 20:32:54 INFO - GECKO(3316) | [Child 3696, Main Thread] WARNING: 'NS_FAILED(GetAccentColor(unused))', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 482
[task 2020-05-15T20:32:54.661Z] 20:32:54 INFO - GECKO(3316) | [Child 1032: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 014BB800 == 1 [pid = 1032] [id = {44ed7e56-c5e7-497b-8806-4f777546437a}]
[task 2020-05-15T20:32:54.664Z] 20:32:54 INFO - GECKO(3316) | [Child 1032, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 855
[task 2020-05-15T20:32:54.664Z] 20:32:54 INFO - GECKO(3316) | [Child 1032: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (01468EF0) [pid = 1032] [serial = 1] [outer = 00000000]
[task 2020-05-15T20:32:54.664Z] 20:32:54 INFO - GECKO(3316) | [Child 1032: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (072DBC00) [pid = 1032] [serial = 2] [outer = 01468EF0]
[task 2020-05-15T20:32:54.725Z] 20:32:54 INFO - GECKO(3316) | [Child 4156: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 00DB3800 == 1 [pid = 4156] [id = {c5b922f9-1200-44b4-a510-ab07bc4f72f1}]
[task 2020-05-15T20:32:54.732Z] 20:32:54 INFO - GECKO(3316) | [Child 4156, Main Thread] WARNING: 'NS_FAIL[ED(rv)', file /builChild 1032, ds/wMaiorker/checkoutsn Thread] WAR/NING: 'NS_FAILEgD(GetAccentColor(unused)e)', file /cbuilds/wkorker/checkouts/gecko/o/widwidget/windows/nsLgookAndFeel.cepp, line 482
[task 2020-05-15T20:32:54.732Z] 20:32:54 INFO - GECKO(3316) | t/windows/nsLookAndFeel.cpp, line 855
[task 2020-05-15T20:32:54.732Z] 20:32:54 INFO - GECKO(3316) | [Child 4156: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (06ABE020) [pid = 4156] [serial = 1] [outer = 00000000]
[task 2020-05-15T20:32:54.732Z] 20:32:54 INFO - GECKO(3316) | [Child 4156: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (06AD6C00) [pid = 4156] [serial = 2] [outer = 06ABE020]
[task 2020-05-15T20:32:54.787Z] 20:32:54 INFO - GECKO(3316) | [Child 4156, Main Thread] WARNING: 'NS_FAILED(GetAccentColor(unused))', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 482
[task 2020-05-15T20:32:54.787Z] 20:32:54 INFO - GECKO(3316) | [Child 920, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 475
[task 2020-05-15T20:32:54.787Z] 20:32:54 INFO - GECKO(3316) | [Child 920, Main Thread] WARNING: '!ipcActor->SendAccumulateChildHistograms(histogramsToSend)', file /builds/worker/checkouts/gecko/toolkit/components/telemetry/core/ipc/TelemetryIPCAccumulator.cpp, line 279
[task 2020-05-15T20:32:54.788Z] 20:32:54 INFO - GECKO(3316) | [Child 920, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 475
[task 2020-05-15T20:32:54.789Z] 20:32:54 INFO - GECKO(3316) | [Child 920, Main Thread] WARNING: '!ipcActor->SendAccumulateChildKeyedHistograms(keyedHistogramsToSend)', file /builds/worker/checkouts/gecko/toolkit/components/telemetry/core/ipc/TelemetryIPCAccumulator.cpp, line 283
[task 2020-05-15T20:32:54.790Z] 20:32:54 INFO - GECKO(3316) | [Child 920, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 475
[task 2020-05-15T20:32:54.790Z] 20:32:54 INFO - GECKO(3316) | [Child 920, Main Thread] WARNING: '!ipcActor->SendRecordDiscardedData(discardedData)', file /builds/worker/checkouts/gecko/toolkit/components/telemetry/core/ipc/TelemetryIPCAccumulator.cpp, line 298
[task 2020-05-15T20:32:54.809Z] 20:32:54 INFO - GECKO(3316) | [Child 1032: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (072DF400) [pid = 1032] [serial = 3] [outer = 01468EF0]
[task 2020-05-15T20:32:55.104Z] 20:32:55 INFO - GECKO(3316) | [Parent 3288, Main Thread] WARNING: Not resolving response because actor is dead.: file /builds/worker/workspace/obj-build/ipc/ipdl/PContentParent.cpp, line 11856
[task 2020-05-15T20:32:55.119Z] 20:32:55 INFO - GECKO(3316) | [Child 4156: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (06ADB000) [pid = 4156] [serial = 3] [outer = 06ABE020]
[task 2020-05-15T20:32:55.134Z] 20:32:55 INFO - GECKO(3316) | [Child 4156: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 06ADD000 == 2 [pid = 4156] [id = {528003b0-1c35-480b-a310-c57556110e93}]
[task 2020-05-15T20:32:55.134Z] 20:32:55 INFO - GECKO(3316) | [Child 4156: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 4 (06ABE240) [pid = 4156] [serial = 4] [outer = 00000000]
[task 2020-05-15T20:32:55.177Z] 20:32:55 INFO - GECKO(3316) | [Child 4156: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 5 (06AE1000) [pid = 4156] [serial = 5] [outer = 06ABE240]
[task 2020-05-15T20:32:55.444Z] 20:32:55 INFO - GECKO(3316) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to c:\users\task_1589571848\appdata\local\temp\tmplxhpud.mozrunner\runtests_leaks_tab_pid2080.log
[task 2020-05-15T20:32:55.444Z] 20:32:55 INFO - GECKO(3316) | [2080, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 224
[task 2020-05-15T20:32:55.504Z] 20:32:55 INFO - GECKO(3316) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to c:\users\task_1589571848\appdata\local\temp\tmplxhpud.mozrunner\runtests_leaks_tab_pid4564.log
[task 2020-05-15T20:32:55.505Z] 20:32:55 INFO - GECKO(3316) | [4564, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 224
[task 2020-05-15T20:32:55.785Z] 20:32:55 INFO - GECKO(3316) | [Child 2080: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 00DC0400 == 1 [pid = 2080] [id = {34bacb4f-9ea5-4614-9069-f1e85069ab3e}]
[task 2020-05-15T20:32:55.785Z] 20:32:55 INFO - GECKO(3316) | [Child 2080, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 855
[task 2020-05-15T20:32:55.786Z] 20:32:55 INFO - GECKO(3316) | [Child 2080: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (00D68EF0) [pid = 2080] [serial = 1] [outer = 00000000]
[task 2020-05-15T20:32:55.786Z] 20:32:55 INFO - GECKO(3316) | [Child 2080: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (06AE3800) [pid = 2080] [serial = 2] [outer = 00D68EF0]
[task 2020-05-15T20:32:55.845Z] 20:32:55 INFO - GECKO(3316) | [Child 2080, Main Thread] WARNING: 'NS_FAILED(GetAccentColor(unused))', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 482
[task 2020-05-15T20:32:55.872Z] 20:32:55 INFO - GECKO(3316) | [Child 4564: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 012BA400 == 1 [pid = 4564] [id = {741a37dd-60fb-4f2b-a114-bd13c7f24c65}]
[task 2020-05-15T20:32:55.872Z] 20:32:55 INFO - GECKO(3316) | [Child 4564, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 855
[task 2020-05-15T20:32:55.873Z] 20:32:55 INFO - GECKO(3316) | [Child 4564: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (01268EF0) [pid = 4564] [serial = 1] [outer = 00000000]
[task 2020-05-15T20:32:55.873Z] 20:32:55 INFO - GECKO(3316) | [Child 4564: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (071DB800) [pid = 4564] [serial = 2] [outer = 01268EF0]
[task 2020-05-15T20:32:55.912Z] 20:32:55 INFO - GECKO(3316) | [Child 2080: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (06AE7400) [pid = 2080] [serial = 3] [outer = 00D68EF0]
[task 2020-05-15T20:32:55.931Z] 20:32:55 INFO - GECKO(3316) | [Child 4564, Main Thread] WARNING: 'NS_FAILED(GetAccentColor(unused))', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 482
[task 2020-05-15T20:32:56.014Z] 20:32:56 INFO - GECKO(3316) | [Child 4564: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (071E0000) [pid = 4564] [serial = 3] [outer = 01268EF0]
[task 2020-05-15T20:32:56.029Z] 20:32:56 INFO - GECKO(3316) | [Child 4564: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 071E1000 == 2 [pid = 4564] [id = {93ab0700-f7a1-4491-bcfd-39a261c0544f}]
[task 2020-05-15T20:32:56.029Z] 20:32:56 INFO - GECKO(3316) | [Child 4564: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 4 (0C02E130) [pid = 4564] [serial = 4] [outer = 00000000]
[task 2020-05-15T20:32:56.069Z] 20:32:56 INFO - GECKO(3316) | [Child 4564: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 5 (071E6000) [pid = 4564] [serial = 5] [outer = 0C02E130]
[task 2020-05-15T20:32:56.256Z] 20:32:56 INFO - GECKO(3316) | console.warn: "Listener for event 'frame' did not return a promise."
[task 2020-05-15T20:32:56.451Z] 20:32:56 INFO - GECKO(3316) | MEMORY STAT | vsize 864MB | vsizeMaxContiguous 364MB | residentFast 302MB | heapAllocated 129MB

The last failure is different from the previous ones: It is a data race on an ASAN build.

I see a previous write here, which means, we are creating a new performance counter.

This seems to be guarded by two mutexes, but those are not checked while reading it somewhere in here. Unfortunately all this is inlined such that stack trace reading alone is not really helping.

Perry?

Flags: needinfo?(perry)
See Also: → 1642488

I feel like the bot got confused when making comment 4? Anyways, I did have a best-guess fix for this without being able to product it, will upload shortly.

Flags: needinfo?(perry)

"Cancel properly" means call WorkerRunnable::Cancel() (or a caller of that, like
the WorkerControlRunnable::Cancel() override). Pretty much a bandaid fix - seems
like a design issue that the subclass overrides must call this method.

This issue appears to be exposed by an assertion that checks that virtual method
calls to Cancel() correctly set the member variable which keeps track of if the
WorkerRunnable is canceled.

Assignee: nobody → perry
Status: NEW → ASSIGNED

Restating the situation of comment 0:

  • WorkerRunnables are cancelable because the spec for workers for close a worker includes the text "Discard any tasks that have been added to workerGlobal's relevant agent's event loop's task queues." Runnables need a way to be told that they won't actually get to run for effect and should instead perform any appropriate semantic cleanup.
    • Under ServiceWorker parent intercept, cancellation ONLY happens as a result of ClearMainEventQueue()! (Note that there are ton of overrides of Cancel, however, so there are a lot of calls from a searchfox perspective as Cancels move up the class hierarchy.)
    • (Under ServiceWorker child intercept https://searchfox.org/mozilla-central/rev/85ae3b911d5fcabd38ef315725df32e25edef83b/dom/serviceworkers/ServiceWorkerPrivate.cpp#1813 cancels runnables that were queued up for execution against the SW once it has spawned. Parent intercept nicely raises things up a level so we are dealing in semantic operations rather than low level runnables.)
    • Our implementation is not really as clean as the spec would make it seem, there's ongoing work to clean it up.
  • WorkerRunnables also provide a lot of assertions and lifecycle management in terms of busy counting, being aware of what thread they're on, etc. See https://github.com/asutherland/asuth-gecko-notes/blob/master/dom/workers/WorkerRunnable.md for some more info.
  • WorkerControlRunnables are WorkerRunnables because they want the assertions and lifecycle management, not cancellation.
    • The ReleaseWorkerRunnable in the patch notably does the same thing under WorkerRun and Cancel
    • CrashIfHangingRunnable also does something meaningful under Cancel, although its behavior is inconsistent when this particular race happens.
  • In comment 0 we're seeing the WorkerControlRunnable being canceled accidentally.
    • I say accidentally because WorkerControlRunnables uses WorkerRunnable::Run as its Run which calls WorkerPrivate::AllPendingRunnablesShouldBeCanceled to see if we're in ClearMainEventQueue and I believe the intent here was to cancel only normal runnables, not control runnables.
      • ClearMainEventQueue explicitly spins the event loop in order to drain all queued runnables, which is intentional.
      • WorkerPrivate::OnProcessNextEvent calls ProcessAllControlRunnables explicitly to deal with random jerk C++ code spinning a nested event loop without being aware of the control runnable queue. I believe the processing of the control runnable queue in this case to be unintentional and primarily a side effect of the arguably awkward and hacky way by which the cancellation is indirectly implemented because of a historical inability to directly access the event loop to cancel the runnables.
    • Bug 1155546 was a bug confronted with a similar situation (control runnable canceled because of ClearMainEventQueue) and gave us https://hg.mozilla.org/mozilla-central/rev/91e9b0c36889
      • The patch adds a null-guard on the JSContext, which stops the crash and adds WorkerControlRunnable::Cancel.
      • At least under the current setup, the change to WorkerControlRunnable::Cancel is very weird. The patch ended up changing the call from WorkerRunnable::Run's cancellation logic to WorkerRunnable::Cancel into a call from WorkerRunnable::Run's cancellation logic to WorkerControlRunnable::Cancel to WorkerRunnable::Run with mCallingCancelWithinRun=true which then makes the logic skip the IsCanceled() fast return and also skips re-triggering the cancellation logic. This ends up letting the normal WorkerRun logic run despite the fact that we just canceled the runnable!
      • The discussion of cancellation in the bug is https://bugzilla.mozilla.org/show_bug.cgi?id=1155546#c6 "Looking closer it seems like WorkerControlRunnable doesn't have a special Cancel hook (that would make it always Run(), like expected). That's what needs to be fixed."
      • The comment is a little ambiguous to me, but my best interpretation amounts to "We always want to run control runnables and so Cancel should still be calling WorkerRun", with me assuming the reference to Run() was meant to be WorkerRun().
      • In any event, the net effect was to end up calling both any custom Cancel() logic implemented by the WorkerControlRunnable subclass plus its WorkerRun() logic, which seems like a bad idea.

For the current patch, it seems like running both the Cancel() logic and WorkerRun() logic would not be an improvement.

I propose the following:

  • Establish and enforce the invariant that WorkerControlRunnables are never cancelled.
    • Any control runnable that potentially needs to deal with the worker being in a state > Running needs to check the worker's state and/or be using abstractions aware of that state, like the WorkerRef family.
  • Do not run control runnables while running ClearMainEventQueue. Specifically:
  • Remove custom Cancel logic from all existing control runnables, making sure the WorkerRun path handles > Running states.

:baku, does this all make sense?

Flags: needinfo?(amarchesini)
Assignee: perry → nobody
Status: ASSIGNED → NEW
Assignee: nobody → sgiesecke
Status: NEW → ASSIGNED
Attachment #9161811 - Attachment is obsolete: true
Assignee: sgiesecke → nobody
Status: ASSIGNED → NEW

I'm going to move forward with the plan I proposed in the bottom of comment 9 as part of the worker event loop cleanup.

Assignee: nobody → bugmail
Status: NEW → ASSIGNED
Flags: needinfo?(amarchesini)
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → ASSIGNED
Status: ASSIGNED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INCOMPLETE

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=330169561&repo=mozilla-esr78&lineNumber=28605

[task 2021-02-17T01:04:49.016Z] 01:04:49 INFO - TEST-START | devtools/shared/resources/tests/browser_target_list_processes.js
[task 2021-02-17T01:04:49.057Z] 01:04:49 INFO - GECKO(4888) | [Child 4976: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 14 (00AE9DF0) [pid = 4976] [serial = 11] [outer = 00000000] [url = about:blank]
[task 2021-02-17T01:04:49.057Z] 01:04:49 INFO - GECKO(4888) | [Child 4976: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 13 (00AE9680) [pid = 4976] [serial = 13] [outer = 00000000] [url = about:blank]
[task 2021-02-17T01:04:49.058Z] 01:04:49 INFO - GECKO(4888) | [Child 4976: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 12 (00AEA010) [pid = 4976] [serial = 23] [outer = 00000000] [url = https://example.com/browser/devtools/shared/resources/tests/fission_iframe.html]
[task 2021-02-17T01:04:49.262Z] 01:04:49 INFO - GECKO(4888) | [Child 2364: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 00DAA800 == 1 [pid = 2364] [id = {ccb3c636-36fa-41a5-9661-82439de44607}]
[task 2021-02-17T01:04:49.262Z] 01:04:49 INFO - GECKO(4888) | [Child 2364, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 855
[task 2021-02-17T01:04:49.263Z] 01:04:49 INFO - GECKO(4888) | [Child 2364: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (00DEE680) [pid = 2364] [serial = 1] [outer = 00000000]
[task 2021-02-17T01:04:49.263Z] 01:04:49 INFO - GECKO(4888) | [Child 2364: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (00DB2000) [pid = 2364] [serial = 2] [outer = 00DEE680]
[task 2021-02-17T01:04:49.307Z] 01:04:49 INFO - GECKO(4888) | [Child 2364, Main Thread] WARNING: 'NS_FAILED(GetAccentColor(unused))', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 482
[task 2021-02-17T01:04:49.473Z] 01:04:49 INFO - GECKO(4888) | [Child 4616: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 11 (073E5C00) [pid = 4616] [serial = 8] [outer = 00000000] [url = data:text/html,<div id=div1>]
[task 2021-02-17T01:04:49.473Z] 01:04:49 INFO - GECKO(4888) | [Child 4616: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0C402C00 == 1 [pid = 4616] [id = {4e560126-1e64-4792-ad82-20c2a2b6aca2}] [url = https://example.com/browser/devtools/shared/resources/tests/fission_iframe.html]
[task 2021-02-17T01:04:49.473Z] 01:04:49 INFO - GECKO(4888) | [Child 4616: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (073F2400) [pid = 4616] [serial = 9] [outer = 00000000] [url = data:text/html,<div id=div3>]
[task 2021-02-17T01:04:49.474Z] 01:04:49 INFO - GECKO(4888) | [Child 4616: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 9 (073F1C00) [pid = 4616] [serial = 7] [outer = 00000000] [url = data:text/html,<div id=div1>]
[task 2021-02-17T01:04:49.474Z] 01:04:49 INFO - GECKO(4888) | [Child 4616: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 8 (073EF000) [pid = 4616] [serial = 4] [outer = 00000000] [url = data:text/html;charset=utf-8,Cache Test]
[task 2021-02-17T01:04:49.474Z] 01:04:49 INFO - GECKO(4888) | [Child 4616: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 7 (073EE800) [pid = 4616] [serial = 11] [outer = 00000000] [url = about:blank]
[task 2021-02-17T01:04:49.474Z] 01:04:49 INFO - GECKO(4888) | [Child 4616: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 012BBC00 == 0 [pid = 4616] [id = {a86618b7-8528-4d4d-baff-38f42363439a}] [url = https://example.com/browser/devtools/shared/resources/tests//fission_document.html]
[task 2021-02-17T01:04:49.495Z] 01:04:49 INFO - GECKO(4888) | [Child 5152: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 12 (08AE6400) [pid = 5152] [serial = 13] [outer = 00000000] [url = data:text/html,Root Node tests]
[task 2021-02-17T01:04:49.495Z] 01:04:49 INFO - GECKO(4888) | [Child 5152: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 11 (068F0800) [pid = 5152] [serial = 6] [outer = 00000000] [url = data:text/html,Console Messages]
[task 2021-02-17T01:04:49.496Z] 01:04:49 INFO - GECKO(4888) | [Child 5152: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (08AE9800) [pid = 5152] [serial = 12] [outer = 00000000] [url = data:text/html,Root Node tests]
[task 2021-02-17T01:04:49.496Z] 01:04:49 INFO - GECKO(4888) | [Child 5152: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 9 (068E6400) [pid = 5152] [serial = 16] [outer = 00000000] [url = about:blank]
[task 2021-02-17T01:04:49.497Z] 01:04:49 INFO - GECKO(4888) | [Child 5152: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 8 (08AE5400) [pid = 5152] [serial = 9] [outer = 00000000] [url = http://localhost:51137/test_page_errors.html]
[task 2021-02-17T01:04:49.497Z] 01:04:49 INFO - GECKO(4888) | [Child 5152: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 7 (068E6C00) [pid = 5152] [serial = 3] [outer = 00000000] [url = data:text/html;charset=utf-8,Cache Test]
[task 2021-02-17T01:04:49.497Z] 01:04:49 INFO - GECKO(4888) | [Child 5152: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 00DB1400 == 0 [pid = 5152] [id = {a1909590-b694-4883-ab14-addb65215816}] [url = about:blank]
[task 2021-02-17T01:04:49.577Z] 01:04:49 INFO - GECKO(4888) | [Parent 1012, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2021-02-17T01:04:49.692Z] 01:04:49 INFO - GECKO(4888) | [Child 4616: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 6 (012F7340) [pid = 4616] [serial = 10] [outer = 00000000] [url = http://example.net/document-builder.sjs?html=net]
[task 2021-02-17T01:04:49.693Z] 01:04:49 INFO - GECKO(4888) | [Child 4616: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 5 (0C40AC00) [pid = 4616] [serial = 12] [outer = 00000000] [url = http://example.net/document-builder.sjs?html=net]
[task 2021-02-17T01:04:49.693Z] 01:04:49 INFO - GECKO(4888) | [Child 4616: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (012F6AC0) [pid = 4616] [serial = 16] [outer = 00000000] [url = https://example.com/browser/devtools/shared/resources/tests/fission_iframe.html]
[task 2021-02-17T01:04:49.694Z] 01:04:49 INFO - GECKO(4888) | [Child 4616: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (073E4800) [pid = 4616] [serial = 14] [outer = 00000000] [url = about:blank]
[task 2021-02-17T01:04:49.694Z] 01:04:49 INFO - GECKO(4888) | [Child 4616: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (012F6790) [pid = 4616] [serial = 13] [outer = 00000000] [url = https://example.com/browser/devtools/shared/resources/tests//fission_document.html]
[task 2021-02-17T01:04:49.695Z] 01:04:49 INFO - GECKO(4888) | [Child 4616: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (073F0C00) [pid = 4616] [serial = 17] [outer = 00000000] [url = https://example.com/browser/devtools/shared/resources/tests/fission_iframe.html]
[task 2021-02-17T01:04:49.695Z] 01:04:49 INFO - GECKO(4888) | [Child 4616: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0C401C00) [pid = 4616] [serial = 15] [outer = 00000000] [url = https://example.com/browser/devtools/shared/resources/tests//fission_document.html]
[task 2021-02-17T01:04:49.710Z] 01:04:49 INFO - GECKO(4888) | [Child 5152: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 6 (00DEC450) [pid = 5152] [serial = 15] [outer = 00000000] [url = http://example.com/document-builder.sjs?html=com]
[task 2021-02-17T01:04:49.710Z] 01:04:49 INFO - GECKO(4888) | [Child 5152: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 5 (00DEBCE0) [pid = 5152] [serial = 10] [outer = 00000000] [url = data:text/html,Root Node tests]
[task 2021-02-17T01:04:49.710Z] 01:04:49 INFO - GECKO(4888) | [Child 5152: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (00DEB790) [pid = 5152] [serial = 18] [outer = 00000000] [url = about:blank]
[task 2021-02-17T01:04:49.710Z] 01:04:49 INFO - GECKO(4888) | [Child 5152: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (08AE8800) [pid = 5152] [serial = 14] [outer = 00000000] [url = data:text/html,Root Node tests]
[task 2021-02-17T01:04:49.711Z] 01:04:49 INFO - GECKO(4888) | [Child 5152: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (08AED800) [pid = 5152] [serial = 17] [outer = 00000000] [url = http://example.com/document-builder.sjs?html=com]
[task 2021-02-17T01:04:49.711Z] 01:04:49 INFO - GECKO(4888) | [Child 5152: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (068E4000) [pid = 5152] [serial = 19] [outer = 00000000] [url = about:blank]
[task 2021-02-17T01:04:49.711Z] 01:04:49 INFO - GECKO(4888) | [Child 5152: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (08AE4000) [pid = 5152] [serial = 20] [outer = 00000000] [url = about:blank]
[task 2021-02-17T01:04:49.718Z] 01:04:49 INFO - GECKO(4888) | [Child 4616, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2021-02-17T01:04:49.733Z] 01:04:49 INFO - GECKO(4888) | [Child 5152, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2021-02-17T01:04:49.976Z] 01:04:49 INFO - GECKO(4888) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to c:\users\task_1613521133\appdata\local\temp\tmptq4qrr.mozrunner\runtests_leaks_tab_pid6132.log
[task 2021-02-17T01:04:50.022Z] 01:04:50 INFO - GECKO(4888) | [Child 4976, Main Thread] WARNING: A runnable was posted to a worker that is already shutting down!: file /builds/worker/checkouts/gecko/dom/workers/WorkerPrivate.cpp, line 1434
[task 2021-02-17T01:04:50.022Z] 01:04:50 INFO - GECKO(4888) | [Child 4976, Main Thread] WARNING: Failed to dispatch offline status change event!: file /builds/worker/checkouts/gecko/dom/workers/WorkerPrivate.cpp, line 1917
[task 2021-02-17T01:04:50.029Z] 01:04:50 INFO - GECKO(4888) | [Child 4976, Worker Launcher] WARNING: '!lock->is<Terminated>()', file /builds/worker/checkouts/gecko/dom/workers/remoteworkers/RemoteWorkerChild.cpp, line 280
[task 2021-02-17T01:04:50.030Z] 01:04:50 INFO - GECKO(4888) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-17T01:04:50.030Z] 01:04:50 INFO - GECKO(4888) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-17T01:04:50.030Z] 01:04:50 INFO - GECKO(4888) | [Child 4976, DOM Worker] WARNING: '!self', file /builds/worker/checkouts/gecko/dom/workers/remoteworkers/RemoteWorkerChild.cpp, line 528
[task 2021-02-17T01:04:50.030Z] 01:04:50 INFO - GECKO(4888) | Assertion failure: IsCanceled() (Subclass Cancel() didn't set IsCanceled()!), at /builds/worker/checkouts/gecko/dom/workers/WorkerRunnable.cpp:245
[task 2021-02-17T01:04:50.037Z] 01:04:50 INFO - GECKO(4888) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-17T01:04:50.038Z] 01:04:50 INFO - GECKO(4888) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: