Closed Bug 1720328 Opened 5 years ago Closed 4 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | devtools/client/debugger/test/mochitest/browser_dbg-browser-toolbox-workers.js (finished) | application timed out after 370 seconds with no output

Categories

(DevTools :: Debugger, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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


INFO - TEST-START | devtools/client/debugger/test/mochitest/browser_dbg-browser-toolbox-workers.js
[task 2021-07-13T14:22:58.025Z] 14:22:58     INFO - GECKO(1711) | [Child 1718: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 10df0cc00 == 1 [pid = 1718] [id = 21] [url = data:text/html,<script>debugger;</script>]
[task 2021-07-13T14:22:58.052Z] 14:22:58     INFO - GECKO(1711) | DevTools Server for Browser Toolbox listening on port: 49376
[task 2021-07-13T14:22:58.055Z] 14:22:58     INFO - GECKO(1711) | Starting Browser Toolbox /opt/worker/tasks/task_162618516441748/build/application/Firefox NightlyDebug.app/Contents/MacOS/firefox -no-remote -foreground -profile /var/folders/14/2_qpfkwn6s91ybykcsrmr3_8000014/T/tmp__txo1mx.mozrunner/chrome_debugger_profile -chrome chrome://devtools/content/framework/browser-toolbox/window.html
[task 2021-07-13T14:22:58.141Z] 14:22:58     INFO - GECKO(1711) | > ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/14/2_qpfkwn6s91ybykcsrmr3_8000014/T/tmp__txo1mx.mozrunner/runtests_leaks.log
[task 2021-07-13T14:22:58.142Z] 14:22:58     INFO - GECKO(1711) | > [1794, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:248
[task 2021-07-13T14:22:58.196Z] 14:22:58     INFO - GECKO(1711) | > [1794, Main Thread] WARNING: !ShouldProcessUpdates(): launching devtools: file /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:4125
[task 2021-07-13T14:22:58.389Z] 14:22:58     INFO - GECKO(1711) | > 1626186178387	Marionette	INFO	Marionette enabled
[task 2021-07-13T14:22:58.389Z] 14:22:58     INFO - GECKO(1711) | > 1626186178387	Marionette	TRACE	Received observer notification profile-after-change
[task 2021-07-13T14:22:58.434Z] 14:22:58     INFO - GECKO(1711) | > 1626186178432	Marionette	TRACE	Received observer notification command-line-startup
[task 2021-07-13T14:22:58.440Z] 14:22:58     INFO - GECKO(1711) | > [Parent 1794: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 11bca2c00 == 1 [pid = 1794] [id = 0]
[task 2021-07-13T14:22:58.441Z] 14:22:58     INFO - GECKO(1711) | > [Parent 1794: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (103f0d580) [pid = 1794] [serial = 1] [outer = 0]
[task 2021-07-13T14:22:58.444Z] 14:22:58     INFO - GECKO(1711) | > [Parent 1794: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (1040c8400) [pid = 1794] [serial = 2] [outer = 103f0d580]
[task 2021-07-13T14:22:58.830Z] 14:22:58     INFO - GECKO(1711) | > [Parent 1794: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 11bf96c00 == 2 [pid = 1794] [id = 1]
[task 2021-07-13T14:22:58.830Z] 14:22:58     INFO - GECKO(1711) | [Parent 1794: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (11ae77740) [pid = 1794] [serial = 3] [outer = 0]
[task 2021-07-13T14:22:58.833Z] 14:22:58     INFO - GECKO(1711) | > [Parent 1794: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 4 (11cf4b400) [pid = 1794] [serial = 4] [outer = 11ae77740]
[task 2021-07-13T14:22:58.833Z] 14:22:58     INFO - GECKO(1711) | 1626186178591	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2021-07-13T14:22:58.834Z] 14:22:58     INFO - GECKO(1711) | 1626186178598	RemoteAgent	DEBUG	WebDriver BiDi enabled
[task 2021-07-13T14:22:58.834Z] 14:22:58     INFO - GECKO(1711) | 1626186178599	RemoteAgent	DEBUG	CDP enabled
[task 2021-07-13T14:22:58.834Z] 14:22:58     INFO - GECKO(1711) | [Parent 1794, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4225
[task 2021-07-13T14:22:58.835Z] 14:22:58     INFO - GECKO(1711) | [Parent 1794, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4225
[task 2021-07-13T14:22:58.835Z] 14:22:58     INFO - GECKO(1711) | [Parent 1794, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /builds/worker/checkouts/gecko/parser/html/nsHtml5StreamParser.cpp:1371
[task 2021-07-13T14:22:58.948Z] 14:22:58     INFO - GECKO(1711) | > [2021-07-13T14:22:58Z WARN  webrender::device::gl] Missing optimized shader source for gpu_cache_update
[task 2021-07-13T14:22:58.984Z] 14:22:58     INFO - GECKO(1711) | > [2021-07-13T14:22:58Z WARN  webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2021-07-13T14:22:58.985Z] 14:22:58     INFO - GECKO(1711) | [2021-07-13T14:22:58Z WARN  webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2021-07-13T14:22:58.985Z] 14:22:58     INFO - GECKO(1711) | [2021-07-13T14:22:58Z WARN  webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
<...>
INFO - Console message: [JavaScript Error: "1626186556029	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
[task 2021-07-13T14:29:16.032Z] 14:29:16     INFO - append@resource://gre/modules/Log.jsm:723:12
[task 2021-07-13T14:29:16.032Z] 14:29:16     INFO - log@resource://gre/modules/Log.jsm:379:16
[task 2021-07-13T14:29:16.032Z] 14:29:16     INFO - error@resource://gre/modules/Log.jsm:387:10
[task 2021-07-13T14:29:16.032Z] 14:29:16     INFO - updateSystemAddons/res<@resource://gre/modules/addons/XPIInstall.jsm:4049:25
[task 2021-07-13T14:29:16.032Z] 14:29:16     INFO - 
[task 2021-07-13T14:30:47.807Z] 14:30:47     INFO - GECKO(1711) | [Parent 1711, Main Thread] WARNING: 'NS_FAILED(aRv)', file /builds/worker/checkouts/gecko/netwerk/ipc/NeckoParent.cpp:861
[task 2021-07-13T14:30:47.807Z] 14:30:47     INFO - GECKO(1711) | [Child 1720, Main Thread] WARNING: NS_ENSURE_TRUE(mRequest) failed: file /builds/worker/checkouts/gecko/netwerk/base/nsBaseChannel.cpp:914
[task 2021-07-13T14:36:57.835Z] 14:36:57     INFO - Buffered messages finished
[task 2021-07-13T14:36:57.836Z] 14:36:57    ERROR - TEST-UNEXPECTED-TIMEOUT | devtools/client/debugger/test/mochitest/browser_dbg-browser-toolbox-workers.js (finished) | application timed out after 370 seconds with no output
[task 2021-07-13T14:36:57.836Z] 14:36:57    ERROR - Force-terminating active process(es).
[task 2021-07-13T14:36:57.836Z] 14:36:57     INFO - Determining child pids from psutil...
[task 2021-07-13T14:36:57.838Z] 14:36:57     INFO - [1717, 1718, 1720, 1721, 1749, 1809]
[task 2021-07-13T14:36:57.838Z] 14:36:57     INFO - ==> process 1711 launched child process 1717
[task 2021-07-13T14:36:57.838Z] 14:36:57     INFO - ==> process 1711 launched child process 1718
[task 2021-07-13T14:36:57.839Z] 14:36:57     INFO - ==> process 1711 launched child process 1720
[task 2021-07-13T14:36:57.839Z] 14:36:57     INFO - ==> process 1711 launched child process 1721
[task 2021-07-13T14:36:57.839Z] 14:36:57     INFO - ==> process 1711 launched child process 1749
[task 2021-07-13T14:36:57.840Z] 14:36:57     INFO - ==> process 1711 launched child process 1809
[task 2021-07-13T14:36:57.840Z] 14:36:57     INFO - Found child pids: {1809, 1749, 1717, 1718, 1720, 1721}
[task 2021-07-13T14:36:57.840Z] 14:36:57     INFO - Killing process: 1809
[task 2021-07-13T14:36:57.841Z] 14:36:57     INFO - TEST-INFO | started process screencapture
[task 2021-07-13T14:36:57.948Z] 14:36:57     INFO - TEST-INFO | screencapture: exit 0
[task 2021-07-13T14:36:57.948Z] 14:36:57     INFO - Killing process: 1749
[task 2021-07-13T14:36:57.948Z] 14:36:57     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-07-13T14:36:57.948Z] 14:36:57     INFO - Killing process: 1717
[task 2021-07-13T14:36:57.949Z] 14:36:57     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-07-13T14:36:57.949Z] 14:36:57     INFO - Killing process: 1718
[task 2021-07-13T14:36:57.949Z] 14:36:57     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-07-13T14:36:57.950Z] 14:36:57     INFO - Killing process: 1720
[task 2021-07-13T14:36:57.950Z] 14:36:57     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-07-13T14:36:57.950Z] 14:36:57     INFO - Killing process: 1721
[task 2021-07-13T14:36:57.951Z] 14:36:57     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-07-13T14:36:58.973Z] 14:36:58     INFO - psutil found pid 1809 dead
<...>
INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-07-13T14:36:59.130Z] 14:36:59     INFO - psutil found pid 1711 dead
[task 2021-07-13T14:36:59.130Z] 14:36:59     INFO - TEST-INFO | Main app process: exit 0
[task 2021-07-13T14:36:59.131Z] 14:36:59    ERROR - TEST-UNEXPECTED-FAIL | ShutdownLeaks | process() called before end of test suite
[task 2021-07-13T14:36:59.131Z] 14:36:59     INFO - TEST-INFO | Confirming we saw 113 DOCSHELL created and 102 destroyed log strings.
[task 2021-07-13T14:36:59.132Z] 14:36:59     INFO - TEST-INFO | Confirming we saw 289 DOMWINDOW created and 267 destroyed log strings.
[task 2021-07-13T14:36:59.132Z] 14:36:59     INFO - runtests.py | Application ran for: 0:16:14.590335
[task 2021-07-13T14:36:59.133Z] 14:36:59     INFO - zombiecheck | Reading PID log: /var/folders/14/2_qpfkwn6s91ybykcsrmr3_8000014/T/tmp2g7mzp4qpidlog
[task 2021-07-13T14:36:59.133Z] 14:36:59     INFO - ==> process 1711 launched child process 1717
[task 2021-07-13T14:36:59.134Z] 14:36:59     INFO - ==> process 1711 launched child process 1718
[task 2021-07-13T14:36:59.134Z] 14:36:59     INFO - ==> process 1711 launched child process 1720
[task 2021-07-13T14:36:59.134Z] 14:36:59     INFO - ==> process 1711 launched child process 1721
[task 2021-07-13T14:36:59.135Z] 14:36:59     INFO - ==> process 1711 launched child process 1749
[task 2021-07-13T14:36:59.135Z] 14:36:59     INFO - ==> process 1711 launched child process 1809
[task 2021-07-13T14:36:59.135Z] 14:36:59     INFO - ==> process 1711 launched child process 2280
[task 2021-07-13T14:36:59.136Z] 14:36:59     INFO - zombiecheck | Checking for orphan process with PID: 2280
[task 2021-07-13T14:36:59.136Z] 14:36:59     INFO - zombiecheck | Checking for orphan process with PID: 1809
[task 2021-07-13T14:36:59.136Z] 14:36:59     INFO - zombiecheck | Checking for orphan process with PID: 1749
[task 2021-07-13T14:36:59.137Z] 14:36:59     INFO - zombiecheck | Checking for orphan process with PID: 1717
[task 2021-07-13T14:36:59.137Z] 14:36:59     INFO - zombiecheck | Checking for orphan process with PID: 1718
[task 2021-07-13T14:36:59.137Z] 14:36:59     INFO - zombiecheck | Checking for orphan process with PID: 1720
[task 2021-07-13T14:36:59.137Z] 14:36:59     INFO - zombiecheck | Checking for orphan process with PID: 1721
[task 2021-07-13T14:36:59.138Z] 14:36:59     INFO - mozcrash Copy/paste: /opt/worker/tasks/task_162618516441748/fetches/minidump_stackwalk/minidump_stackwalk /var/folders/14/2_qpfkwn6s91ybykcsrmr3_8000014/T/tmp__txo1mx.mozrunner/minidumps/ECD707D6-7F5E-4BB6-84F4-A858864AB37B.dmp /opt/worker/tasks/task_162618516441748/build/symbols
[task 2021-07-13T14:37:04.332Z] 14:37:04     INFO - mozcrash Saved minidump as /opt/worker/tasks/task_162618516441748/build/blobber_upload_dir/ECD707D6-7F5E-4BB6-84F4-A858864AB37B.dmp
[task 2021-07-13T14:37:04.333Z] 14:37:04     INFO - mozcrash Saved app info as /opt/worker/tasks/task_162618516441748/build/blobber_upload_dir/ECD707D6-7F5E-4BB6-84F4-A858864AB37B.extra
[task 2021-07-13T14:37:04.459Z] 14:37:04     INFO - PROCESS-CRASH | Main app process exited normally | application crashed [@ google_breakpad::ReceivePort::WaitForMessage(google_breakpad::MachReceiveMessage*, unsigned int)]
[task 2021-07-13T14:37:04.459Z] 14:37:04     INFO - Crash dump filename: /var/folders/14/2_qpfkwn6s91ybykcsrmr3_8000014/T/tmp__txo1mx.mozrunner/minidumps/ECD707D6-7F5E-4BB6-84F4-A858864AB37B.dmp
[task 2021-07-13T14:37:04.459Z] 14:37:04     INFO - Operating system: Mac OS X
[task 2021-07-13T14:37:04.459Z] 14:37:04     INFO -                   10.15.7 19H524
[task 2021-07-13T14:37:04.459Z] 14:37:04     INFO - CPU: amd64
[task 2021-07-13T14:37:04.459Z] 14:37:04     INFO -      family 6 model 158 stepping 10
[task 2021-07-13T14:37:04.459Z] 14:37:04     INFO -      12 CPUs
[task 2021-07-13T14:37:04.459Z] 14:37:04     INFO - 
[task 2021-07-13T14:37:04.459Z] 14:37:04     INFO - GPU: UNKNOWN
[task 2021-07-13T14:37:04.459Z] 14:37:04     INFO - 
[task 2021-07-13T14:37:04.459Z] 14:37:04     INFO - Crash reason:  EXC_SOFTWARE / SIGABRT
INFO - Crash address: 0x7fff6f780dfa
[task 2021-07-13T14:37:04.459Z] 14:37:04     INFO - Process uptime: 974 seconds
[task 2021-07-13T14:37:04.459Z] 14:37:04     INFO - 
[task 2021-07-13T14:37:04.459Z] 14:37:04     INFO - Thread 0 (crashed) - MainThread 0  libsystem_kernel.dylib!mach_msg_trap + 0xa
[task 2021-07-13T14:37:04.459Z] 14:37:04     INFO -     rax = 0x000000000100001f   rdx = 0x0000000000000000
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     rcx = 0x00007ffee308fd48   rbx = 0x0000000000000102
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     rsi = 0x0000000000000102   rdi = 0x00007ffee308fe00
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     rbp = 0x00007ffee308fda0   rsp = 0x00007ffee308fd48
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -      r8 = 0x000000000000892f    r9 = 0x0000000000001388
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     r10 = 0x000000000000041c   r11 = 0x0000000000000202
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     r12 = 0x0000000000000102   r13 = 0x000000000000041c
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     r14 = 0x00007ffee308fe00   r15 = 0x0000000000000000
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     rip = 0x00007fff6f780dfa
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     Found by: given as instruction pointer in context
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -  1  XUL!google_breakpad::ReceivePort::WaitForMessage(google_breakpad::MachReceiveMessage*, unsigned int) [MachIPC.mm:035499c85eb9b3117e0081b22caf1d6bd70815ed : 249 + 0x18]
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     rbp = 0x00007ffee308fdc0   rsp = 0x00007ffee308fdb0
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     rip = 0x000000011774d17a
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     Found by: previous frame's frame pointer
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -  2  XUL!google_breakpad::CrashGenerationClient::RequestDumpForException(int, int, long long, unsigned int, unsigned int) [crash_generation_client.cc:035499c85eb9b3117e0081b22caf1d6bd70815ed : 70 + 0xd]
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     rbp = 0x00007ffee3090670   rsp = 0x00007ffee308fdd0
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     rip = 0x0000000117740e69
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     Found by: call frame info
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -  3  XUL!google_breakpad::ExceptionHandler::WriteMinidumpWithException(int, int, long long, __darwin_ucontext*, unsigned int, unsigned int, bool, bool) [exception_handler.cc:035499c85eb9b3117e0081b22caf1d6bd70815ed : 464 + 0x25]
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     rbx = 0x0000000000000000   rbp = 0x00007ffee3090770
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     rsp = 0x00007ffee3090680   r12 = 0x00007fff6f844425
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     r14 = 0x0000000000000016   r15 = 0x000000000005a501
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     rip = 0x0000000117744857
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     Found by: call frame info
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -  4  XUL!google_breakpad::ExceptionHandler::SignalHandler(int, __siginfo*, void*) [exception_handler.cc:035499c85eb9b3117e0081b22caf1d6bd70815ed : 707 + 0x24]
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     rbx = 0x4e300b772f4300cc   rbp = 0x00007ffee30907b0
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     rsp = 0x00007ffee3090780   r12 = 0x7fffffffffffffff
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     r14 = 0x0000000111c5add8   r15 = 0x00007ffee3090e50
[task 2021-07-13T14:37:04.460Z] 14:37:04     INFO -     rip = 0x00000001177450f4
[task 2021-07-13T14:37:04.461Z] 14:37:04     INFO -     Found by: call frame info
[task 2021-07-13T14:37:04.461Z] 14:37:04     INFO -  5  libsystem_platform.dylib!_sigtramp + 0x1d
[task 2021-07-13T14:37:04.461Z] 14:37:04     INFO -     rbx = 0x4e300b772f4300cc   rbp = 0x00007ffee30907c0
[task 2021-07-13T14:37:04.461Z] 14:37:04     INFO -     rsp = 0x00007ffee30907c0   r12 = 0x7fffffffffffffff
[task 2021-07-13T14:37:04.461Z] 14:37:04     INFO -     r14 = 0x000000000000ffff   r15 = 0x00007ffee3090e50
[task 2021-07-13T14:37:04.461Z] 14:37:04     INFO -     rip = 0x00007fff6f8385fd
[task 2021-07-13T14:37:04.461Z] 14:37:04     INFO -     Found by: call frame info
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 5 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.