Closed Bug 1742677 Opened 2 years ago Closed 11 months ago

Intermittent TEST-UNEXPECTED-TIMEOUT | Last test finished | application timed out after 370 seconds with no output

Categories

(WebExtensions :: General, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

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

Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=358992374&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/M7TGIpdKQ8umY-l2Ps-Y9g/runs/0/artifacts/public/logs/live_backing.log


[task 2021-11-23T18:30:02.575Z] 18:30:02     INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_startup_canary.html
[task 2021-11-23T18:30:02.694Z] 18:30:02     INFO - GECKO(18200) | MEMORY STAT | vsize 2801MB | residentFast 364MB | heapAllocated 14MB
[task 2021-11-23T18:30:02.710Z] 18:30:02     INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_startup_canary.html | took 135ms
[task 2021-11-23T18:30:02.763Z] 18:30:02     INFO - TEST-START | Shutdown
[task 2021-11-23T18:30:02.763Z] 18:30:02     INFO - Passed:  3817
[task 2021-11-23T18:30:02.763Z] 18:30:02     INFO - Failed:  0
[task 2021-11-23T18:30:02.764Z] 18:30:02     INFO - Todo:    1
[task 2021-11-23T18:30:02.764Z] 18:30:02     INFO - Mode:    e10s
[task 2021-11-23T18:30:02.764Z] 18:30:02     INFO - Slowest: 46549ms - /tests/toolkit/components/extensions/test/mochitest/test_ext_tabs_permissions.html
[task 2021-11-23T18:30:02.766Z] 18:30:02     INFO - SimpleTest FINISHED
[task 2021-11-23T18:30:02.766Z] 18:30:02     INFO - TEST-INFO | Ran 1 Loops
[task 2021-11-23T18:30:02.766Z] 18:30:02     INFO - SimpleTest FINISHED
[task 2021-11-23T18:30:02.857Z] 18:30:02     INFO - GECKO(18200) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 575: NotFoundError: No such JSWindowActor 'SpecialPowers'
[task 2021-11-23T18:30:02.947Z] 18:30:02     INFO - GECKO(18200) | 1637692202946	Marionette	TRACE	Received observer notification quit-application
[task 2021-11-23T18:30:02.949Z] 18:30:02     INFO - GECKO(18200) | 1637692202947	Marionette	INFO	Stopped listening on port 2828
[task 2021-11-23T18:30:02.949Z] 18:30:02     INFO - GECKO(18200) | 1637692202947	Marionette	DEBUG	Marionette stopped listening
[task 2021-11-23T18:30:03.082Z] 18:30:03     INFO - GECKO(18200) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-11-23T18:30:03.084Z] 18:30:03     INFO - GECKO(18200) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-11-23T18:30:03.091Z] 18:30:03     INFO - GECKO(18200) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-11-23T18:30:03.091Z] 18:30:03     INFO - GECKO(18200) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-11-23T18:30:03.098Z] 18:30:03     INFO - GECKO(18200) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-11-23T18:30:03.828Z] 18:30:03     INFO - GECKO(18200) | *** WIFI GEO: shutdown called
[task 2021-11-23T18:30:03.906Z] 18:30:03     INFO - GECKO(18200) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-11-23T18:30:15.239Z] 18:30:15     INFO - GECKO(18200) | Waiting in WillDestroyCurrentMessageLoop for pid 22174
[task 2021-11-23T18:31:06.885Z] 18:31:06     INFO - GECKO(18200) | RunWatchdog: Mainthread nested event loops during hang:
[task 2021-11-23T18:31:06.886Z] 18:31:06     INFO - GECKO(18200) |  --- (no nested event loop active)
[task 2021-11-23T18:31:07.889Z] 18:31:07     INFO - GECKO(18200) | ExceptionHandler::GenerateDump cloned child 22280
[task 2021-11-23T18:31:07.889Z] 18:31:07     INFO - GECKO(18200) | ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2021-11-23T18:31:07.890Z] 18:31:07     INFO - GECKO(18200) | ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2021-11-23T18:37:17.901Z] 18:37:17     INFO - Buffered messages finished
[task 2021-11-23T18:37:17.902Z] 18:37:17    ERROR - TEST-UNEXPECTED-TIMEOUT | Last test finished | application timed out after 370 seconds with no output
[task 2021-11-23T18:37:17.902Z] 18:37:17    ERROR - Force-terminating active process(es).
[task 2021-11-23T18:37:17.903Z] 18:37:17     INFO - Determining child pids from psutil...
[task 2021-11-23T18:37:17.916Z] 18:37:17     INFO - []
[task 2021-11-23T18:37:17.917Z] 18:37:17     INFO - ==> process 18200 launched child process 18222
[task 2021-11-23T18:37:17.917Z] 18:37:17     INFO - ==> process 18200 launched child process 18282
[task 2021-11-23T18:37:17.918Z] 18:37:17     INFO - ==> process 18200 launched child process 18285
[task 2021-11-23T18:37:17.918Z] 18:37:17     INFO - ==> process 18200 launched child process 18327

