Closed Bug 1684441 Opened 3 years ago Closed 2 years ago

Intermittent SUMMARY: AddressSanitizer: SEGV /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:233:5 in mozilla::(anonymous namespace)::RunWatchdog(void*)

Categories

(Core :: DOM: Core & HTML, defect)

defect

Tracking

()

RESOLVED WORKSFORME

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug, Blocks 1 open bug)

Details

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

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


[task 2020-12-29T10:40:01.420Z] 10:40:01     INFO - GECKO(3272) | -----------------------------------------------------
[task 2020-12-29T10:43:05.879Z] 10:43:05     INFO - GECKO(3272) | AddressSanitizer:DEADLYSIGNAL
[task 2020-12-29T10:43:05.880Z] 10:43:05     INFO - GECKO(3272) | =================================================================
[task 2020-12-29T10:43:05.880Z] 10:43:05    ERROR - GECKO(3272) | ==3272==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000001 (pc 0x7f58e302aefe bp 0x7f589cd0fdd0 sp 0x7f589cd0fd20 T80)
[task 2020-12-29T10:43:05.880Z] 10:43:05     INFO - GECKO(3272) | ==3272==The signal is caused by a WRITE memory access.
[task 2020-12-29T10:43:05.881Z] 10:43:05     INFO - GECKO(3272) | ==3272==Hint: address points to the zero page.
[task 2020-12-29T10:43:06.339Z] 10:43:06     INFO - GECKO(3272) |     #0 0x7f58e302aefe in mozilla::(anonymous namespace)::RunWatchdog(void*) /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:233:5
[task 2020-12-29T10:43:06.339Z] 10:43:06     INFO - GECKO(3272) |     #1 0x7f58f92d8dce in _pt_root /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:201:5
[task 2020-12-29T10:43:06.355Z] 10:43:06     INFO - GECKO(3272) |     #2 0x7f58fd0b86da in start_thread /build/glibc-2ORdQG/glibc-2.27/nptl/pthread_create.c:463
[task 2020-12-29T10:43:06.398Z] 10:43:06     INFO - GECKO(3272) |     #3 0x7f58fc096a3e in clone /build/glibc-2ORdQG/glibc-2.27/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:95
[task 2020-12-29T10:43:06.398Z] 10:43:06     INFO - GECKO(3272) | AddressSanitizer can not provide additional info.
[task 2020-12-29T10:43:06.398Z] 10:43:06     INFO - GECKO(3272) | SUMMARY: AddressSanitizer: SEGV /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:233:5 in mozilla::(anonymous namespace)::RunWatchdog(void*)
[task 2020-12-29T10:43:06.399Z] 10:43:06     INFO - GECKO(3272) | Thread T80 (Shutdow~minator) created by T0 here:
[task 2020-12-29T10:43:06.415Z] 10:43:06     INFO - GECKO(3272) |     #0 0x55eaf49b667a in pthread_create /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/asan/asan_interceptors.cpp:214:3
[task 2020-12-29T10:43:06.415Z] 10:43:06     INFO - GECKO(3272) |     #1 0x7f58f92c9044 in _PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:458:14
[task 2020-12-29T10:43:06.416Z] 10:43:06     INFO - GECKO(3272) |     #2 0x7f58f92ba18e in PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:533:12
[task 2020-12-29T10:43:06.417Z] 10:43:06     INFO - GECKO(3272) |     #3 0x7f58e302ac26 in CreateSystemThread /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:103:7
[task 2020-12-29T10:43:06.418Z] 10:43:06     INFO - GECKO(3272) |     #4 0x7f58e302ac26 in mozilla::nsTerminator::StartWatchdog() /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:442:7
[task 2020-12-29T10:43:06.418Z] 10:43:06     INFO - GECKO(3272) |     #5 0x7f58e302b1e3 in Start /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:383:3
[task 2020-12-29T10:43:06.419Z] 10:43:06     INFO - GECKO(3272) |     #6 0x7f58e302b1e3 in mozilla::nsTerminator::Observe(nsISupports*, char const*, char16_t const*) /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:493:5
[task 2020-12-29T10:43:06.420Z] 10:43:06     INFO - GECKO(3272) |     #7 0x7f58d7dfff5e in nsObserverList::NotifyObservers(nsISupports*, char const*, char16_t const*) /builds/worker/checkouts/gecko/xpcom/ds/nsObserverList.cpp:70:19
[task 2020-12-29T10:43:06.427Z] 10:43:06     INFO - GECKO(3272) |     #8 0x7f58d7e069d1 in nsObserverService::NotifyObservers(nsISupports*, char const*, char16_t const*) /builds/worker/checkouts/gecko/xpcom/ds/nsObserverService.cpp:287:19
[task 2020-12-29T10:43:06.428Z] 10:43:06     INFO - GECKO(3272) |     #9 0x7f58e2e5a67e in nsAppStartup::Quit(unsigned int, int, bool*) /builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp:446:19
[task 2020-12-29T10:43:06.428Z] 10:43:06     INFO - GECKO(3272) |     #10 0x7f58d7f8e331 in NS_InvokeByIndex /builds/worker/checkouts/gecko/xpcom/reflect/xptcall/md/unix/xptcinvoke_asm_x86_64_unix.S:101
[task 2020-12-29T10:43:06.448Z] 10:43:06     INFO - GECKO(3272) |     #11 0x7f58d9a7b858 in Invoke /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1620:10
[task 2020-12-29T10:43:06.448Z] 10:43:06     INFO - GECKO(3272) |     #12 0x7f58d9a7b858 in Call /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1176:19
[task 2020-12-29T10:43:06.449Z] 10:43:06     INFO - GECKO(3272) |     #13 0x7f58d9a7b858 in XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1142:23
[task 2020-12-29T10:43:06.449Z] 10:43:06     INFO - GECKO(3272) |     #14 0x7f58d9a80dc4 in XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNativeJSOps.cpp:925:10
[task 2020-12-29T10:43:06.466Z] 10:43:06     INFO - GECKO(3272) |     #15 0x7f58e32c27c6 in CallJSNative /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:503:13
[task 2020-12-29T10:43:06.466Z] 10:43:06     INFO - GECKO(3272) |     #16 0x7f58e32c27c6 in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:594:12
[task 2020-12-29T10:43:06.466Z] 10:43:06     INFO - GECKO(3272) |     #17 0x7f58e32c466e in InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:647:10
[task 2020-12-29T10:43:06.466Z] 10:43:06     INFO - GECKO(3272) |     #18 0x7f58e32abf0d in CallFromStack /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:651:10
[task 2020-12-29T10:43:06.466Z] 10:43:06     INFO - GECKO(3272) |     #19 0x7f58e32abf0d in Interpret(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:3309:16
[task 2020-12-29T10:43:06.466Z] 10:43:06     INFO - GECKO(3272) |     #20 0x7f58e328daeb in js::RunScript(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:473:13
[task 2020-12-29T10:43:06.466Z] 10:43:06     INFO - GECKO(3272) |     #21 0x7f58e32c25c9 in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:619:13
[task 2020-12-29T10:43:06.466Z] 10:43:06     INFO - GECKO(3272) |     #22 0x7f58e32c466e in InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:647:10
[task 2020-12-29T10:43:06.466Z] 10:43:06     INFO - GECKO(3272) |     #23 0x7f58e32c49f0 in js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:664:8
[task 2020-12-29T10:43:06.481Z] 10:43:06     INFO - GECKO(3272) |     #24 0x7f58e3bcedc2 in JS::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/js/src/jsapi.cpp:2861:10
[task 2020-12-29T10:43:06.525Z] 10:43:06     INFO - GECKO(3272) |     #25 0x7f58db771065 in mozilla::dom::MessageListener::ReceiveMessage(mozilla::dom::BindingCallContext&, JS::Handle<JS::Value>, mozilla::dom::ReceiveMessageArgument const&, JS::MutableHandle<JS::Value>, mozilla::ErrorResult&) /builds/worker/workspace/obj-build/dom/bindings/MessageManagerBinding.cpp:6298:8
[task 2020-12-29T10:43:06.532Z] 10:43:06     INFO - GECKO(3272) |     #26 0x7f58dee27878 in mozilla::dom::MessageListener::ReceiveMessage(mozilla::dom::ReceiveMessageArgument const&, JS::MutableHandle<JS::Value>, mozilla::ErrorResult&, char const*, mozilla::dom::CallbackObject::ExceptionHandling, JS::Realm*) /builds/worker/workspace/obj-build/dist/include/mozilla/dom/MessageManagerBinding.h:783:12
[task 2020-12-29T10:43:06.533Z] 10:43:06     INFO - GECKO(3272) |     #27 0x7f58dee2745e in mozilla::dom::JSActor::CallReceiveMessage(JSContext*, mozilla::dom::JSActorMessageMeta const&, JS::Handle<JS::Value>, JS::MutableHandle<JS::Value>, mozilla::ErrorResult&) /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSActor.cpp:271:22
[task 2020-12-29T10:43:06.534Z] 10:43:06     INFO - GECKO(3272) |     #28 0x7f58dee27aff in mozilla::dom::JSActor::ReceiveMessage(JSContext*, mozilla::dom::JSActorMessageMeta const&, JS::Handle<JS::Value>, mozilla::ErrorResult&) /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSActor.cpp:284:3
[task 2020-12-29T10:43:06.534Z] 10:43:06     INFO - GECKO(3272) |     #29 0x7f58dee2e14d in mozilla::dom::JSActorManager::ReceiveRawMessage(mozilla::dom::JSActorMessageMeta const&, mozilla::Maybe<mozilla::dom::ipc::StructuredCloneData>&&, mozilla::Maybe<mozilla::dom::ipc::StructuredCloneData>&&) /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSActorManager.cpp:182:14
[task 2020-12-29T10:43:06.550Z] 10:43:06     INFO - GECKO(3272) |     #30 0x7f58dee0f94f in mozilla::dom::WindowGlobalParent::RecvRawMessage(mozilla::dom::JSActorMessageMeta const&, mozilla::Maybe<mozilla::dom::ClonedMessageData> const&, mozilla::Maybe<mozilla::dom::ClonedMessageData> const&) /builds/worker/checkouts/gecko/dom/ipc/WindowGlobalParent.cpp:441:3