[task 2021-11-23T18:37:24.478Z] 18:37:24     INFO - PROCESS-CRASH | Main app process exited normally | application crashed [@ mozilla::(anonymous namespace)::RunWatchdog(void*)]
[task 2021-11-23T18:37:24.478Z] 18:37:24     INFO - Mozilla crash reason: MOZ_CRASH(Shutdown hanging after all known phases and workers finished.)
[task 2021-11-23T18:37:24.478Z] 18:37:24     INFO - Crash dump filename: /tmp/tmppjavdlov.mozrunner/minidumps/4a41bae3-da26-cd59-7075-0628887c8250.dmp
[task 2021-11-23T18:37:24.478Z] 18:37:24     INFO - Operating system: Linux
[task 2021-11-23T18:37:24.478Z] 18:37:24     INFO -                   0.0.0 Linux 4.4.0-1014-aws #14taskcluster1-Ubuntu SMP Tue Apr 3 10:27:00 UTC 2018 x86_64
[task 2021-11-23T18:37:24.478Z] 18:37:24     INFO - CPU: amd64
[task 2021-11-23T18:37:24.478Z] 18:37:24     INFO -      family 6 model 85 stepping 4
[task 2021-11-23T18:37:24.478Z] 18:37:24     INFO -      4 CPUs
[task 2021-11-23T18:37:24.478Z] 18:37:24     INFO - Linux Ubuntu 18.04 - bionic (Ubuntu 18.04.6 LTS)
[task 2021-11-23T18:37:24.478Z] 18:37:24     INFO - 
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO - Crash reason:  SIGSEGV / SEGV_MAPERR
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO - Crash address: 0x0
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO - Process uptime: not available
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO - 
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO - Thread 27  (crashed)
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO -  0  libxul.so!mozilla::(anonymous namespace)::RunWatchdog(void*) [nsTerminator.cpp:9cd4e2e23e4062375c3d55d8f42f4d05349a2510 : 256 + 0x19]
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO -     rax = 0x00007f77c8cd22b7   rdx = 0x00007f77e795c240
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO -     rcx = 0x00005620aebfb230   rbx = 0x00007f77994fee40
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO -     rsi = 0x0000000000000000   rdi = 0x00007f77e795c240
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO -     rbp = 0x00007f77994fee60   rsp = 0x00007f77994fee30
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO -      r8 = 0x0000000000000000    r9 = 0x0000000000000000
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO -     r10 = 0x00007f77e7d3c8f0   r11 = 0x0000000000000022
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO -     r12 = 0x00007f778e5575e0   r13 = 0x0000000000000007
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO -     r14 = 0x00007f77883efc40   r15 = 0x00000000000056f5
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO -     rip = 0x00007f77d4db67ca
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO -     Found by: given as instruction pointer in context
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO -  1  libnspr4.so!_pt_root [ptthread.c:9cd4e2e23e4062375c3d55d8f42f4d05349a2510 : 201 + 0x9]
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO -     rbx = 0x00007f77e795c450   rbp = 0x00007f77994feeb0
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO -     rsp = 0x00007f77994fee70   r12 = 0x00007f778e5575e0
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO -     r13 = 0x0000000000000007   r14 = 0x00007f77994ff700
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO -     r15 = 0x00000000000056f5   rip = 0x00007f77e8e7254f
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO -     Found by: call frame info
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO -  2  libpthread.so.0!start_thread [pthread_create.c : 463 + 0xc]
[task 2021-11-23T18:37:24.479Z] 18:37:24     INFO -     rbx = 0x0000000000000000   rbp = 0x0000000000000000
[task 2021-11-23T18:37:24.480Z] 18:37:24     INFO -     rsp = 0x00007f77994feec0   r12 = 0x00007f77994fef80
[task 2021-11-23T18:37:24.480Z] 18:37:24     INFO -     r13 = 0x0000000000000000   r14 = 0x00007f778e5575e0
[task 2021-11-23T18:37:24.480Z] 18:37:24     INFO -     r15 = 0x00007ffcac15c568   rip = 0x00007f77e8af26db
[task 2021-11-23T18:37:24.480Z] 18:37:24     INFO -     Found by: call frame info
[task 2021-11-23T18:37:24.480Z] 18:37:24     INFO -  3  libc.so.6!__GI___clone + 0x3e
[task 2021-11-23T18:37:24.480Z] 18:37:24     INFO -     rbx = 0x00007f77994ff700   rbp = 0x0000000000000000
[task 2021-11-23T18:37:24.480Z] 18:37:24     INFO -     rsp = 0x00007f77994fef80   r12 = 0x00007f77994fef80
[task 2021-11-23T18:37:24.480Z] 18:37:24     INFO -     r13 = 0x0000000000000000   r14 = 0x00007f778e5575e0
[task 2021-11-23T18:37:24.480Z] 18:37:24     INFO -     r15 = 0x00007ffcac15c568   rip = 0x00007f77e7cd8a3f
[task 2021-11-23T18:37:24.480Z] 18:37:24     INFO -     Found by: call frame info