------[task 2020-12-29T10:39:58.565Z] 10:39:58     INFO - TEST-START | Shutdown---------```
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

(In reply to Bogdan Tara[:bogdan_tara | bogdant] from comment #6)

This is still happening.

Recent failure: https://treeherder.mozilla.org/logviewer?job_id=332650288&repo=autoland&lineNumber=3157

This seems to be an intentional shutdown hang crash. The log does not contain much hints on what might be the root cause of the hang (if not just slow execution). If we happen to be able to get a pernosco trace for this, it might be worth looking at it, otherwise I see not much actionable here.

(In reply to Atila Butkovits from comment #14)

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

So this one contains an interesting piece of information:

[task 2021-04-10T09:49:29.106Z] 09:49:29     INFO - Slowest: 2283ms - /tests/dom/tests/mochitest/general/test_interfaces_secureContext.html
[task 2021-04-10T09:49:29.107Z] 09:49:29     INFO - SimpleTest FINISHED
[task 2021-04-10T09:49:29.108Z] 09:49:29     INFO - TEST-INFO | Ran 1 Loops
[task 2021-04-10T09:49:29.110Z] 09:49:29     INFO - SimpleTest FINISHED
[task 2021-04-10T09:49:29.218Z] 09:49:29     INFO - GECKO(3898) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 575: NotFoundError: No such JSWindowActor 'SpecialPowers'
[task 2021-04-10T09:49:29.424Z] 09:49:29     INFO - GECKO(3898) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-04-10T09:49:29.447Z] 09:49:29     INFO - GECKO(3898) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-04-10T09:49:29.617Z] 09:49:29     INFO - GECKO(3898) | WARNING: A blocker encountered an error while we were waiting.
[task 2021-04-10T09:49:29.619Z] 09:49:29     INFO - GECKO(3898) |           Blocker:  Flush WebExtension StartupCache
[task 2021-04-10T09:49:29.620Z] 09:49:29     INFO - GECKO(3898) |           Phase: IOUtils: waiting for profileBeforeChange IO to complete
[task 2021-04-10T09:49:29.621Z] 09:49:29     INFO - GECKO(3898) |           State: (none)
[task 2021-04-10T09:49:29.622Z] 09:49:29     INFO - GECKO(3898) | WARNING: Error: The object has been already finalized.
[task 2021-04-10T09:49:29.623Z] 09:49:29     INFO - GECKO(3898) | WARNING: finalize@resource://gre/modules/DeferredTask.jsm:267:13
[task 2021-04-10T09:49:29.625Z] 09:49:29     INFO - GECKO(3898) | save/<@resource://gre/modules/ExtensionParent.jsm:1725:32
[task 2021-04-10T09:49:29.625Z] 09:49:29     INFO - GECKO(3898) | trigger@resource://gre/modules/AsyncShutdown.jsm:747:23
[task 2021-04-10T09:49:29.626Z] 09:49:29     INFO - GECKO(3898) | _wait@resource://gre/modules/AsyncShutdown.jsm:899:15
[task 2021-04-10T09:49:29.626Z] 09:49:29     INFO - GECKO(3898) | wait@resource://gre/modules/AsyncShutdown.jsm:880:34
[task 2021-04-10T09:49:29.627Z] 09:49:29     INFO - GECKO(3898) | wait@resource://gre/modules/nsAsyncShutdown.jsm:209:25
[task 2021-04-10T09:49:29.627Z] 09:49:29     INFO - GECKO(3898) | addBlocker/moduleBlocker/<@resource://gre/modules/nsAsyncShutdown.jsm:156:30
[task 2021-04-10T09:49:29.627Z] 09:49:29     INFO - GECKO(3898) | moduleBlocker@resource://gre/modules/nsAsyncShutdown.jsm:152:9
[task 2021-04-10T09:49:29.628Z] 09:49:29     INFO - GECKO(3898) | trigger@resource://gre/modules/AsyncShutdown.jsm:747:23
[task 2021-04-10T09:49:29.628Z] 09:49:29     INFO - GECKO(3898) | _wait@resource://gre/modules/AsyncShutdown.jsm:899:15
[task 2021-04-10T09:49:29.628Z] 09:49:29     INFO - GECKO(3898) | wait@resource://gre/modules/AsyncShutdown.jsm:880:34
[task 2021-04-10T09:49:29.629Z] 09:49:29     INFO - GECKO(3898) | observe@resource://gre/modules/AsyncShutdown.jsm:557:10
...
[task 2021-04-10T09:49:29.654Z] 09:49:29     INFO - GECKO(3898) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
...
[task 2021-04-10T09:49:29.704Z] 09:49:29     INFO - GECKO(3898) | JavaScript error: resource://gre/modules/DeferredTask.jsm, line 267: Error: The object has been already finalized.
...
[task 2021-04-10T09:49:31.028Z] 09:49:31     INFO - GECKO(3898) | 1618048171017	Marionette	TRACE	Received observer notification xpcom-will-shutdown
[task 2021-04-10T09:49:31.028Z] 09:49:31     INFO - GECKO(3898) | 1618048171017	Marionette	INFO	Stopped listening on port 2828
...
[task 2021-04-10T09:54:35.318Z] 09:54:35     INFO - GECKO(3898) | AddressSanitizer:DEADLYSIGNAL
[task 2021-04-10T09:54:35.319Z] 09:54:35     INFO - GECKO(3898) | =================================================================
[task 2021-04-10T09:54:35.320Z] 09:54:35    ERROR - GECKO(3898) | ==3898==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000001 (pc 0x7f802f7d470f bp 0x7f7ff6809dd0 sp 0x7f7ff6809d20 T74)
[task 2021-04-10T09:54:35.320Z] 09:54:35     INFO - GECKO(3898) | ==3898==The signal is caused by a WRITE memory access.
[task 2021-04-10T09:54:35.321Z] 09:54:35     INFO - GECKO(3898) | ==3898==Hint: address points to the zero page.
[task 2021-04-10T09:54:35.824Z] 09:54:35     INFO - GECKO(3898) |     #0 0x7f802f7d470f in mozilla::(anonymous namespace)::RunWatchdog(void*) /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:246:5
[task 2021-04-10T09:54:35.825Z] 09:54:35     INFO - GECKO(3898) |     #1 0x7f80461d7bfe in _pt_root /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:201:5
[task 2021-04-10T09:54:35.840Z] 09:54:35     INFO - GECKO(3898) |     #2 0x7f8049fff6da in start_thread /build/glibc-2ORdQG/glibc-2.27/nptl/pthread_create.c:463
[task 2021-04-10T09:54:35.901Z] 09:54:35     INFO - GECKO(3898) |     #3 0x7f8048fdda3e in clone /build/glibc-2ORdQG/glibc-2.27/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:95
[task 2021-04-10T09:54:35.902Z] 09:54:35     INFO - GECKO(3898) | AddressSanitizer can not provide additional info.
[task 2021-04-10T09:54:35.902Z] 09:54:35     INFO - GECKO(3898) | SUMMARY: AddressSanitizer: SEGV /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:246:5 in mozilla::(anonymous namespace)::RunWatchdog(void*)
[task 2021-04-10T09:54:35.902Z] 09:54:35     INFO - GECKO(3898) | Thread T74 (Shutdow~minator) created by T0 here:
[task 2021-04-10T09:54:35.917Z] 09:54:35     INFO - GECKO(3898) |     #0 0x558e048f032a in pthread_create /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/asan/asan_interceptors.cpp:214:3
[task 2021-04-10T09:54:35.918Z] 09:54:35     INFO - GECKO(3898) |     #1 0x7f80461c7f24 in _PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:458:14
[task 2021-04-10T09:54:35.919Z] 09:54:35     INFO - GECKO(3898) |     #2 0x7f80461b8fde in PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:533:12

We are stuck in an async shutdown blocker's spin loop. I am not good in reading Javascript, but from the log it seems:

[task 2021-04-10T09:49:29.619Z] 09:49:29     INFO - GECKO(3898) |           Blocker:  Flush WebExtension StartupCache
...
[task 2021-04-10T09:49:29.622Z] 09:49:29     INFO - GECKO(3898) | WARNING: Error: The object has been already finalized.
[task 2021-04-10T09:49:29.623Z] 09:49:29     INFO - GECKO(3898) | WARNING: finalize@resource://gre/modules/DeferredTask.jsm:267:13

that there might be an exception during Flush WebExtension StartupCache that then gets ignored by our spin event loop?

Flags: needinfo?(nika)

Just a wild guess, but I see in bug 1695580 that we made some changes that can cancel delayed runnables, and I see DeferredTask.jsm involved here, saying that the task was already finalized (canceled?).
The DeferredTask in question saves some data to a file. It would be interesting, if this ever happened and we just fail the cleanup of the deferred task somehow or if we are simply seeing some long lasting (or failing?) disk IO. Is there a way we can check this within the remaining artifacts we have from that task?

Flags: needinfo?(atila.butkovits)

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

that there might be an exception during Flush WebExtension StartupCache that then gets ignored by our spin event loop?

I don't think we actually bubble most errors out of the nested event loop, as they should generally be caught & cleared before returning due to the AutoNoJSAPI we put on the stack in ProcessNextEvent. The errors we're seeing credited to that particular line are probably errors being reported in an AutoEntryScript from native code, as they might produce the incorrect line numbers for backtraces etc. For example, I think this line is probably firing from https://searchfox.org/mozilla-central/rev/3de2db87f3c9001ae478318d47a2ca3427574382/dom/ipc/jsactor/JSActorManager.cpp#136 and being reported with the wrong line number, as no JS is on the stack in a nested event loop:

[task 2021-04-10T09:49:29.218Z] 09:49:29     INFO - GECKO(3898) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 575: NotFoundError: No such JSWindowActor 'SpecialPowers'

I see those exceptions happening, but I'm not sure if they'll cause the shutdown hang, as if we throw an exception, the blocker should be being cleared IIRC, so that blocker which raised an exception isn't causing an issue anymore.

Unfortunately, I don't really know how to get the active shutdown blockers etc. easily here. Perhaps we could turn on async shutdown debug logs temporarially to get some test failures with the logging turned on? I think that would require setting "toolkit.asyncshutdown.log" to true based on https://searchfox.org/mozilla-central/rev/3de2db87f3c9001ae478318d47a2ca3427574382/toolkit/components/asyncshutdown/AsyncShutdown.jsm#228-231

Flags: needinfo?(nika)

Aryx, could you help us out with the request from comment18?

Thank you!

Flags: needinfo?(atila.butkovits) → needinfo?(aryx.bugmail)

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

The DeferredTask in question saves some data to a file. It would be interesting, if this ever happened and we just fail the cleanup of the deferred task somehow or if we are simply seeing some long lasting (or failing?) disk IO. Is there a way we can check this within the remaining artifacts we have from that task?

We have only the log. Attempts to create an interactive task failed (bug 1705354).

Flush WebExtension StartupCache has been around for some time, see e.g. bug 1675173 comment 0.

Flags: needinfo?(aryx.bugmail)

Update:

There have been 84 failures within the last 7 days, all of them on Linux 18.04 x64 asan opt.

Recent failure: https://treeherder.mozilla.org/logviewer?job_id=337624536&repo=autoland&lineNumber=3556

[task 2021-04-24T16:46:15.312Z] 16:46:15     INFO - GECKO(3576) | AddressSanitizer:DEADLYSIGNAL
[task 2021-04-24T16:46:15.312Z] 16:46:15     INFO - GECKO(3576) | =================================================================
[task 2021-04-24T16:46:15.313Z] 16:46:15    ERROR - GECKO(3576) | ==3576==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000001 (pc 0x7f82e468c0af bp 0x7f8228615dd0 sp 0x7f8228615d20 T83)
[task 2021-04-24T16:46:15.313Z] 16:46:15     INFO - GECKO(3576) | ==3576==The signal is caused by a WRITE memory access.
[task 2021-04-24T16:46:15.316Z] 16:46:15     INFO - GECKO(3576) | ==3576==Hint: address points to the zero page.
[task 2021-04-24T16:46:15.794Z] 16:46:15     INFO - GECKO(3576) |     #0 0x7f82e468c0af in mozilla::(anonymous namespace)::RunWatchdog(void*) /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:246:5
[task 2021-04-24T16:46:15.795Z] 16:46:15     INFO - GECKO(3576) |     #1 0x7f82fb1d7bfe in _pt_root /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:201:5
[task 2021-04-24T16:46:15.812Z] 16:46:15     INFO - GECKO(3576) |     #2 0x7f82feff26da in start_thread /build/glibc-2ORdQG/glibc-2.27/nptl/pthread_create.c:463
[task 2021-04-24T16:46:15.860Z] 16:46:15     INFO - GECKO(3576) |     #3 0x7f82fdfd0a3e in clone /build/glibc-2ORdQG/glibc-2.27/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:95
[task 2021-04-24T16:46:15.860Z] 16:46:15     INFO - GECKO(3576) | AddressSanitizer can not provide additional info.
[task 2021-04-24T16:46:15.861Z] 16:46:15     INFO - GECKO(3576) | SUMMARY: AddressSanitizer: SEGV /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:246:5 in mozilla::(anonymous namespace)::RunWatchdog(void*)
[task 2021-04-24T16:46:15.861Z] 16:46:15     INFO - GECKO(3576) | Thread T83 (Shutdow~minator) created by T0 here:
[task 2021-04-24T16:46:15.877Z] 16:46:15     INFO - GECKO(3576) |     #0 0x556e5464332a in pthread_create /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/asan/asan_interceptors.cpp:214:3
[task 2021-04-24T16:46:15.877Z] 16:46:15     INFO - GECKO(3576) |     #1 0x7f82fb1c7f24 in _PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:458:14
[task 2021-04-24T16:46:15.877Z] 16:46:15     INFO - GECKO(3576) |     #2 0x7f82fb1b8fde in PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:533:12
[task 2021-04-24T16:46:15.877Z] 16:46:15     INFO - GECKO(3576) |     #3 0x7f82e468b8b2 in CreateSystemThread /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:116:7
[task 2021-04-24T16:46:15.877Z] 16:46:15     INFO - GECKO(3576) |     #4 0x7f82e468b8b2 in mozilla::nsTerminator::StartWatchdog() /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:469:7
[task 2021-04-24T16:46:15.877Z] 16:46:15     INFO - GECKO(3576) |     #5 0x7f82e468bb9b in Start /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:383:3
[task 2021-04-24T16:46:15.878Z] 16:46:15     INFO - GECKO(3576) |     #6 0x7f82e468bb9b in mozilla::nsTerminator::AdvancePhase(mozilla::ShutdownPhase) /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:517:5
[task 2021-04-24T16:46:15.894Z] 16:46:15     INFO - GECKO(3576) |     #7 0x7f82d9ce37b1 in mozilla::AdvanceShutdownPhaseInternal(mozilla::ShutdownPhase, bool, char16_t const*, nsCOMPtr<nsISupports> const&) /builds/worker/checkouts/gecko/xpcom/base/AppShutdown.cpp:318:18
[task 2021-04-24T16:46:15.894Z] 16:46:15     INFO - GECKO(3576) |     #8 0x7f82e44d7d17 in nsAppStartup::Quit(unsigned int, int, bool*) /builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp:447:5
[task 2021-04-24T16:46:15.894Z] 16:46:15     INFO - GECKO(3576) |     #9 0x7f82d9f4e461 in NS_InvokeByIndex /builds/worker/checkouts/gecko/xpcom/reflect/xptcall/md/unix/xptcinvoke_asm_x86_64_unix.S:101
[task 2021-04-24T16:46:15.902Z] 16:46:15     INFO - GECKO(3576) |     #10 0x7f82db90cdca in Invoke /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1623:10
[task 2021-04-24T16:46:15.902Z] 16:46:15     INFO - GECKO(3576) |     #11 0x7f82db90cdca in Call /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1176:19
[task 2021-04-24T16:46:15.902Z] 16:46:15     INFO - GECKO(3576) |     #12 0x7f82db90cdca in XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1142:23
[task 2021-04-24T16:46:15.902Z] 16:46:15     INFO - GECKO(3576) |     #13 0x7f82db911df9 in XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNativeJSOps.cpp:925:10
[task 2021-04-24T16:46:15.918Z] 16:46:15     INFO - GECKO(3576) |     #14 0x7f82e490c5e4 in CallJSNative /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:437:13
[task 2021-04-24T16:46:15.918Z] 16:46:15     INFO - GECKO(3576) |     #15 0x7f82e490c5e4 in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:522:12
[task 2021-04-24T16:46:15.918Z] 16:46:15     INFO - GECKO(3576) |     #16 0x7f82e490e409 in InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:582:10
[task 2021-04-24T16:46:15.934Z] 16:46:15     INFO - GECKO(3576) |     #17 0x7f82e56c82d3 in js::jit::DoCallFallback(JSContext*, js::jit::BaselineFrame*, js::jit::ICCall_Fallback*, unsigned int, JS::Value*, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/js/src/jit/BaselineIC.cpp:1840:10
[task 2021-04-24T16:46:15.941Z] 16:46:15     INFO - GECKO(3576) |     #18 0x7f824ec12d87  (<unknown module>)
[task 2021-04-24T16:46:15.948Z] 16:46:15     INFO - GECKO(3576) |     #19 0x621001b5cbbf  (<unknown module>)
[task 2021-04-24T16:46:15.956Z] 16:46:15     INFO - GECKO(3576) |     #20 0x7f824ec1056e  (<unknown module>)
[task 2021-04-24T16:46:15.959Z] 16:46:15     INFO - GECKO(3576) |     #21 0x7f82e5a80576 in EnterJit /builds/worker/checkouts/gecko/js/src/jit/Jit.cpp:109:5
[task 2021-04-24T16:46:15.960Z] 16:46:15     INFO - GECKO(3576) |     #22 0x7f82e5a80576 in js::jit::MaybeEnterJit(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/jit/Jit.cpp:207:10
[task 2021-04-24T16:46:15.961Z] 16:46:15     INFO - GECKO(3576) |     #23 0x7f82e48dc0a0 in js::RunScript(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:396:32
[task 2021-04-24T16:46:15.961Z] 16:46:15     INFO - GECKO(3576) |     #24 0x7f82e490c723 in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:554:13
[task 2021-04-24T16:46:15.962Z] 16:46:15     INFO - GECKO(3576) |     #25 0x7f82e490e409 in InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:582:10
[task 2021-04-24T16:46:15.963Z] 16:46:15     INFO - GECKO(3576) |     #26 0x7f82e490e68b in js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:599:8
[task 2021-04-24T16:46:15.979Z] 16:46:15     INFO - GECKO(3576) |     #27 0x7f82e5170812 in JS::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/js/src/jsapi.cpp:2861:10
[task 2021-04-24T16:46:16.020Z] 16:46:16     INFO - GECKO(3576) |     #28 0x7f82dd40f647 in mozilla::dom::MessageListener::ReceiveMessage(mozilla::dom::BindingCallContext&, JS::Handle<JS::Value>, mozilla::dom::ReceiveMessageArgument const&, JS::MutableHandle<JS::Value>, mozilla::ErrorResult&) /builds/worker/workspace/obj-build/dom/bindings/MessageManagerBinding.cpp:6310:8
[task 2021-04-24T16:46:16.021Z] 16:46:16     INFO - GECKO(3576) |     #29 0x7f82e0751e98 in mozilla::dom::MessageListener::ReceiveMessage(mozilla::dom::ReceiveMessageArgument const&, JS::MutableHandle<JS::Value>, mozilla::ErrorResult&, char const*, mozilla::dom::CallbackObject::ExceptionHandling, JS::Realm*) /builds/worker/workspace/obj-build/dist/include/mozilla/dom/MessageManagerBinding.h:783:12
[task 2021-04-24T16:46:16.022Z] 16:46:16     INFO - GECKO(3576) |     #30 0x7f82e0751a6e in mozilla::dom::JSActor::CallReceiveMessage(JSContext*, mozilla::dom::JSActorMessageMeta const&, JS::Handle<JS::Value>, JS::MutableHandle<JS::Value>, mozilla::ErrorResult&) /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSActor.cpp:271:22
[task 2021-04-24T16:46:16.023Z] 16:46:16     INFO - GECKO(3576) |     #31 0x7f82e075211f in mozilla::dom::JSActor::ReceiveMessage(JSContext*, mozilla::dom::JSActorMessageMeta const&, JS::Handle<JS::Value>, mozilla::ErrorResult&) /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSActor.cpp:284:3
[task 2021-04-24T16:46:16.023Z] 16:46:16     INFO - GECKO(3576) |     #32 0x7f82e0757c5e in mozilla::dom::JSActorManager::ReceiveRawMessage(mozilla::dom::JSActorMessageMeta const&, mozilla::Maybe<mozilla::dom::ipc::StructuredCloneData>&&, mozilla::Maybe<mozilla::dom::ipc::StructuredCloneData>&&) /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSActorManager.cpp:184:14
[task 2021-04-24T16:46:16.039Z] 16:46:16     INFO - GECKO(3576) |     #33 0x7f82e073619f in mozilla::dom::WindowGlobalParent::RecvRawMessage(mozilla::dom::JSActorMessageMeta const&, mozilla::Maybe<mozilla::dom::ClonedMessageData> const&, mozilla::Maybe<mozilla::dom::ClonedMessageData> const&) /builds/worker/checkouts/gecko/dom/ipc/WindowGlobalParent.cpp:477:3
[task 2021-04-24T16:46:16.056Z] 16:46:16     INFO - GECKO(3576) |     #34 0x7f82db6387ab in mozilla::dom::PWindowGlobalParent::OnMessageReceived(IPC::Message const&) /builds/worker/workspace/obj-build/ipc/ipdl/PWindowGlobalParent.cpp:755:62
[task 2021-04-24T16:46:16.094Z] 16:46:16     INFO - GECKO(3576) |     #35 0x7f82db1f82fc in mozilla::dom::PContentParent::OnMessageReceived(IPC::Message const&) /builds/worker/workspace/obj-build/ipc/ipdl/PContentParent.cpp:6617:32
[task 2021-04-24T16:46:16.096Z] 16:46:16     INFO - GECKO(3576) |     #36 0x7f82db006fe9 in mozilla::ipc::MessageChannel::DispatchAsyncMessage(mozilla::ipc::ActorLifecycleProxy*, IPC::Message const&) /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:2152:25
[task 2021-04-24T16:46:16.097Z] 16:46:16     INFO - GECKO(3576) |     #37 0x7f82db004586 in mozilla::ipc::MessageChannel::DispatchMessage(IPC::Message&&) /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:2076:9
[task 2021-04-24T16:46:16.098Z] 16:46:16     INFO - GECKO(3576) |     #38 0x7f82db0057ae in mozilla::ipc::MessageChannel::RunMessage(mozilla::ipc::MessageChannel::MessageTask&) /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1924:3
[task 2021-04-24T16:46:16.099Z] 16:46:16     INFO - GECKO(3576) |     #39 0x7f82db005f2b in mozilla::ipc::MessageChannel::MessageTask::Run() /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1955:13
[task 2021-04-24T16:46:16.116Z] 16:46:16     INFO - GECKO(3576) |     #40 0x7f82d9f1bdba in mozilla::RunnableTask::Run() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:473:16
[task 2021-04-24T16:46:16.117Z] 16:46:16     INFO - GECKO(3576) |     #41 0x7f82d9ee8320 in mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:757:26
[task 2021-04-24T16:46:16.118Z] 16:46:16     INFO - GECKO(3576) |     #42 0x7f82d9ee5e57 in mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:612:15
[task 2021-04-24T16:46:16.120Z] 16:46:16     INFO - GECKO(3576) |     #43 0x7f82d9ee62ad in mozilla::TaskController::ProcessPendingMTTask(bool) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:396:36
[task 2021-04-24T16:46:16.122Z] 16:46:16     INFO - GECKO(3576) |     #44 0x7f82d9f25141 in operator() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:135:37
[task 2021-04-24T16:46:16.123Z] 16:46:16     INFO - GECKO(3576) |     #45 0x7f82d9f25141 in mozilla::detail::RunnableFunction<mozilla::TaskController::InitializeInternal()::$_0>::Run() /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.h:534:5
[task 2021-04-24T16:46:16.124Z] 16:46:16     INFO - GECKO(3576) |     #46 0x7f82d9f03123 in nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1159:16
[task 2021-04-24T16:46:16.125Z] 16:46:16     INFO - GECKO(3576) |     #47 0x7f82d9f0e0ac in NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:548:10
[task 2021-04-24T16:46:16.126Z] 16:46:16     INFO - GECKO(3576) |     #48 0x7f82db00ca9a in mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:85:21
[task 2021-04-24T16:46:16.127Z] 16:46:16     INFO - GECKO(3576) |     #49 0x7f82daf385a1 in RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:335:10
[task 2021-04-24T16:46:16.129Z] 16:46:16     INFO - GECKO(3576) |     #50 0x7f82daf385a1 in RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:328:3
[task 2021-04-24T16:46:16.130Z] 16:46:16     INFO - GECKO(3576) |     #51 0x7f82daf385a1 in MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:310:3
[task 2021-04-24T16:46:16.131Z] 16:46:16     INFO - GECKO(3576) |     #52 0x7f82e0eac7c7 in nsBaseAppShell::Run() /builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp:137:27
[task 2021-04-24T16:46:16.132Z] 16:46:16     INFO - GECKO(3576) |     #53 0x7f82e44d6cc7 in nsAppStartup::Run() /builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp:273:30
[task 2021-04-24T16:46:16.146Z] 16:46:16     INFO - GECKO(3576) |     #54 0x7f82e46dbe4a in XREMain::XRE_mainRun() /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5348:22
[task 2021-04-24T16:46:16.147Z] 16:46:16     INFO - GECKO(3576) |     #55 0x7f82e46de174 in XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5539:8
[task 2021-04-24T16:46:16.147Z] 16:46:16     INFO - GECKO(3576) |     #56 0x7f82e46dee83 in XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5598:21
[task 2021-04-24T16:46:16.147Z] 16:46:16     INFO - GECKO(3576) |     #57 0x556e5468ba12 in do_main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:220:22
[task 2021-04-24T16:46:16.147Z] 16:46:16     INFO - GECKO(3576) |     #58 0x556e5468ba12 in main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:347:16
[task 2021-04-24T16:46:16.147Z] 16:46:16     INFO - GECKO(3576) |     #59 0x7f82fded0b96 in __libc_start_main /build/glibc-2ORdQG/glibc-2.27/csu/../csu/libc-start.c:310
[task 2021-04-24T16:46:16.147Z] 16:46:16     INFO - GECKO(3576) | ==3576==ABORTING

Nika isn't this a duplicate of bug 1358898?

Flags: needinfo?(nika)

(In reply to Andreea Pavel [:apavel] from comment #31)

Nika isn't this a duplicate of bug 1358898?

Yes, this is the same underlying issue but with a different signature due to asan changing the apparent signature for shutdown hangs in ASAN builds. In https://bugzilla.mozilla.org/show_bug.cgi?id=1358898#c421 :mstange mentions that there has been a recent surge of macOS shutdown hangs due to native menus, however the particular issues in this bug appear to be unrelated, as they're on Linux. It seems there's also been a recent spike of linux crashes in bug 1358898 as well.

I couldn't find any super actionable information here which we could use to distinguish these bugs, especially as it appears there are no stacks for the main thread in the log. Based on the crash stack line number, it appears as though it's crashing here: https://searchfox.org/mozilla-central/rev/9f76a47f4aa935b49754c5608a1c8e72ee358c46/toolkit/components/terminator/nsTerminator.cpp#246, which unfortunately doesn't make why the crash is occurring very clear at all. It's "sometime after the call to XPCOMShutdownNotified here: https://searchfox.org/mozilla-central/rev/9f76a47f4aa935b49754c5608a1c8e72ee358c46/xpcom/build/XPCOMInit.cpp#614"

Flags: needinfo?(nika)
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Depends on: 1709019
No longer depends on: 1709019

Mid-air collision...

Depends on: 1709019
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

There are 126 total failures in the last 7 days on linux1804-64-asan opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=339107477&repo=autoland&lineNumber=4706

[task 2021-05-07T21:47:48.091Z] 21:47:48 INFO - TEST-START | browser/components/extensions/test/browser/browser_toolbar_prefers_color_scheme.js
[task 2021-05-07T21:47:48.123Z] 21:47:48 INFO - GECKO(1570) | [SimpleTest.requestLongerTimeout()] ignoring request, maybe you meant to call the global requestLongerTimeout instead?
[task 2021-05-07T21:47:48.996Z] 21:47:48 INFO - GECKO(1570) | MEMORY STAT | vsize 20976821MB | residentFast 2382MB
[task 2021-05-07T21:47:48.998Z] 21:47:48 INFO - TEST-OK | browser/components/extensions/test/browser/browser_toolbar_prefers_color_scheme.js | took 906ms
[task 2021-05-07T21:47:49.029Z] 21:47:49 INFO - checking window state
[task 2021-05-07T21:47:54.692Z] 21:47:54 INFO - GECKO(1570) | Completed ShutdownLeaks collections in process 1830
[task 2021-05-07T21:47:55.058Z] 21:47:55 INFO - GECKO(1570) | Completed ShutdownLeaks collections in process 1653
[task 2021-05-07T21:47:55.101Z] 21:47:55 INFO - GECKO(1570) | Completed ShutdownLeaks collections in process 1718
[task 2021-05-07T21:47:55.142Z] 21:47:55 INFO - GECKO(1570) | Completed ShutdownLeaks collections in process 1776
[task 2021-05-07T21:47:55.201Z] 21:47:55 INFO - GECKO(1570) | Completed ShutdownLeaks collections in process 1753
[task 2021-05-07T21:47:55.312Z] 21:47:55 INFO - GECKO(1570) | Completed ShutdownLeaks collections in process 1639
[task 2021-05-07T21:47:57.595Z] 21:47:57 INFO - GECKO(1570) | Completed ShutdownLeaks collections in process 1570
[task 2021-05-07T21:47:57.597Z] 21:47:57 INFO - TEST-START | Shutdown
[task 2021-05-07T21:47:57.599Z] 21:47:57 INFO - Browser Chrome Test Summary
[task 2021-05-07T21:47:57.600Z] 21:47:57 INFO - Passed: 8183
[task 2021-05-07T21:47:57.600Z] 21:47:57 INFO - Failed: 0
[task 2021-05-07T21:47:57.601Z] 21:47:57 INFO - Todo: 0
[task 2021-05-07T21:47:57.602Z] 21:47:57 INFO - Mode: e10s
[task 2021-05-07T21:47:57.602Z] 21:47:57 INFO - *** End BrowserChrome Test Results ***
[task 2021-05-07T21:47:58.347Z] 21:47:58 INFO - GECKO(1570) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-05-07T21:47:58.368Z] 21:47:58 INFO - GECKO(1570) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-05-07T21:47:58.411Z] 21:47:58 INFO - GECKO(1570) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-05-07T21:48:01.624Z] 21:48:01 INFO - GECKO(1570) | 1620424081622 Marionette TRACE Received observer notification xpcom-will-shutdown
[task 2021-05-07T21:48:01.627Z] 21:48:01 INFO - GECKO(1570) | 1620424081623 Marionette INFO Stopped listening on port 2828
[task 2021-05-07T21:48:01.631Z] 21:48:01 INFO - GECKO(1570) | 1620424081623 Marionette DEBUG Marionette stopped listening
[task 2021-05-07T21:48:03.557Z] 21:48:03 INFO - GECKO(1570) | -----------------------------------------------------
[task 2021-05-07T21:48:03.558Z] 21:48:03 INFO - GECKO(1570) | Suppressions used:
[task 2021-05-07T21:48:03.558Z] 21:48:03 INFO - GECKO(1570) | count bytes template
[task 2021-05-07T21:48:03.558Z] 21:48:03 INFO - GECKO(1570) | 20 624 nsComponentManagerImpl
[task 2021-05-07T21:48:03.558Z] 21:48:03 INFO - GECKO(1570) | 2 288 libfontconfig.so
[task 2021-05-07T21:48:03.558Z] 21:48:03 INFO - GECKO(1570) | -----------------------------------------------------
[task 2021-05-07T21:48:03.580Z] 21:48:03 INFO - GECKO(1570) | -----------------------------------------------------
[task 2021-05-07T21:48:03.582Z] 21:48:03 INFO - GECKO(1570) | Suppressions used:
[task 2021-05-07T21:48:03.583Z] 21:48:03 INFO - GECKO(1570) | count bytes template
[task 2021-05-07T21:48:03.584Z] 21:48:03 INFO - GECKO(1570) | 14 448 nsComponentManagerImpl
[task 2021-05-07T21:48:03.584Z] 21:48:03 INFO - GECKO(1570) | 2 288 libfontconfig.so
[task 2021-05-07T21:48:03.585Z] 21:48:03 INFO - GECKO(1570) | -----------------------------------------------------
[task 2021-05-07T21:48:03.590Z] 21:48:03 INFO - GECKO(1570) | -----------------------------------------------------
[task 2021-05-07T21:48:03.590Z] 21:48:03 INFO - GECKO(1570) | Suppressions used:
[task 2021-05-07T21:48:03.593Z] 21:48:03 INFO - GECKO(1570) | count bytes template
[task 2021-05-07T21:48:03.594Z] 21:48:03 INFO - GECKO(1570) | 44 1328 nsComponentManagerImpl
[task 2021-05-07T21:48:03.595Z] 21:48:03 INFO - GECKO(1570) | 2 288 libfontconfig.so
[task 2021-05-07T21:48:03.596Z] 21:48:03 INFO - GECKO(1570) | -----------------------------------------------------
[task 2021-05-07T21:48:03.610Z] 21:48:03 INFO - GECKO(1570) | -----------------------------------------------------
[task 2021-05-07T21:48:03.611Z] 21:48:03 INFO - GECKO(1570) | Suppressions used:
[task 2021-05-07T21:48:03.613Z] 21:48:03 INFO - GECKO(1570) | count bytes template
[task 2021-05-07T21:48:03.615Z] 21:48:03 INFO - GECKO(1570) | 47 1416 nsComponentManagerImpl
[task 2021-05-07T21:48:03.616Z] 21:48:03 INFO - GECKO(1570) | 2 288 libfontconfig.so
[task 2021-05-07T21:48:03.618Z] 21:48:03 INFO - GECKO(1570) | 4 176 _PR_Getfd
[task 2021-05-07T21:48:03.619Z] 21:48:03 INFO - GECKO(1570) | -----------------------------------------------------
[task 2021-05-07T21:48:04.518Z] 21:48:04 INFO - GECKO(1570) | -----------------------------------------------------
[task 2021-05-07T21:48:04.519Z] 21:48:04 INFO - GECKO(1570) | Suppressions used:
[task 2021-05-07T21:48:04.522Z] 21:48:04 INFO - GECKO(1570) | count bytes template
[task 2021-05-07T21:48:04.522Z] 21:48:04 INFO - GECKO(1570) | 17 536 nsComponentManagerImpl
[task 2021-05-07T21:48:04.522Z] 21:48:04 INFO - GECKO(1570) | 2 288 libfontconfig.so
[task 2021-05-07T21:48:04.523Z] 21:48:04 INFO - GECKO(1570) | -----------------------------------------------------
[task 2021-05-07T21:48:04.523Z] 21:48:04 INFO - GECKO(1570) | -----------------------------------------------------
[task 2021-05-07T21:48:04.524Z] 21:48:04 INFO - GECKO(1570) | Suppressions used:
[task 2021-05-07T21:48:04.524Z] 21:48:04 INFO - GECKO(1570) | count bytes template
[task 2021-05-07T21:48:04.525Z] 21:48:04 INFO - GECKO(1570) | 1 32 nsComponentManagerImpl
[task 2021-05-07T21:48:04.525Z] 21:48:04 INFO - GECKO(1570) | -----------------------------------------------------
[task 2021-05-07T21:53:05.901Z] 21:53:05 INFO - GECKO(1570) | AddressSanitizer:DEADLYSIGNAL
[task 2021-05-07T21:53:05.903Z] 21:53:05 INFO - GECKO(1570) | =================================================================
[task 2021-05-07T21:53:05.906Z] 21:53:05 ERROR - GECKO(1570) | ==1570==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000001 (pc 0x7f1a2dc3688c bp 0x7f19940f3e10 sp 0x7f19940f3d60 T373)
[task 2021-05-07T21:53:05.907Z] 21:53:05 INFO - GECKO(1570) | ==1570==The signal is caused by a WRITE memory access.
[task 2021-05-07T21:53:05.908Z] 21:53:05 INFO - GECKO(1570) | ==1570==Hint: address points to the zero page.
[task 2021-05-07T21:53:06.629Z] 21:53:06 INFO - GECKO(1570) | #0 0x7f1a2dc3688c in mozilla::(anonymous namespace)::RunWatchdog(void*) /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:246:5
[task 2021-05-07T21:53:06.633Z] 21:53:06 INFO - GECKO(1570) | #1 0x7f1a443d745e in _pt_root /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:201:5
[task 2021-05-07T21:53:06.646Z] 21:53:06 INFO - GECKO(1570) | #2 0x7f1a481cb6da in start_thread /build/glibc-2ORdQG/glibc-2.27/nptl/pthread_create.c:463
[task 2021-05-07T21:53:06.706Z] 21:53:06 INFO - GECKO(1570) | #3 0x7f1a471a9a3e in clone /build/glibc-2ORdQG/glibc-2.27/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:95
[task 2021-05-07T21:53:06.707Z] 21:53:06 INFO - GECKO(1570) | AddressSanitizer can not provide additional info.
[task 2021-05-07T21:53:06.707Z] 21:53:06 INFO - GECKO(1570) | SUMMARY: AddressSanitizer: SEGV /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:246:5 in mozilla::(anonymous namespace)::RunWatchdog(void*)
[task 2021-05-07T21:53:06.707Z] 21:53:06 INFO - GECKO(1570) | Thread T373 (Shutdow~minator) created by T0 here:
[task 2021-05-07T21:53:06.723Z] 21:53:06 INFO - GECKO(1570) | #0 0x55a76eee5b5c in pthread_create /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/asan/asan_interceptors.cpp:205:3
[task 2021-05-07T21:53:06.724Z] 21:53:06 INFO - GECKO(1570) | #1 0x7f1a443c7764 in _PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:458:14
[task 2021-05-07T21:53:06.725Z] 21:53:06 INFO - GECKO(1570) | #2 0x7f1a443b8c3e in PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:533:12
[task 2021-05-07T21:53:06.727Z] 21:53:06 INFO - GECKO(1570) | #3 0x7f1a2dc360e2 in CreateSystemThread /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:116:7
[task 2021-05-07T21:53:06.727Z] 21:53:06 INFO - GECKO(1570) | #4 0x7f1a2dc360e2 in mozilla::nsTerminator::StartWatchdog() /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:469:7
[task 2021-05-07T21:53:06.727Z] 21:53:06 INFO - GECKO(1570) | #5 0x7f1a2dc363cb in Start /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:383:3
[task 2021-05-07T21:53:06.727Z] 21:53:06 INFO - GECKO(1570) | #6 0x7f1a2dc363cb in mozilla::nsTerminator::AdvancePhase(mozilla::ShutdownPhase) /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:517:5
[task 2021-05-07T21:53:06.738Z] 21:53:06 INFO - GECKO(1570) | #7 0x7f1a22c79fe1 in mozilla::AdvanceShutdownPhaseInternal(mozilla::ShutdownPhase, bool, char16_t const*, nsCOMPtr<nsISupports> const&) /builds/worker/checkouts/gecko/xpcom/base/AppShutdown.cpp:318:18
[task 2021-05-07T21:53:06.743Z] 21:53:06 INFO - GECKO(1570) | #8 0x7f1a2da81a27 in nsAppStartup::Quit(unsigned int, int, bool*) /builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp:447:5
[task 2021-05-07T21:53:06.744Z] 21:53:06 INFO - GECKO(1570) | #9 0x7f1a22eeb3c1 in NS_InvokeByIndex /builds/worker/checkouts/gecko/xpcom/reflect/xptcall/md/unix/xptcinvoke_asm_x86_64_unix.S:101
[task 2021-05-07T21:53:06.759Z] 21:53:06 INFO - GECKO(1570) | #10 0x7f1a24824b89 in Invoke /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1644:10
[task 2021-05-07T21:53:06.759Z] 21:53:06 INFO - GECKO(1570) | #11 0x7f1a24824b89 in Call /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1197:19
[task 2021-05-07T21:53:06.760Z] 21:53:06 INFO - GECKO(1570) | #12 0x7f1a24824b89 in XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1143:23
[task 2021-05-07T21:53:06.761Z] 21:53:06 INFO - GECKO(1570) | #13 0x7f1a248295cf in XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNativeJSOps.cpp:925:10
[task 2021-05-07T21:53:06.777Z] 21:53:06 INFO - GECKO(1570) | #14 0x7f1a2deb62b2 in CallJSNative /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:427:13
[task 2021-05-07T21:53:06.779Z] 21:53:06 INFO - GECKO(1570) | #15 0x7f1a2deb62b2 in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:512:12
[task 2021-05-07T21:53:06.779Z] 21:53:06 INFO - GECKO(1570) | #16 0x7f1a2de9da55 in CallFromStack /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:576:10
[task 2021-05-07T21:53:06.780Z] 21:53:06 INFO - GECKO(1570) | #17 0x7f1a2de9da55 in Interpret(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:3227:16
[task 2021-05-07T21:53:06.781Z] 21:53:06 INFO - GECKO(1570) | #18 0x7f1a2de870c6 in js::RunScript(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:396:13
[task 2021-05-07T21:53:06.782Z] 21:53:06 INFO - GECKO(1570) | #19 0x7f1a2deb63eb in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:544:13
[task 2021-05-07T21:53:06.782Z] 21:53:06 INFO - GECKO(1570) | #20 0x7f1a2deb7feb in js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:589:8
[task 2021-05-07T21:53:06.795Z] 21:53:06 INFO - GECKO(1570) | #21 0x7f1a2e70a900 in JS_CallFunctionValue(JSContext*, JS::Handle<JSObject*>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/js/src/jsapi.cpp:2766:10
[task 2021-05-07T21:53:06.796Z] 21:53:06 INFO - GECKO(1570) | #22 0x7f1a248166d9 in nsXPCWrappedJS::CallMethod(unsigned short, nsXPTMethodInfo const*, nsXPTCMiniVariant*) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedJSClass.cpp:971:17
[task 2021-05-07T21:53:06.797Z] 21:53:06 INFO - GECKO(1570) | #23 0x7f1a22eecd52 in PrepareAndDispatch /builds/worker/checkouts/gecko/xpcom/reflect/xptcall/md/unix/xptcstubs_x86_64_linux.cpp:115:37
[task 2021-05-07T21:53:06.798Z] 21:53:06 INFO - GECKO(1570) | #24 0x7f1a22eebada in SharedStub (/builds/worker/workspace/build/application/firefox/libxul.so+0x3513ada)
[task 2021-05-07T21:53:06.822Z] 21:53:06 INFO - GECKO(1570) | #25 0x7f1a247dc7ef in PreciseGCRunnable::Run() /builds/worker/checkouts/gecko/js/xpconnect/src/XPCComponents.cpp:1681:16
[task 2021-05-07T21:53:06.845Z] 21:53:06 INFO - GECKO(1570) | #26 0x7f1a22eb7eb2 in mozilla::RunnableTask::Run() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:482:16
[task 2021-05-07T21:53:06.845Z] 21:53:06 INFO - GECKO(1570) | #27 0x7f1a22e84940 in mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:766:26
[task 2021-05-07T21:53:06.846Z] 21:53:06 INFO - GECKO(1570) | #28 0x7f1a22e82447 in mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:621:15
[task 2021-05-07T21:53:06.846Z] 21:53:06 INFO - GECKO(1570) | #29 0x7f1a22e8289d in mozilla::TaskController::ProcessPendingMTTask(bool) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:405:36
[task 2021-05-07T21:53:06.847Z] 21:53:06 INFO - GECKO(1570) | #30 0x7f1a22ec2181 in operator() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:138:37
[task 2021-05-07T21:53:06.848Z] 21:53:06 INFO - GECKO(1570) | #31 0x7f1a22ec2181 in mozilla::detail::RunnableFunction<mozilla::TaskController::InitializeInternal()::$_0>::Run() /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.h:534:5
[task 2021-05-07T21:53:06.848Z] 21:53:06 INFO - GECKO(1570) | #32 0x7f1a22e9f3b8 in nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1159:16
[task 2021-05-07T21:53:06.849Z] 21:53:06 INFO - GECKO(1570) | #33 0x7f1a22eaa16c in NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:548:10
[task 2021-05-07T21:53:06.860Z] 21:53:06 INFO - GECKO(1570) | #34 0x7f1a23f2186a in mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:85:21
[task 2021-05-07T21:53:06.870Z] 21:53:06 INFO - GECKO(1570) | #35 0x7f1a23e4ddd1 in RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:335:10
[task 2021-05-07T21:53:06.871Z] 21:53:06 INFO - GECKO(1570) | #36 0x7f1a23e4ddd1 in RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:328:3
[task 2021-05-07T21:53:06.871Z] 21:53:06 INFO - GECKO(1570) | #37 0x7f1a23e4ddd1 in MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:310:3
[task 2021-05-07T21:53:06.878Z] 21:53:06 INFO - GECKO(1570) | #38 0x7f1a29d710d7 in nsBaseAppShell::Run() /builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp:137:27
[task 2021-05-07T21:53:06.879Z] 21:53:06 INFO - GECKO(1570) | #39 0x7f1a2da809d7 in nsAppStartup::Run() /builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp:273:30
[task 2021-05-07T21:53:06.889Z] 21:53:06 INFO - GECKO(1570) | #40 0x7f1a2dc85987 in XREMain::XRE_mainRun() /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5367:22
[task 2021-05-07T21:53:06.889Z] 21:53:06 INFO - GECKO(1570) | #41 0x7f1a2dc879de in XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5565:8
[task 2021-05-07T21:53:06.890Z] 21:53:06 INFO - GECKO(1570) | #42 0x7f1a2dc88733 in XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5624:21
[task 2021-05-07T21:53:06.890Z] 21:53:06 INFO - GECKO(1570) | #43 0x55a76ef2fdcf in do_main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:224:22
[task 2021-05-07T21:53:06.891Z] 21:53:06 INFO - GECKO(1570) | #44 0x55a76ef2fdcf in main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:351:16
[task 2021-05-07T21:53:06.891Z] 21:53:06 INFO - GECKO(1570) | #45 0x7f1a470a9b96 in __libc_start_main /build/glibc-2ORdQG/glibc-2.27/csu/../csu/libc-start.c:310
[task 2021-05-07T21:53:06.892Z] 21:53:06 INFO - GECKO(1570) | ==1570==ABORTING
[task 2021-05-07T21:59:16.892Z] 21:59:16 INFO - Buffered messages finished
[task 2021-05-07T21:59:16.893Z] 21:59:16 ERROR - TEST-UNEXPECTED-TIMEOUT | Last test finished | application timed out after 370 seconds with no output
[task 2021-05-07T21:59:16.894Z] 21:59:16 ERROR - Force-terminating active process(es).
[task 2021-05-07T21:59:16.894Z] 21:59:16 INFO - Determining child pids from psutil...
[task 2021-05-07T21:59:16.906Z] 21:59:16 INFO - []
[task 2021-05-07T21:59:16.910Z] 21:59:16 INFO - ==> process 1570 launched child process 1586
[task 2021-05-07T21:59:16.911Z] 21:59:16 INFO - ==> process 1570 launched child process 1639
[task 2021-05-07T21:59:16.911Z] 21:59:16 INFO - ==> process 1570 launched child process 1653
[task 2021-05-07T21:59:16.912Z] 21:59:16 INFO - ==> process 1570 launched child process 1718
[task 2021-05-07T21:59:16.912Z] 21:59:16 INFO - ==> process 1570 launched child process 1753
[task 2021-05-07T21:59:16.913Z] 21:59:16 INFO - ==> process 1570 launched child process 1776
[task 2021-05-07T21:59:16.914Z] 21:59:16 INFO - ==> process 1570 launched child process 1810
[task 2021-05-07T21:59:16.914Z] 21:59:16 INFO - ==> process 1570 launched child process 1830
[task 2021-05-07T21:59:16.915Z] 21:59:16 INFO - ==> process 1570 launched child process 1933
[task 2021-05-07T21:59:16.915Z] 21:59:16 INFO - ==> process 1570 launched child process 2162
[task 2021-05-07T21:59:16.916Z] 21:59:16 INFO - ==> process 1570 launched child process 2190
[task 2021-05-07T21:59:16.917Z] 21:59:16 INFO - Found child pids: {1830, 1639, 1933, 2190, 1776, 1586, 1810, 2162, 1653, 1718, 1753}
[task 2021-05-07T21:59:16.917Z] 21:59:16 INFO - Failed to get child procs
[task 2021-05-07T21:59:16.918Z] 21:59:16 INFO - Killing process: 1830
[task 2021-05-07T21:59:16.919Z] 21:59:16 INFO - TEST-INFO | started process screentopng
[task 2021-05-07T21:59:17.206Z] 21:59:17 INFO - TEST-INFO | screentopng: exit 0
[task 2021-05-07T21:59:17.206Z] 21:59:17 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-07T21:59:17.208Z] 21:59:17 INFO - Error: Failed to kill process 1830: psutil.NoSuchProcess no process found with pid 1830
[task 2021-05-07T21:59:17.209Z] 21:59:17 INFO - Killing process: 1639
[task 2021-05-07T21:59:17.210Z] 21:59:17 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-07T21:59:17.210Z] 21:59:17 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-07T21:59:47.251Z] 21:59:47 INFO - failed to kill pid 1639 after 30s
[task 2021-05-07T21:59:47.251Z] 21:59:47 INFO - Killing process: 1933
[task 2021-05-07T21:59:47.252Z] 21:59:47 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-07T21:59:47.252Z] 21:59:47 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-07T21:59:47.252Z] 21:59:47 INFO - Error: Failed to kill process 1933: psutil.NoSuchProcess no process found with pid 1933
[task 2021-05-07T21:59:47.253Z] 21:59:47 INFO - Killing process: 2190
[task 2021-05-07T21:59:47.253Z] 21:59:47 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-07T21:59:47.253Z] 21:59:47 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-07T21:59:47.254Z] 21:59:47 INFO - Error: Failed to kill process 2190: psutil.NoSuchProcess no process found with pid 2190
[task 2021-05-07T21:59:47.254Z] 21:59:47 INFO - Killing process: 1776
[task 2021-05-07T21:59:47.254Z] 21:59:47 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-07T21:59:47.255Z] 21:59:47 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-07T21:59:47.255Z] 21:59:47 INFO - Error: Failed to kill process 1776: psutil.NoSuchProcess no process found with pid 1776
[task 2021-05-07T21:59:47.255Z] 21:59:47 INFO - Killing process: 1586
[task 2021-05-07T21:59:47.256Z] 21:59:47 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-07T21:59:47.256Z] 21:59:47 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-07T21:59:47.256Z] 21:59:47 INFO - Error: Failed to kill process 1586: psutil.NoSuchProcess no process found with pid 1586
[task 2021-05-07T21:59:47.257Z] 21:59:47 INFO - Killing process: 1810
[task 2021-05-07T21:59:47.257Z] 21:59:47 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-07T21:59:47.257Z] 21:59:47 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-07T22:00:17.299Z] 22:00:17 INFO - failed to kill pid 1810 after 30s
[task 2021-05-07T22:00:17.300Z] 22:00:17 INFO - Killing process: 2162
[task 2021-05-07T22:00:17.300Z] 22:00:17 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-07T22:00:17.300Z] 22:00:17 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-07T22:00:17.301Z] 22:00:17 INFO - Error: Failed to kill process 2162: psutil.NoSuchProcess no process found with pid 2162
[task 2021-05-07T22:00:17.301Z] 22:00:17 INFO - Killing process: 1653
[task 2021-05-07T22:00:17.302Z] 22:00:17 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-07T22:00:17.302Z] 22:00:17 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-07T22:00:47.337Z] 22:00:47 INFO - failed to kill pid 1653 after 30s
[task 2021-05-07T22:00:47.338Z] 22:00:47 INFO - Killing process: 1718
[task 2021-05-07T22:00:47.339Z] 22:00:47 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-07T22:00:47.340Z] 22:00:47 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-07T22:01:17.378Z] 22:01:17 INFO - failed to kill pid 1718 after 30s
[task 2021-05-07T22:01:17.385Z] 22:01:17 INFO - Killing process: 1753
[task 2021-05-07T22:01:17.386Z] 22:01:17 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-07T22:01:17.387Z] 22:01:17 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-07T22:01:17.388Z] 22:01:17 INFO - Error: Failed to kill process 1753: psutil.NoSuchProcess no process found with pid 1753
[task 2021-05-07T22:01:17.388Z] 22:01:17 INFO - Killing process: 1570
[task 2021-05-07T22:01:17.389Z] 22:01:17 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-07T22:01:17.389Z] 22:01:17 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-07T22:01:17.390Z] 22:01:17 INFO - psutil found pid 1570 dead
[task 2021-05-07T22:01:17.391Z] 22:01:17 INFO - psutil found pid 1570 dead
[task 2021-05-07T22:01:17.391Z] 22:01:17 INFO - TEST-INFO | Main app process: exit 0

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

Update:

There have been 72 failures within the last 7 days, all of them on Linux 18.04 x64 asan opt.

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

Hi Christian, could you please take a look at this?

There are 145 total failures in the last 7 days on linux1804-64-asan and linux1804-64-asan-qr opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=340323377&repo=autoland&lineNumber=2532

[task 2021-05-20T14:50:02.932Z] 14:50:02 INFO - TEST-START | toolkit/components/pictureinpicture/tests/browser_videoSelection.js
[task 2021-05-20T14:50:05.259Z] 14:50:05 INFO - GECKO(1565) | MEMORY STAT | vsize 20975543MB | residentFast 1154MB
[task 2021-05-20T14:50:05.261Z] 14:50:05 INFO - TEST-OK | toolkit/components/pictureinpicture/tests/browser_videoSelection.js | took 2329ms
[task 2021-05-20T14:50:05.348Z] 14:50:05 INFO - checking window state
[task 2021-05-20T14:50:07.309Z] 14:50:07 INFO - GECKO(1565) | Completed ShutdownLeaks collections in process 1747
[task 2021-05-20T14:50:07.312Z] 14:50:07 INFO - GECKO(1565) | Completed ShutdownLeaks collections in process 1792
[task 2021-05-20T14:50:07.332Z] 14:50:07 INFO - GECKO(1565) | Completed ShutdownLeaks collections in process 1761
[task 2021-05-20T14:50:07.393Z] 14:50:07 INFO - GECKO(1565) | Completed ShutdownLeaks collections in process 1628
[task 2021-05-20T14:50:07.422Z] 14:50:07 INFO - GECKO(1565) | Completed ShutdownLeaks collections in process 1649
[task 2021-05-20T14:50:07.447Z] 14:50:07 INFO - GECKO(1565) | Completed ShutdownLeaks collections in process 1717
[task 2021-05-20T14:50:07.987Z] 14:50:07 INFO - GECKO(1565) | Completed ShutdownLeaks collections in process 1565
[task 2021-05-20T14:50:07.988Z] 14:50:07 INFO - TEST-START | Shutdown
[task 2021-05-20T14:50:07.988Z] 14:50:07 INFO - Browser Chrome Test Summary
[task 2021-05-20T14:50:07.991Z] 14:50:07 INFO - Passed: 342
[task 2021-05-20T14:50:07.992Z] 14:50:07 INFO - Failed: 0
[task 2021-05-20T14:50:07.993Z] 14:50:07 INFO - Todo: 0
[task 2021-05-20T14:50:07.994Z] 14:50:07 INFO - Mode: e10s
[task 2021-05-20T14:50:07.995Z] 14:50:07 INFO - *** End BrowserChrome Test Results ***
[task 2021-05-20T14:50:08.281Z] 14:50:08 INFO - GECKO(1565) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-05-20T14:50:09.911Z] 14:50:09 INFO - GECKO(1565) | 1621522209910 Marionette TRACE Received observer notification xpcom-will-shutdown
[task 2021-05-20T14:50:09.916Z] 14:50:09 INFO - GECKO(1565) | 1621522209915 Marionette INFO Stopped listening on port 2828
[task 2021-05-20T14:50:09.920Z] 14:50:09 INFO - GECKO(1565) | 1621522209920 Marionette DEBUG Marionette stopped listening
[task 2021-05-20T14:50:11.724Z] 14:50:11 INFO - GECKO(1565) | -----------------------------------------------------
[task 2021-05-20T14:50:11.725Z] 14:50:11 INFO - GECKO(1565) | Suppressions used:
[task 2021-05-20T14:50:11.726Z] 14:50:11 INFO - GECKO(1565) | count bytes template
[task 2021-05-20T14:50:11.727Z] 14:50:11 INFO - GECKO(1565) | 14 448 nsComponentManagerImpl
[task 2021-05-20T14:50:11.728Z] 14:50:11 INFO - GECKO(1565) | 2 288 libfontconfig.so
[task 2021-05-20T14:50:11.728Z] 14:50:11 INFO - GECKO(1565) | -----------------------------------------------------
[task 2021-05-20T14:50:11.866Z] 14:50:11 INFO - GECKO(1565) | -----------------------------------------------------
[task 2021-05-20T14:50:11.867Z] 14:50:11 INFO - GECKO(1565) | Suppressions used:
[task 2021-05-20T14:50:11.868Z] 14:50:11 INFO - GECKO(1565) | count bytes template
[task 2021-05-20T14:50:11.869Z] 14:50:11 INFO - GECKO(1565) | 14 448 nsComponentManagerImpl
[task 2021-05-20T14:50:11.870Z] 14:50:11 INFO - GECKO(1565) | 2 288 libfontconfig.so
[task 2021-05-20T14:50:11.871Z] 14:50:11 INFO - GECKO(1565) | -----------------------------------------------------
[task 2021-05-20T14:50:12.105Z] 14:50:12 INFO - GECKO(1565) | -----------------------------------------------------
[task 2021-05-20T14:50:12.107Z] 14:50:12 INFO - GECKO(1565) | Suppressions used:
[task 2021-05-20T14:50:12.109Z] 14:50:12 INFO - GECKO(1565) | count bytes template
[task 2021-05-20T14:50:12.110Z] 14:50:12 INFO - GECKO(1565) | 14 448 nsComponentManagerImpl
[task 2021-05-20T14:50:12.112Z] 14:50:12 INFO - GECKO(1565) | 2 288 libfontconfig.so
[task 2021-05-20T14:50:12.113Z] 14:50:12 INFO - GECKO(1565) | -----------------------------------------------------
[task 2021-05-20T14:50:12.184Z] 14:50:12 INFO - GECKO(1565) | -----------------------------------------------------
[task 2021-05-20T14:50:12.185Z] 14:50:12 INFO - GECKO(1565) | Suppressions used:
[task 2021-05-20T14:50:12.186Z] 14:50:12 INFO - GECKO(1565) | count bytes template
[task 2021-05-20T14:50:12.187Z] 14:50:12 INFO - GECKO(1565) | 14 448 nsComponentManagerImpl
[task 2021-05-20T14:50:12.188Z] 14:50:12 INFO - GECKO(1565) | 2 288 libfontconfig.so
[task 2021-05-20T14:50:12.188Z] 14:50:12 INFO - GECKO(1565) | -----------------------------------------------------
[task 2021-05-20T14:50:12.388Z] 14:50:12 INFO - GECKO(1565) | -----------------------------------------------------
[task 2021-05-20T14:50:12.390Z] 14:50:12 INFO - GECKO(1565) | Suppressions used:
[task 2021-05-20T14:50:12.391Z] 14:50:12 INFO - GECKO(1565) | count bytes template
[task 2021-05-20T14:50:12.392Z] 14:50:12 INFO - GECKO(1565) | 14 448 nsComponentManagerImpl
[task 2021-05-20T14:50:12.392Z] 14:50:12 INFO - GECKO(1565) | 2 288 libfontconfig.so
[task 2021-05-20T14:50:12.393Z] 14:50:12 INFO - GECKO(1565) | -----------------------------------------------------
[task 2021-05-20T14:50:13.149Z] 14:50:13 INFO - GECKO(1565) | -----------------------------------------------------
[task 2021-05-20T14:50:13.150Z] 14:50:13 INFO - GECKO(1565) | Suppressions used:
[task 2021-05-20T14:50:13.150Z] 14:50:13 INFO - GECKO(1565) | count bytes template
[task 2021-05-20T14:50:13.150Z] 14:50:13 INFO - GECKO(1565) | 1 32 nsComponentManagerImpl
[task 2021-05-20T14:50:13.150Z] 14:50:13 INFO - GECKO(1565) | -----------------------------------------------------
[task 2021-05-20T14:55:14.170Z] 14:55:14 INFO - GECKO(1565) | AddressSanitizer:DEADLYSIGNAL
[task 2021-05-20T14:55:14.170Z] 14:55:14 INFO - GECKO(1565) | =================================================================
[task 2021-05-20T14:55:14.172Z] 14:55:14 ERROR - GECKO(1565) | ==1565==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000001 (pc 0x7fae7bfdd34c bp 0x7fae4d66ce10 sp 0x7fae4d66cd60 T155)
[task 2021-05-20T14:55:14.172Z] 14:55:14 INFO - GECKO(1565) | ==1565==The signal is caused by a WRITE memory access.
[task 2021-05-20T14:55:14.173Z] 14:55:14 INFO - GECKO(1565) | ==1565==Hint: address points to the zero page.
[task 2021-05-20T14:55:14.695Z] 14:55:14 INFO - GECKO(1565) | #0 0x7fae7bfdd34c in mozilla::(anonymous namespace)::RunWatchdog(void*) /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:246:5
[task 2021-05-20T14:55:14.699Z] 14:55:14 INFO - GECKO(1565) | #1 0x7fae929bd45e in _pt_root /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:201:5
[task 2021-05-20T14:55:14.715Z] 14:55:14 INFO - GECKO(1565) | #2 0x7fae9667b6da in start_thread /build/glibc-2ORdQG/glibc-2.27/nptl/pthread_create.c:463
[task 2021-05-20T14:55:14.782Z] 14:55:14 INFO - GECKO(1565) | #3 0x7fae95659a3e in clone /build/glibc-2ORdQG/glibc-2.27/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:95
[task 2021-05-20T14:55:14.784Z] 14:55:14 INFO - GECKO(1565) | AddressSanitizer can not provide additional info.
[task 2021-05-20T14:55:14.784Z] 14:55:14 INFO - GECKO(1565) | SUMMARY: AddressSanitizer: SEGV /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:246:5 in mozilla::(anonymous namespace)::RunWatchdog(void*)
[task 2021-05-20T14:55:14.785Z] 14:55:14 INFO - GECKO(1565) | Thread T155 (Shutdow~minator) created by T0 here:
[task 2021-05-20T14:55:14.797Z] 14:55:14 INFO - GECKO(1565) | #0 0x55e328953b5c in pthread_create /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/asan/asan_interceptors.cpp:205:3
[task 2021-05-20T14:55:14.801Z] 14:55:14 INFO - GECKO(1565) | #1 0x7fae929ad764 in _PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:458:14
[task 2021-05-20T14:55:14.801Z] 14:55:14 INFO - GECKO(1565) | #2 0x7fae9299ec3e in PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:533:12
[task 2021-05-20T14:55:14.801Z] 14:55:14 INFO - GECKO(1565) | #3 0x7fae7bfdcba2 in CreateSystemThread /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:116:7
[task 2021-05-20T14:55:14.802Z] 14:55:14 INFO - GECKO(1565) | #4 0x7fae7bfdcba2 in mozilla::nsTerminator::StartWatchdog() /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:469:7
[task 2021-05-20T14:55:14.802Z] 14:55:14 INFO - GECKO(1565) | #5 0x7fae7bfdce8b in Start /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:383:3
[task 2021-05-20T14:55:14.803Z] 14:55:14 INFO - GECKO(1565) | #6 0x7fae7bfdce8b in mozilla::nsTerminator::AdvancePhase(mozilla::ShutdownPhase) /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:517:5
[task 2021-05-20T14:55:14.810Z] 14:55:14 INFO - GECKO(1565) | #7 0x7fae70f36781 in mozilla::AdvanceShutdownPhaseInternal(mozilla::ShutdownPhase, bool, char16_t const*, nsCOMPtr<nsISupports> const&) /builds/worker/checkouts/gecko/xpcom/base/AppShutdown.cpp:318:18
[task 2021-05-20T14:55:14.812Z] 14:55:14 INFO - GECKO(1565) | #8 0x7fae7be285b7 in nsAppStartup::Quit(unsigned int, int, bool*) /builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp:447:5
[task 2021-05-20T14:55:14.813Z] 14:55:14 INFO - GECKO(1565) | #9 0x7fae711a7581 in NS_InvokeByIndex /builds/worker/checkouts/gecko/xpcom/reflect/xptcall/md/unix/xptcinvoke_asm_x86_64_unix.S:101
[task 2021-05-20T14:55:14.823Z] 14:55:14 INFO - GECKO(1565) | #10 0x7fae72b72c09 in Invoke /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1644:10
[task 2021-05-20T14:55:14.823Z] 14:55:14 INFO - GECKO(1565) | #11 0x7fae72b72c09 in Call /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1197:19
[task 2021-05-20T14:55:14.824Z] 14:55:14 INFO - GECKO(1565) | #12 0x7fae72b72c09 in XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1143:23
[task 2021-05-20T14:55:14.825Z] 14:55:14 INFO - GECKO(1565) | #13 0x7fae72b7764f in XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNativeJSOps.cpp:925:10
[task 2021-05-20T14:55:14.838Z] 14:55:14 INFO - GECKO(1565) | #14 0x7fae7c25d3f2 in CallJSNative /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:427:13
[task 2021-05-20T14:55:14.839Z] 14:55:14 INFO - GECKO(1565) | #15 0x7fae7c25d3f2 in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:512:12
[task 2021-05-20T14:55:14.839Z] 14:55:14 INFO - GECKO(1565) | #16 0x7fae7c244ba5 in CallFromStack /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:576:10
[task 2021-05-20T14:55:14.840Z] 14:55:14 INFO - GECKO(1565) | #17 0x7fae7c244ba5 in Interpret(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:3227:16
[task 2021-05-20T14:55:14.841Z] 14:55:14 INFO - GECKO(1565) | #18 0x7fae7c22e216 in js::RunScript(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:396:13
[task 2021-05-20T14:55:14.842Z] 14:55:14 INFO - GECKO(1565) | #19 0x7fae7c25d52b in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:544:13
[task 2021-05-20T14:55:14.842Z] 14:55:14 INFO - GECKO(1565) | #20 0x7fae7c25f12b in js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:589:8
[task 2021-05-20T14:55:14.857Z] 14:55:14 INFO - GECKO(1565) | #21 0x7fae7cab0f70 in JS_CallFunctionValue(JSContext*, JS::Handle<JSObject*>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/js/src/jsapi.cpp:2733:10
[task 2021-05-20T14:55:14.858Z] 14:55:14 INFO - GECKO(1565) | #22 0x7fae72b64759 in nsXPCWrappedJS::CallMethod(unsigned short, nsXPTMethodInfo const*, nsXPTCMiniVariant*) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedJSClass.cpp:971:17
[task 2021-05-20T14:55:14.858Z] 14:55:14 INFO - GECKO(1565) | #23 0x7fae711a8f12 in PrepareAndDispatch /builds/worker/checkouts/gecko/xpcom/reflect/xptcall/md/unix/xptcstubs_x86_64_linux.cpp:115:37
[task 2021-05-20T14:55:14.859Z] 14:55:14 INFO - GECKO(1565) | #24 0x7fae711a7c9a in SharedStub (/builds/worker/workspace/build/application/firefox/libxul.so+0x353ac9a)
[task 2021-05-20T14:55:14.873Z] 14:55:14 INFO - GECKO(1565) | #25 0x7fae72b2993f in PreciseGCRunnable::Run() /builds/worker/checkouts/gecko/js/xpconnect/src/XPCComponents.cpp:1681:16
[task 2021-05-20T14:55:14.889Z] 14:55:14 INFO - GECKO(1565) | #26 0x7fae71174a72 in mozilla::RunnableTask::Run() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:482:16
[task 2021-05-20T14:55:14.891Z] 14:55:14 INFO - GECKO(1565) | #27 0x7fae71141490 in mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:766:26
[task 2021-05-20T14:55:14.892Z] 14:55:14 INFO - GECKO(1565) | #28 0x7fae7113ef97 in mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:621:15
[task 2021-05-20T14:55:14.893Z] 14:55:14 INFO - GECKO(1565) | #29 0x7fae7113f3ed in mozilla::TaskController::ProcessPendingMTTask(bool) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:405:36
[task 2021-05-20T14:55:14.893Z] 14:55:14 INFO - GECKO(1565) | #30 0x7fae7117ed51 in operator() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:138:37
[task 2021-05-20T14:55:14.894Z] 14:55:14 INFO - GECKO(1565) | #31 0x7fae7117ed51 in mozilla::detail::RunnableFunction<mozilla::TaskController::InitializeInternal()::$_0>::Run() /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.h:534:5
[task 2021-05-20T14:55:14.895Z] 14:55:14 INFO - GECKO(1565) | #32 0x7fae7115bf78 in nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1159:16
[task 2021-05-20T14:55:14.896Z] 14:55:14 INFO - GECKO(1565) | #33 0x7fae71166d2c in NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:548:10
[task 2021-05-20T14:55:14.905Z] 14:55:14 INFO - GECKO(1565) | #34 0x7fae721e670a in mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:85:21
[task 2021-05-20T14:55:14.912Z] 14:55:14 INFO - GECKO(1565) | #35 0x7fae721111f1 in RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:335:10
[task 2021-05-20T14:55:14.913Z] 14:55:14 INFO - GECKO(1565) | #36 0x7fae721111f1 in RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:328:3
[task 2021-05-20T14:55:14.914Z] 14:55:14 INFO - GECKO(1565) | #37 0x7fae721111f1 in MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:310:3
[task 2021-05-20T14:55:14.919Z] 14:55:14 INFO - GECKO(1565) | #38 0x7fae780f0497 in nsBaseAppShell::Run() /builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp:137:27
[task 2021-05-20T14:55:14.920Z] 14:55:14 INFO - GECKO(1565) | #39 0x7fae7be27567 in nsAppStartup::Run() /builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp:273:30
[task 2021-05-20T14:55:14.925Z] 14:55:14 INFO - GECKO(1565) | #40 0x7fae7c02c3a7 in XREMain::XRE_mainRun() /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5239:22
[task 2021-05-20T14:55:14.926Z] 14:55:14 INFO - GECKO(1565) | #41 0x7fae7c02e3fe in XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5437:8
[task 2021-05-20T14:55:14.929Z] 14:55:14 INFO - GECKO(1565) | #42 0x7fae7c02f153 in XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5496:21
[task 2021-05-20T14:55:14.930Z] 14:55:14 INFO - GECKO(1565) | #43 0x55e32899ddcf in do_main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:224:22
[task 2021-05-20T14:55:14.930Z] 14:55:14 INFO - GECKO(1565) | #44 0x55e32899ddcf in main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:351:16
[task 2021-05-20T14:55:14.931Z] 14:55:14 INFO - GECKO(1565) | #45 0x7fae95559b96 in __libc_start_main /build/glibc-2ORdQG/glibc-2.27/csu/../csu/libc-start.c:310
[task 2021-05-20T14:55:14.931Z] 14:55:14 INFO - GECKO(1565) | ==1565==ABORTING
[task 2021-05-20T15:01:24.941Z] 15:01:24 INFO - Buffered messages finished
[task 2021-05-20T15:01:24.942Z] 15:01:24 ERROR - TEST-UNEXPECTED-TIMEOUT | Last test finished | application timed out after 370 seconds with no output

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

We had 150 failures in the past week, all of them on linux1804-64-asan and linux1804-64-asan-qr opt.
Most recent one: https://treeherder.mozilla.org/logviewer?job_id=341221772&repo=autoland&lineNumber=6795

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

(In reply to Andreea Pavel [:apavel] from comment #51)

Hi Christian, could you please take a look at this?

There are 145 total failures in the last 7 days on linux1804-64-asan and linux1804-64-asan-qr opt

Per previous comments, this is highly unlikely to be happening on ASan only. However, on ASan the signature looks different. Comment 33 seems to suggest that we have these shutdown hangs on other platforms as well. Can you please check if you have related shutdown hangs elsewhere too? ASan is just showing a different crash due to how the crash reporter there works.

Flags: needinfo?(choller)

(In reply to Christian Holler (:decoder) from comment #63)

(In reply to Andreea Pavel [:apavel] from comment #51)

Hi Christian, could you please take a look at this?

There are 145 total failures in the last 7 days on linux1804-64-asan and linux1804-64-asan-qr opt

Per previous comments, this is highly unlikely to be happening on ASan only. However, on ASan the signature looks different. Comment 33 seems to suggest that we have these shutdown hangs on other platforms as well. Can you please check if you have related shutdown hangs elsewhere too? ASan is just showing a different crash due to how the crash reporter there works.

Hi, for this exact match, just asan, however since this is probably a duplicate of bug 1358898 (which doesn't have any asan failures) as mentioned above, here is an example of a win failure:
https://treeherder.mozilla.org/logviewer?job_id=341437998&repo=autoland&lineNumber=19624

[task 2021-06-01T18:16:38.807Z] 18:16:38 INFO - REFTEST TEST-START | layout/reftests/svg/smil/syncbase/filtered-interval-1.svg == layout/reftests/svg/smil/syncbase/green-box-ref.svg
[task 2021-06-01T18:16:38.808Z] 18:16:38 INFO - REFTEST TEST-LOAD | file:///Z:/task_1622570431/build/tests/reftest/tests/layout/reftests/svg/smil/syncbase/filtered-interval-1.svg | 81 / 82 (98%)
[task 2021-06-01T18:16:38.897Z] 18:16:38 INFO - REFTEST TEST-PASS | layout/reftests/svg/smil/syncbase/filtered-interval-1.svg == layout/reftests/svg/smil/syncbase/green-box-ref.svg | image comparison, max difference: 0, number of differing pixels: 0
[task 2021-06-01T18:16:38.897Z] 18:16:38 INFO - REFTEST TEST-END | layout/reftests/svg/smil/syncbase/filtered-interval-1.svg == layout/reftests/svg/smil/syncbase/green-box-ref.svg
[task 2021-06-01T18:16:38.933Z] 18:16:38 INFO - REFTEST INFO | Slowest test took 605ms (file:///Z:/task_1622570431/build/tests/reftest/tests/layout/reftests/svg/smil/syncbase/new-interval-simple-1.svg)
[task 2021-06-01T18:16:38.933Z] 18:16:38 INFO - REFTEST INFO | Total canvas count = 3
[task 2021-06-01T18:16:39.043Z] 18:16:39 INFO - [Child 7400, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-06-01T18:16:39.046Z] 18:16:39 INFO - [Child 7400, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-06-01T18:16:39.101Z] 18:16:39 INFO - [Child 7400, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-06-01T18:16:39.109Z] 18:16:39 INFO - [Child 7400, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-06-01T18:16:39.111Z] 18:16:39 INFO - [Child 7400, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-06-01T18:16:39.119Z] 18:16:39 INFO - [Child 7400, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-06-01T18:16:39.126Z] 18:16:39 INFO - [Child 7400, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-06-01T18:16:39.134Z] 18:16:39 INFO - [Child 7400, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-06-01T18:16:39.415Z] 18:16:39 INFO - ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-06-01T18:16:39.651Z] 18:16:39 INFO - [Child 7400, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3357
[task 2021-06-01T18:16:39.684Z] 18:16:39 INFO - [Child 7400, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4442
[task 2021-06-01T18:16:40.135Z] 18:16:40 INFO - ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost

[task 2021-06-01T18:16:40.810Z] 18:16:40 INFO - ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-06-01T18:16:40.935Z] 18:16:40 INFO - [GPU 4820, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4442
[task 2021-06-01T18:16:41.231Z] 18:16:41 INFO - [Child 9996, Main Thread] WARNING: Finishing incremental GC in progress during CC: file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3293
[task 2021-06-01T18:16:41.937Z] 18:16:41 INFO - [Child 9996, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3357
[task 2021-06-01T18:16:42.348Z] 18:16:42 INFO - [Parent 10932, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3357
[task 2021-06-01T18:17:44.769Z] 18:17:44 INFO - XPCOM_MEM_BLOAT_LOG: C:\Users\task_1622570431\AppData\Local\Temp\tmp_55b5w9r.mozrunner\runreftest_leaks.log
[task 2021-06-01T18:17:44.770Z] 18:17:44 INFO - Writing to log: C:\Users\task_1622570431\AppData\Local\Temp\tmp_55b5w9r.mozrunner\runreftest_leaks.log
[task 2021-06-01T18:17:45.771Z] 18:17:45 INFO - Hit MOZ_CRASH(Shutdown hanging after all known phases and workers finished.) at /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:246
[task 2021-06-01T18:17:45.987Z] 18:17:45 INFO - Initializing stack-fixing for the first stack frame, this may take a while...
[task 2021-06-01T18:18:07.945Z] 18:18:07 INFO - #01: mozilla::anonymous namespace'::RunWatchdog(void*) [toolkit/components/terminator/nsTerminator.cpp:246] [task 2021-06-01T18:18:08.242Z] 18:18:08 INFO - #02: _PR_NativeRunThread(void*) [nsprpub/pr/src/threads/combined/pruthr.c:399] [task 2021-06-01T18:18:08.243Z] 18:18:08 INFO - #03: pr_root(void*) [nsprpub/pr/src/md/windows/w95thred.c:139] [task 2021-06-01T18:18:08.250Z] 18:18:08 INFO - fix-stacks: error: failed to read debug info fileucrtbase.pdbforC:\Windows\System32\ucrtbase.dll[task 2021-06-01T18:18:08.251Z] 18:18:08 INFO - fix-stacks: note: this is expected and harmless for all PDB files on opt automation runs [task 2021-06-01T18:18:08.251Z] 18:18:08 INFO - fix-stacks: The system cannot find the file specified. (os error 2) [task 2021-06-01T18:18:08.252Z] 18:18:08 INFO - #04: o____lc_collate_cp_func [C:\Windows\System32\ucrtbase.dll + 0x3e8af] [task 2021-06-01T18:18:08.257Z] 18:18:08 INFO - fix-stacks: error: failed to read debug info filewkernel32.pdbforC:\Windows\System32\KERNEL32.DLL[task 2021-06-01T18:18:08.257Z] 18:18:08 INFO - fix-stacks: note: this is expected and harmless for all PDB files on opt automation runs [task 2021-06-01T18:18:08.257Z] 18:18:08 INFO - fix-stacks: The system cannot find the file specified. (os error 2) [task 2021-06-01T18:18:08.258Z] 18:18:08 INFO - #05: BaseThreadInitThunk [C:\Windows\System32\KERNEL32.DLL + 0x18484] [task 2021-06-01T18:18:08.264Z] 18:18:08 INFO - fix-stacks: error: failed to read debug info filewntdll.pdbforC:\Windows\SYSTEM32\ntdll.dll[task 2021-06-01T18:18:08.265Z] 18:18:08 INFO - fix-stacks: note: this is expected and harmless for all PDB files on opt automation runs [task 2021-06-01T18:18:08.265Z] 18:18:08 INFO - fix-stacks: The system cannot find the file specified. (os error 2) [task 2021-06-01T18:18:08.266Z] 18:18:08 INFO - #06: RtlValidSecurityDescriptor [C:\Windows\SYSTEM32\ntdll.dll + 0x6305a] [task 2021-06-01T18:18:08.267Z] 18:18:08 INFO - #07: RtlValidSecurityDescriptor [C:\Windows\SYSTEM32\ntdll.dll + 0x6302a] [task 2021-06-01T18:18:08.268Z] 18:18:08 ERROR - TEST-UNEXPECTED-FAIL | Last test finished | application terminated with exit code 1 [task 2021-06-01T18:18:08.269Z] 18:18:08 INFO - REFTEST INFO | Copy/paste: Z:/task_1622570431/fetches\minidump_stackwalk\minidump_stackwalk.exe C:\Users\task_1622570431\AppData\Local\Temp\tmp_55b5w9r.mozrunner\minidumps\f611915b-b9af-45fd-8b83-0d10c8e41e4c.dmp Z:\task_1622570431\build\symbols [task 2021-06-01T18:18:27.985Z] 18:18:27 INFO - REFTEST INFO | Saved minidump as Z:\task_1622570431\build\blobber_upload_dir\f611915b-b9af-45fd-8b83-0d10c8e41e4c.dmp [task 2021-06-01T18:18:27.988Z] 18:18:27 INFO - REFTEST INFO | Saved app info as Z:\task_1622570431\build\blobber_upload_dir\f611915b-b9af-45fd-8b83-0d10c8e41e4c.extra [task 2021-06-01T18:18:28.025Z] 18:18:28 INFO - REFTEST PROCESS-CRASH | Last test finished | application crashed [@ mozilla::anonymous namespace'::RunWatchdog(void*)]
[task 2021-06-01T18:18:28.025Z] 18:18:28 INFO - Mozilla crash reason: MOZ_CRASH(Shutdown hanging after all known phases and workers finished.)
[task 2021-06-01T18:18:28.025Z] 18:18:28 INFO - Crash dump filename: C:\Users\task_1622570431\AppData\Local\Temp\tmp_55b5w9r.mozrunner\minidumps\f611915b-b9af-45fd-8b83-0d10c8e41e4c.dmp
[task 2021-06-01T18:18:28.026Z] 18:18:28 INFO - Operating system: Windows NT
[task 2021-06-01T18:18:28.026Z] 18:18:28 INFO - 10.0.17134
[task 2021-06-01T18:18:28.026Z] 18:18:28 INFO - CPU: x86
[task 2021-06-01T18:18:28.026Z] 18:18:28 INFO - GenuineIntel family 6 model 79 stepping 1
[task 2021-06-01T18:18:28.027Z] 18:18:28 INFO - 4 CPUs
[task 2021-06-01T18:18:28.027Z] 18:18:28 INFO -
[task 2021-06-01T18:18:28.027Z] 18:18:28 INFO - GPU: UNKNOWN
[task 2021-06-01T18:18:28.027Z] 18:18:28 INFO -
[task 2021-06-01T18:18:28.027Z] 18:18:28 INFO - Crash reason: EXCEPTION_BREAKPOINT
[task 2021-06-01T18:18:28.028Z] 18:18:28 INFO - Crash address: 0x64e74ff9
[task 2021-06-01T18:18:28.028Z] 18:18:28 INFO - Process uptime: 96 seconds
[task 2021-06-01T18:18:28.028Z] 18:18:28 INFO -
[task 2021-06-01T18:18:28.028Z] 18:18:28 INFO - Thread 13 (crashed)
[task 2021-06-01T18:18:28.028Z] 18:18:28 INFO - 0 xul.dll!mozilla::`anonymous namespace'::RunWatchdog(void*) [nsTerminator.cpp:3434dc6057b3a75542b2ddcd222f37e3631fb144 : 246 + 0x0]
[task 2021-06-01T18:18:28.028Z] 18:18:28 INFO - eip = 0x64e74ff9 esp = 0x2430fabc ebp = 0x2430fad0 ebx = 0x15e3d840
[task 2021-06-01T18:18:28.029Z] 18:18:28 INFO - esi = 0x00000276 edi = 0x77296490 eax = 0x6a9c6608 ecx = 0x00000000
[task 2021-06-01T18:18:28.029Z] 18:18:28 INFO - edx = 0x00000048 efl = 0x00000202
[task 2021-06-01T18:18:28.029Z] 18:18:28 INFO - Found by: given as instruction pointer in context
[task 2021-06-01T18:18:28.029Z] 18:18:28 INFO - 1 nss3.dll!_PR_NativeRunThread(void*) [pruthr.c:3434dc6057b3a75542b2ddcd222f37e3631fb144 : 399 + 0xf]
[task 2021-06-01T18:18:28.029Z] 18:18:28 INFO - eip = 0x6a2977d8 esp = 0x2430fad8 ebp = 0x2430faf8 esi = 0x1f6f7480
[task 2021-06-01T18:18:28.030Z] 18:18:28 INFO - edi = 0x1945b970
[task 2021-06-01T18:18:28.030Z] 18:18:28 INFO - Found by: call frame info
[task 2021-06-01T18:18:28.030Z] 18:18:28 INFO - 2 nss3.dll!pr_root(void*) [w95thred.c:3434dc6057b3a75542b2ddcd222f37e3631fb144 : 139 + 0xf]
[task 2021-06-01T18:18:28.030Z] 18:18:28 INFO - eip = 0x6a2890a6 esp = 0x2430fb00 ebp = 0x2430fb08 ebx = 0x15e3d840
[task 2021-06-01T18:18:28.030Z] 18:18:28 INFO - esi = 0x1945b970 edi = 0x15e3d840
[task 2021-06-01T18:18:28.031Z] 18:18:28 INFO - Found by: call frame info
[task 2021-06-01T18:18:28.031Z] 18:18:28 INFO - 3 ucrtbase.dll!EtwNotificationRegister + 0x3f
[task 2021-06-01T18:18:28.031Z] 18:18:28 INFO - eip = 0x76cae8af esp = 0x2430fb10 ebp = 0x2430fb44 esi = 0x6a289090
[task 2021-06-01T18:18:28.031Z] 18:18:28 INFO - Found by: call frame info
[task 2021-06-01T18:18:28.031Z] 18:18:28 INFO - 4 kernel32.dll!_pi_by_2_to_61 + 0x126fa
[task 2021-06-01T18:18:28.031Z] 18:18:28 INFO - eip = 0x77298484 esp = 0x2430fb4c ebp = 0x2430fb58
[task 2021-06-01T18:18:28.032Z] 18:18:28 INFO - Found by: call frame info
[task 2021-06-01T18:18:28.032Z] 18:18:28 INFO - 5 ntdll.dll!_RtlUserThreadStart + 0x2f
[task 2021-06-01T18:18:28.032Z] 18:18:28 INFO - eip = 0x7754305a esp = 0x2430fb60 ebp = 0x2430fba0
[task 2021-06-01T18:18:28.032Z] 18:18:28 INFO - Found by: previous frame's frame pointer
[task 2021-06-01T18:18:28.032Z] 18:18:28 INFO - 6 ntdll.dll!_RtlUserThreadStart + 0x1b
[task 2021-06-01T18:18:28.032Z] 18:18:28 INFO - eip = 0x7754302a esp = 0x2430fba8 ebp = 0x2430fbb0
[task 2021-06-01T18:18:28.032Z] 18:18:28 INFO - Found by: call frame info

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