Jens, isn't this a duplicate of Bug 1358898 just like Bug 1685912?

Flags: needinfo?(jstutte)

There are 37 failures in the last 5 days.
Most of them (34) are on linux1804-64-qr and 2 of them are on macosx1015-64-qr

See Also: → 1724337

(In reply to Alexandru Michis [:malexandru] from comment #2)

Jens, isn't this a duplicate of Bug 1358898 just like Bug 1685912?

It is a shutdown hang, but I think it is more the special case of bug 1730374.

Flags: needinfo?(jstutte)

There are 92 total failures in the last 7 days on

  • linux1804-64-ccov-qr opt
  • linux1804-64-qr debug
  • linux1804-64-tsan-qr opt
  • macosx1015-64-qr debug

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=360175244&repo=autoland&lineNumber=5466

task 2021-12-04T14:59:33.415Z] 14:59:33     INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_startup_canary.html
[task 2021-12-04T14:59:33.927Z] 14:59:33     INFO - GECKO(5200) | MEMORY STAT | vsize 130550644MB | residentFast 673MB
[task 2021-12-04T14:59:33.972Z] 14:59:33     INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_startup_canary.html | took 557ms
[task 2021-12-04T14:59:34.179Z] 14:59:34     INFO - TEST-START | Shutdown
[task 2021-12-04T14:59:34.179Z] 14:59:34     INFO - Passed:  2089
[task 2021-12-04T14:59:34.179Z] 14:59:34     INFO - Failed:  0
[task 2021-12-04T14:59:34.180Z] 14:59:34     INFO - Todo:    1
[task 2021-12-04T14:59:34.181Z] 14:59:34     INFO - Mode:    e10s
[task 2021-12-04T14:59:34.183Z] 14:59:34     INFO - Slowest: 91289ms - /tests/toolkit/components/extensions/test/mochitest/test_ext_tabs_permissions.html
[task 2021-12-04T14:59:34.194Z] 14:59:34     INFO - SimpleTest FINISHED
[task 2021-12-04T14:59:34.195Z] 14:59:34     INFO - TEST-INFO | Ran 1 Loops
[task 2021-12-04T14:59:34.198Z] 14:59:34     INFO - SimpleTest FINISHED
[task 2021-12-04T14:59:34.613Z] 14:59:34     INFO - GECKO(5200) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 575: NotFoundError: No such JSWindowActor 'SpecialPowers'
[task 2021-12-04T14:59:34.900Z] 14:59:34     INFO - GECKO(5200) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 575: NotFoundError: No such JSWindowActor 'AppTestDelegate'
[task 2021-12-04T14:59:34.903Z] 14:59:34     INFO - GECKO(5200) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 575: NotFoundError: No such JSWindowActor 'AppTestDelegate'
[task 2021-12-04T14:59:35.140Z] 14:59:35     INFO - GECKO(5200) | 1638629975139	Marionette	TRACE	Received observer notification quit-application
[task 2021-12-04T14:59:35.144Z] 14:59:35     INFO - GECKO(5200) | 1638629975140	Marionette	INFO	Stopped listening on port 2828
[task 2021-12-04T14:59:35.148Z] 14:59:35     INFO - GECKO(5200) | 1638629975142	Marionette	DEBUG	Marionette stopped listening
[task 2021-12-04T14:59:35.994Z] 14:59:35     INFO - GECKO(5200) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-12-04T14:59:35.997Z] 14:59:35     INFO - GECKO(5200) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-12-04T14:59:36.058Z] 14:59:36     INFO - GECKO(5200) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-12-04T14:59:36.061Z] 14:59:36     INFO - GECKO(5200) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-12-04T14:59:38.618Z] 14:59:38     INFO - GECKO(5200) | *** WIFI GEO: shutdown called
[task 2021-12-04T14:59:38.798Z] 14:59:38     INFO - GECKO(5200) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-12-04T14:59:51.431Z] 14:59:51     INFO - GECKO(5200) | Waiting in WillDestroyCurrentMessageLoop for pid 8664
[task 2021-12-04T15:05:41.961Z] 15:05:41     INFO - GECKO(5200) | RunWatchdog: Mainthread nested event loops during hang:
[task 2021-12-04T15:05:41.962Z] 15:05:41     INFO - GECKO(5200) |  --- (no nested event loop active)
[task 2021-12-04T15:05:42.962Z] 15:05:42     INFO - GECKO(5200) | ThreadSanitizer:DEADLYSIGNAL
[task 2021-12-04T15:05:42.963Z] 15:05:42     INFO - GECKO(5200) | ==5200==ERROR: ThreadSanitizer: SEGV on unknown address 0x000000000000 (pc 0x7efdd3abbb35 bp 0x000000000e2e sp 0x7efd3cb4f1f0 T8768)
[task 2021-12-04T15:05:42.963Z] 15:05:42     INFO - GECKO(5200) | ==5200==The signal is caused by a WRITE memory access.
[task 2021-12-04T15:05:42.964Z] 15:05:42     INFO - GECKO(5200) | ==5200==Hint: address points to the zero page.
[task 2021-12-04T15:05:43.009Z] 15:05:43     INFO - GECKO(5200) |     #0 mozilla::(anonymous namespace)::RunWatchdog(void*) /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:256:5 (libxul.so+0x6fc2b35)
[task 2021-12-04T15:05:43.010Z] 15:05:43     INFO - GECKO(5200) |     #1 _pt_root /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:201:5 (libnspr4.so+0x44fbd)
[task 2021-12-04T15:05:43.011Z] 15:05:43     INFO - GECKO(5200) |     #2 __tsan_thread_start_func /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/tsan/rtl/tsan_interceptors_posix.cpp:967:15 (firefox+0x590fc)
[task 2021-12-04T15:05:43.013Z] 15:05:43     INFO - GECKO(5200) |     #3 start_thread /tmp/glibc/nptl/pthread_create.c:463 (libpthread.so.0+0x76da)
[task 2021-12-04T15:05:43.014Z] 15:05:43     INFO - GECKO(5200) |     #4 __clone /tmp/glibc/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:95 (libc.so.6+0x121a3e)
[task 2021-12-04T15:05:43.015Z] 15:05:43     INFO - GECKO(5200) | ThreadSanitizer can not provide additional info.
[task 2021-12-04T15:05:43.016Z] 15:05:43     INFO - GECKO(5200) | SUMMARY: ThreadSanitizer: SEGV /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:256:5 in mozilla::(anonymous namespace)::RunWatchdog(void*)
[task 2021-12-04T15:05:43.018Z] 15:05:43     INFO - GECKO(5200) | ==5200==ABORTING
[task 2021-12-04T15:11:53.024Z] 15:11:53     INFO - Buffered messages finished
[task 2021-12-04T15:11:53.026Z] 15:11:53    ERROR - TEST-UNEXPECTED-TIMEOUT | Last test finished | application timed out after 370 seconds with no output
[task 2021-12-04T15:11:53.026Z] 15:11:53    ERROR - Force-terminating active process(es).
[task 2021-12-04T15:11:53.027Z] 15:11:53     INFO - Determining child pids from psutil...
[task 2021-12-04T15:11:53.036Z] 15:11:53     INFO - []
[task 2021-12-04T15:11:53.037Z] 15:11:53     INFO - ==> process 5200 launched child process 5215

[task 2021-12-04T15:12:23.558Z] 15:12:23     INFO - Error: Failed to kill process 6653: psutil.NoSuchProcess no process found with pid 6653
[task 2021-12-04T15:12:23.558Z] 15:12:23     INFO - Killing process: 5200
[task 2021-12-04T15:12:23.559Z] 15:12:23     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-04T15:12:23.559Z] 15:12:23     INFO - Can't trigger Breakpad, just killing process
[task 2021-12-04T15:12:23.560Z] 15:12:23     INFO - psutil found pid 5200 dead
[task 2021-12-04T15:12:23.560Z] 15:12:23     INFO - psutil found pid 5200 dead
[task 2021-12-04T15:12:23.561Z] 15:12:23     INFO - TEST-INFO | Main app process: exit 0
Whiteboard: [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

There are 93 total failures in the last 7 days on

  • linux1804-64-ccov-qr opt
  • linux1804-64-qr debug
  • macosx1015-64-qr debug

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=361980249&repo=mozilla-central&lineNumber=52187

[task 2021-12-21T10:09:20.522Z] 10:09:20     INFO - TEST-START | browser/modules/test/browser/browser_urlBar_zoom.js
[task 2021-12-21T10:09:20.563Z] 10:09:20     INFO - GECKO(9543) | [Child 12253: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7ffa15372400 == 1 [pid = 12253] [id = 0]
[task 2021-12-21T10:09:20.563Z] 10:09:20     INFO - GECKO(9543) | [Child 12253: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (7ffa2aa7d740) [pid = 12253] [serial = 1] [outer = 0]
[task 2021-12-21T10:09:20.566Z] 10:09:20     INFO - GECKO(9543) | [Child 12253: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (7ffa15372800) [pid = 12253] [serial = 2] [outer = 7ffa2aa7d740]
[task 2021-12-21T10:09:20.591Z] 10:09:20     INFO - GECKO(9543) | [Child 9688: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 25 (7f5941ca0740) [pid = 9688] [serial = 59] [outer = 0] [url = about:newtab]
[task 2021-12-21T10:09:20.593Z] 10:09:20     INFO - GECKO(9543) | [Child 9688: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 24 (7f594447e740) [pid = 9688] [serial = 56] [outer = 0] [url = about:newtab]
[task 2021-12-21T10:09:20.593Z] 10:09:20     INFO - GECKO(9543) | [Child 9688: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 23 (7f5941ca0c80) [pid = 9688] [serial = 61] [outer = 0] [url = about:newtab]
[task 2021-12-21T10:09:20.594Z] 10:09:20     INFO - GECKO(9543) | [Child 9688: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 22 (7f5942a2ee40) [pid = 9688] [serial = 54] [outer = 0] [url = about:blank]
[task 2021-12-21T10:09:20.595Z] 10:09:20     INFO - GECKO(9543) | [Child 9688: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 21 (7f594447e580) [pid = 9688] [serial = 51] [outer = 0] [url = about:newtab]
[task 2021-12-21T10:09:20.627Z] 10:09:20     INFO - GECKO(9543) | Waiting for browser load
[task 2021-12-21T10:09:20.628Z] 10:09:20     INFO - GECKO(9543) | Waiting for browser state change
[task 2021-12-21T10:09:20.775Z] 10:09:20     INFO - GECKO(9543) | Saw state f0001 and status 0
[task 2021-12-21T10:09:20.990Z] 10:09:20     INFO - GECKO(9543) | [Child 12253, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp:348
[task 2021-12-21T10:09:20.991Z] 10:09:20     INFO - GECKO(9543) | [Child 12253, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp:348
[task 2021-12-21T10:09:20.996Z] 10:09:20     INFO - GECKO(9543) | [Child 12253: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (7ffa15374c00) [pid = 12253] [serial = 3] [outer = 7ffa2aa7d740]
[task 2021-12-21T10:09:21.245Z] 10:09:21     INFO - GECKO(9543) | Saw state c0010 and status 0
[task 2021-12-21T10:09:21.246Z] 10:09:21     INFO - GECKO(9543) | Browser got expected state change https://example.com/
[task 2021-12-21T10:09:21.330Z] 10:09:21     INFO - GECKO(9543) | [Child 12253, Main Thread] WARNING: Scrolled rect smaller than scrollport?: file /builds/worker/checkouts/gecko/layout/generic/nsGfxScrollFrame.cpp:7102
[task 2021-12-21T10:09:21.618Z] 10:09:21     INFO - GECKO(9543) | [Child 12277: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7faae5c82400 == 1 [pid = 12277] [id = 0]
[task 2021-12-21T10:09:21.620Z] 10:09:21     INFO - GECKO(9543) | [Child 12277: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (7faafb37d740) [pid = 12277] [serial = 1] [outer = 0]
[task 2021-12-21T10:09:21.621Z] 10:09:21     INFO - GECKO(9543) | [Child 12277: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (7faae5c82800) [pid = 12277] [serial = 2] [outer = 7faafb37d740]
[task 2021-12-21T10:09:21.705Z] 10:09:21     INFO - GECKO(9543) | Waiting for browser load
[task 2021-12-21T10:09:21.710Z] 10:09:21     INFO - GECKO(9543) | Waiting for browser state change

[task 2021-12-21T10:09:38.153Z] 10:09:38     INFO - GECKO(9543) | [RDD 11154, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4438
[task 2021-12-21T10:09:51.046Z] 10:09:51     INFO - GECKO(9543) | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 446))
[task 2021-12-21T10:10:41.220Z] 10:10:41     INFO - GECKO(9543) | XPCOM_MEM_BLOAT_LOG: /tmp/tmpniabj9iq.mozrunner/runtests_leaks.log
[task 2021-12-21T10:10:41.222Z] 10:10:41     INFO - GECKO(9543) | Writing to log: /tmp/tmpniabj9iq.mozrunner/runtests_leaks.log
[task 2021-12-21T10:10:41.223Z] 10:10:41     INFO - GECKO(9543) | RunWatchdog: Mainthread nested event loops during hang:
[task 2021-12-21T10:10:41.224Z] 10:10:41     INFO - GECKO(9543) |  --- CompositorThreadHolder::Shutdown
[task 2021-12-21T10:10:42.228Z] 10:10:42     INFO - GECKO(9543) | Hit MOZ_CRASH(Shutdown hanging after all known phases and workers finished.) at /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:256
[task 2021-12-21T10:10:42.236Z] 10:10:42     INFO -  Initializing stack-fixing for the first stack frame, this may take a while...
[task 2021-12-21T10:10:52.583Z] 10:10:52     INFO - GECKO(9543) | #01: mozilla::(anonymous namespace)::RunWatchdog(void*) [toolkit/components/terminator/nsTerminator.cpp:256]
[task 2021-12-21T10:10:52.599Z] 10:10:52     INFO - GECKO(9543) | #02: _pt_root [nsprpub/pr/src/pthreads/ptthread.c:204]
[task 2021-12-21T10:10:52.601Z] 10:10:52     INFO - GECKO(9543) | #03: ??? [/lib/x86_64-linux-gnu/libpthread.so.0 + 0x76db]
[task 2021-12-21T10:10:52.605Z] 10:10:52     INFO - GECKO(9543) | #04: clone [/lib/x86_64-linux-gnu/libc.so.6 + 0x121a3f]
[task 2021-12-21T10:10:52.606Z] 10:10:52     INFO - GECKO(9543) | #05: ??? (???:???)
[task 2021-12-21T10:10:52.606Z] 10:10:52     INFO - GECKO(9543) | ExceptionHandler::GenerateDump cloned child 12401
[task 2021-12-21T10:10:52.607Z] 10:10:52     INFO - GECKO(9543) | ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2021-12-21T10:10:52.610Z] 10:10:52     INFO - GECKO(9543) | ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2021-12-21T10:10:52.610Z] 10:10:52     INFO - GECKO(9543) | [Child 9980, IPC I/O Child] WARNING: [D95291CAC36F580E.F635102BAADF04E8]: Ignoring message 'EVENT_MESSAGE' to peer 1.1 due to a missing broker: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:349
[task 2021-12-21T10:10:52.610Z] 10:10:52     INFO - GECKO(9543) | [Child 9980, IPC I/O Child] WARNING: [D95291CAC36F580E.F635102BAADF04E8]: Ignoring message 'EVENT_MESSAGE' to peer 1.1 due to a missing broker: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:349
[task 2021-12-21T10:10:52.611Z] 10:10:52     INFO - GECKO(9543) | [Child 9980, IPC I/O Child] WARNING: [D95291CAC36F580E.F635102BAADF04E8]: Ignoring message 'EVENT_MESSAGE' to peer 1.1 due to a missing broker: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:349
[task 2021-12-21T10:10:52.611Z] 10:10:52     INFO - GECKO(9543) | [Child 9980, IPC I/O Child] WARNING: [D95291CAC36F580E.F635102BAADF04E8]: Ignoring message 'EVENT_MESSAGE' to peer 1.1 due to a missing broker: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:349
[task 2021-12-21T10:10:52.612Z] 10:10:52     INFO - GECKO(9543) | [Child 9980, Main Thread] WARNING: IPC message 'PContent::Msg_GraphicsError' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:523
[task 2021-12-21T10:10:52.612Z] 10:10:52     INFO - GECKO(9543) | [GFX1-]: Receive IPC close with reason=AbnormalShutdown
[task 2021-12-21T10:17:02.624Z] 10:17:02     INFO - Buffered messages finished
[task 2021-12-21T10:17:02.625Z] 10:17:02    ERROR - TEST-UNEXPECTED-TIMEOUT | Last test finished | application timed out after 370 seconds with no output
[task 2021-12-21T10:17:02.626Z] 10:17:02    ERROR - Force-terminating active process(es).
[task 2021-12-21T10:17:02.627Z] 10:17:02     INFO - Determining child pids from psutil...
[task 2021-12-21T10:17:02.631Z] 10:17:02     INFO - []
[task 2021-12-21T10:17:02.633Z] 10:17:02     INFO - ==> process 9543 launched child process 9559
[task 2021-12-21T10:17:02.634Z] 10:17:02     INFO - ==> process 9543 launched child process 9614
[task 2021-12-21T10:17:02.636Z] 10:17:02     INFO - ==> process 9543 launched child process 9633
[task 2021-12-21T10:17:02.637Z] 10:17:02     INFO - ==> process 9543 launched child process 9688
[task 2021-12-21T10:17:02.639Z] 10:17:02     INFO - ==> process 9543 launched child process 9712
[task 2021-12-21T10:17:02.640Z] 10:17:02     INFO - ==> process 9543 launched child process 9725

[task 2021-12-21T10:17:02.782Z] 10:17:02     INFO - ==> process 9543 launched child process 12344
[task 2021-12-21T10:17:02.783Z] 10:17:02     INFO - ==> process 9543 launched child process 12348
[task 2021-12-21T10:17:02.784Z] 10:17:02     INFO - Found child pids: {10754, 11268, 10246, 11782, 11277, 11283, 10778, 11814, 9770, 10284, 9774, 12341, 10808, 12344, 12348, 11838, 10306, 10826, 9810, 10330, 11866, 10332, 10335, 11366, 11370, 10859, 11889, 9853, 10880, 10881, 11921, 11412, 11416, 10915, 9901, 11953, 10425, 10939, 11462, 10440, 11980, 10446, 10964, 11990, 9943, 11486, 11487, 10482, 11510, 11002, 9980, 12028, 10505, 9996, 11024, 11540, 12059, 11044, 10022, 10538, 10543, 11572, 11067, 11582, 11076, 10058, 9559, 12119, 10586, 11620, 10092, 12144, 12146, 11126, 10618, 11137, 10120, 10634, 11661, 9614, 10126, 11154, 12187, 9633, 11685, 10664, 11693, 11696, 10162, 10678, 12221, 11199, 10181, 10186, 9688, 10712, 12253, 10730, 11242, 11759, 9712, 12277, 9725, 12286}
[task 2021-12-21T10:17:02.785Z] 10:17:02     INFO - Failed to get child procs
[task 2021-12-21T10:17:02.786Z] 10:17:02     INFO - Killing process: 10754
[task 2021-12-21T10:17:02.787Z] 10:17:02     INFO - TEST-INFO | started process screentopng
[task 2021-12-21T10:17:03.060Z] 10:17:03     INFO - TEST-INFO | screentopng: exit 0

Shane, can you please take a look? Thank you.

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

Tom, from comment 16, it looks like it is all fission related, though not all the failures in there have extension tests. Can you get a look at this?

Flags: needinfo?(mixedpuppy) → needinfo?(tomica)

This doesn't look like an issue in extensions framework code, I looked at a few dozen logs and less than half of them are related to extensions (like the last one linked), and of those that are failing after extension tests, they're all over the place, not specific to a single test/module/API/functionality or anything else in common.

Very likely an issue in lower level code, and I have nothing to go on from these logs. Probably a dupe/special case of one of these:

(In reply to Jens Stutte [:jstutte] from comment #5)

(In reply to Alexandru Michis [:malexandru] from comment #2)

Jens, isn't this a duplicate of Bug 1358898 just like Bug 1685912?

It is a shutdown hang, but I think it is more the special case of bug 1730374.

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

Here I read:

FATAL ERROR: AsyncShutdown timeout in profile-before-change Conditions: [
 {"name":"ContentParent: id=7f25d516f900","state":{"remoteTypePrefix":"prealloc"},
  "filename":"/builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp","lineNumber":3589,
  "stack":["resource://gre/modules/nsAsyncShutdown.jsm:addBlocker:162"]},
 {"name":"ContentParent: id=7f25d2f95500",
  "state":{"remoteTypePrefix":"prealloc"},
  "filename":"/builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp","lineNumber":3589,
  "stack":["resource://gre/modules/nsAsyncShutdown.jsm:addBlocker:162"]}
] 
At least one completion condition failed to complete within a reasonable amount of time. Causing a crash to ensure that we do not leave the user with an unresponsive process draining resources.

This is a manifestation of a double shutdown blocker for the same ContentParent. That alone should not cause hangs, but there are also some possible races around the shutdown blockers. Bug 1764251 might help here to some extent.

See Also: → 1764251
Status: NEW → RESOLVED
Closed: 11 months ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.