There are 157 total failures in the last 7 days on

  • linux1804-64-asan opt
  • linux1804-64-asan-qr opt

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

[task 2021-05-30T01:04:38.743Z] 01:04:38 INFO - TEST-START | toolkit/components/pictureinpicture/tests/browser_videoSelection.js
[task 2021-05-30T01:04:40.991Z] 01:04:40 INFO - GECKO(6034) | MEMORY STAT | vsize 20975522MB | residentFast 1154MB
[task 2021-05-30T01:04:40.993Z] 01:04:40 INFO - TEST-OK | toolkit/components/pictureinpicture/tests/browser_videoSelection.js | took 2249ms
[task 2021-05-30T01:04:41.053Z] 01:04:41 INFO - checking window state
[task 2021-05-30T01:04:43.147Z] 01:04:43 INFO - GECKO(6034) | Completed ShutdownLeaks collections in process 6094
[task 2021-05-30T01:04:43.175Z] 01:04:43 INFO - GECKO(6034) | Completed ShutdownLeaks collections in process 6284
[task 2021-05-30T01:04:43.253Z] 01:04:43 INFO - GECKO(6034) | Completed ShutdownLeaks collections in process 6234
[task 2021-05-30T01:04:43.314Z] 01:04:43 INFO - GECKO(6034) | Completed ShutdownLeaks collections in process 6216
[task 2021-05-30T01:04:43.357Z] 01:04:43 INFO - GECKO(6034) | Completed ShutdownLeaks collections in process 6115
[task 2021-05-30T01:04:43.395Z] 01:04:43 INFO - GECKO(6034) | Completed ShutdownLeaks collections in process 6181
[task 2021-05-30T01:04:44.009Z] 01:04:44 INFO - GECKO(6034) | Completed ShutdownLeaks collections in process 6034
[task 2021-05-30T01:04:44.011Z] 01:04:44 INFO - TEST-START | Shutdown
[task 2021-05-30T01:04:44.013Z] 01:04:44 INFO - Browser Chrome Test Summary
[task 2021-05-30T01:04:44.014Z] 01:04:44 INFO - Passed: 342
[task 2021-05-30T01:04:44.015Z] 01:04:44 INFO - Failed: 0
[task 2021-05-30T01:04:44.016Z] 01:04:44 INFO - Todo: 0
[task 2021-05-30T01:04:44.017Z] 01:04:44 INFO - Mode: e10s

[task 2021-05-30T01:09:50.105Z] 01:09:50 INFO - GECKO(6034) | AddressSanitizer:DEADLYSIGNAL
[task 2021-05-30T01:09:50.106Z] 01:09:50 INFO - GECKO(6034) | =================================================================
[task 2021-05-30T01:09:50.106Z] 01:09:50 ERROR - GECKO(6034) | ==6034==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000001 (pc 0x7fa91ff5e84c bp 0x7fa8eb255e10 sp 0x7fa8eb255d60 T156)
[task 2021-05-30T01:09:50.107Z] 01:09:50 INFO - GECKO(6034) | ==6034==The signal is caused by a WRITE memory access.
[task 2021-05-30T01:09:50.108Z] 01:09:50 INFO - GECKO(6034) | ==6034==Hint: address points to the zero page.
[task 2021-05-30T01:09:50.688Z] 01:09:50 INFO - GECKO(6034) | #0 0x7fa91ff5e84c in mozilla::(anonymous namespace)::RunWatchdog(void*) /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:246:5
[task 2021-05-30T01:09:50.693Z] 01:09:50 INFO - GECKO(6034) | #1 0x7fa93699645e in _pt_root /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:201:5
[task 2021-05-30T01:09:50.705Z] 01:09:50 INFO - GECKO(6034) | #2 0x7fa93a6546da in start_thread /build/glibc-2ORdQG/glibc-2.27/nptl/pthread_create.c:463
[task 2021-05-30T01:09:50.761Z] 01:09:50 INFO - GECKO(6034) | #3 0x7fa939632a3e in clone /build/glibc-2ORdQG/glibc-2.27/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:95
[task 2021-05-30T01:09:50.762Z] 01:09:50 INFO - GECKO(6034) | AddressSanitizer can not provide additional info.
[task 2021-05-30T01:09:50.763Z] 01:09:50 INFO - GECKO(6034) | SUMMARY: AddressSanitizer: SEGV /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:246:5 in mozilla::(anonymous namespace)::RunWatchdog(void*)
[task 2021-05-30T01:09:50.764Z] 01:09:50 INFO - GECKO(6034) | Thread T156 (Shutdow~minator) created by T0 here:
[task 2021-05-30T01:09:50.775Z] 01:09:50 INFO - GECKO(6034) | #0 0x55eb16d3ab5c in pthread_create /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/asan/asan_interceptors.cpp:205:3
[task 2021-05-30T01:09:50.777Z] 01:09:50 INFO - GECKO(6034) | #1 0x7fa936986764 in _PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:458:14
[task 2021-05-30T01:09:50.779Z] 01:09:50 INFO - GECKO(6034) | #2 0x7fa936977c3e in PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:533:12
[task 2021-05-30T01:09:50.780Z] 01:09:50 INFO - GECKO(6034) | #3 0x7fa91ff5e0a2 in CreateSystemThread /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:116:7
[task 2021-05-30T01:09:50.781Z] 01:09:50 INFO - GECKO(6034) | #4 0x7fa91ff5e0a2 in mozilla::nsTerminator::StartWatchdog() /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:469:7
[task 2021-05-30T01:09:50.782Z] 01:09:50 INFO - GECKO(6034) | #5 0x7fa91ff5e38b in Start /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:383:3
[task 2021-05-30T01:09:50.782Z] 01:09:50 INFO - GECKO(6034) | #6 0x7fa91ff5e38b in mozilla::nsTerminator::AdvancePhase(mozilla::ShutdownPhase) /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:517:5
[task 2021-05-30T01:09:50.791Z] 01:09:50 INFO - GECKO(6034) | #7 0x7fa914e7bd31 in mozilla::AdvanceShutdownPhaseInternal(mozilla::ShutdownPhase, bool, char16_t const*, nsCOMPtr<nsISupports> const&) /builds/worker/checkouts/gecko/xpcom/base/AppShutdown.cpp:318:18
[task 2021-05-30T01:09:50.795Z] 01:09:50 INFO - GECKO(6034) | #8 0x7fa91fda9d37 in nsAppStartup::Quit(unsigned int, int, bool*) /builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp:447:5
[task 2021-05-30T01:09:50.796Z] 01:09:50 INFO - GECKO(6034) | #9 0x7fa9150ec911 in NS_InvokeByIndex /builds/worker/checkouts/gecko/xpcom/reflect/xptcall/md/unix/xptcinvoke_asm_x86_64_unix.S:101
[task 2021-05-30T01:09:50.810Z] 01:09:50 INFO - GECKO(6034) | #10 0x7fa916ac0ed9 in Invoke /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1644:10
[task 2021-05-30T01:09:50.811Z] 01:09:50 INFO - GECKO(6034) | #11 0x7fa916ac0ed9 in Call /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1197:19
[task 2021-05-30T01:09:50.812Z] 01:09:50 INFO - GECKO(6034) | #12 0x7fa916ac0ed9 in XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1143:23
[task 2021-05-30T01:09:50.813Z] 01:09:50 INFO - GECKO(6034) | #13 0x7fa916ac591f in XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNativeJSOps.cpp:922:10
[task 2021-05-30T01:09:50.827Z] 01:09:50 INFO - GECKO(6034) | #14 0x7fa9201e1732 in CallJSNative /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:427:13
[task 2021-05-30T01:09:50.828Z] 01:09:50 INFO - GECKO(6034) | #15 0x7fa9201e1732 in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:512:12
[task 2021-05-30T01:09:50.829Z] 01:09:50 INFO - GECKO(6034) | #16 0x7fa9201c8ee5 in CallFromStack /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:576:10
[task 2021-05-30T01:09:50.830Z] 01:09:50 INFO - GECKO(6034) | #17 0x7fa9201c8ee5 in Interpret(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:3227:16
[task 2021-05-30T01:09:50.831Z] 01:09:50 INFO - GECKO(6034) | #18 0x7fa9201b2556 in js::RunScript(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:396:13
[task 2021-05-30T01:09:50.832Z] 01:09:50 INFO - GECKO(6034) | #19 0x7fa9201e186b in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:544:13
[task 2021-05-30T01:09:50.833Z] 01:09:50 INFO - GECKO(6034) | #20 0x7fa9201e346b in js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:589:8
[task 2021-05-30T01:09:50.845Z] 01:09:50 INFO - GECKO(6034) | #21 0x7fa920a36280 in JS_CallFunctionValue(JSContext*, JS::Handle<JSObject*>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/js/src/jsapi.cpp:2724:10
[task 2021-05-30T01:09:50.846Z] 01:09:50 INFO - GECKO(6034) | #22 0x7fa916ab2a29 in nsXPCWrappedJS::CallMethod(unsigned short, nsXPTMethodInfo const*, nsXPTCMiniVariant*) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedJSClass.cpp:971:17
[task 2021-05-30T01:09:50.846Z] 01:09:50 INFO - GECKO(6034) | #23 0x7fa9150ee2a2 in PrepareAndDispatch /builds/worker/checkouts/gecko/xpcom/reflect/xptcall/md/unix/xptcstubs_x86_64_linux.cpp:115:37
[task 2021-05-30T01:09:50.847Z] 01:09:50 INFO - GECKO(6034) | #24 0x7fa9150ed02a in SharedStub (/builds/worker/workspace/build/application/firefox/libxul.so+0x354d02a)
[task 2021-05-30T01:09:50.868Z] 01:09:50 INFO - GECKO(6034) | #25 0x7fa916a77aaf in PreciseGCRunnable::Run() /builds/worker/checkouts/gecko/js/xpconnect/src/XPCComponents.cpp:1681:16
[task 2021-05-30T01:09:50.888Z] 01:09:50 INFO - GECKO(6034) | #26 0x7fa9150b9e02 in mozilla::RunnableTask::Run() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:482:16
[task 2021-05-30T01:09:50.890Z] 01:09:50 INFO - GECKO(6034) | #27 0x7fa915086a70 in mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:766:26
[task 2021-05-30T01:09:50.890Z] 01:09:50 INFO - GECKO(6034) | #28 0x7fa915084577 in mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:621:15
[task 2021-05-30T01:09:50.891Z] 01:09:50 INFO - GECKO(6034) | #29 0x7fa9150849cd in mozilla::TaskController::ProcessPendingMTTask(bool) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:405:36
[task 2021-05-30T01:09:50.892Z] 01:09:50 INFO - GECKO(6034) | #30 0x7fa9150c40e1 in operator() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:138:37
[task 2021-05-30T01:09:50.893Z] 01:09:50 INFO - GECKO(6034) | #31 0x7fa9150c40e1 in mozilla::detail::RunnableFunction<mozilla::TaskController::InitializeInternal()::$_0>::Run() /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.h:534:5
[task 2021-05-30T01:09:50.893Z] 01:09:50 INFO - GECKO(6034) | #32 0x7fa9150a1378 in nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1159:16
[task 2021-05-30T01:09:50.894Z] 01:09:50 INFO - GECKO(6034) | #33 0x7fa9150ac0bc in NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:548:10
[task 2021-05-30T01:09:50.906Z] 01:09:50 INFO - GECKO(6034) | #34 0x7fa91613289a in mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:85:21
[task 2021-05-30T01:09:50.916Z] 01:09:50 INFO - GECKO(6034) | #35 0x7fa91605d381 in RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:335:10
[task 2021-05-30T01:09:50.916Z] 01:09:50 INFO - GECKO(6034) | #36 0x7fa91605d381 in RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:328:3
[task 2021-05-30T01:09:50.917Z] 01:09:50 INFO - GECKO(6034) | #37 0x7fa91605d381 in MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:310:3
[task 2021-05-30T01:09:50.924Z] 01:09:50 INFO - GECKO(6034) | #38 0x7fa91c05edd7 in nsBaseAppShell::Run() /builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp:137:27
[task 2021-05-30T01:09:50.925Z] 01:09:50 INFO - GECKO(6034) | #39 0x7fa91fda8ce7 in nsAppStartup::Run() /builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp:273:30
[task 2021-05-30T01:09:50.932Z] 01:09:50 INFO - GECKO(6034) | #40 0x7fa91ffad92c in XREMain::XRE_mainRun() /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5244:22
[task 2021-05-30T01:09:50.933Z] 01:09:50 INFO - GECKO(6034) | #41 0x7fa91ffaf98e in XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5442:8
[task 2021-05-30T01:09:50.933Z] 01:09:50 INFO - GECKO(6034) | #42 0x7fa91ffb06e3 in XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5501:21
[task 2021-05-30T01:09:50.934Z] 01:09:50 INFO - GECKO(6034) | #43 0x55eb16d84dcf in do_main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:224:22
[task 2021-05-30T01:09:50.934Z] 01:09:50 INFO - GECKO(6034) | #44 0x55eb16d84dcf in main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:351:16
[task 2021-05-30T01:09:50.935Z] 01:09:50 INFO - GECKO(6034) | #45 0x7fa939532b96 in __libc_start_main /build/glibc-2ORdQG/glibc-2.27/csu/../csu/libc-start.c:310
[task 2021-05-30T01:09:50.935Z] 01:09:50 INFO - GECKO(6034) | ==6034==ABORTING
[task 2021-05-30T01:16:00.951Z] 01:16:00 INFO - Buffered messages finished
[task 2021-05-30T01:16:00.952Z] 01:16:00 ERROR - TEST-UNEXPECTED-TIMEOUT | Last test finished | application timed out after 370 seconds with no output
[task 2021-05-30T01:16:00.952Z] 01:16:00 ERROR - Force-terminating active process(es).
[task 2021-05-30T01:16:00.952Z] 01:16:00 INFO - Determining child pids from psutil...
[task 2021-05-30T01:16:00.959Z] 01:16:00 INFO - []
[task 2021-05-30T01:16:00.959Z] 01:16:00 INFO - ==> process 6034 launched child process 6050
[task 2021-05-30T01:16:00.960Z] 01:16:00 INFO - ==> process 6034 launched child process 6094
[task 2021-05-30T01:16:00.961Z] 01:16:00 INFO - ==> process 6034 launched child process 6115
[task 2021-05-30T01:16:00.961Z] 01:16:00 INFO - ==> process 6034 launched child process 6181
[task 2021-05-30T01:16:00.962Z] 01:16:00 INFO - ==> process 6034 launched child process 6211
[task 2021-05-30T01:16:00.963Z] 01:16:00 INFO - ==> process 6034 launched child process 6216
[task 2021-05-30T01:16:00.963Z] 01:16:00 INFO - ==> process 6034 launched child process 6234
[task 2021-05-30T01:16:00.964Z] 01:16:00 INFO - ==> process 6034 launched child process 6284
[task 2021-05-30T01:16:00.964Z] 01:16:00 INFO - ==> process 6034 launched child process 6289
[task 2021-05-30T01:16:00.965Z] 01:16:00 INFO - Found child pids: {6050, 6211, 6115, 6181, 6216, 6284, 6094, 6289, 6234}
[task 2021-05-30T01:16:00.965Z] 01:16:00 INFO - Failed to get child procs
[task 2021-05-30T01:16:00.966Z] 01:16:00 INFO - Killing process: 6050
[task 2021-05-30T01:16:00.967Z] 01:16:00 INFO - TEST-INFO | started process screentopng
[task 2021-05-30T01:16:01.201Z] 01:16:01 INFO - TEST-INFO | screentopng: exit 0
[task 2021-05-30T01:16:01.202Z] 01:16:01 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-30T01:16:01.203Z] 01:16:01 INFO - Error: Failed to kill process 6050: psutil.NoSuchProcess no process found with pid 6050
[task 2021-05-30T01:16:01.204Z] 01:16:01 INFO - Killing process: 6211
[task 2021-05-30T01:16:01.204Z] 01:16:01 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-30T01:16:01.205Z] 01:16:01 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-30T01:16:01.206Z] 01:16:01 INFO - Error: Failed to kill process 6211: psutil.NoSuchProcess no process found with pid 6211
[task 2021-05-30T01:16:01.207Z] 01:16:01 INFO - Killing process: 6115
[task 2021-05-30T01:16:01.207Z] 01:16:01 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-30T01:16:01.208Z] 01:16:01 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-30T01:16:01.209Z] 01:16:01 INFO - Error: Failed to kill process 6115: psutil.NoSuchProcess no process found with pid 6115
[task 2021-05-30T01:16:01.209Z] 01:16:01 INFO - Killing process: 6181
[task 2021-05-30T01:16:01.211Z] 01:16:01 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-30T01:16:01.211Z] 01:16:01 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-30T01:16:01.212Z] 01:16:01 INFO - Error: Failed to kill process 6181: psutil.NoSuchProcess no process found with pid 6181
[task 2021-05-30T01:16:01.212Z] 01:16:01 INFO - Killing process: 6216
[task 2021-05-30T01:16:01.213Z] 01:16:01 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-30T01:16:01.214Z] 01:16:01 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-30T01:16:31.258Z] 01:16:31 INFO - failed to kill pid 6216 after 30s
[task 2021-05-30T01:16:31.259Z] 01:16:31 INFO - Killing process: 6284
[task 2021-05-30T01:16:31.259Z] 01:16:31 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-30T01:16:31.261Z] 01:16:31 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-30T01:17:01.306Z] 01:17:01 INFO - failed to kill pid 6284 after 30s
[task 2021-05-30T01:17:01.307Z] 01:17:01 INFO - Killing process: 6094
[task 2021-05-30T01:17:01.311Z] 01:17:01 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-30T01:17:01.311Z] 01:17:01 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-30T01:17:01.312Z] 01:17:01 INFO - Error: Failed to kill process 6094: psutil.NoSuchProcess no process found with pid 6094
[task 2021-05-30T01:17:01.315Z] 01:17:01 INFO - Killing process: 6289
[task 2021-05-30T01:17:01.315Z] 01:17:01 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-30T01:17:01.316Z] 01:17:01 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-30T01:17:31.359Z] 01:17:31 INFO - failed to kill pid 6289 after 30s
[task 2021-05-30T01:17:31.360Z] 01:17:31 INFO - Killing process: 6234
[task 2021-05-30T01:17:31.361Z] 01:17:31 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-30T01:17:31.362Z] 01:17:31 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-30T01:18:01.402Z] 01:18:01 INFO - failed to kill pid 6234 after 30s
[task 2021-05-30T01:18:01.404Z] 01:18:01 INFO - Killing process: 6034
[task 2021-05-30T01:18:01.405Z] 01:18:01 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-30T01:18:01.406Z] 01:18:01 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-30T01:18:01.423Z] 01:18:01 INFO - psutil found pid 6034 dead
[task 2021-05-30T01:18:01.423Z] 01:18:01 INFO - psutil found pid 6034 dead
[task 2021-05-30T01:18:01.423Z] 01:18:01 INFO - TEST-INFO | Main app process: exit 0

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

There are 166 total failures in the last 7 days on

  • linux1804-64-asan opt
  • linux1804-64-asan-qr opt

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

Flags: needinfo?(jstutte)

To help to make this actionable, we might want to write the collected annotations that would have been reported to crash-reporter to the log (or somewhere else). This could help to make visible some nested event loop spinning, maybe. Keeping the ni for now.

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

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

To help to make this actionable, we might want to write the collected annotations that would have been reported to crash-reporter to the log (or somewhere else). This could help to make visible some nested event loop spinning, maybe. Keeping the ni for now.

:aryx, is there a way to get the same annotations we see in crash stats here?

Flags: needinfo?(jstutte) → needinfo?(aryx.bugmail)

Does https://treeherder.mozilla.org/logviewer?job_id=343206675&repo=mozilla-central&lineNumber=4395 mean the garbage collection takes too long?

Another log https://treeherder.mozilla.org/logviewer?job_id=343879973&repo=autoland&lineNumber=39807-39808 has many telemetry messages:

[task 2021-06-25T17:56:22.300Z] 17:56:22     INFO - GECKO(10442) | [Child 11474, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:527
[task 2021-06-25T17:56:22.302Z] 17:56:22     INFO - GECKO(10442) | [Child 11474, Main Thread] WARNING: '!ipcActor->SendRecordDiscardedData(discardedData)', file /builds/worker/checkouts/gecko/toolkit/components/telemetry/core/ipc/TelemetryIPCAccumulator.cpp:298

Which might explain the OOM logged later. (There is also a crash stack listed even further down.)

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

There are 28 total failures in the last 7 days on linux1804-64-asan opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=344046186&repo=mozilla-central&lineNumber=7811

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

(In reply to Sebastian Hengst [:aryx] (needinfo on intermittent or backout) from comment #87)

Does https://treeherder.mozilla.org/logviewer?job_id=343206675&repo=mozilla-central&lineNumber=4395 mean the garbage collection takes too long?

No, this is just the stack that reacts at the Quit event which creates the terminator thread that then later will crash due to timeout. The log gives no clue about the running threads in the moment of the timeout at all, which was the reason I asked if we can get the same information we see on other crashes in crash-stats.mozilla.org.

There have been 50 total failures in the last 7 days (recent failure log).
Affected platforms are: linux1804-64-asan-qr

There have been 56 total failures in the last 7 days, recent failure log.
Affected platforms are:

  • linux1804-64-asan-qr
[task 2021-08-13T23:22:00.560Z] 23:22:00     INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_window_postMessage.html
[task 2021-08-13T23:22:00.842Z] 23:22:00     INFO - GECKO(13076) | Console message: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_window_postMessage.html" line: 0}]
[task 2021-08-13T23:22:00.868Z] 23:22:00     INFO - GECKO(13076) | Console message: Warning: attempting to write 12857 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
[task 2021-08-13T23:22:01.583Z] 23:22:01     INFO - GECKO(13076) | MEMORY STAT | vsize 20974573MB | residentFast 859MB
[task 2021-08-13T23:22:01.614Z] 23:22:01     INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_window_postMessage.html | took 1053ms
[task 2021-08-13T23:22:01.759Z] 23:22:01     INFO - TEST-START | Shutdown
[task 2021-08-13T23:22:01.759Z] 23:22:01     INFO - Passed:  3693
[task 2021-08-13T23:22:01.761Z] 23:22:01     INFO - Failed:  0
[task 2021-08-13T23:22:01.762Z] 23:22:01     INFO - Todo:    1
[task 2021-08-13T23:22:01.763Z] 23:22:01     INFO - Mode:    e10s
[task 2021-08-13T23:22:01.771Z] 23:22:01     INFO - Slowest: 86855ms - /tests/toolkit/components/extensions/test/mochitest/test_ext_tabs_permissions.html
[task 2021-08-13T23:22:01.772Z] 23:22:01     INFO - SimpleTest FINISHED
[task 2021-08-13T23:22:01.772Z] 23:22:01     INFO - TEST-INFO | Ran 1 Loops
[task 2021-08-13T23:22:01.772Z] 23:22:01     INFO - SimpleTest FINISHED
[task 2021-08-13T23:22:01.936Z] 23:22:01     INFO - GECKO(13076) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 575: NotFoundError: No such JSWindowActor 'SpecialPowers'
[task 2021-08-13T23:22:02.101Z] 23:22:02     INFO - GECKO(13076) | 1628896922100	Marionette	TRACE	Received observer notification quit-application
[task 2021-08-13T23:22:02.102Z] 23:22:02     INFO - GECKO(13076) | 1628896922101	Marionette	INFO	Stopped listening on port 2828
[task 2021-08-13T23:22:02.104Z] 23:22:02     INFO - GECKO(13076) | 1628896922103	Marionette	DEBUG	Marionette stopped listening
[task 2021-08-13T23:22:02.273Z] 23:22:02     INFO - GECKO(13076) | JavaScript error: resource:///modules/Interactions.jsm, line 230: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIUserIdleService.removeIdleObserver]
[task 2021-08-13T23:22:02.360Z] 23:22:02     INFO - GECKO(13076) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-08-13T23:22:02.458Z] 23:22:02     INFO - GECKO(13076) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-08-13T23:22:02.461Z] 23:22:02     INFO - GECKO(13076) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-08-13T23:22:04.577Z] 23:22:04     INFO - GECKO(13076) | *** WIFI GEO: shutdown called
[task 2021-08-13T23:22:05.876Z] 23:22:05     INFO - GECKO(13076) | -----------------------------------------------------
[task 2021-08-13T23:22:05.878Z] 23:22:05     INFO - GECKO(13076) | Suppressions used:
[task 2021-08-13T23:22:05.879Z] 23:22:05     INFO - GECKO(13076) |   count      bytes template
[task 2021-08-13T23:22:05.879Z] 23:22:05     INFO - GECKO(13076) |      13        416 nsComponentManagerImpl
[task 2021-08-13T23:22:05.880Z] 23:22:05     INFO - GECKO(13076) |       2        288 libfontconfig.so
[task 2021-08-13T23:22:05.881Z] 23:22:05     INFO - GECKO(13076) | -----------------------------------------------------
[task 2021-08-13T23:22:05.924Z] 23:22:05     INFO - GECKO(13076) | -----------------------------------------------------
[task 2021-08-13T23:22:05.925Z] 23:22:05     INFO - GECKO(13076) | Suppressions used:
[task 2021-08-13T23:22:05.926Z] 23:22:05     INFO - GECKO(13076) |   count      bytes template
[task 2021-08-13T23:22:05.926Z] 23:22:05     INFO - GECKO(13076) |      13        416 nsComponentManagerImpl
[task 2021-08-13T23:22:05.927Z] 23:22:05     INFO - GECKO(13076) |       2        288 libfontconfig.so
[task 2021-08-13T23:22:05.928Z] 23:22:05     INFO - GECKO(13076) | -----------------------------------------------------
[task 2021-08-13T23:22:06.033Z] 23:22:06     INFO - GECKO(13076) | -----------------------------------------------------
[task 2021-08-13T23:22:06.035Z] 23:22:06     INFO - GECKO(13076) | Suppressions used:
[task 2021-08-13T23:22:06.036Z] 23:22:06     INFO - GECKO(13076) |   count      bytes template
[task 2021-08-13T23:22:06.036Z] 23:22:06     INFO - GECKO(13076) |      13        416 nsComponentManagerImpl
[task 2021-08-13T23:22:06.037Z] 23:22:06     INFO - GECKO(13076) |       2        288 libfontconfig.so
[task 2021-08-13T23:22:06.038Z] 23:22:06     INFO - GECKO(13076) | -----------------------------------------------------
[task 2021-08-13T23:22:06.493Z] 23:22:06     INFO - GECKO(13076) | -----------------------------------------------------
[task 2021-08-13T23:22:06.494Z] 23:22:06     INFO - GECKO(13076) | Suppressions used:
[task 2021-08-13T23:22:06.495Z] 23:22:06     INFO - GECKO(13076) |   count      bytes template
[task 2021-08-13T23:22:06.496Z] 23:22:06     INFO - GECKO(13076) |      16        504 nsComponentManagerImpl
[task 2021-08-13T23:22:06.497Z] 23:22:06     INFO - GECKO(13076) |       2        288 libfontconfig.so
[task 2021-08-13T23:22:06.497Z] 23:22:06     INFO - GECKO(13076) | -----------------------------------------------------
[task 2021-08-13T23:22:06.754Z] 23:22:06     INFO - GECKO(13076) | -----------------------------------------------------
[task 2021-08-13T23:22:06.755Z] 23:22:06     INFO - GECKO(13076) | Suppressions used:
[task 2021-08-13T23:22:06.756Z] 23:22:06     INFO - GECKO(13076) |   count      bytes template
[task 2021-08-13T23:22:06.756Z] 23:22:06     INFO - GECKO(13076) |      16        504 nsComponentManagerImpl
[task 2021-08-13T23:22:06.757Z] 23:22:06     INFO - GECKO(13076) |       2        288 libfontconfig.so
[task 2021-08-13T23:22:06.758Z] 23:22:06     INFO - GECKO(13076) | -----------------------------------------------------
[task 2021-08-13T23:27:08.920Z] 23:27:08     INFO - GECKO(13076) | AddressSanitizer:DEADLYSIGNAL
[task 2021-08-13T23:27:08.921Z] 23:27:08     INFO - GECKO(13076) | =================================================================
[task 2021-08-13T23:27:08.921Z] 23:27:08    ERROR - GECKO(13076) | ==13076==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000001 (pc 0x7fcdf70b105c bp 0x7fcdc3b4ee10 sp 0x7fcdc3b4ed60 T254)
[task 2021-08-13T23:27:08.923Z] 23:27:08     INFO - GECKO(13076) | ==13076==The signal is caused by a WRITE memory access.
[task 2021-08-13T23:27:08.925Z] 23:27:08     INFO - GECKO(13076) | ==13076==Hint: address points to the zero page.
[task 2021-08-13T23:27:11.777Z] 23:27:11     INFO - GECKO(13076) |     #0 0x7fcdf70b105c in mozilla::(anonymous namespace)::RunWatchdog(void*) /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:246:5
[task 2021-08-13T23:27:11.783Z] 23:27:11     INFO - GECKO(13076) |     #1 0x7fce0d5d770e in _pt_root /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:201:5
[task 2021-08-13T23:27:11.810Z] 23:27:11     INFO - GECKO(13076) |     #2 0x7fce112956da in start_thread /tmp/glibc/nptl/pthread_create.c:463
[task 2021-08-13T23:27:11.894Z] 23:27:11     INFO - GECKO(13076) |     #3 0x7fce10273a3e in clone /tmp/glibc/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:95
[task 2021-08-13T23:27:11.896Z] 23:27:11     INFO - GECKO(13076) | AddressSanitizer can not provide additional info.
[task 2021-08-13T23:27:11.899Z] 23:27:11     INFO - GECKO(13076) | SUMMARY: AddressSanitizer: SEGV /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:246:5 in mozilla::(anonymous namespace)::RunWatchdog(void*)
[task 2021-08-13T23:27:11.900Z] 23:27:11     INFO - GECKO(13076) | Thread T254 (Shutdow~minator) created by T0 here:
[task 2021-08-13T23:27:11.936Z] 23:27:11     INFO - GECKO(13076) |     #0 0x563d6c0ffb5c in pthread_create /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/asan/asan_interceptors.cpp:205:3
[task 2021-08-13T23:27:11.939Z] 23:27:11     INFO - GECKO(13076) |     #1 0x7fce0d5c7784 in _PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:458:14
[task 2021-08-13T23:27:11.941Z] 23:27:11     INFO - GECKO(13076) |     #2 0x7fce0d5b8c5e in PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:533:12
[task 2021-08-13T23:27:11.945Z] 23:27:11     INFO - GECKO(13076) |     #3 0x7fcdf70b08b2 in CreateSystemThread /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:116:7
[task 2021-08-13T23:27:11.946Z] 23:27:11     INFO - GECKO(13076) |     #4 0x7fcdf70b08b2 in mozilla::nsTerminator::StartWatchdog() /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:469:7
[task 2021-08-13T23:27:11.950Z] 23:27:11     INFO - GECKO(13076) |     #5 0x7fcdf70b0b9b in Start /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:383:3
[task 2021-08-13T23:27:11.951Z] 23:27:11     INFO - GECKO(13076) |     #6 0x7fcdf70b0b9b in mozilla::nsTerminator::AdvancePhase(mozilla::ShutdownPhase) /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:517:5
[task 2021-08-13T23:27:11.974Z] 23:27:11     INFO - GECKO(13076) |     #7 0x7fcdebf65be1 in mozilla::AdvanceShutdownPhaseInternal(mozilla::ShutdownPhase, bool, char16_t const*, nsCOMPtr<nsISupports> const&) /builds/worker/checkouts/gecko/xpcom/base/AppShutdown.cpp:316:18
[task 2021-08-13T23:27:11.981Z] 23:27:11     INFO - GECKO(13076) |     #8 0x7fcdf6efc707 in nsAppStartup::Quit(unsigned int, int, bool*) /builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp:448:5
[task 2021-08-13T23:27:11.986Z] 23:27:11     INFO - GECKO(13076) |     #9 0x7fcdec1db101 in NS_InvokeByIndex /builds/worker/checkouts/gecko/xpcom/reflect/xptcall/md/unix/xptcinvoke_asm_x86_64_unix.S:101
[task 2021-08-13T23:27:12.009Z] 23:27:12     INFO - GECKO(13076) |     #10 0x7fcdedc423f9 in Invoke /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1631:10
[task 2021-08-13T23:27:12.009Z] 23:27:12     INFO - GECKO(13076) |     #11 0x7fcdedc423f9 in Call /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1184:19
[task 2021-08-13T23:27:12.011Z] 23:27:12     INFO - GECKO(13076) |     #12 0x7fcdedc423f9 in XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1130:23
[task 2021-08-13T23:27:12.013Z] 23:27:12     INFO - GECKO(13076) |     #13 0x7fcdedc46e3f in XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNativeJSOps.cpp:921:10
[task 2021-08-13T23:27:12.039Z] 23:27:12     INFO - GECKO(13076) |     #14 0x7fcdf7340ec2 in CallJSNative /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:402:13
[task 2021-08-13T23:27:12.040Z] 23:27:12     INFO - GECKO(13076) |     #15 0x7fcdf7340ec2 in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:489:12
[task 2021-08-13T23:27:12.078Z] 23:27:12     INFO - GECKO(13076) |     #16 0x7fcdf810d720 in js::jit::DoCallFallback(JSContext*, js::jit::BaselineFrame*, js::jit::ICFallbackStub*, unsigned int, JS::Value*, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/js/src/jit/BaselineIC.cpp:1587:10
[task 2021-08-13T23:27:12.107Z] 23:27:12     INFO - GECKO(13076) |     #17 0x3c3a5334ee47  (<unknown module>)
[task 2021-08-13T23:27:12.132Z] 23:27:12     INFO - GECKO(13076) |     #18 0x62900168bc87  (<unknown module>)
[task 2021-08-13T23:27:12.181Z] 23:27:12     INFO - GECKO(13076) |     #19 0x3c3a5334c56e  (<unknown module>)
[task 2021-08-13T23:27:12.191Z] 23:27:12     INFO - GECKO(13076) |     #20 0x7fcdf84de77b in EnterJit /builds/worker/checkouts/gecko/js/src/jit/Jit.cpp:112:5
[task 2021-08-13T23:27:12.193Z] 23:27:12     INFO - GECKO(13076) |     #21 0x7fcdf84de77b in js::jit::MaybeEnterJit(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/jit/Jit.cpp:210:10
[task 2021-08-13T23:27:12.196Z] 23:27:12     INFO - GECKO(13076) |     #22 0x7fcdf73123fb in js::RunScript(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:361:32
[task 2021-08-13T23:27:12.198Z] 23:27:12     INFO - GECKO(13076) |     #23 0x7fcdf7340ffb in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:521:13
[task 2021-08-13T23:27:12.200Z] 23:27:12     INFO - GECKO(13076) |     #24 0x7fcdf7342bfb in js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:566:8
[task 2021-08-13T23:27:12.216Z] 23:27:12     INFO - GECKO(13076) |     #25 0x7fcdf758d135 in JS::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/js/src/vm/CallAndConstruct.cpp:117:10
[task 2021-08-13T23:27:12.290Z] 23:27:12     INFO - GECKO(13076) |     #26 0x7fcdef743444 in mozilla::dom::MessageListener::ReceiveMessage(mozilla::dom::BindingCallContext&, JS::Handle<JS::Value>, mozilla::dom::ReceiveMessageArgument const&, JS::MutableHandle<JS::Value>, mozilla::ErrorResult&) /builds/worker/workspace/obj-build/dom/bindings/MessageManagerBinding.cpp:6099:8
[task 2021-08-13T23:27:12.304Z] 23:27:12     INFO - GECKO(13076) |     #27 0x7fcdf2aecca8 in mozilla::dom::MessageListener::ReceiveMessage(mozilla::dom::ReceiveMessageArgument const&, JS::MutableHandle<JS::Value>, mozilla::ErrorResult&, char const*, mozilla::dom::CallbackObject::ExceptionHandling, JS::Realm*) /builds/worker/workspace/obj-build/dist/include/mozilla/dom/MessageManagerBinding.h:782:12
[task 2021-08-13T23:27:12.306Z] 23:27:12     INFO - GECKO(13076) |     #28 0x7fcdf2aec874 in mozilla::dom::JSActor::CallReceiveMessage(JSContext*, mozilla::dom::JSActorMessageMeta const&, JS::Handle<JS::Value>, JS::MutableHandle<JS::Value>, mozilla::ErrorResult&) /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSActor.cpp:271:22
[task 2021-08-13T23:27:12.309Z] 23:27:12     INFO - GECKO(13076) |     #29 0x7fcdf2aecf2f in mozilla::dom::JSActor::ReceiveMessage(JSContext*, mozilla::dom::JSActorMessageMeta const&, JS::Handle<JS::Value>, mozilla::ErrorResult&) /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSActor.cpp:284:3
[task 2021-08-13T23:27:12.311Z] 23:27:12     INFO - GECKO(13076) |     #30 0x7fcdf2af2a6a in mozilla::dom::JSActorManager::ReceiveRawMessage(mozilla::dom::JSActorMessageMeta const&, mozilla::Maybe<mozilla::dom::ipc::StructuredCloneData>&&, mozilla::Maybe<mozilla::dom::ipc::StructuredCloneData>&&) /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSActorManager.cpp:194:14
[task 2021-08-13T23:27:12.334Z] 23:27:12     INFO - GECKO(13076) |     #31 0x7fcdf2ace2f3 in mozilla::dom::WindowGlobalParent::RecvRawMessage(mozilla::dom::JSActorMessageMeta const&, mozilla::Maybe<mozilla::dom::ClonedMessageData> const&, mozilla::Maybe<mozilla::dom::ClonedMessageData> const&) /builds/worker/checkouts/gecko/dom/ipc/WindowGlobalParent.cpp:524:3
[task 2021-08-13T23:27:12.363Z] 23:27:12     INFO - GECKO(13076) |     #32 0x7fcded94857c in mozilla::dom::PWindowGlobalParent::OnMessageReceived(IPC::Message const&) /builds/worker/workspace/obj-build/ipc/ipdl/PWindowGlobalParent.cpp:852:62
[task 2021-08-13T23:27:12.447Z] 23:27:12     INFO - GECKO(13076) |     #33 0x7fcded4a7109 in mozilla::dom::PContentParent::OnMessageReceived(IPC::Message const&) /builds/worker/workspace/obj-build/ipc/ipdl/PContentParent.cpp:6576:32
[task 2021-08-13T23:27:12.479Z] 23:27:12     INFO - GECKO(13076) |     #34 0x7fcded293366 in mozilla::ipc::MessageChannel::DispatchAsyncMessage(mozilla::ipc::ActorLifecycleProxy*, IPC::Message const&) /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:2051:25
[task 2021-08-13T23:27:12.482Z] 23:27:12     INFO - GECKO(13076) |     #35 0x7fcded290e6c in mozilla::ipc::MessageChannel::DispatchMessage(IPC::Message&&) /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1978:9
[task 2021-08-13T23:27:12.484Z] 23:27:12     INFO - GECKO(13076) |     #36 0x7fcded29216b in mozilla::ipc::MessageChannel::RunMessage(mozilla::ipc::MessageChannel::MessageTask&) /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1826:3
[task 2021-08-13T23:27:12.487Z] 23:27:12     INFO - GECKO(13076) |     #37 0x7fcded2927fb in mozilla::ipc::MessageChannel::MessageTask::Run() /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1857:13
[task 2021-08-13T23:27:12.521Z] 23:27:12     INFO - GECKO(13076) |     #38 0x7fcdec1a7eb2 in mozilla::RunnableTask::Run() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:502:16
[task 2021-08-13T23:27:12.524Z] 23:27:12     INFO - GECKO(13076) |     #39 0x7fcdec174b23 in mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:805:26
[task 2021-08-13T23:27:12.526Z] 23:27:12     INFO - GECKO(13076) |     #40 0x7fcdec172388 in mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:641:15
[task 2021-08-13T23:27:12.528Z] 23:27:12     INFO - GECKO(13076) |     #41 0x7fcdec172a9d in mozilla::TaskController::ProcessPendingMTTask(bool) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:425:36
[task 2021-08-13T23:27:12.532Z] 23:27:12     INFO - GECKO(13076) |     #42 0x7fcdec1b2171 in operator() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:135:37
[task 2021-08-13T23:27:12.533Z] 23:27:12     INFO - GECKO(13076) |     #43 0x7fcdec1b2171 in mozilla::detail::RunnableFunction<mozilla::TaskController::InitializeInternal()::$_0>::Run() /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.h:532:5
[task 2021-08-13T23:27:12.535Z] 23:27:12     INFO - GECKO(13076) |     #44 0x7fcdec18f627 in nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1148:16
[task 2021-08-13T23:27:12.536Z] 23:27:12     INFO - GECKO(13076) |     #45 0x7fcdec19a19c in NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:466:10
[task 2021-08-13T23:27:12.537Z] 23:27:12     INFO - GECKO(13076) |     #46 0x7fcded299fea in mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:85:21
[task 2021-08-13T23:27:12.557Z] 23:27:12     INFO - GECKO(13076) |     #47 0x7fcded1a7141 in RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:331:10
[task 2021-08-13T23:27:12.559Z] 23:27:12     INFO - GECKO(13076) |     #48 0x7fcded1a7141 in RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:324:3
[task 2021-08-13T23:27:12.561Z] 23:27:12     INFO - GECKO(13076) |     #49 0x7fcded1a7141 in MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:306:3
[task 2021-08-13T23:27:12.575Z] 23:27:12     INFO - GECKO(13076) |     #50 0x7fcdf322bb57 in nsBaseAppShell::Run() /builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp:137:27
[task 2021-08-13T23:27:12.577Z] 23:27:12     INFO - GECKO(13076) |     #51 0x7fcdf6efb6d7 in nsAppStartup::Run() /builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp:274:30
[task 2021-08-13T23:27:12.597Z] 23:27:12     INFO - GECKO(13076) |     #52 0x7fcdf7101e7d in XREMain::XRE_mainRun() /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5287:22
[task 2021-08-13T23:27:12.600Z] 23:27:12     INFO - GECKO(13076) |     #53 0x7fcdf7103f2e in XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5479:8
[task 2021-08-13T23:27:12.602Z] 23:27:12     INFO - GECKO(13076) |     #54 0x7fcdf7104c83 in XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5538:21
[task 2021-08-13T23:27:12.605Z] 23:27:12     INFO - GECKO(13076) |     #55 0x563d6c149a2f in do_main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:225:22
[task 2021-08-13T23:27:12.606Z] 23:27:12     INFO - GECKO(13076) |     #56 0x563d6c149a2f in main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:378:16
[task 2021-08-13T23:27:12.608Z] 23:27:12     INFO - GECKO(13076) |     #57 0x7fce10173b96 in __libc_start_main /tmp/glibc/csu/../csu/libc-start.c:310
[task 2021-08-13T23:27:12.614Z] 23:27:12     INFO - GECKO(13076) | ==13076==ABORTING
[task 2021-08-13T23:29:12.329Z] 23:29:12     INFO - GECKO(13076) | out of memory: 0x0000000019300000 bytes requested
[task 2021-08-13T23:29:12.329Z] 23:29:12     INFO - GECKO(13076) | AddressSanitizer:DEADLYSIGNAL
[task 2021-08-13T23:29:12.329Z] 23:29:12     INFO - GECKO(13076) | =================================================================
[task 2021-08-13T23:29:12.329Z] 23:29:12    ERROR - GECKO(13076) | ==15978==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000001 (pc 0x55c98dbe7648 bp 0x7ffe8d40ca50 sp 0x7ffe8d40ca40 T0)
[task 2021-08-13T23:29:12.330Z] 23:29:12     INFO - GECKO(13076) | ==15978==The signal is caused by a WRITE memory access.
[task 2021-08-13T23:29:12.330Z] 23:29:12     INFO - GECKO(13076) | ==15978==Hint: address points to the zero page.
[task 2021-08-13T23:29:12.424Z] 23:29:12     INFO - GECKO(13076) | ==15978==WARNING: failed to fork (errno 12)
[task 2021-08-13T23:29:12.448Z] 23:29:12     INFO - GECKO(13076) | ==15978==WARNING: failed to fork (errno 12)
[task 2021-08-13T23:29:12.466Z] 23:29:12     INFO - GECKO(13076) | ==15978==WARNING: failed to fork (errno 12)
[task 2021-08-13T23:29:12.483Z] 23:29:12     INFO - GECKO(13076) | ==15978==WARNING: failed to fork (errno 12)
[task 2021-08-13T23:29:12.504Z] 23:29:12     INFO - GECKO(13076) | ==15978==WARNING: failed to fork (errno 12)
[task 2021-08-13T23:29:12.510Z] 23:29:12     INFO - GECKO(13076) | ==15978==WARNING: Failed to use and restart external symbolizer!
[task 2021-08-13T23:29:12.511Z] 23:29:12     INFO - GECKO(13076) |     #0 0x55c98dbe7648  (/builds/worker/workspace/build/application/firefox/firefox+0x10b648)
[task 2021-08-13T23:29:12.511Z] 23:29:12     INFO - GECKO(13076) |     #1 0x55c98dbe77dd  (/builds/worker/workspace/build/application/firefox/firefox+0x10b7dd)
[task 2021-08-13T23:29:12.511Z] 23:29:12     INFO - GECKO(13076) |     #2 0x55c98dbe7d0b  (/builds/worker/workspace/build/application/firefox/firefox+0x10bd0b)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #3 0x7f614770e043  (/builds/worker/workspace/build/application/firefox/libxul.so+0x346f043)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #4 0x7f61483d96de  (/builds/worker/workspace/build/application/firefox/libxul.so+0x413a6de)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #5 0x7f61483cbd9a  (/builds/worker/workspace/build/application/firefox/libxul.so+0x412cd9a)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #6 0x7f6148509791  (/builds/worker/workspace/build/application/firefox/libxul.so+0x426a791)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #7 0x7f6148547b7f  (/builds/worker/workspace/build/application/firefox/libxul.so+0x42a8b7f)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #8 0x7f61479a7eb2  (/builds/worker/workspace/build/application/firefox/libxul.so+0x3708eb2)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #9 0x7f6147974b23  (/builds/worker/workspace/build/application/firefox/libxul.so+0x36d5b23)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #10 0x7f6147972388  (/builds/worker/workspace/build/application/firefox/libxul.so+0x36d3388)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #11 0x7f6147972a9d  (/builds/worker/workspace/build/application/firefox/libxul.so+0x36d3a9d)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #12 0x7f61479b2171  (/builds/worker/workspace/build/application/firefox/libxul.so+0x3713171)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #13 0x7f614798f627  (/builds/worker/workspace/build/application/firefox/libxul.so+0x36f0627)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #14 0x7f614799a19c  (/builds/worker/workspace/build/application/firefox/libxul.so+0x36fb19c)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #15 0x7f6148a99fea  (/builds/worker/workspace/build/application/firefox/libxul.so+0x47fafea)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #16 0x7f61489a7141  (/builds/worker/workspace/build/application/firefox/libxul.so+0x4708141)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #17 0x7f614ea2bb57  (/builds/worker/workspace/build/application/firefox/libxul.so+0xa78cb57)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #18 0x7f615290a06f  (/builds/worker/workspace/build/application/firefox/libxul.so+0xe66b06f)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #19 0x7f61489a7141  (/builds/worker/workspace/build/application/firefox/libxul.so+0x4708141)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #20 0x7f6152909a44  (/builds/worker/workspace/build/application/firefox/libxul.so+0xe66aa44)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #21 0x55c98dbe108d  (/builds/worker/workspace/build/application/firefox/firefox+0x10508d)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #22 0x55c98dbe14b1  (/builds/worker/workspace/build/application/firefox/firefox+0x1054b1)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #23 0x7f616b8abb96  (/lib/x86_64-linux-gnu/libc.so.6+0x21b96)
[task 2021-08-13T23:29:12.513Z] 23:29:12     INFO - GECKO(13076) |     #24 0x55c98db3274c  (/builds/worker/workspace/build/application/firefox/firefox+0x5674c)
[task 2021-08-13T23:29:12.514Z] 23:29:12     INFO - GECKO(13076) | AddressSanitizer can not provide additional info.
[task 2021-08-13T23:29:12.514Z] 23:29:12     INFO - GECKO(13076) | SUMMARY: AddressSanitizer: SEGV (/builds/worker/workspace/build/application/firefox/firefox+0x10b648)
[task 2021-08-13T23:29:12.514Z] 23:29:12     INFO - GECKO(13076) | ==15978==ABORTING
[task 2021-08-13T23:29:12.848Z] 23:29:12     INFO - TEST-INFO | Main app process: exit 0
[task 2021-08-13T23:29:12.852Z] 23:29:12     INFO - runtests.py | Application ran for: 0:15:17.574770
[task 2021-08-13T23:29:12.855Z] 23:29:12     INFO - zombiecheck | Reading PID log: /tmp/tmp5h6h5yr1pidlog
[task 2021-08-13T23:29:12.859Z] 23:29:12     INFO - ==> process 13076 launched child process 13092
[task 2021-08-13T23:29:12.866Z] 23:29:12     INFO - ==> process 13076 launched child process 13152
[task 2021-08-13T23:29:12.867Z] 23:29:12     INFO - ==> process 13076 launched child process 13186
[task 2021-08-13T23:29:12.867Z] 23:29:12     INFO - ==> process 13076 launched child process 13188
[task 2021-08-13T23:29:12.868Z] 23:29:12     INFO - ==> process 13076 launched child process 13227
[task 2021-08-13T23:29:12.869Z] 23:29:12     INFO - ==> process 13076 launched child process 13254
[task 2021-08-13T23:29:12.869Z] 23:29:12     INFO - ==> process 13076 launched child process 13258
[task 2021-08-13T23:29:12.870Z] 23:29:12     INFO - ==> process 13076 launched child process 13311
[task 2021-08-13T23:29:12.870Z] 23:29:12     INFO - ==> process 13076 launched child process 13325
[task 2021-08-13T23:29:12.871Z] 23:29:12     INFO - ==> process 13076 launched child process 13364
[task 2021-08-13T23:29:12.874Z] 23:29:12     INFO - ==> process 13076 launched child process 13393
[task 2021-08-13T23:29:12.874Z] 23:29:12     INFO - ==> process 13076 launched child process 13397
[task 2021-08-13T23:29:12.875Z] 23:29:12     INFO - ==> process 13076 launched child process 13444
[task 2021-08-13T23:29:12.875Z] 23:29:12     INFO - ==> process 13076 launched child process 13470
[task 2021-08-13T23:29:12.876Z] 23:29:12     INFO - ==> process 13076 launched child process 13518
[task 2021-08-13T23:29:12.876Z] 23:29:12     INFO - ==> process 13076 launched child process 13524
[task 2021-08-13T23:29:12.876Z] 23:29:12     INFO - ==> process 13076 launched child process 13578
[task 2021-08-13T23:29:12.876Z] 23:29:12     INFO - ==> process 13076 launched child process 13585
[task 2021-08-13T23:29:12.877Z] 23:29:12     INFO - ==> process 13076 launched child process 13591
[task 2021-08-13T23:29:12.877Z] 23:29:12     INFO - ==> process 13076 launched child process 13641
[task 2021-08-13T23:29:12.877Z] 23:29:12     INFO - ==> process 13076 launched child process 13672
[task 2021-08-13T23:29:12.878Z] 23:29:12     INFO - ==> process 13076 launched child process 13696
[task 2021-08-13T23:29:12.878Z] 23:29:12     INFO - ==> process 13076 launched child process 13703
[task 2021-08-13T23:29:12.879Z] 23:29:12     INFO - ==> process 13076 launched child process 13743
[task 2021-08-13T23:29:12.879Z] 23:29:12     INFO - ==> process 13076 launched child process 13750
[task 2021-08-13T23:29:12.879Z] 23:29:12     INFO - ==> process 13076 launched child process 13796
[task 2021-08-13T23:29:12.879Z] 23:29:12     INFO - ==> process 13076 launched child process 13800
[task 2021-08-13T23:29:12.879Z] 23:29:12     INFO - ==> process 13076 launched child process 13845
[task 2021-08-13T23:29:12.879Z] 23:29:12     INFO - ==> process 13076 launched child process 13851
[task 2021-08-13T23:29:12.879Z] 23:29:12     INFO - ==> process 13076 launched child process 13905
[task 2021-08-13T23:29:12.879Z] 23:29:12     INFO - ==> process 13076 launched child process 13910
[task 2021-08-13T23:29:12.880Z] 23:29:12     INFO - ==> process 13076 launched child process 13953
[task 2021-08-13T23:29:12.880Z] 23:29:12     INFO - ==> process 13076 launched child process 13983
[task 2021-08-13T23:29:12.880Z] 23:29:12     INFO - ==> process 13076 launched child process 14008
[task 2021-08-13T23:29:12.880Z] 23:29:12     INFO - ==> process 13076 launched child process 14011
[task 2021-08-13T23:29:12.880Z] 23:29:12     INFO - ==> process 13076 launched child process 14064
[task 2021-08-13T23:29:12.881Z] 23:29:12     INFO - ==> process 13076 launched child process 14085
[task 2021-08-13T23:29:12.881Z] 23:29:12     INFO - ==> process 13076 launched child process 14124
[task 2021-08-13T23:29:12.881Z] 23:29:12     INFO - ==> process 13076 launched child process 14148
[task 2021-08-13T23:29:12.882Z] 23:29:12     INFO - ==> process 13076 launched child process 14152
[task 2021-08-13T23:29:12.882Z] 23:29:12     INFO - ==> process 13076 launched child process 14203
[task 2021-08-13T23:29:12.883Z] 23:29:12     INFO - ==> process 13076 launched child process 14234
[task 2021-08-13T23:29:12.883Z] 23:29:12     INFO - ==> process 13076 launched child process 14262
[task 2021-08-13T23:29:12.884Z] 23:29:12     INFO - ==> process 13076 launched child process 14297
[task 2021-08-13T23:29:12.884Z] 23:29:12     INFO - ==> process 13076 launched child process 14323
[task 2021-08-13T23:29:12.885Z] 23:29:12     INFO - ==> process 13076 launched child process 14348
[task 2021-08-13T23:29:12.885Z] 23:29:12     INFO - ==> process 13076 launched child process 14370
[task 2021-08-13T23:29:12.886Z] 23:29:12     INFO - ==> process 13076 launched child process 14406
[task 2021-08-13T23:29:12.887Z] 23:29:12     INFO - ==> process 13076 launched child process 14407
[task 2021-08-13T23:29:12.894Z] 23:29:12     INFO - ==> process 13076 launched child process 14443
[task 2021-08-13T23:29:12.895Z] 23:29:12     INFO - ==> process 13076 launched child process 14470
[task 2021-08-13T23:29:12.895Z] 23:29:12     INFO - ==> process 13076 launched child process 14487
[task 2021-08-13T23:29:12.896Z] 23:29:12     INFO - ==> process 13076 launched child process 14522
[task 2021-08-13T23:29:12.896Z] 23:29:12     INFO - ==> process 13076 launched child process 14523
[task 2021-08-13T23:29:12.897Z] 23:29:12     INFO - ==> process 13076 launched child process 14583
[task 2021-08-13T23:29:12.898Z] 23:29:12     INFO - ==> process 13076 launched child process 14585
[task 2021-08-13T23:29:12.898Z] 23:29:12     INFO - ==> process 13076 launched child process 14627
[task 2021-08-13T23:29:12.899Z] 23:29:12     INFO - ==> process 13076 launched child process 14638
[task 2021-08-13T23:29:12.900Z] 23:29:12     INFO - ==> process 13076 launched child process 14680
[task 2021-08-13T23:29:12.900Z] 23:29:12     INFO - ==> process 13076 launched child process 14695
[task 2021-08-13T23:29:12.901Z] 23:29:12     INFO - ==> process 13076 launched child process 14699
[task 2021-08-13T23:29:12.902Z] 23:29:12     INFO - ==> process 13076 launched child process 14714
[task 2021-08-13T23:29:12.902Z] 23:29:12     INFO - ==> process 13076 launched child process 14776
[task 2021-08-13T23:29:12.903Z] 23:29:12     INFO - ==> process 13076 launched child process 14784
[task 2021-08-13T23:29:12.904Z] 23:29:12     INFO - ==> process 13076 launched child process 14820
[task 2021-08-13T23:29:12.904Z] 23:29:12     INFO - ==> process 13076 launched child process 14838
[task 2021-08-13T23:29:12.905Z] 23:29:12     INFO - ==> process 13076 launched child process 14868
[task 2021-08-13T23:29:12.905Z] 23:29:12     INFO - ==> process 13076 launched child process 14876
[task 2021-08-13T23:29:12.906Z] 23:29:12     INFO - ==> process 13076 launched child process 14911
[task 2021-08-13T23:29:12.909Z] 23:29:12     INFO - ==> process 13076 launched child process 14930
[task 2021-08-13T23:29:12.909Z] 23:29:12     INFO - ==> process 13076 launched child process 14959
[task 2021-08-13T23:29:12.909Z] 23:29:12     INFO - ==> process 13076 launched child process 14998
[task 2021-08-13T23:29:12.910Z] 23:29:12     INFO - ==> process 13076 launched child process 15016
[task 2021-08-13T23:29:12.911Z] 23:29:12     INFO - ==> process 13076 launched child process 15017
[task 2021-08-13T23:29:12.912Z] 23:29:12     INFO - ==> process 13076 launched child process 15019
[task 2021-08-13T23:29:12.912Z] 23:29:12     INFO - ==> process 13076 launched child process 15068
[task 2021-08-13T23:29:12.913Z] 23:29:12     INFO - ==> process 13076 launched child process 15098
[task 2021-08-13T23:29:12.913Z] 23:29:12     INFO - ==> process 13076 launched child process 15127
[task 2021-08-13T23:29:12.914Z] 23:29:12     INFO - ==> process 13076 launched child process 15128
[task 2021-08-13T23:29:12.914Z] 23:29:12     INFO - ==> process 13076 launched child process 15176
[task 2021-08-13T23:29:12.915Z] 23:29:12     INFO - ==> process 13076 launched child process 15187
[task 2021-08-13T23:29:12.916Z] 23:29:12     INFO - ==> process 13076 launched child process 15242
[task 2021-08-13T23:29:12.916Z] 23:29:12     INFO - ==> process 13076 launched child process 15248
[task 2021-08-13T23:29:12.918Z] 23:29:12     INFO - ==> process 13076 launched child process 15261
[task 2021-08-13T23:29:12.919Z] 23:29:12     INFO - ==> process 13076 launched child process 15272
[task 2021-08-13T23:29:12.919Z] 23:29:12     INFO - ==> process 13076 launched child process 15323
[task 2021-08-13T23:29:12.920Z] 23:29:12     INFO - ==> process 13076 launched child process 15357
[task 2021-08-13T23:29:12.920Z] 23:29:12     INFO - ==> process 13076 launched child process 15364
[task 2021-08-13T23:29:12.921Z] 23:29:12     INFO - ==> process 13076 launched child process 15383
[task 2021-08-13T23:29:12.922Z] 23:29:12     INFO - ==> process 13076 launched child process 15419
[task 2021-08-13T23:29:12.925Z] 23:29:12     INFO - ==> process 13076 launched child process 15420
[task 2021-08-13T23:29:12.926Z] 23:29:12     INFO - ==> process 13076 launched child process 15467
[task 2021-08-13T23:29:12.926Z] 23:29:12     INFO - ==> process 13076 launched child process 15498
[task 2021-08-13T23:29:12.927Z] 23:29:12     INFO - ==> process 13076 launched child process 15515
[task 2021-08-13T23:29:12.927Z] 23:29:12     INFO - ==> process 13076 launched child process 15517
[task 2021-08-13T23:29:12.928Z] 23:29:12     INFO - ==> process 13076 launched child process 15563
[task 2021-08-13T23:29:12.929Z] 23:29:12     INFO - ==> process 13076 launched child process 15596
[task 2021-08-13T23:29:12.929Z] 23:29:12     INFO - ==> process 13076 launched child process 15611
[task 2021-08-13T23:29:12.930Z] 23:29:12     INFO - ==> process 13076 launched child process 15616
[task 2021-08-13T23:29:12.931Z] 23:29:12     INFO - ==> process 13076 launched child process 15644
[task 2021-08-13T23:29:12.931Z] 23:29:12     INFO - ==> process 13076 launched child process 15670
[task 2021-08-13T23:29:12.932Z] 23:29:12     INFO - ==> process 13076 launched child process 15708
[task 2021-08-13T23:29:12.932Z] 23:29:12     INFO - ==> process 13076 launched child process 15739
[task 2021-08-13T23:29:12.933Z] 23:29:12     INFO - ==> process 13076 launched child process 15750
[task 2021-08-13T23:29:12.942Z] 23:29:12     INFO - ==> process 13076 launched child process 15754
[task 2021-08-13T23:29:12.943Z] 23:29:12     INFO - ==> process 13076 launched child process 15794
[task 2021-08-13T23:29:12.943Z] 23:29:12     INFO - ==> process 13076 launched child process 15815
[task 2021-08-13T23:29:12.944Z] 23:29:12     INFO - ==> process 13076 launched child process 15849
[task 2021-08-13T23:29:12.944Z] 23:29:12     INFO - ==> process 13076 launched child process 15862
[task 2021-08-13T23:29:12.945Z] 23:29:12     INFO - ==> process 13076 launched child process 15897
[task 2021-08-13T23:29:12.946Z] 23:29:12     INFO - ==> process 13076 launched child process 15908
[task 2021-08-13T23:29:12.946Z] 23:29:12     INFO - ==> process 13076 launched child process 15977
[task 2021-08-13T23:29:12.947Z] 23:29:12     INFO - ==> process 13076 launched child process 15978
[task 2021-08-13T23:29:12.947Z] 23:29:12     INFO - ==> process 13076 launched child process 16036
[task 2021-08-13T23:29:12.948Z] 23:29:12     INFO - ==> process 13076 launched child process 16039
[task 2021-08-13T23:29:12.948Z] 23:29:12     INFO - ==> process 13076 launched child process 16069
[task 2021-08-13T23:29:12.948Z] 23:29:12     INFO - ==> process 13076 launched child process 16093
[task 2021-08-13T23:29:12.949Z] 23:29:12     INFO - ==> process 13076 launched child process 16116
[task 2021-08-13T23:29:12.949Z] 23:29:12     INFO - ==> process 13076 launched child process 16147
[task 2021-08-13T23:29:12.950Z] 23:29:12     INFO - ==> process 13076 launched child process 16177
[task 2021-08-13T23:29:12.950Z] 23:29:12     INFO - ==> process 13076 launched child process 16209
[task 2021-08-13T23:29:12.950Z] 23:29:12     INFO - ==> process 13076 launched child process 16250
[task 2021-08-13T23:29:12.951Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15364
[task 2021-08-13T23:29:12.951Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14348
[task 2021-08-13T23:29:12.952Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 13325
[task 2021-08-13T23:29:12.952Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14868
[task 2021-08-13T23:29:12.953Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 13845
[task 2021-08-13T23:29:12.953Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15383
[task 2021-08-13T23:29:12.954Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15897
[task 2021-08-13T23:29:12.955Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 13851
[task 2021-08-13T23:29:12.955Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14876
[task 2021-08-13T23:29:12.956Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14370
[task 2021-08-13T23:29:12.957Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15908
[task 2021-08-13T23:29:12.957Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 13364
[task 2021-08-13T23:29:12.958Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15419
[task 2021-08-13T23:29:12.959Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15420
[task 2021-08-13T23:29:12.959Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14911
[task 2021-08-13T23:29:12.960Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14406
[task 2021-08-13T23:29:12.961Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14407
[task 2021-08-13T23:29:12.961Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 13393
[task 2021-08-13T23:29:12.962Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 13905
[task 2021-08-13T23:29:12.963Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14930
[task 2021-08-13T23:29:12.963Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 13397
[task 2021-08-13T23:29:12.964Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 13910
[task 2021-08-13T23:29:12.965Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15977
[task 2021-08-13T23:29:12.965Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15978
[task 2021-08-13T23:29:12.974Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14443
[task 2021-08-13T23:29:12.975Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15467
[task 2021-08-13T23:29:12.975Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14959
[task 2021-08-13T23:29:12.976Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 13953
[task 2021-08-13T23:29:12.977Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 13444
[task 2021-08-13T23:29:12.977Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14470
[task 2021-08-13T23:29:12.978Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15498
[task 2021-08-13T23:29:12.979Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14998
[task 2021-08-13T23:29:12.979Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14487
[task 2021-08-13T23:29:12.980Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15515
[task 2021-08-13T23:29:12.981Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15517
[task 2021-08-13T23:29:12.981Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 13470
[task 2021-08-13T23:29:12.982Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 13983
[task 2021-08-13T23:29:12.983Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 16036
[task 2021-08-13T23:29:12.984Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 16039
[task 2021-08-13T23:29:12.985Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15016
[task 2021-08-13T23:29:12.985Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15017
[task 2021-08-13T23:29:12.986Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15019
[task 2021-08-13T23:29:12.986Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14008
[task 2021-08-13T23:29:12.987Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14522
[task 2021-08-13T23:29:12.987Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14011
[task 2021-08-13T23:29:12.988Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14523
[task 2021-08-13T23:29:12.989Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 16069
[task 2021-08-13T23:29:12.989Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15563
[task 2021-08-13T23:29:12.990Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 13518
[task 2021-08-13T23:29:12.990Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 13524
[task 2021-08-13T23:29:12.991Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15068
[task 2021-08-13T23:29:12.992Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 16093
[task 2021-08-13T23:29:12.992Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15596
[task 2021-08-13T23:29:12.993Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14064
[task 2021-08-13T23:29:12.993Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 16116
[task 2021-08-13T23:29:12.993Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14583
[task 2021-08-13T23:29:12.993Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14585
[task 2021-08-13T23:29:12.993Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15098
[task 2021-08-13T23:29:12.993Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15611
[task 2021-08-13T23:29:12.994Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15616
[task 2021-08-13T23:29:12.994Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14085
[task 2021-08-13T23:29:12.995Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 13578
[task 2021-08-13T23:29:12.995Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 13585
[task 2021-08-13T23:29:12.997Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 16147
[task 2021-08-13T23:29:12.997Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 13591
[task 2021-08-13T23:29:12.998Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15127
[task 2021-08-13T23:29:12.998Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15128
[task 2021-08-13T23:29:12.999Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 15644
[task 2021-08-13T23:29:12.999Z] 23:29:12     INFO - zombiecheck | Checking for orphan process with PID: 14627
[task 2021-08-13T23:29:13.000Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 13092
[task 2021-08-13T23:29:13.001Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 14124
[task 2021-08-13T23:29:13.002Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 14638
[task 2021-08-13T23:29:13.004Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 16177
[task 2021-08-13T23:29:13.004Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 15670
[task 2021-08-13T23:29:13.005Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 14148
[task 2021-08-13T23:29:13.005Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 14152
[task 2021-08-13T23:29:13.006Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 13641
[task 2021-08-13T23:29:13.006Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 15176
[task 2021-08-13T23:29:13.007Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 16209
[task 2021-08-13T23:29:13.007Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 15187
[task 2021-08-13T23:29:13.008Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 14680
[task 2021-08-13T23:29:13.008Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 15708
[task 2021-08-13T23:29:13.009Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 13152
[task 2021-08-13T23:29:13.009Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 14695
[task 2021-08-13T23:29:13.010Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 13672
[task 2021-08-13T23:29:13.010Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 14699
[task 2021-08-13T23:29:13.011Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 14714
[task 2021-08-13T23:29:13.011Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 14203
[task 2021-08-13T23:29:13.012Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 15739
[task 2021-08-13T23:29:13.013Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 16250
[task 2021-08-13T23:29:13.014Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 13696
[task 2021-08-13T23:29:13.014Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 13186
[task 2021-08-13T23:29:13.015Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 13188
[task 2021-08-13T23:29:13.015Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 15750
[task 2021-08-13T23:29:13.015Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 13703
[task 2021-08-13T23:29:13.015Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 15242
[task 2021-08-13T23:29:13.016Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 15754
[task 2021-08-13T23:29:13.016Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 15248
[task 2021-08-13T23:29:13.016Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 14234
[task 2021-08-13T23:29:13.016Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 15261
[task 2021-08-13T23:29:13.016Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 15272
[task 2021-08-13T23:29:13.017Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 13227
[task 2021-08-13T23:29:13.018Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 13743
[task 2021-08-13T23:29:13.019Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 15794
[task 2021-08-13T23:29:13.019Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 13750
[task 2021-08-13T23:29:13.020Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 14262
[task 2021-08-13T23:29:13.021Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 14776
[task 2021-08-13T23:29:13.021Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 14784
[task 2021-08-13T23:29:13.022Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 13254
[task 2021-08-13T23:29:13.022Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 15815
[task 2021-08-13T23:29:13.023Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 13258
[task 2021-08-13T23:29:13.024Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 14297
[task 2021-08-13T23:29:13.025Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 15323
[task 2021-08-13T23:29:13.025Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 13796
[task 2021-08-13T23:29:13.026Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 14820
[task 2021-08-13T23:29:13.026Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 13800
[task 2021-08-13T23:29:13.026Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 15849
[task 2021-08-13T23:29:13.027Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 14323
[task 2021-08-13T23:29:13.027Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 14838
[task 2021-08-13T23:29:13.028Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 15862
[task 2021-08-13T23:29:13.028Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 15357
[task 2021-08-13T23:29:13.028Z] 23:29:13     INFO - zombiecheck | Checking for orphan process with PID: 13311
[task 2021-08-13T23:29:13.029Z] 23:29:13     INFO - runtests.py | Running with scheme: https
[task 2021-08-13T23:29:13.029Z] 23:29:13     INFO - runtests.py | Running with e10s: True
[task 2021-08-13T23:29:13.030Z] 23:29:13     INFO - runtests.py | Running with fission: True
[task 2021-08-13T23:29:13.030Z] 23:29:13     INFO - runtests.py | Running with cross-origin iframes: False
[task 2021-08-13T23:29:13.030Z] 23:29:13     INFO - runtests.py | Running with serviceworker_e10s: True
[task 2021-08-13T23:29:13.031Z] 23:29:13     INFO - runtests.py | Running with socketprocess_e10s: False
[task 2021-08-13T23:29:13.031Z] 23:29:13     INFO - runtests.py | Running tests: start.
[task 2021-08-13T23:29:13.031Z] 23:29:13     INFO - 
[task 2021-08-13T23:29:13.032Z] 23:29:13     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -foreground -profile /tmp/tmpt8dvjfrg.mozrunner
[task 2021-08-13T23:29:13.032Z] 23:29:13     INFO - runtests.py | Application pid: 16287
[task 2021-08-13T23:29:13.032Z] 23:29:13     INFO - TEST-INFO | started process GECKO(16287)
[task 2021-08-13T23:29:16.953Z] 23:29:16     INFO - GECKO(16287) | 1628897356951	Marionette	INFO	Marionette enabled
[task 2021-08-13T23:29:22.862Z] 23:29:22     INFO - GECKO(16287) | 1628897362860	Marionette	TRACE	Received observer notification marionette-startup-requested
[task 2021-08-13T23:29:22.863Z] 23:29:22     INFO - GECKO(16287) | 1628897362860	Marionette	TRACE	Waiting until startup recorder finished recording startup scripts...
[task 2021-08-13T23:29:22.889Z] 23:29:22     INFO - GECKO(16287) | 1628897362888	Marionette	TRACE	All scripts recorded.
[task 2021-08-13T23:29:22.891Z] 23:29:22     INFO - GECKO(16287) | 1628897362890	Marionette	INFO	Listening on port 2828
[task 2021-08-13T23:29:22.893Z] 23:29:22     INFO - GECKO(16287) | 1628897362891	Marionette	DEBUG	Marionette is listening
[task 2021-08-13T23:29:22.987Z] 23:29:22     INFO - GECKO(16287) | 1628897362986	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:37718
[task 2021-08-13T23:29:22.997Z] 23:29:22     INFO - GECKO(16287) | 1628897362996	Marionette	DEBUG	Closed connection 0
[task 2021-08-13T23:29:23.000Z] 23:29:22     INFO - GECKO(16287) | 1628897362999	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:37720
[task 2021-08-13T23:29:23.020Z] 23:29:23     INFO - GECKO(16287) | 1628897363019	Marionette	DEBUG	1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2021-08-13T23:29:23.067Z] 23:29:23     INFO - GECKO(16287) | 1628897363065	Marionette	DEBUG	1 <- [1,1,null,{"sessionId":"482715a7-29f8-4a1a-a013-1149a0b56337","capabilities":{"browserName":"firefox","browserVersion":"93.0a ... .mozrunner","moz:shutdownTimeout":300000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2021-08-13T23:29:23.104Z] 23:29:23     INFO - GECKO(16287) | 1628897363102	Marionette	DEBUG	1 -> [0,2,"Addon:Install",{"path":"/tmp/tmpwxyd65jm.zip","temporary":false}]
[task 2021-08-13T23:29:23.399Z] 23:29:23     INFO - GECKO(16287) | 1628897363398	Marionette	DEBUG	1 <- [1,2,null,{"value":"special-powers@mozilla.org"}]
[task 2021-08-13T23:29:23.454Z] 23:29:23     INFO - GECKO(16287) | 1628897363451	Marionette	DEBUG	1 -> [0,3,"Addon:Install",{"path":"/tmp/tmpesrewap_.zip","temporary":false}]
[task 2021-08-13T23:29:23.825Z] 23:29:23     INFO - GECKO(16287) | 1628897363824	Marionette	DEBUG	1 <- [1,3,null,{"value":"mochikit@mozilla.org"}]
[task 2021-08-13T23:29:23.855Z] 23:29:23     INFO - GECKO(16287) | 1628897363854	Marionette	DEBUG	1 -> [0,4,"Marionette:GetContext",{}]
[task 2021-08-13T23:29:23.860Z] 23:29:23     INFO - GECKO(16287) | 1628897363858	Marionette	DEBUG	1 <- [1,4,null,{"value":"content"}]
[task 2021-08-13T23:29:23.867Z] 23:29:23     INFO - GECKO(16287) | 1628897363866	Marionette	DEBUG	1 -> [0,5,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-08-13T23:29:23.871Z] 23:29:23     INFO - GECKO(16287) | 1628897363867	Marionette	DEBUG	1 <- [1,5,null,{"value":null}]
[task 2021-08-13T23:29:23.878Z] 23:29:23     INFO - GECKO(16287) | 1628897363877	Marionette	DEBUG	1 -> [0,6,"WebDriver:ExecuteScript",{"script":"/* This Source Code Form is subject to the terms of the Mozilla Public\n * License, ... ry=%2Ftmp&cleanupCrashes=true"}],"newSandbox":true,"sandbox":"default","line":1936,"filename":"tests/mochitest/runtests.py"}]
[task 2021-08-13T23:29:23.885Z] 23:29:23     INFO - GECKO(16287) | 1628897363885	Marionette	TRACE	[1] MarionetteCommands actor created for window id 2
[task 2021-08-13T23:29:23.919Z] 23:29:23     INFO - GECKO(16287) | 1628897363918	Marionette	DEBUG	1 <- [1,6,null,{"value":null}]
[task 2021-08-13T23:29:23.962Z] 23:29:23     INFO - GECKO(16287) | 1628897363959	Marionette	DEBUG	1 -> [0,7,"Marionette:SetContext",{"value":"content"}]
[task 2021-08-13T23:29:23.967Z] 23:29:23     INFO - GECKO(16287) | 1628897363961	Marionette	DEBUG	1 <- [1,7,null,{"value":null}]
[task 2021-08-13T23:29:24.158Z] 23:29:24     INFO - GECKO(16287) | 1628897364157	Marionette	DEBUG	1 -> [0,8,"WebDriver:DeleteSession",{}]
[task 2021-08-13T23:29:24.172Z] 23:29:24     INFO - GECKO(16287) | 1628897364171	Marionette	DEBUG	1 <- [1,8,null,{"value":null}]
[task 2021-08-13T23:29:24.189Z] 23:29:24     INFO - runtests.py | Waiting for browser...
[task 2021-08-13T23:29:24.229Z] 23:29:24     INFO - GECKO(16287) | 1628897364228	Marionette	DEBUG	Closed connection 1
[task 2021-08-13T23:29:25.774Z] 23:29:25     INFO - SimpleTest START

There have been 41 total failures in the last 7 days (recent failure log).
Affected platforms are:

  • linux1804-64-asan-qr
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

Update:
There have been 50 failures within the last 7 days, all on Linux 18.04 x64 WebRender asan opt.
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=349909830&repo=autoland&lineNumber=15416

Hello Jens, could you help us assign this to someone?
Thank you.

Flags: needinfo?(jstutte)

This is most probably our intermittent variant of bug 1505660.

If this happens so frequently under asan, we might have a chance to catch an rr/pernosco trace here somehow?

And it would be really helpful if we could write out some of the information we usually see as annotations on crash reports, like MOZ_CRASH Reason.

FWIW, I read in the recent log right before the hang:

[task 2021-08-30T01:43:38.565Z] 01:43:38     INFO - GECKO(21053) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 575: NotFoundError: No such JSWindowActor 'SpecialPowers'
[task 2021-08-30T01:43:38.894Z] 01:43:38     INFO - GECKO(21053) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 575: NotFoundError: No such JSWindowActor 'AppTestDelegate'
[task 2021-08-30T01:43:38.895Z] 01:43:38     INFO - GECKO(21053) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 575: NotFoundError: No such JSWindowActor 'AppTestDelegate'

which might indicate some test-harness problem, too?

Flags: needinfo?(jstutte) → needinfo?(imoraru)
See Also: → 1505660

Actually looking at AsyncShutdown.jsm I read:

    // Now, spin the event loop
    debug("Spinning the event loop");
    promise.then(() => (satisfied = true)); // This promise cannot reject
    let thread = Services.tm.mainThread;
    while (!satisfied) {
      try {
        thread.processNextEvent(true);
      } catch (ex) {
        // An uncaught error should not stop us, but it should still
        // be reported and cause tests to fail.
        Promise.reject(ex);
      }
    }

So it might be intentional that we first see exceptions in the log and then a timeout as we continue spinning ? Might it be necessary to inspect the exception here for fatal conditions that prevent our promise from being ever resolved ?

Marco, any thoughts on this?

Flags: needinfo?(mak)

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

So it might be intentional that we first see exceptions in the log and then a timeout as we continue spinning ? Might it be necessary to inspect the exception here for fatal conditions that prevent our promise from being ever resolved ?

I may say something obvious, but the promise here is waiting for the async shutdown barrier, that is waiting for some consumer. Async shutdown adds annotations to crash reports to understand which consumer is awaiting for, but it is up to the consumer to provide a state object, so that from crash-stats one can ideally say what was happening when it forces a crash (there's a shutdown blocker label though).
I don't know if those annotations are available in test logs, if this crash is started by async shutdown the annotation should be present. Comment 80 is still relevant imo, can we get annotations in the logs?

I see the same exception in other parts of this log, without a crash after it, that makes me think some code may be using specialpowers in the wrong scope and AsyncShutdown happens to intercept that exception when it spins the events loop, but has no direct control over that code. It could be a red herring, I can't tell for sure.
It looks like after these exceptions, quit-application-granted (based on "JavaScript error: resource:///modules/Interactions.jsm" in the log) notification is sent and handled, so if there's a not resolving shutdown promise it may be registered there https://searchfox.org/mozilla-central/search?q=.quitApplicationGranted&path=&case=true&regexp=false and the barrier we are waiting is probably that one.

I must note the fact Interactions.uninit() throws is causing later uninits to not be invoked (https://searchfox.org/mozilla-central/rev/5a362eb7d054740dc9d7c82c79a2efbc5f3e4776/browser/components/BrowserGlue.jsm#1968-1974) and then maybe some of these are misbehaving on later shutdown. I filed bug 1728102 for that and I'll fix it, but I have no idea if it will help.

Flags: needinfo?(mak)

Thanks for the clarifications, then let's see if bug 1728102 has some effect here.

Iulian, still having the crash annotations in the log would be great, not only for this bug. Should I file a bug in the Taskcluster/General component or is there a better place?

See Also: → 1728102

Such a bug should be filed in Testing :: Mochitest (or Firefox Build System :: Task Config if it it's more general). Taskcluster is the platform which executes the tasks but should be regarded as independent from their content.

Flags: needinfo?(imoraru)
Depends on: 1728721
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

There have been 37 total failures in the last 7 days, recent failure log.
Affected platforms are:

  • linux1804-64-asan-qr

There have been 61 total failures in the last 7 days, recent failure log.
Affected platforms are:

  • linux1804-64-asan-qr
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork]

mccr8, please take a look after the Fission memory stuff. Thank you.

Flags: needinfo?(continuation)
See Also: → 1730374
See Also: 1730374

There have been 78 total failures in the last 7 days, recent failure log.
Affected platforms are:

  • linux1804-64-asan-qr
See Also: → 1724168
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

There are 78 total failures in the last 7 days on linux1804-64-asan-qr opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=355748508&repo=autoland&lineNumber=3253

[task 2021-10-22T12:43:15.171Z] 12:43:15     INFO - TEST-START | browser/base/content/test/about/browser_bug633691.js
[task 2021-10-22T12:43:16.874Z] 12:43:16     INFO - GECKO(1557) | MEMORY STAT | vsize 20976100MB | residentFast 1444MB
[task 2021-10-22T12:43:16.878Z] 12:43:16     INFO - TEST-OK | browser/base/content/test/about/browser_bug633691.js | took 1707ms

[task 2021-10-22T12:43:37.569Z] 12:43:37     INFO - GECKO(1557) | JavaScript error: resource:///modules/sessionstore/SessionStore.jsm, line 5094: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIWindowMediator.getEnumerator]
[task 2021-10-22T12:48:29.149Z] 12:48:29     INFO - GECKO(1557) | RunWatchdog: Mainthread nested event loops during hang:
[task 2021-10-22T12:48:29.150Z] 12:48:29     INFO - GECKO(1557) |  --- (no nested event loop active)
[task 2021-10-22T12:48:30.154Z] 12:48:30     INFO - GECKO(1557) | AddressSanitizer:DEADLYSIGNAL
[task 2021-10-22T12:48:30.155Z] 12:48:30     INFO - GECKO(1557) | =================================================================
[task 2021-10-22T12:48:30.156Z] 12:48:30    ERROR - GECKO(1557) | ==1557==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000001 (pc 0x7f297ba08774 bp 0x7f2919344e10 sp 0x7f2919344d40 T237)
[task 2021-10-22T12:48:30.157Z] 12:48:30     INFO - GECKO(1557) | ==1557==The signal is caused by a WRITE memory access.
[task 2021-10-22T12:48:30.158Z] 12:48:30     INFO - GECKO(1557) | ==1557==Hint: address points to the zero page.
[task 2021-10-22T12:48:32.252Z] 12:48:32     INFO - GECKO(1557) |     #0 0x7f297ba08774 in mozilla::(anonymous namespace)::RunWatchdog(void*) /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:256:5
[task 2021-10-22T12:48:32.253Z] 12:48:32     INFO - GECKO(1557) |     #1 0x7f2991dd8ade in _pt_root /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:201:5
[task 2021-10-22T12:48:32.254Z] 12:48:32     INFO - GECKO(1557) |     #2 0x7f2993bc36da in start_thread /tmp/glibc/nptl/pthread_create.c:463
[task 2021-10-22T12:48:32.255Z] 12:48:32     INFO - GECKO(1557) |     #3 0x7f2992ba1a3e in __clone /tmp/glibc/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:95
[task 2021-10-22T12:48:32.256Z] 12:48:32     INFO - GECKO(1557) | AddressSanitizer can not provide additional info.
[task 2021-10-22T12:48:32.259Z] 12:48:32     INFO - GECKO(1557) | SUMMARY: AddressSanitizer: SEGV /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:256:5 in mozilla::(anonymous namespace)::RunWatchdog(void*)
[task 2021-10-22T12:48:32.260Z] 12:48:32     INFO - GECKO(1557) | Thread T237 (Shutdow~minator) created by T0 (GeckoMain) here:
[task 2021-10-22T12:48:32.567Z] 12:48:32     INFO - GECKO(1557) |     #0 0x55c352ec045c in __interceptor_pthread_create /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/asan/asan_interceptors.cpp:207:3
[task 2021-10-22T12:48:32.568Z] 12:48:32     INFO - GECKO(1557) |     #1 0x7f2991dc8b74 in _PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:458:14
[task 2021-10-22T12:48:32.569Z] 12:48:32     INFO - GECKO(1557) |     #2 0x7f2991db9e1e in PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:533:12
[task 2021-10-22T12:48:32.570Z] 12:48:32     INFO - GECKO(1557) |     #3 0x7f297ba07edc in CreateSystemThread /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:117:7
[task 2021-10-22T12:48:32.570Z] 12:48:32     INFO - GECKO(1557) |     #4 0x7f297ba07edc in mozilla::nsTerminator::StartWatchdog() /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:479:7
[task 2021-10-22T12:48:32.571Z] 12:48:32     INFO - GECKO(1557) |     #5 0x7f297ba081cb in Start /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:393:3
[task 2021-10-22T12:48:32.572Z] 12:48:32     INFO - GECKO(1557) |     #6 0x7f297ba081cb in mozilla::nsTerminator::AdvancePhase(mozilla::ShutdownPhase) /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:527:5
[task 2021-10-22T12:48:32.572Z] 12:48:32     INFO - GECKO(1557) |     #7 0x7f29708f8fa1 in mozilla::AdvanceShutdownPhaseInternal(mozilla::ShutdownPhase, bool, char16_t const*, nsCOMPtr<nsISupports> const&) /builds/worker/checkouts/gecko/xpcom/base/AppShutdown.cpp:342:18
[task 2021-10-22T12:48:32.573Z] 12:48:32     INFO - GECKO(1557) |     #8 0x7f297b8537a5 in nsAppStartup::Quit(unsigned int, int, bool*) /builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp:484:5
[task 2021-10-22T12:48:32.573Z] 12:48:32     INFO - GECKO(1557) |     #9 0x7f2970b7a0c5 in NS_InvokeByIndex /builds/worker/checkouts/gecko/xpcom/reflect/xptcall/md/unix/xptcinvoke_asm_x86_64_unix.S:101
[task 2021-10-22T12:48:32.573Z] 12:48:32     INFO - GECKO(1557) |     #10 0x7f29726fc8fe in Invoke /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1631:10
[task 2021-10-22T12:48:32.573Z] 12:48:32     INFO - GECKO(1557) |     #11 0x7f29726fc8fe in Call /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1184:19
[task 2021-10-22T12:48:32.573Z] 12:48:32     INFO - GECKO(1557) |     #12 0x7f29726fc8fe in XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNative.cpp:1130:23
[task 2021-10-22T12:48:32.573Z] 12:48:32     INFO - GECKO(1557) |     #13 0x7f29727012d4 in XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNativeJSOps.cpp:921:10
[task 2021-10-22T12:48:32.573Z] 12:48:32     INFO - GECKO(1557) |     #14 0x7f297bc98871 in CallJSNative /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:385:13
[task 2021-10-22T12:48:32.581Z] 12:48:32     INFO - GECKO(1557) |     #15 0x7f297bc98871 in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:472:12
[task 2021-10-22T12:48:32.582Z] 12:48:32     INFO - GECKO(1557) |     #16 0x7f297bc84ed3 in CallFromStack /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:536:10
[task 2021-10-22T12:48:32.585Z] 12:48:32     INFO - GECKO(1557) |     #17 0x7f297bc84ed3 in Interpret(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:3240:16
[task 2021-10-22T12:48:32.590Z] 12:48:32     INFO - GECKO(1557) |     #18 0x7f297bc69fcc in js::RunScript(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:354:13
[task 2021-10-22T12:48:32.591Z] 12:48:32     INFO - GECKO(1557) |     #19 0x7f297bc989ac in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:504:13
[task 2021-10-22T12:48:32.592Z] 12:48:32     INFO - GECKO(1557) |     #20 0x7f297bc9a7eb in js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:549:8
[task 2021-10-22T12:48:32.593Z] 12:48:32     INFO - GECKO(1557) |     #21 0x7f297beb46dc in JS_CallFunctionValue(JSContext*, JS::Handle<JSObject*>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/js/src/vm/CallAndConstruct.cpp:53:10
[task 2021-10-22T12:48:32.594Z] 12:48:32     INFO - GECKO(1557) |     #22 0x7f29726ede98 in nsXPCWrappedJS::CallMethod(unsigned short, nsXPTMethodInfo const*, nsXPTCMiniVariant*) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedJSClass.cpp:973:17
[task 2021-10-22T12:48:32.595Z] 12:48:32     INFO - GECKO(1557) |     #23 0x7f2970b7ba62 in PrepareAndDispatch /builds/worker/checkouts/gecko/xpcom/reflect/xptcall/md/unix/xptcstubs_x86_64_linux.cpp:115:37
[task 2021-10-22T12:48:32.596Z] 12:48:32     INFO - GECKO(1557) |     #24 0x7f2970b7a7ea in SharedStub xptcstubs_x86_64_linux.cpp
[task 2021-10-22T12:48:32.596Z] 12:48:32     INFO - GECKO(1557) |     #25 0x7f29726b0c5f in PreciseGCRunnable::Run() /builds/worker/checkouts/gecko/js/xpconnect/src/XPCComponents.cpp:1689:16
[task 2021-10-22T12:48:32.597Z] 12:48:32     INFO - GECKO(1557) |     #26 0x7f2970b44b62 in mozilla::RunnableTask::Run() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:467:16
[task 2021-10-22T12:48:32.598Z] 12:48:32     INFO - GECKO(1557) |     #27 0x7f2970b0bc50 in mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:770:26
[task 2021-10-22T12:48:32.606Z] 12:48:32     INFO - GECKO(1557) |     #28 0x7f2970b09408 in mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:606:15
[task 2021-10-22T12:48:32.606Z] 12:48:32     INFO - GECKO(1557) |     #29 0x7f2970b09b19 in mozilla::TaskController::ProcessPendingMTTask(bool) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:390:36
[task 2021-10-22T12:48:32.607Z] 12:48:32     INFO - GECKO(1557) |     #30 0x7f2970b4e391 in operator() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:123:37
[task 2021-10-22T12:48:32.608Z] 12:48:32     INFO - GECKO(1557) |     #31 0x7f2970b4e391 in mozilla::detail::RunnableFunction<mozilla::TaskController::InitializeInternal()::$_0>::Run() /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.h:531:5
[task 2021-10-22T12:48:32.609Z] 12:48:32     INFO - GECKO(1557) |     #32 0x7f2970b2b2e7 in nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1174:16
[task 2021-10-22T12:48:32.609Z] 12:48:32     INFO - GECKO(1557) |     #33 0x7f2970b367ec in NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:467:10
[task 2021-10-22T12:48:32.610Z] 12:48:32     INFO - GECKO(1557) |     #34 0x7f2971ca1c88 in mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:85:21
[task 2021-10-22T12:48:32.611Z] 12:48:32     INFO - GECKO(1557) |     #35 0x7f2971bad111 in RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:331:10
[task 2021-10-22T12:48:32.612Z] 12:48:32     INFO - GECKO(1557) |     #36 0x7f2971bad111 in RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:324:3
[task 2021-10-22T12:48:32.612Z] 12:48:32     INFO - GECKO(1557) |     #37 0x7f2971bad111 in MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:306:3
[task 2021-10-22T12:48:32.613Z] 12:48:32     INFO - GECKO(1557) |     #38 0x7f2977b3c447 in nsBaseAppShell::Run() /builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp:137:27
[task 2021-10-22T12:48:32.614Z] 12:48:32     INFO - GECKO(1557) |     #39 0x7f297b8527d7 in nsAppStartup::Run() /builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp:295:30
[task 2021-10-22T12:48:32.615Z] 12:48:32     INFO - GECKO(1557) |     #40 0x7f297ba59ec8 in XREMain::XRE_mainRun() /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5293:22
[task 2021-10-22T12:48:32.616Z] 12:48:32     INFO - GECKO(1557) |     #41 0x7f297ba5c2a9 in XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5478:8
[task 2021-10-22T12:48:32.616Z] 12:48:32     INFO - GECKO(1557) |     #42 0x7f297ba5cfe3 in XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5537:21
[task 2021-10-22T12:48:32.617Z] 12:48:32     INFO - GECKO(1557) |     #43 0x55c352f0b01c in do_main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:225:22
[task 2021-10-22T12:48:32.618Z] 12:48:32     INFO - GECKO(1557) |     #44 0x55c352f0b01c in main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:395:16
[task 2021-10-22T12:48:32.619Z] 12:48:32     INFO - GECKO(1557) |     #45 0x7f2992aa1b96 in __libc_start_main /tmp/glibc/csu/../csu/libc-start.c:310
[task 2021-10-22T12:48:32.620Z] 12:48:32     INFO - GECKO(1557) | ==1557==ABORTING
[task 2021-10-22T12:51:05.767Z] 12:51:05     INFO - GECKO(1557) | out of memory: 0x0000000019300000 bytes requested
[task 2021-10-22T12:51:05.770Z] 12:51:05     INFO - GECKO(1557) | AddressSanitizer:DEADLYSIGNAL
[task 2021-10-22T12:51:05.770Z] 12:51:05     INFO - GECKO(1557) | =================================================================
[task 2021-10-22T12:51:05.770Z] 12:51:05    ERROR - GECKO(1557) | ==3936==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000001 (pc 0x56008c9e0c98 bp 0x7ffea726c170 sp 0x7ffea726c160 T0)
[task 2021-10-22T12:51:05.770Z] 12:51:05     INFO - GECKO(1557) | ==3936==The signal is caused by a WRITE memory access.
[task 2021-10-22T12:51:05.770Z] 12:51:05     INFO - GECKO(1557) | ==3936==Hint: address points to the zero page.
[task 2021-10-22T12:51:05.903Z] 12:51:05     INFO - GECKO(1557) | ==3936==WARNING: failed to fork (errno 12)
[task 2021-10-22T12:51:05.928Z] 12:51:05     INFO - GECKO(1557) | ==3936==WARNING: failed to fork (errno 12)
[task 2021-10-22T12:51:05.955Z] 12:51:05     INFO - GECKO(1557) | ==3936==WARNING: failed to fork (errno 12)
[task 2021-10-22T12:51:05.982Z] 12:51:05     INFO - GECKO(1557) | ==3936==WARNING: failed to fork (errno 12)
[task 2021-10-22T12:51:06.012Z] 12:51:06     INFO - GECKO(1557) | ==3936==WARNING: failed to fork (errno 12)
[task 2021-10-22T12:51:06.013Z] 12:51:06     INFO - GECKO(1557) | ==3936==WARNING: Failed to use and restart external symbolizer!
[task 2021-10-22T12:51:06.015Z] 12:51:06     INFO - GECKO(1557) |     #0 0x56008c9e0c98  (/builds/worker/workspace/build/application/firefox/firefox+0x10dc98)
[task 2021-10-22T12:51:06.016Z] 12:51:06     INFO - GECKO(1557) |     #1 0x56008c9e0e3d  (/builds/worker/workspace/build/application/firefox/firefox+0x10de3d)
[task 2021-10-22T12:51:06.019Z] 12:51:06     INFO - GECKO(1557) |     #2 0x56008c9e136b  (/builds/worker/workspace/build/application/firefox/firefox+0x10e36b)
[task 2021-10-22T12:51:06.020Z] 12:51:06     INFO - GECKO(1557) |     #3 0x7fb98249dfc3  (/builds/worker/workspace/build/application/firefox/libxul.so+0x3e7bfc3)
[task 2021-10-22T12:51:06.022Z] 12:51:06     INFO - GECKO(1557) |     #4 0x7fb9831c648e  (/builds/worker/workspace/build/application/firefox/libxul.so+0x4ba448e)
[task 2021-10-22T12:51:06.022Z] 12:51:06     INFO - GECKO(1557) |     #5 0x7fb9831b8b7a  (/builds/worker/workspace/build/application/firefox/libxul.so+0x4b96b7a)
[task 2021-10-22T12:51:06.023Z] 12:51:06     INFO - GECKO(1557) |     #6 0x7fb9832f7281  (/builds/worker/workspace/build/application/firefox/libxul.so+0x4cd5281)
[task 2021-10-22T12:51:06.026Z] 12:51:06     INFO - GECKO(1557) |     #7 0x7fb98333603f  (/builds/worker/workspace/build/application/firefox/libxul.so+0x4d1403f)
[task 2021-10-22T12:51:06.027Z] 12:51:06     INFO - GECKO(1557) |     #8 0x7fb982744b62  (/builds/worker/workspace/build/application/firefox/libxul.so+0x4122b62)
[task 2021-10-22T12:51:06.028Z] 12:51:06     INFO - GECKO(1557) |     #9 0x7fb98270bc50  (/builds/worker/workspace/build/application/firefox/libxul.so+0x40e9c50)
[task 2021-10-22T12:51:06.029Z] 12:51:06     INFO - GECKO(1557) |     #10 0x7fb982709408  (/builds/worker/workspace/build/application/firefox/libxul.so+0x40e7408)
[task 2021-10-22T12:51:06.030Z] 12:51:06     INFO - GECKO(1557) |     #11 0x7fb982709b19  (/builds/worker/workspace/build/application/firefox/libxul.so+0x40e7b19)
[task 2021-10-22T12:51:06.030Z] 12:51:06     INFO - GECKO(1557) |     #12 0x7fb98274e391  (/builds/worker/workspace/build/application/firefox/libxul.so+0x412c391)
[task 2021-10-22T12:51:06.031Z] 12:51:06     INFO - GECKO(1557) |     #13 0x7fb98272b2e7  (/builds/worker/workspace/build/application/firefox/libxul.so+0x41092e7)
[task 2021-10-22T12:51:06.033Z] 12:51:06     INFO - GECKO(1557) |     #14 0x7fb9827367ec  (/builds/worker/workspace/build/application/firefox/libxul.so+0x41147ec)
[task 2021-10-22T12:51:06.034Z] 12:51:06     INFO - GECKO(1557) |     #15 0x7fb9838a1c88  (/builds/worker/workspace/build/application/firefox/libxul.so+0x527fc88)
[task 2021-10-22T12:51:06.035Z] 12:51:06     INFO - GECKO(1557) |     #16 0x7fb9837ad111  (/builds/worker/workspace/build/application/firefox/libxul.so+0x518b111)
[task 2021-10-22T12:51:06.038Z] 12:51:06     INFO - GECKO(1557) |     #17 0x7fb98973c447  (/builds/worker/workspace/build/application/firefox/libxul.so+0xb11a447)
[task 2021-10-22T12:51:06.039Z] 12:51:06     INFO - GECKO(1557) |     #18 0x7fb98d66240f  (/builds/worker/workspace/build/application/firefox/libxul.so+0xf04040f)
[task 2021-10-22T12:51:06.040Z] 12:51:06     INFO - GECKO(1557) |     #19 0x7fb9837ad111  (/builds/worker/workspace/build/application/firefox/libxul.so+0x518b111)
[task 2021-10-22T12:51:06.041Z] 12:51:06     INFO - GECKO(1557) |     #20 0x7fb98d661e36  (/builds/worker/workspace/build/application/firefox/libxul.so+0xf03fe36)
[task 2021-10-22T12:51:06.042Z] 12:51:06     INFO - GECKO(1557) |     #21 0x56008c9da6ad  (/builds/worker/workspace/build/application/firefox/firefox+0x1076ad)
[task 2021-10-22T12:51:06.043Z] 12:51:06     INFO - GECKO(1557) |     #22 0x56008c9daacd  (/builds/worker/workspace/build/application/firefox/firefox+0x107acd)
[task 2021-10-22T12:51:06.044Z] 12:51:06     INFO - GECKO(1557) |     #23 0x7fb9a46a8b96  (/lib/x86_64-linux-gnu/libc.so.6+0x21b96)
[task 2021-10-22T12:51:06.045Z] 12:51:06     INFO - GECKO(1557) |     #24 0x56008c92979c  (/builds/worker/workspace/build/application/firefox/firefox+0x5679c)
[task 2021-10-22T12:51:06.046Z] 12:51:06     INFO - GECKO(1557) | AddressSanitizer can not provide additional info.
[task 2021-10-22T12:51:06.047Z] 12:51:06     INFO - GECKO(1557) | SUMMARY: AddressSanitizer: SEGV (/builds/worker/workspace/build/application/firefox/firefox+0x10dc98)
[task 2021-10-22T12:51:06.048Z] 12:51:06     INFO - GECKO(1557) | ==3936==ABORTING
[task 2021-10-22T12:51:06.370Z] 12:51:06     INFO - TEST-INFO | Main app process: exit 0

Andrew, are you working on this?

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

This is failing all over the place. I'm not sure what might be going wrong. Have there been recent changes to the machines we're running tests on? I vaguely recall reading something about how we're using slower machines now. Although from the logs it looks like it might be hanging for 5 minutes, so I'm not sure increasing the timeouts will really help.

Yeah, the time limits look like they are 5 or 6 minutes for ASan and TSan: https://searchfox.org/mozilla-central/rev/2e3b0483e31abffe0b4374480a34c6d23f5186ea/modules/libpref/init/all.js#814-818

Flags: needinfo?(continuation)

Does the frequency change align with any migrations?

Flags: needinfo?(jmaher)

I see this spiking around September 16th. I am not aware of any changes on the linux docker images we run at AWS. I would assume this is probably related to a change in the product.

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

Looking at some of these (again), I saw in those I clicked on:

[task 2021-10-24T16:46:55.931Z] 16:46:55     INFO - GECKO(2482) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 575: NotFoundError: No such JSWindowActor 'SpecialPowers'
...
[task 2021-10-24T16:47:11.612Z] 16:47:11     INFO - GECKO(2482) | JavaScript error: resource:///modules/sessionstore/SessionStore.jsm, line 5094: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIWindowMediator.getEnumerator]
[task 2021-10-24T16:53:02.682Z] 16:53:02     INFO - GECKO(2482) | RunWatchdog: Mainthread nested event loops during hang:
[task 2021-10-24T16:53:02.683Z] 16:53:02     INFO - GECKO(2482) |  --- (no nested event loop active)

This tells me that we have no nested event loop on the main thread involved here but the async shutdown blocker is receiving some unexpected error code. Looking at SessionStore.jsm it seems we want to get an enumerator but that throws NS_ERROR_UNEXPECTED. A possible cause for this is in GetEnumerator. My doubt would be then that we try to fetch an enumerator after we reached xpcom-shutdown as this sets mReady to false. I am not sure if this can cause a hang, but it definitely feels wrong. Either all (late) callers of GetEnumerator must handle well this error, making it become less unexpected, or we should just return an empty enumerator in this case (which sounds more robust and consistent to me, but I ignore all the details, of course).

There are many other NS_ENSURE_STATE(mReady); in nsWindowMediator.cpp that might need a revision, too.

Andrew, I just ni you as you were active here recently.

Flags: needinfo?(continuation)
See Also: → 1730374

Bug 1730374 is the non-ASan/TSan version of this shutdown hang, at least in terms of what is causing the crash. The other bug is likely more actionable because the crash dumps there will actually show the main thread stack, whereas in this one it won't.

I see the GetEnumerator failure in a few logs, but not most of them, so I don't know if it is really a universal explanation. I did a try push just now with debug logging for AsyncShutdown.jsm enabled (hopefully). If I can trigger a failure there, maybe it'll shed some light on what is going wrong, or at least give us some indication that AsyncShutdown is not at fault.

https://treeherder.mozilla.org/jobs?repo=try&revision=8bfd7ac885ccfb5d53fe0e59a1c8873216f19bfd

Unfortunately my Taskcluster skills failed so here's another attempt with the logging directly enabled.
https://treeherder.mozilla.org/#/jobs?repo=try&revision=bb0b924c9f0b411d6e600a42bf428d006ba6796c

It looks like we print out all of the same AsyncShutdown DEBUG stuff when we hang as when we don't, so I guess we're not spinning in a loop in that code.

Flags: needinfo?(continuation)

(In reply to Andrew McCreight [:mccr8] from comment #149)

I see the GetEnumerator failure in a few logs, but not most of them, so I don't know if it is really a universal explanation. I did a try push just now with debug logging for AsyncShutdown.jsm enabled (hopefully). If I can trigger a failure there, maybe it'll shed some light on what is going wrong, or at least give us some indication that AsyncShutdown is not at fault.

https://treeherder.mozilla.org/jobs?repo=try&revision=8bfd7ac885ccfb5d53fe0e59a1c8873216f19bfd

FWIW, in that try run I can see the same NS_ERROR_UNEXPECTED failure as described in comment 146. It is also the last sign of life before we have a pause and then the watchdog crash.

(In reply to Andrew McCreight [:mccr8] from comment #150)

https://treeherder.mozilla.org/#/jobs?repo=try&revision=bb0b924c9f0b411d6e600a42bf428d006ba6796c

Here instead it is not present. The last message is:

[task 2021-10-26T22:39:40.625Z] 22:39:40     INFO - GECKO(15585) | DEBUG: Finished phase web-workers-shutdown

followed by some valgrind messages and it comes from Spinner.observe. Then again a pause and then the crash. It is not clear to me, what would have been the next output without hang here in order to narrow down the possible range of code where we are hanging.

Looking at this code leads me to the side-question, if we should not better use spinEventLoopUntil instead of doing our own thing here which would make those spins visible in annotations, too.

Anyhow, I too see no evidence, that the NS_ERROR_UNEXPECTED can cause such a hang. Still the error handling for NS_ENSURE_STATE(mReady); caused errors looks incomplete to me and might merit a second look independently.

Whiteboard: [stockwell disable-recommended] → [stockwell needswork]

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

Anyhow, I too see no evidence, that the NS_ERROR_UNEXPECTED can cause such a hang. Still the error handling for NS_ENSURE_STATE(mReady); caused errors looks incomplete to me and might merit a second look independently.

Yeah, you are right that it doesn't look like a good idea.

See Also: → 1738185

(In reply to Andrew McCreight [:mccr8] from comment #154)

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

Anyhow, I too see no evidence, that the NS_ERROR_UNEXPECTED can cause such a hang. Still the error handling for NS_ENSURE_STATE(mReady); caused errors looks incomplete to me and might merit a second look independently.

Yeah, you are right that it doesn't look like a good idea.

I filed bug 1738185 for this.

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

Looking at some recent failure logs, they have the "Waiting in WillDestroyCurrentMessageLoop for pid 5128" annotations I added in bug 1740529, so it does look like it could be another instance of a child process not shutting down (bug 1730374). There's less logging, so I can't tell what test is creating the process. I did notice that the process we're waiting for seems to have a null crash right afterwards, so maybe symbolicating that crash stack could give some information about what it is doing when we're waiting for it.

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

Poking from time to time into a log I found another weird one: The process with pid 9598 is never mentioned before we get there, only 5 minutes later we find in the log (after the timeout crash):

[task 2021-11-21T11:14:02.298Z] 11:14:02    ERROR - GECKO(7518) | ==9598==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000001 (pc 0x55f2873fc547 bp 0x7ffc6d73ce30 sp 0x7ffc6d73ce10 T0)
[task 2021-11-21T11:14:02.298Z] 11:14:02     INFO - GECKO(7518) | ==9598==The signal is caused by a WRITE memory access.
[task 2021-11-21T11:14:02.298Z] 11:14:02     INFO - GECKO(7518) | ==9598==Hint: address points to the zero page.
[task 2021-11-21T11:14:02.452Z] 11:14:02     INFO - GECKO(7518) | ==9598==WARNING: failed to fork (errno 12)
[task 2021-11-21T11:14:02.472Z] 11:14:02     INFO - GECKO(7518) | ==9598==WARNING: failed to fork (errno 12)
[task 2021-11-21T11:14:02.489Z] 11:14:02     INFO - GECKO(7518) | ==9598==WARNING: failed to fork (errno 12)
[task 2021-11-21T11:14:02.507Z] 11:14:02     INFO - GECKO(7518) | ==9598==WARNING: failed to fork (errno 12)
[task 2021-11-21T11:14:02.525Z] 11:14:02     INFO - GECKO(7518) | ==9598==WARNING: failed to fork (errno 12)
[task 2021-11-21T11:14:02.526Z] 11:14:02     INFO - GECKO(7518) | ==9598==WARNING: Failed to use and restart external symbolizer!
[task 2021-11-21T11:14:02.529Z] 11:14:02     INFO - GECKO(7518) |     #0 0x55f2873fc547  (/builds/worker/workspace/build/application/firefox/firefox+0x10f547)
[task 2021-11-21T11:14:02.535Z] 11:14:02     INFO - GECKO(7518) |     #1 0x55f2873fbd3d  (/builds/worker/workspace/build/application/firefox/firefox+0x10ed3d)
[task 2021-11-21T11:14:02.536Z] 11:14:02     INFO - GECKO(7518) |     #2 0x55f2873fc26b  (/builds/worker/workspace/build/application/firefox/firefox+0x10f26b)
[task 2021-11-21T11:14:02.537Z] 11:14:02     INFO - GECKO(7518) |     #3 0x7f2c943b8433  (/builds/worker/workspace/build/application/firefox/libxul.so+0x3bbe433)
[task 2021-11-21T11:14:02.537Z] 11:14:02     INFO - GECKO(7518) |     #4 0x7f2c9510eb0e  (/builds/worker/workspace/build/application/firefox/libxul.so+0x4914b0e)
... more frames without symbols ...
[task 2021-11-21T11:14:02.556Z] 11:14:02     INFO - GECKO(7518) | AddressSanitizer can not provide additional info.
[task 2021-11-21T11:14:02.558Z] 11:14:02     INFO - GECKO(7518) | SUMMARY: AddressSanitizer: SEGV (/builds/worker/workspace/build/application/firefox/firefox+0x10f547)
[task 2021-11-21T11:14:02.559Z] 11:14:02     INFO - GECKO(7518) | ==9598==ABORTING

as if that process had an assert on startup? I suspect we see some late logging and can not really trust the timestamps?

Flags: needinfo?(continuation)

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

as if that process had an assert on startup? I suspect we see some late logging and can not really trust the timestamps?

That kind of sounds like the failures in bug 1730374. ASan builds aren't debug and don't have ++DOMWINDOW logging or the leakcheck log files, so I could imagine that these processes that start but don't really do anything just don't get any logging.

Flags: needinfo?(continuation)

The only logging I see much of is: ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost. I'm not sure why we wouldn't produce it for child processes, too.

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

There have been 55 total failures in the last 7 days, recent failure log.
Affected platforms are:

  • linux1804-64-asan-qr
  • linux1804-64-qr
  • linux1804-64-tsan-qr
See Also: → 1724337
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

There have been 52 total failures in the last 7 days, recent failure log.
Affected platforms are:

  • linux1804-64-asan-qr
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]
Whiteboard: [stockwell needswork:owner][stockwell needswork:owner][stockwell needswork:owner] → [stockwell needswork:owner]
See Also: → 1791335

This specific report is moot now for 5 months (I am sure we still see other flavors of shutdown hangs, of course).

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