1758115 - Intermittent SUMMARY: ThreadSanitizer: lock-order-inversion (potential deadlock) /builds/worker/checkouts/gecko/mozglue/misc/Mutex_posix.cpp:96:3 in mutexLock

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

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

---

[task 2022-03-04T13:00:12.787Z] 13:00:12     INFO - TEST-START | dom/animation/test/mozilla/test_restyles.html
[task 2022-03-04T13:00:21.464Z] 13:00:21     INFO - GECKO(1583) | ==================
[task 2022-03-04T13:00:21.464Z] 13:00:21     INFO - GECKO(1583) | WARNING: ThreadSanitizer: lock-order-inversion (potential deadlock) (pid=1760)
[task 2022-03-04T13:00:21.465Z] 13:00:21     INFO - GECKO(1583) |   Cycle in lock order graph: M82889003342243712 (0x000000000000) => M872989194249890096 (0x000000000000) => M82889003342243712
[task 2022-03-04T13:00:21.466Z] 13:00:21     INFO - GECKO(1583) |   Mutex M872989194249890096 acquired here while holding mutex M82889003342243712 in main thread:
[task 2022-03-04T13:00:21.466Z] 13:00:21     INFO - GECKO(1583) |     #0 pthread_mutex_lock /builds/worker/fetches/llvm-project/compiler-rt/lib/tsan/../sanitizer_common/sanitizer_common_interceptors.inc:4249:3 (firefox+0x77448)
[task 2022-03-04T13:00:21.467Z] 13:00:21     INFO - GECKO(1583) |     #1 mutexLock /builds/worker/checkouts/gecko/mozglue/misc/Mutex_posix.cpp:96:3 (firefox+0x137e5b)
[task 2022-03-04T13:00:21.467Z] 13:00:21     INFO - GECKO(1583) |     #2 mozilla::detail::MutexImpl::lock() /builds/worker/checkouts/gecko/mozglue/misc/Mutex_posix.cpp:118:43 (firefox+0x137e5b)
[task 2022-03-04T13:00:21.476Z] 13:00:21     INFO - GECKO(1583) |     #3 Lock /builds/worker/workspace/obj-build/dist/include/mozilla/Mutex.h:63:23 (libxul.so+0x6cd6077)
[task 2022-03-04T13:00:21.476Z] 13:00:21     INFO - GECKO(1583) |     #4 Lock /builds/worker/workspace/obj-build/dist/include/mozilla/StaticMutex.h:38:26 (libxul.so+0x6cd6077)
[task 2022-03-04T13:00:21.476Z] 13:00:21     INFO - GECKO(1583) |     #5 BaseAutoLock /builds/worker/workspace/obj-build/dist/include/mozilla/Mutex.h:158:57 (libxul.so+0x6cd6077)
[task 2022-03-04T13:00:21.476Z] 13:00:21     INFO - GECKO(1583) |     #6 mozilla::TimelineConsumers::IsEmpty() /builds/worker/checkouts/gecko/docshell/base/timeline/TimelineConsumers.cpp:147:23 (libxul.so+0x6cd6077)
[task 2022-03-04T13:00:21.476Z] 13:00:21     INFO - GECKO(1583) |     #7 mozilla::CycleCollectedJSRuntime::GCNurseryCollectionCallback(JSContext*, JS::GCNurseryProgress, JS::GCReason) /builds/worker/checkouts/gecko/xpcom/base/CycleCollectedJSRuntime.cpp:1162:32 (libxul.so+0xea888a)
[task 2022-03-04T13:00:21.477Z] 13:00:21     INFO - GECKO(1583) |     #8 js::gcstats::Statistics::beginNurseryCollection(JS::GCReason) /builds/worker/checkouts/gecko/js/src/gc/Statistics.cpp:1112:5 (libxul.so+0x7aa5338)
[task 2022-03-04T13:00:21.477Z] 13:00:21     INFO - GECKO(1583) |     #9 js::Nursery::collect(JS::GCOptions, JS::GCReason) /builds/worker/checkouts/gecko/js/src/gc/Nursery.cpp:1091:11 (libxul.so+0x7a8c928)
[task 2022-03-04T13:00:21.478Z] 13:00:21     INFO - GECKO(1583) |     #10 js::gc::GCRuntime::collectNursery(JS::GCOptions, JS::GCReason, js::gcstats::PhaseKind) /builds/worker/checkouts/gecko/js/src/gc/GC.cpp:4143:13 (libxul.so+0x7a634a5)
[task 2022-03-04T13:00:21.478Z] 13:00:21     INFO - GECKO(1583) |     #11 js::gc::GCRuntime::minorGC(JS::GCReason, js::gcstats::PhaseKind) /builds/worker/checkouts/gecko/js/src/gc/GC.cpp:4109:3 (libxul.so+0x7a6692f)
[task 2022-03-04T13:00:21.479Z] 13:00:21     INFO - GECKO(1583) |     #12 tryNewNurseryObject<js::CanGC> /builds/worker/checkouts/gecko/js/src/gc/Allocator.cpp:128:23 (libxul.so+0x7a442b9)
[task 2022-03-04T13:00:21.479Z] 13:00:21     INFO - GECKO(1583) |     #13 JSObject* js::AllocateObject<(js::AllowGC)1>(JSContext*, js::gc::AllocKind, unsigned long, js::gc::InitialHeap, JSClass const*, js::gc::AllocSite*) /builds/worker/checkouts/gecko/js/src/gc/Allocator.cpp:79:28 (libxul.so+0x7a442b9)
[task 2022-03-04T13:00:21.479Z] 13:00:21     INFO - GECKO(1583) |     #14 js::NativeObject::create(JSContext*, js::gc::AllocKind, js::gc::InitialHeap, JS::Handle<js::Shape*>, js::gc::AllocSite*) /builds/worker/checkouts/gecko/js/src/vm/NativeObject-inl.h:445:7 (libxul.so+0x73e9052)
[task 2022-03-04T13:00:21.480Z] 13:00:21     INFO - GECKO(1583) |     #15 createWithShape /builds/worker/checkouts/gecko/js/src/vm/PlainObject-inl.h:36:23 (libxul.so+0x75b4116)
[task 2022-03-04T13:00:21.480Z] 13:00:21     INFO - GECKO(1583) |     #16 js::NewPlainObject(JSContext*, js::NewObjectKind) /builds/worker/checkouts/gecko/js/src/vm/PlainObject.cpp:166:10 (libxul.so+0x75b4116)
[task 2022-03-04T13:00:21.481Z] 13:00:21     INFO - GECKO(1583) |     #17 JS_NewPlainObject(JSContext*) /builds/worker/checkouts/gecko/js/src/jsapi.cpp:1850:10 (libxul.so+0x77c8707)
[task 2022-03-04T13:00:21.481Z] 13:00:21     INFO - GECKO(1583) |     #18 mozilla::dom::ProfileTimelineStackFrame::ToObjectInternal(JSContext*, JS::MutableHandle<JS::Value>) const /builds/worker/workspace/obj-build/dom/bindings/ProfileTimelineMarkerBinding.cpp:292:33 (libxul.so+0x2becb14)
[task 2022-03-04T13:00:21.482Z] 13:00:21     INFO - GECKO(1583) |     #19 ToJSValue<mozilla::dom::RootedDictionary<mozilla::dom::ProfileTimelineStackFrame> > /builds/worker/workspace/obj-build/dist/include/mozilla/dom/ToJSValue.h:283:20 (libxul.so+0x6ccd77b)
[task 2022-03-04T13:00:21.482Z] 13:00:21     INFO - GECKO(1583) |     #20 mozilla::JavascriptTimelineMarker::AddDetails(JSContext*, mozilla::dom::ProfileTimelineMarker&) /builds/worker/checkouts/gecko/docshell/base/timeline/JavascriptTimelineMarker.h:75:11 (libxul.so+0x6ccd77b)
[task 2022-03-04T13:00:21.482Z] 13:00:21     INFO - GECKO(1583) |     #21 mozilla::ObservedDocShell::PopMarkers(JSContext*, nsTArray<mozilla::dom::ProfileTimelineMarker>&) /builds/worker/checkouts/gecko/docshell/base/timeline/ObservedDocShell.cpp:148:27 (libxul.so+0x6cd7d1e)
[task 2022-03-04T13:00:21.483Z] 13:00:21     INFO - GECKO(1583) |     #22 mozilla::TimelineConsumers::PopMarkers(nsDocShell*, JSContext*, nsTArray<mozilla::dom::ProfileTimelineMarker>&) /builds/worker/checkouts/gecko/docshell/base/timeline/TimelineConsumers.cpp:268:25 (libxul.so+0x6cd90bb)
[task 2022-03-04T13:00:21.483Z] 13:00:21     INFO - GECKO(1583) |     #23 nsDocShell::PopProfileTimelineMarkers(JSContext*, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/docshell/base/nsDocShell.cpp:2300:14 (libxul.so+0x6c62f1a)
[task 2022-03-04T13:00:21.484Z] 13:00:21     INFO - GECKO(1583) |     #24 non-virtual thunk to nsDocShell::PopProfileTimelineMarkers(JSContext*, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/docshell/base/nsDocShell.cpp (libxul.so+0x6c6316c)
[task 2022-03-04T13:00:21.484Z] 13:00:21     INFO - GECKO(1583) |     #25 NS_InvokeByIndex /builds/worker/checkouts/gecko/xpcom/reflect/xptcall/md/unix/xptcinvoke_asm_x86_64_unix.S:101 (libxul.so+0xfe6355)
[task 2022-03-04T13:00:21.485Z] 13:00:21     INFO - GECKO(1583) |     #26 XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNativeJSOps.cpp:923:10 (libxul.so+0x1b5ed36)
[task 2022-03-04T13:00:21.485Z] 13:00:21     INFO - GECKO(1583) |     #27 <null> <null> (0x7f49d3f0ca31)
[task 2022-03-04T13:00:21.485Z] 13:00:21     INFO - GECKO(1583) |     #28 js::RunScript(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:384:32 (libxul.so+0x73c7b05)
[task 2022-03-04T13:00:21.486Z] 13:00:21     INFO - GECKO(1583) |     #29 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:544:13 (libxul.so+0x73de789)
[task 2022-03-04T13:00:21.486Z] 13:00:21     INFO - GECKO(1583) |     #30 InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:572:10 (libxul.so+0x73df63e)
[task 2022-03-04T13:00:21.487Z] 13:00:21     INFO - GECKO(1583) |     #31 js::CallFromStack(JSContext*, JS::CallArgs const&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:576:10 (libxul.so+0x73df513)
[task 2022-03-04T13:00:21.487Z] 13:00:21     INFO - GECKO(1583) |     #32 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:1595:10 (libxul.so+0x7b67831)
[task 2022-03-04T13:00:21.488Z] 13:00:21     INFO - GECKO(1583) |     #33 <null> <null> (0x7f49d3e78e18)
[task 2022-03-04T13:00:21.488Z] 13:00:21     INFO - GECKO(1583) |     #34 js::RunScript(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:384:32 (libxul.so+0x73c7b05)
[task 2022-03-04T13:00:21.489Z] 13:00:21     INFO - GECKO(1583) |     #35 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:544:13 (libxul.so+0x73de789)
[task 2022-03-04T13:00:21.489Z] 13:00:21     INFO - GECKO(1583) |     #36 InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:572:10 (libxul.so+0x73df63e)
[task 2022-03-04T13:00:21.490Z] 13:00:21     INFO - GECKO(1583) |     #37 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 (libxul.so+0x73df71a)
[task 2022-03-04T13:00:21.490Z] 13:00:21     INFO - GECKO(1583) |     #38 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 (libxul.so+0x74a63b8)
[task 2022-03-04T13:00:21.490Z] 13:00:21     INFO - GECKO(1583) |     #39 xpc::FunctionForwarder(JSContext*, unsigned int, JS::Value*) /builds/worker/checkouts/gecko/js/xpconnect/src/ExportHelpers.cpp:382:12 (libxul.so+0x1b03151)
[task 2022-03-04T13:00:21.491Z] 13:00:21     INFO - GECKO(1583) |     #40 CallJSNative /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:425:13 (libxul.so+0x73de602)
[task 2022-03-04T13:00:21.491Z] 13:00:21     INFO - GECKO(1583) |     #41 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:512:12 (libxul.so+0x73de602)
[task 2022-03-04T13:00:21.492Z] 13:00:21     INFO - GECKO(1583) |     #42 InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:572:10 (libxul.so+0x73df63e)
[task 2022-03-04T13:00:21.492Z] 13:00:21     INFO - GECKO(1583) |     #43 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 (libxul.so+0x73df71a)
[task 2022-03-04T13:00:21.493Z] 13:00:21     INFO - GECKO(1583) |     #44 js::ScriptedProxyHandler::call(JSContext*, JS::Handle<JSObject*>, JS::CallArgs const&) const /builds/worker/checkouts/gecko/js/src/proxy/ScriptedProxyHandler.cpp:1322:10 (libxul.so+0x7811ce5)
[task 2022-03-04T13:00:21.493Z] 13:00:21     INFO - GECKO(1583) |     #45 js::Proxy::call(JSContext*, JS::Handle<JSObject*>, JS::CallArgs const&) /builds/worker/checkouts/gecko/js/src/proxy/Proxy.cpp:654:19 (libxul.so+0x7809d23)
[task 2022-03-04T13:00:21.493Z] 13:00:21     INFO - GECKO(1583) |     #46 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:492:14 (libxul.so+0x73ded15)
[task 2022-03-04T13:00:21.502Z] 13:00:21     INFO - GECKO(1583) |     #47 InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:572:10 (libxul.so+0x73df63e)
[task 2022-03-04T13:00:21.508Z] 13:00:21     INFO - GECKO(1583) |     #48 js::CallFromStack(JSContext*, JS::CallArgs const&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:576:10 (libxul.so+0x73df513)
[task 2022-03-04T13:00:21.509Z] 13:00:21     INFO - GECKO(1583) |     #49 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:1595:10 (libxul.so+0x7b67831)
[task 2022-03-04T13:00:21.509Z] 13:00:21     INFO - GECKO(1583) |     #50 <null> <null> (0x7f49d3e78e18)
[task 2022-03-04T13:00:21.510Z] 13:00:21     INFO - GECKO(1583) |     #51 js::RunScript(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:384:32 (libxul.so+0x73c7b05)
[task 2022-03-04T13:00:21.510Z] 13:00:21     INFO - GECKO(1583) |     #52 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:544:13 (libxul.so+0x73de789)
[task 2022-03-04T13:00:21.511Z] 13:00:21     INFO - GECKO(1583) |     #53 InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:572:10 (libxul.so+0x73df63e)
[task 2022-03-04T13:00:21.511Z] 13:00:21     INFO - GECKO(1583) |     #54 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 (libxul.so+0x73df71a)
[task 2022-03-04T13:00:21.512Z] 13:00:21     INFO - GECKO(1583) |     #55 Call /builds/worker/checkouts/gecko/js/src/vm/Interpreter.h:106:10 (libxul.so+0x760af77)
[task 2022-03-04T13:00:21.512Z] 13:00:21     INFO - GECKO(1583) |     #56 PromiseReactionJob(JSContext*, unsigned int, JS::Value*) /builds/worker/checkouts/gecko/js/src/builtin/Promise.cpp:2067:10 (libxul.so+0x760af77)
[task 2022-03-04T13:00:21.513Z] 13:00:21     INFO - GECKO(1583) |     #57 CallJSNative /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:425:13 (libxul.so+0x73de602)
[task 2022-03-04T13:00:21.513Z] 13:00:21     INFO - GECKO(1583) |     #58 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:512:12 (libxul.so+0x73de602)
[task 2022-03-04T13:00:21.514Z] 13:00:21     INFO - GECKO(1583) |     #59 InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:572:10 (libxul.so+0x73df63e)
[task 2022-03-04T13:00:21.514Z] 13:00:21     INFO - GECKO(1583) |     #60 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 (libxul.so+0x73df71a)
[task 2022-03-04T13:00:21.515Z] 13:00:21     INFO - GECKO(1583) |     #61 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 (libxul.so+0x74a63b8)
[task 2022-03-04T13:00:21.516Z] 13:00:21     INFO - GECKO(1583) |     #62 mozilla::dom::PromiseJobCallback::Call(mozilla::dom::BindingCallContext&, JS::Handle<JS::Value>, mozilla::ErrorResult&) /builds/worker/workspace/obj-build/dom/bindings/PromiseBinding.cpp:35:8 (libxul.so+0x2bf0a2e)
[task 2022-03-04T13:00:21.516Z] 13:00:21     INFO - GECKO(1583) |     #63 Call /builds/worker/workspace/obj-build/dist/include/mozilla/dom/PromiseBinding.h:89:12 (libxul.so+0xeb438e)
[task 2022-03-04T13:00:21.517Z] 13:00:21     INFO - GECKO(1583) |     #64 Call /builds/worker/workspace/obj-build/dist/include/mozilla/dom/PromiseBinding.h:102:12 (libxul.so+0xeb438e)
[task 2022-03-04T13:00:21.517Z] 13:00:21     INFO - GECKO(1583) |     #65 mozilla::PromiseJobRunnable::Run(mozilla::AutoSlowOperation&) /builds/worker/checkouts/gecko/xpcom/base/CycleCollectedJSContext.cpp:213:18 (libxul.so+0xeb438e)
[task 2022-03-04T13:00:21.518Z] 13:00:21     INFO - GECKO(1583) |     #66 mozilla::CycleCollectedJSContext::PerformMicroTaskCheckPoint(bool) /builds/worker/checkouts/gecko/xpcom/base/CycleCollectedJSContext.cpp:676:17 (libxul.so+0xea1b54)
[task 2022-03-04T13:00:21.518Z] 13:00:21     INFO - GECKO(1583) |     #67 LeaveMicroTask /builds/worker/workspace/obj-build/dist/include/mozilla/CycleCollectedJSContext.h:244:7 (libxul.so+0x3680de7)
[task 2022-03-04T13:00:21.519Z] 13:00:21     INFO - GECKO(1583) |     #68 mozilla::dom::CallbackObject::CallSetup::~CallSetup() /builds/worker/checkouts/gecko/dom/bindings/CallbackObject.cpp:393:11 (libxul.so+0x3680de7)
[task 2022-03-04T13:00:21.522Z] 13:00:21     INFO - GECKO(1583) |     #69 Call /builds/worker/workspace/obj-build/dist/include/mozilla/dom/AnimationFrameProviderBinding.h:86:3 (libxul.so+0x54721e6)
[task 2022-03-04T13:00:21.522Z] 13:00:21     INFO - GECKO(1583) |     #70 Call /builds/worker/workspace/obj-build/dist/include/mozilla/dom/AnimationFrameProviderBinding.h:98:12 (libxul.so+0x54721e6)
[task 2022-03-04T13:00:21.522Z] 13:00:21     INFO - GECKO(1583) |     #71 nsRefreshDriver::RunFrameRequestCallbacks(mozilla::TimeStamp) /builds/worker/checkouts/gecko/layout/base/nsRefreshDriver.cpp:2114:44 (libxul.so+0x54721e6)
[task 2022-03-04T13:00:21.522Z] 13:00:21     INFO - GECKO(1583) |     #72 nsRefreshDriver::Tick(mozilla::layers::BaseTransactionId<mozilla::VsyncIdType>, mozilla::TimeStamp, nsRefreshDriver::IsExtraTick) /builds/worker/checkouts/gecko/layout/base/nsRefreshDriver.cpp:2385:7 (libxul.so+0x546ec07)
[task 2022-03-04T13:00:21.522Z] 13:00:21     INFO - GECKO(1583) |     #73 TickDriver /builds/worker/checkouts/gecko/layout/base/nsRefreshDriver.cpp:350:13 (libxul.so+0x5478709)
[task 2022-03-04T13:00:21.522Z] 13:00:21     INFO - GECKO(1583) |     #74 mozilla::RefreshDriverTimer::TickRefreshDrivers(mozilla::layers::BaseTransactionId<mozilla::VsyncIdType>, mozilla::TimeStamp, nsTArray<RefPtr<nsRefreshDriver> >&) /builds/worker/checkouts/gecko/layout/base/nsRefreshDriver.cpp:328:7 (libxul.so+0x5478709)
[task 2022-03-04T13:00:21.522Z] 13:00:21     INFO - GECKO(1583) |     #75 mozilla::RefreshDriverTimer::Tick(mozilla::layers::BaseTransactionId<mozilla::VsyncIdType>, mozilla::TimeStamp) /builds/worker/checkouts/gecko/layout/base/nsRefreshDriver.cpp:344:5 (libxul.so+0x5478506)
[task 2022-03-04T13:00:21.523Z] 13:00:21     INFO - GECKO(1583) |     #76 mozilla::VsyncRefreshDriverTimer::RunRefreshDrivers(mozilla::layers::BaseTransactionId<mozilla::VsyncIdType>, mozilla::TimeStamp) /builds/worker/checkouts/gecko/layout/base/nsRefreshDriver.cpp:788:5 (libxul.so+0x54782ee)
[task 2022-03-04T13:00:21.523Z] 13:00:21     INFO - GECKO(1583) |     #77 mozilla::VsyncRefreshDriverTimer::RefreshDriverVsyncObserver::TickRefreshDriver(mozilla::layers::BaseTransactionId<mozilla::VsyncIdType>, mozilla::TimeStamp) /builds/worker/checkouts/gecko/layout/base/nsRefreshDriver.cpp:693:16 (libxul.so+0x5477b9b)
[task 2022-03-04T13:00:21.524Z] 13:00:21     INFO - GECKO(1583) |     #78 mozilla::VsyncRefreshDriverTimer::RefreshDriverVsyncObserver::NotifyVsyncOnMainThread() /builds/worker/checkouts/gecko/layout/base/nsRefreshDriver.cpp:610:7 (libxul.so+0x547746d)
[task 2022-03-04T13:00:21.524Z] 13:00:21     INFO - GECKO(1583) |     #79 mozilla::VsyncRefreshDriverTimer::RefreshDriverVsyncObserver::NotifyVsync(mozilla::VsyncEvent const&) /builds/worker/checkouts/gecko/layout/base/nsRefreshDriver.cpp:516:9 (libxul.so+0x5476ffa)
[task 2022-03-04T13:00:21.525Z] 13:00:21     INFO - GECKO(1583) |     #80 mozilla::dom::VsyncMainChild::RecvNotify(mozilla::VsyncEvent const&, float const&) /builds/worker/checkouts/gecko/dom/ipc/VsyncMainChild.cpp:68:15 (libxul.so+0x4aa5fbe)
[task 2022-03-04T13:00:21.526Z] 13:00:21     INFO - GECKO(1583) |     #81 mozilla::dom::PVsyncChild::OnMessageReceived(IPC::Message const&) /builds/worker/workspace/obj-build/ipc/ipdl/PVsyncChild.cpp:209:54 (libxul.so+0x4c6474d)
[task 2022-03-04T13:00:21.526Z] 13:00:21     INFO - GECKO(1583) |     #82 mozilla::ipc::PBackgroundChild::OnMessageReceived(IPC::Message const&) /builds/worker/workspace/obj-build/ipc/ipdl/PBackgroundChild.cpp:6193:32 (libxul.so+0x1a48e9e)
[task 2022-03-04T13:00:21.527Z] 13:00:21     INFO - GECKO(1583) |     #83 mozilla::ipc::MessageChannel::DispatchAsyncMessage(mozilla::ipc::ActorLifecycleProxy*, IPC::Message const&) /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1674:25 (libxul.so+0x1a0279b)
[task 2022-03-04T13:00:21.527Z] 13:00:21     INFO - GECKO(1583) |     #84 mozilla::ipc::MessageChannel::DispatchMessage(mozilla::ipc::ActorLifecycleProxy*, IPC::Message&&) /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1599:9 (libxul.so+0x1a011d3)
[task 2022-03-04T13:00:21.528Z] 13:00:21     INFO - GECKO(1583) |     #85 mozilla::ipc::MessageChannel::RunMessage(mozilla::ipc::ActorLifecycleProxy*, mozilla::ipc::MessageChannel::MessageTask&) /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1462:3 (libxul.so+0x1a017f4)
[task 2022-03-04T13:00:21.528Z] 13:00:21     INFO - GECKO(1583) |     #86 mozilla::ipc::MessageChannel::MessageTask::Run() /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1496:14 (libxul.so+0x1a01e47)
[task 2022-03-04T13:00:21.529Z] 13:00:21     INFO - GECKO(1583) |     #87 mozilla::RunnableTask::Run() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:467:16 (libxul.so+0xfc9b77)
[task 2022-03-04T13:00:21.529Z] 13:00:21     INFO - GECKO(1583) |     #88 mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:770:26 (libxul.so+0xfa3dcd)
[task 2022-03-04T13:00:21.529Z] 13:00:21     INFO - GECKO(1583) |     #89 mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:606:15 (libxul.so+0xfa24a6)
[task 2022-03-04T13:00:21.530Z] 13:00:21     INFO - GECKO(1583) |     #90 mozilla::TaskController::ProcessPendingMTTask(bool) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:390:36 (libxul.so+0xfa2782)
[task 2022-03-04T13:00:21.530Z] 13:00:21     INFO - GECKO(1583) |     #91 operator() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:127:37 (libxul.so+0xfcd10a)
[task 2022-03-04T13:00:21.531Z] 13:00:21     INFO - GECKO(1583) |     #92 mozilla::detail::RunnableFunction<mozilla::TaskController::InitializeInternal()::$_1>::Run() /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.h:531:5 (libxul.so+0xfcd10a)
[task 2022-03-04T13:00:21.531Z] 13:00:21     INFO - GECKO(1583) |     #93 nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1173:16 (libxul.so+0xfb7313)
[task 2022-03-04T13:00:21.532Z] 13:00:21     INFO - GECKO(1583) |     #94 NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:467:10 (libxul.so+0xfbe362)
[task 2022-03-04T13:00:21.532Z] 13:00:21     INFO - GECKO(1583) |     #95 mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:107:5 (libxul.so+0x1a062d0)
[task 2022-03-04T13:00:21.532Z] 13:00:21     INFO - GECKO(1583) |     #96 mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:268:30 (libxul.so+0x1a06d0b)
[task 2022-03-04T13:00:21.533Z] 13:00:21     INFO - GECKO(1583) |     #97 RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:331:10 (libxul.so+0x1981a4c)
[task 2022-03-04T13:00:21.534Z] 13:00:21     INFO - GECKO(1583) |     #98 RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:324:3 (libxul.so+0x1981a4c)
[task 2022-03-04T13:00:21.535Z] 13:00:21     INFO - GECKO(1583) |     #99 MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:306:3 (libxul.so+0x1981a4c)
[task 2022-03-04T13:00:21.535Z] 13:00:21     INFO - GECKO(1583) |     #100 nsBaseAppShell::Run() /builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp:137:27 (libxul.so+0x5169f66)
[task 2022-03-04T13:00:21.536Z] 13:00:21     INFO - GECKO(1583) |     #101 XRE_RunAppShell() /builds/worker/checkouts/gecko/toolkit/xre/nsEmbedFunctions.cpp:870:20 (libxul.so+0x72a0559)
[task 2022-03-04T13:00:21.536Z] 13:00:21     INFO - GECKO(1583) |     #102 mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:235:9 (libxul.so+0x1a06cbd)
[task 2022-03-04T13:00:21.537Z] 13:00:21     INFO - GECKO(1583) |     #103 RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:331:10 (libxul.so+0x1981a4c)
[task 2022-03-04T13:00:21.537Z] 13:00:21     INFO - GECKO(1583) |     #104 RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:324:3 (libxul.so+0x1981a4c)
[task 2022-03-04T13:00:21.538Z] 13:00:21     INFO - GECKO(1583) |     #105 MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:306:3 (libxul.so+0x1981a4c)
[task 2022-03-04T13:00:21.538Z] 13:00:21     INFO - GECKO(1583) |     #106 XRE_InitChildProcess(int, char**, XREChildData const*) /builds/worker/checkouts/gecko/toolkit/xre/nsEmbedFunctions.cpp:729:34 (libxul.so+0x72a029a)
[task 2022-03-04T13:00:21.539Z] 13:00:21     INFO - GECKO(1583) |     #107 mozilla::BootstrapImpl::XRE_InitChildProcess(int, char**, XREChildData const*) /builds/worker/checkouts/gecko/toolkit/xre/Bootstrap.cpp:67:12 (libxul.so+0x72a8092)
[task 2022-03-04T13:00:21.540Z] 13:00:21     INFO - GECKO(1583) |     #108 content_process_main /builds/worker/checkouts/gecko/browser/app/../../ipc/contentproc/plugin-container.cpp:57:28 (firefox+0xd0297)
[task 2022-03-04T13:00:21.540Z] 13:00:21     INFO - GECKO(1583) |     #109 main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:327:18 (firefox+0xd0297)
[task 2022-03-04T13:00:21.541Z] 13:00:21     INFO - GECKO(1583) |     Hint: use TSAN_OPTIONS=second_deadlock_stack=1 to get more informative warning message
[task 2022-03-04T13:00:21.541Z] 13:00:21     INFO - GECKO(1583) |   Mutex M82889003342243712 acquired here while holding mutex M872989194249890096 in main thread:
[task 2022-03-04T13:00:21.542Z] 13:00:21     INFO - GECKO(1583) |     #0 pthread_mutex_lock /builds/worker/fetches/llvm-project/compiler-rt/lib/tsan/../sanitizer_common/sanitizer_common_interceptors.inc:4249:3 (firefox+0x77448)
[task 2022-03-04T13:00:21.542Z] 13:00:21     INFO - GECKO(1583) |     #1 mutexLock /builds/worker/checkouts/gecko/mozglue/misc/Mutex_posix.cpp:96:3 (firefox+0x137e5b)
[task 2022-03-04T13:00:21.543Z] 13:00:21     INFO - GECKO(1583) |     #2 mozilla::detail::MutexImpl::lock() /builds/worker/checkouts/gecko/mozglue/misc/Mutex_posix.cpp:118:43 (firefox+0x137e5b)
[task 2022-03-04T13:00:21.543Z] 13:00:21     INFO - GECKO(1583) |     #3 Lock /builds/worker/workspace/obj-build/dist/include/mozilla/Mutex.h:63:23 (libxul.so+0x6cd71b7)
[task 2022-03-04T13:00:21.544Z] 13:00:21     INFO - GECKO(1583) |     #4 BaseAutoLock /builds/worker/workspace/obj-build/dist/include/mozilla/Mutex.h:158:57 (libxul.so+0x6cd71b7)
[task 2022-03-04T13:00:21.544Z] 13:00:21     INFO - GECKO(1583) |     #5 mozilla::ObservedDocShell::ClearMarkers() /builds/worker/checkouts/gecko/docshell/base/timeline/ObservedDocShell.cpp:51:17 (libxul.so+0x6cd71b7)
[task 2022-03-04T13:00:21.545Z] 13:00:21     INFO - GECKO(1583) |     #6 mozilla::TimelineConsumers::RemoveConsumer(nsDocShell*) /builds/worker/checkouts/gecko/docshell/base/timeline/TimelineConsumers.cpp:134:19 (libxul.so+0x6cd8b36)
[task 2022-03-04T13:00:21.545Z] 13:00:21     INFO - GECKO(1583) |     #7 SetRecordProfileTimelineMarkers /builds/worker/checkouts/gecko/docshell/base/nsDocShell.cpp:2276:16 (libxul.so+0x6c62d76)
[task 2022-03-04T13:00:21.546Z] 13:00:21     INFO - GECKO(1583) |     #8 non-virtual thunk to nsDocShell::SetRecordProfileTimelineMarkers(bool) /builds/worker/checkouts/gecko/docshell/base/nsDocShell.cpp (libxul.so+0x6c62d76)
[task 2022-03-04T13:00:21.547Z] 13:00:21     INFO - GECKO(1583) |     #9 NS_InvokeByIndex /builds/worker/checkouts/gecko/xpcom/reflect/xptcall/md/unix/xptcinvoke_asm_x86_64_unix.S:101 (libxul.so+0xfe6355)
[task 2022-03-04T13:00:21.547Z] 13:00:21     INFO - GECKO(1583) |     #10 SetAttribute /builds/worker/checkouts/gecko/js/xpconnect/src/xpcprivate.h:1484:12 (libxul.so+0x1b5f216)
[task 2022-03-04T13:00:21.548Z] 13:00:21     INFO - GECKO(1583) |     #11 XPC_WN_GetterSetter(JSContext*, unsigned int, JS::Value*) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNativeJSOps.cpp:954:19 (libxul.so+0x1b5f216)
[task 2022-03-04T13:00:21.548Z] 13:00:21     INFO - GECKO(1583) |     #12 CallJSNative /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:425:13 (libxul.so+0x73de602)
[task 2022-03-04T13:00:21.549Z] 13:00:21     INFO - GECKO(1583) |     #13 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:512:12 (libxul.so+0x73de602)
[task 2022-03-04T13:00:21.549Z] 13:00:21     INFO - GECKO(1583) |     #14 InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:572:10 (libxul.so+0x73df63e)
[task 2022-03-04T13:00:21.550Z] 13:00:21     INFO - GECKO(1583) |     #15 Call /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:589:8 (libxul.so+0x73e08b4)
[task 2022-03-04T13:00:21.550Z] 13:00:21     INFO - GECKO(1583) |     #16 js::CallSetter(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::Handle<JS::Value>) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:730:10 (libxul.so+0x73e08b4)
[task 2022-03-04T13:00:21.551Z] 13:00:21     INFO - GECKO(1583) |     #17 SetExistingProperty(JSContext*, JS::Handle<JS::PropertyKey>, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::Handle<js::NativeObject*>, js::PropertyResult const&, JS::ObjectOpResult&) /builds/worker/checkouts/gecko/js/src/vm/NativeObject.cpp:2493:8 (libxul.so+0x75a431a)
[task 2022-03-04T13:00:21.552Z] 13:00:21     INFO - GECKO(1583) |     #18 bool js::NativeSetProperty<(js::QualifiedBool)1>(JSContext*, JS::Handle<js::NativeObject*>, JS::Handle<JS::PropertyKey>, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::ObjectOpResult&) /builds/worker/checkouts/gecko/js/src/vm/NativeObject.cpp:2527:14 (libxul.so+0x75a30a7)
[task 2022-03-04T13:00:21.552Z] 13:00:21     INFO - GECKO(1583) |     #19 SetProperty /builds/worker/checkouts/gecko/js/src/vm/ObjectOperations-inl.h:308:10 (libxul.so+0x7618d16)
[task 2022-03-04T13:00:21.553Z] 13:00:21     INFO - GECKO(1583) |     #20 Reflect_set(JSContext*, unsigned int, JS::Value*) /builds/worker/checkouts/gecko/js/src/builtin/Reflect.cpp:158:8 (libxul.so+0x7618d16)
[task 2022-03-04T13:00:21.554Z] 13:00:21     INFO - GECKO(1583) |     #21 <null> <null> (0x7f49d3ee27d0)
[task 2022-03-04T13:00:21.554Z] 13:00:21     INFO - GECKO(1583) |     #22 js::RunScript(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:384:32 (libxul.so+0x73c7b05)
[task 2022-03-04T13:00:21.555Z] 13:00:21     INFO - GECKO(1583) |     #23 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:544:13 (libxul.so+0x73de789)
[task 2022-03-04T13:00:21.555Z] 13:00:21     INFO - GECKO(1583) |     #24 InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:572:10 (libxul.so+0x73df63e)
[task 2022-03-04T13:00:21.556Z] 13:00:21     INFO - GECKO(1583) |     #25 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 (libxul.so+0x73df71a)
[task 2022-03-04T13:00:21.556Z] 13:00:21     INFO - GECKO(1583) |     #26 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 (libxul.so+0x74a63b8)
[task 2022-03-04T13:00:21.557Z] 13:00:21     INFO - GECKO(1583) |     #27 xpc::FunctionForwarder(JSContext*, unsigned int, JS::Value*) /builds/worker/checkouts/gecko/js/xpconnect/src/ExportHelpers.cpp:382:12 (libxul.so+0x1b03151)
[task 2022-03-04T13:00:21.558Z] 13:00:21     INFO - GECKO(1583) |     #28 CallJSNative /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:425:13 (libxul.so+0x73de602)
[task 2022-03-04T13:00:21.558Z] 13:00:21     INFO - GECKO(1583) |     #29 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:512:12 (libxul.so+0x73de602)
[task 2022-03-04T13:00:21.559Z] 13:00:21     INFO - GECKO(1583) |     #30 InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:572:10 (libxul.so+0x73df63e)
[task 2022-03-04T13:00:21.560Z] 13:00:21     INFO - GECKO(1583) |     #31 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 (libxul.so+0x73df71a)
[task 2022-03-04T13:00:21.560Z] 13:00:21     INFO - GECKO(1583) |     #32 js::ScriptedProxyHandler::set(JSContext*, JS::Handle<JSObject*>, JS::Handle<JS::PropertyKey>, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::ObjectOpResult&) const /builds/worker/checkouts/gecko/js/src/proxy/ScriptedProxyHandler.cpp:1232:10 (libxul.so+0x78114a5)
[task 2022-03-04T13:00:21.561Z] 13:00:21     INFO - GECKO(1583) |     #33 setInternal /builds/worker/checkouts/gecko/js/src/proxy/Proxy.cpp:542:19 (libxul.so+0x7808db4)
[task 2022-03-04T13:00:21.562Z] 13:00:21     INFO - GECKO(1583) |     #34 js::ProxySetProperty(JSContext*, JS::Handle<JSObject*>, JS::Handle<JS::PropertyKey>, JS::Handle<JS::Value>, bool) /builds/worker/checkouts/gecko/js/src/proxy/Proxy.cpp:557:8 (libxul.so+0x7808db4)
[task 2022-03-04T13:00:21.562Z] 13:00:21     INFO - GECKO(1583) |     #35 <null> <null> (0x7f49d3e7b166)
[task 2022-03-04T13:00:21.563Z] 13:00:21     INFO - GECKO(1583) |     #36 js::RunScript(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:384:32 (libxul.so+0x73c7b05)
[task 2022-03-04T13:00:21.564Z] 13:00:21     INFO - GECKO(1583) |     #37 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:544:13 (libxul.so+0x73de789)
[task 2022-03-04T13:00:21.564Z] 13:00:21     INFO - GECKO(1583) |     #38 InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:572:10 (libxul.so+0x73df63e)
[task 2022-03-04T13:00:21.565Z] 13:00:21     INFO - GECKO(1583) |     #39 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 (libxul.so+0x73df71a)
[task 2022-03-04T13:00:21.566Z] 13:00:21     INFO - GECKO(1583) |     #40 Call /builds/worker/checkouts/gecko/js/src/vm/Interpreter.h:106:10 (libxul.so+0x760af77)
[task 2022-03-04T13:00:21.566Z] 13:00:21     INFO - GECKO(1583) |     #41 PromiseReactionJob(JSContext*, unsigned int, JS::Value*) /builds/worker/checkouts/gecko/js/src/builtin/Promise.cpp:2067:10 (libxul.so+0x760af77)
[task 2022-03-04T13:00:21.567Z] 13:00:21     INFO - GECKO(1583) |     #42 CallJSNative /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:425:13 (libxul.so+0x73de602)
[task 2022-03-04T13:00:21.567Z] 13:00:21     INFO - GECKO(1583) |     #43 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:512:12 (libxul.so+0x73de602)
[task 2022-03-04T13:00:21.568Z] 13:00:21     INFO - GECKO(1583) |     #44 InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:572:10 (libxul.so+0x73df63e)
[task 2022-03-04T13:00:21.569Z] 13:00:21     INFO - GECKO(1583) |     #45 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 (libxul.so+0x73df71a)
[task 2022-03-04T13:00:21.569Z] 13:00:21     INFO - GECKO(1583) |     #46 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 (libxul.so+0x74a63b8)
[task 2022-03-04T13:00:21.573Z] 13:00:21     INFO - GECKO(1583) |     #47 mozilla::dom::PromiseJobCallback::Call(mozilla::dom::BindingCallContext&, JS::Handle<JS::Value>, mozilla::ErrorResult&) /builds/worker/workspace/obj-build/dom/bindings/PromiseBinding.cpp:35:8 (libxul.so+0x2bf0a2e)
[task 2022-03-04T13:00:21.573Z] 13:00:21     INFO - GECKO(1583) |     #48 Call /builds/worker/workspace/obj-build/dist/include/mozilla/dom/PromiseBinding.h:89:12 (libxul.so+0xeb438e)
[task 2022-03-04T13:00:21.573Z] 13:00:21     INFO - GECKO(1583) |     #49 Call /builds/worker/workspace/obj-build/dist/include/mozilla/dom/PromiseBinding.h:102:12 (libxul.so+0xeb438e)
[task 2022-03-04T13:00:21.573Z] 13:00:21     INFO - GECKO(1583) |     #50 mozilla::PromiseJobRunnable::Run(mozilla::AutoSlowOperation&) /builds/worker/checkouts/gecko/xpcom/base/CycleCollectedJSContext.cpp:213:18 (libxul.so+0xeb438e)
[task 2022-03-04T13:00:21.573Z] 13:00:21     INFO - GECKO(1583) |     #51 mozilla::CycleCollectedJSContext::PerformMicroTaskCheckPoint(bool) /builds/worker/checkouts/gecko/xpcom/base/CycleCollectedJSContext.cpp:676:17 (libxul.so+0xea1b54)
[task 2022-03-04T13:00:21.573Z] 13:00:21     INFO - GECKO(1583) |     #52 LeaveMicroTask /builds/worker/workspace/obj-build/dist/include/mozilla/CycleCollectedJSContext.h:244:7 (libxul.so+0x3680de7)
[task 2022-03-04T13:00:21.573Z] 13:00:21     INFO - GECKO(1583) |     #53 mozilla::dom::CallbackObject::CallSetup::~CallSetup() /builds/worker/checkouts/gecko/dom/bindings/CallbackObject.cpp:393:11 (libxul.so+0x3680de7)
[task 2022-03-04T13:00:21.574Z] 13:00:21     INFO - GECKO(1583) |     #54 Call /builds/worker/workspace/obj-build/dist/include/mozilla/dom/AnimationFrameProviderBinding.h:86:3 (libxul.so+0x54721e6)
[task 2022-03-04T13:00:21.574Z] 13:00:21     INFO - GECKO(1583) |     #55 Call /builds/worker/workspace/obj-build/dist/include/mozilla/dom/AnimationFrameProviderBinding.h:98:12 (libxul.so+0x54721e6)
[task 2022-03-04T13:00:21.574Z] 13:00:21     INFO - GECKO(1583) |     #56 nsRefreshDriver::RunFrameRequestCallbacks(mozilla::TimeStamp) /builds/worker/checkouts/gecko/layout/base/nsRefreshDriver.cpp:2114:44 (libxul.so+0x54721e6)
[task 2022-03-04T13:00:21.575Z] 13:00:21     INFO - GECKO(1583) |     #57 nsRefreshDriver::Tick(mozilla::layers::BaseTransactionId<mozilla::VsyncIdType>, mozilla::TimeStamp, nsRefreshDriver::IsExtraTick) /builds/worker/checkouts/gecko/layout/base/nsRefreshDriver.cpp:2385:7 (libxul.so+0x546ec07)
[task 2022-03-04T13:00:21.575Z] 13:00:21     INFO - GECKO(1583) |     #58 TickDriver /builds/worker/checkouts/gecko/layout/base/nsRefreshDriver.cpp:350:13 (libxul.so+0x5478709)
[task 2022-03-04T13:00:21.576Z] 13:00:21     INFO - GECKO(1583) |     #59 mozilla::RefreshDriverTimer::TickRefreshDrivers(mozilla::layers::BaseTransactionId<mozilla::VsyncIdType>, mozilla::TimeStamp, nsTArray<RefPtr<nsRefreshDriver> >&) /builds/worker/checkouts/gecko/layout/base/nsRefreshDriver.cpp:328:7 (libxul.so+0x5478709)
[task 2022-03-04T13:00:21.576Z] 13:00:21     INFO - GECKO(1583) |     #60 mozilla::RefreshDriverTimer::Tick(mozilla::layers::BaseTransactionId<mozilla::VsyncIdType>, mozilla::TimeStamp) /builds/worker/checkouts/gecko/layout/base/nsRefreshDriver.cpp:344:5 (libxul.so+0x5478506)
[task 2022-03-04T13:00:21.577Z] 13:00:21     INFO - GECKO(1583) |     #61 mozilla::VsyncRefreshDriverTimer::RunRefreshDrivers(mozilla::layers::BaseTransactionId<mozilla::VsyncIdType>, mozilla::TimeStamp) /builds/worker/checkouts/gecko/layout/base/nsRefreshDriver.cpp:788:5 (libxul.so+0x54782ee)
[task 2022-03-04T13:00:21.578Z] 13:00:21     INFO - GECKO(1583) |     #62 mozilla::VsyncRefreshDriverTimer::RefreshDriverVsyncObserver::TickRefreshDriver(mozilla::layers::BaseTransactionId<mozilla::VsyncIdType>, mozilla::TimeStamp) /builds/worker/checkouts/gecko/layout/base/nsRefreshDriver.cpp:693:16 (libxul.so+0x5477b9b)
[task 2022-03-04T13:00:21.578Z] 13:00:21     INFO - GECKO(1583) |     #63 mozilla::VsyncRefreshDriverTimer::RefreshDriverVsyncObserver::NotifyVsyncOnMainThread() /builds/worker/checkouts/gecko/layout/base/nsRefreshDriver.cpp:610:7 (libxul.so+0x547746d)
[task 2022-03-04T13:00:21.579Z] 13:00:21     INFO - GECKO(1583) |     #64 mozilla::VsyncRefreshDriverTimer::RefreshDriverVsyncObserver::NotifyVsync(mozilla::VsyncEvent const&) /builds/worker/checkouts/gecko/layout/base/nsRefreshDriver.cpp:516:9 (libxul.so+0x5476ffa)
[task 2022-03-04T13:00:21.580Z] 13:00:21     INFO - GECKO(1583) |     #65 mozilla::dom::VsyncMainChild::RecvNotify(mozilla::VsyncEvent const&, float const&) /builds/worker/checkouts/gecko/dom/ipc/VsyncMainChild.cpp:68:15 (libxul.so+0x4aa5fbe)
[task 2022-03-04T13:00:21.580Z] 13:00:21     INFO - GECKO(1583) |     #66 mozilla::dom::PVsyncChild::OnMessageReceived(IPC::Message const&) /builds/worker/workspace/obj-build/ipc/ipdl/PVsyncChild.cpp:209:54 (libxul.so+0x4c6474d)
[task 2022-03-04T13:00:21.581Z] 13:00:21     INFO - GECKO(1583) |     #67 mozilla::ipc::PBackgroundChild::OnMessageReceived(IPC::Message const&) /builds/worker/workspace/obj-build/ipc/ipdl/PBackgroundChild.cpp:6193:32 (libxul.so+0x1a48e9e)
[task 2022-03-04T13:00:21.581Z] 13:00:21     INFO - GECKO(1583) |     #68 mozilla::ipc::MessageChannel::DispatchAsyncMessage(mozilla::ipc::ActorLifecycleProxy*, IPC::Message const&) /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1674:25 (libxul.so+0x1a0279b)
[task 2022-03-04T13:00:21.582Z] 13:00:21     INFO - GECKO(1583) |     #69 mozilla::ipc::MessageChannel::DispatchMessage(mozilla::ipc::ActorLifecycleProxy*, IPC::Message&&) /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1599:9 (libxul.so+0x1a011d3)
[task 2022-03-04T13:00:21.582Z] 13:00:21     INFO - GECKO(1583) |     #70 mozilla::ipc::MessageChannel::RunMessage(mozilla::ipc::ActorLifecycleProxy*, mozilla::ipc::MessageChannel::MessageTask&) /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1462:3 (libxul.so+0x1a017f4)
[task 2022-03-04T13:00:21.583Z] 13:00:21     INFO - GECKO(1583) |     #71 mozilla::ipc::MessageChannel::MessageTask::Run() /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1496:14 (libxul.so+0x1a01e47)
[task 2022-03-04T13:00:21.583Z] 13:00:21     INFO - GECKO(1583) |     #72 mozilla::RunnableTask::Run() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:467:16 (libxul.so+0xfc9b77)
[task 2022-03-04T13:00:21.584Z] 13:00:21     INFO - GECKO(1583) |     #73 mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:770:26 (libxul.so+0xfa3dcd)
[task 2022-03-04T13:00:21.585Z] 13:00:21     INFO - GECKO(1583) |     #74 mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:606:15 (libxul.so+0xfa24a6)
[task 2022-03-04T13:00:21.585Z] 13:00:21     INFO - GECKO(1583) |     #75 mozilla::TaskController::ProcessPendingMTTask(bool) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:390:36 (libxul.so+0xfa2782)
[task 2022-03-04T13:00:21.586Z] 13:00:21     INFO - GECKO(1583) |     #76 operator() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:127:37 (libxul.so+0xfcd10a)
[task 2022-03-04T13:00:21.587Z] 13:00:21     INFO - GECKO(1583) |     #77 mozilla::detail::RunnableFunction<mozilla::TaskController::InitializeInternal()::$_1>::Run() /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.h:531:5 (libxul.so+0xfcd10a)
[task 2022-03-04T13:00:21.587Z] 13:00:21     INFO - GECKO(1583) |     #78 nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1173:16 (libxul.so+0xfb7313)
[task 2022-03-04T13:00:21.588Z] 13:00:21     INFO - GECKO(1583) |     #79 NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:467:10 (libxul.so+0xfbe362)
[task 2022-03-04T13:00:21.588Z] 13:00:21     INFO - GECKO(1583) |     #80 mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:107:5 (libxul.so+0x1a062d0)
[task 2022-03-04T13:00:21.589Z] 13:00:21     INFO - GECKO(1583) |     #81 mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:268:30 (libxul.so+0x1a06d0b)
[task 2022-03-04T13:00:21.589Z] 13:00:21     INFO - GECKO(1583) |     #82 RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:331:10 (libxul.so+0x1981a4c)
[task 2022-03-04T13:00:21.590Z] 13:00:21     INFO - GECKO(1583) |     #83 RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:324:3 (libxul.so+0x1981a4c)
[task 2022-03-04T13:00:21.590Z] 13:00:21     INFO - GECKO(1583) |     #84 MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:306:3 (libxul.so+0x1981a4c)
[task 2022-03-04T13:00:21.591Z] 13:00:21     INFO - GECKO(1583) |     #85 nsBaseAppShell::Run() /builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp:137:27 (libxul.so+0x5169f66)
[task 2022-03-04T13:00:21.591Z] 13:00:21     INFO - GECKO(1583) |     #86 XRE_RunAppShell() /builds/worker/checkouts/gecko/toolkit/xre/nsEmbedFunctions.cpp:870:20 (libxul.so+0x72a0559)
[task 2022-03-04T13:00:21.592Z] 13:00:21     INFO - GECKO(1583) |     #87 mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:235:9 (libxul.so+0x1a06cbd)
[task 2022-03-04T13:00:21.592Z] 13:00:21     INFO - GECKO(1583) |     #88 RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:331:10 (libxul.so+0x1981a4c)
[task 2022-03-04T13:00:21.593Z] 13:00:21     INFO - GECKO(1583) |     #89 RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:324:3 (libxul.so+0x1981a4c)
[task 2022-03-04T13:00:21.593Z] 13:00:21     INFO - GECKO(1583) |     #90 MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:306:3 (libxul.so+0x1981a4c)
[task 2022-03-04T13:00:21.593Z] 13:00:21     INFO - GECKO(1583) |     #91 XRE_InitChildProcess(int, char**, XREChildData const*) /builds/worker/checkouts/gecko/toolkit/xre/nsEmbedFunctions.cpp:729:34 (libxul.so+0x72a029a)
[task 2022-03-04T13:00:21.594Z] 13:00:21     INFO - GECKO(1583) |     #92 mozilla::BootstrapImpl::XRE_InitChildProcess(int, char**, XREChildData const*) /builds/worker/checkouts/gecko/toolkit/xre/Bootstrap.cpp:67:12 (libxul.so+0x72a8092)
[task 2022-03-04T13:00:21.594Z] 13:00:21     INFO - GECKO(1583) |     #93 content_process_main /builds/worker/checkouts/gecko/browser/app/../../ipc/contentproc/plugin-container.cpp:57:28 (firefox+0xd0297)
[task 2022-03-04T13:00:21.595Z] 13:00:21     INFO - GECKO(1583) |     #94 main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:327:18 (firefox+0xd0297)
[task 2022-03-04T13:00:21.595Z] 13:00:21     INFO - GECKO(1583) | SUMMARY: ThreadSanitizer: lock-order-inversion (potential deadlock) /builds/worker/checkouts/gecko/mozglue/misc/Mutex_posix.cpp:96:3 in mutexLock
[task 2022-03-04T13:00:21.596Z] 13:00:21     INFO - GECKO(1583) | ==================
[task 2022-03-04T13:00:21.596Z] 13:00:21     INFO - GECKO(1583) | ###!!! [Parent][PContentParent] Error: Send(msgname=PContent::Msg_FlushTabState) Channel error: cannot send/recv
[task 2022-03-04T13:00:21.596Z] 13:00:21     INFO - GECKO(1583) | ###!!! [Parent][PContentParent] Error: Send(msgname=PContent::Msg_CommitBrowsingContextTransaction) Channel error: cannot send/recv
[task 2022-03-04T13:00:21.597Z] 13:00:21     INFO - GECKO(1583) | ###!!! [Parent][PContentParent] Error: Send(msgname=PContent::Msg_DiscardBrowsingContext) Channel error: cannot send/recv
[task 2022-03-04T13:00:21.940Z] 13:00:21    ERROR - GECKO(1583) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2022-03-04T13:00:22.384Z] 13:00:22     INFO - GECKO(1583) | 1646398822383	Marionette	TRACE	Received observer notification quit-application
[task 2022-03-04T13:00:22.386Z] 13:00:22     INFO - GECKO(1583) | 1646398822384	Marionette	INFO	Stopped listening on port 2828
[task 2022-03-04T13:00:22.388Z] 13:00:22     INFO - GECKO(1583) | 1646398822385	Marionette	DEBUG	Marionette stopped listening
[task 2022-03-04T13:00:23.141Z] 13:00:23     INFO - GECKO(1583) | ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-04T13:00:23.143Z] 13:00:23     INFO - GECKO(1583) | ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-04T13:00:23.152Z] 13:00:23     INFO - GECKO(1583) | ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-04T13:00:23.152Z] 13:00:23     INFO - GECKO(1583) | ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-04T13:00:23.157Z] 13:00:23     INFO - GECKO(1583) | ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-04T13:00:33.218Z] 13:00:33     INFO - TEST-INFO | Main app process: exit 0
[task 2022-03-04T13:00:33.222Z] 13:00:33     INFO - runtests.py | Application ran for: 0:01:10.340564
[task 2022-03-04T13:00:33.222Z] 13:00:33     INFO - zombiecheck | Reading PID log: /tmp/tmpkmuuiw3cpidlog
[task 2022-03-04T13:00:33.222Z] 13:00:33     INFO - ==> process 1583 launched child process 1599
[task 2022-03-04T13:00:33.222Z] 13:00:33     INFO - ==> process 1583 launched child process 1689
[task 2022-03-04T13:00:33.222Z] 13:00:33     INFO - ==> process 1583 launched child process 1712
[task 2022-03-04T13:00:33.222Z] 13:00:33     INFO - ==> process 1583 launched child process 1759
[task 2022-03-04T13:00:33.222Z] 13:00:33     INFO - ==> process 1583 launched child process 1760
[task 2022-03-04T13:00:33.222Z] 13:00:33     INFO - ==> process 1583 launched child process 1811
[task 2022-03-04T13:00:33.222Z] 13:00:33     INFO - ==> process 1583 launched child process 1848
[task 2022-03-04T13:00:33.222Z] 13:00:33     INFO - ==> process 1583 launched child process 1868
[task 2022-03-04T13:00:33.223Z] 13:00:33     INFO - zombiecheck | Checking for orphan process with PID: 1760
[task 2022-03-04T13:00:33.223Z] 13:00:33     INFO - zombiecheck | Checking for orphan process with PID: 1868
[task 2022-03-04T13:00:33.223Z] 13:00:33     INFO - zombiecheck | Checking for orphan process with PID: 1599
[task 2022-03-04T13:00:33.223Z] 13:00:33     INFO - zombiecheck | Checking for orphan process with PID: 1712
[task 2022-03-04T13:00:33.223Z] 13:00:33     INFO - zombiecheck | Checking for orphan process with PID: 1811
[task 2022-03-04T13:00:33.223Z] 13:00:33     INFO - zombiecheck | Checking for orphan process with PID: 1848
[task 2022-03-04T13:00:33.223Z] 13:00:33     INFO - zombiecheck | Checking for orphan process with PID: 1689
[task 2022-03-04T13:00:33.223Z] 13:00:33     INFO - zombiecheck | Checking for orphan process with PID: 1759
[task 2022-03-04T13:00:33.223Z] 13:00:33     INFO - Stopping web server
[task 2022-03-04T13:00:33.236Z] 13:00:33     INFO - Server shut down.
[task 2022-03-04T13:00:33.258Z] 13:00:33     INFO - Web server killed.
[task 2022-03-04T13:00:33.259Z] 13:00:33     INFO - Stopping web socket server
[task 2022-03-04T13:00:33.278Z] 13:00:33     INFO - Stopping ssltunnel
[task 2022-03-04T13:00:33.299Z] 13:00:33  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2022-03-04T13:00:33.299Z] 13:00:33     INFO - runtests.py | Running tests: end.
[task 2022-03-04T13:00:33.322Z] 13:00:33     INFO - Buffered messages logged at 13:00:14
[task 2022-03-04T13:00:33.323Z] 13:00:33     INFO - add_task | Entering test 
[task 2022-03-04T13:00:33.323Z] 13:00:33     INFO - add_task | Leaving test 
[task 2022-03-04T13:00:33.323Z] 13:00:33     INFO - add_task | Entering test restyling_for_main_thread_animations
[task 2022-03-04T13:00:33.324Z] 13:00:33     INFO - TEST-PASS | dom/animation/test/mozilla/test_restyles.html | undefined assertion name 

Comment 1

[Intermittent Failures Robot]

6 failures in 3063 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 5
• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-tsan-qr: 6
  • opt: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1758115&startday=2022-02-28&endday=2022-03-06&tree=all

Comment 2

[Cristian Tuns]

Hello, this might be caused by Bug 1757100, can you please take a look?

Comment 4

[Intermittent Failures Robot]

14 failures in 2837 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 10
• mozilla-central: 4

Platform and build breakdown:

• linux1804-64-tsan-qr: 14
  • opt: 14

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1758115&startday=2022-03-07&endday=2022-03-13&tree=all

Comment 5

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

The TSAN report is about two mutexes, locked using pthread_mutex_lock, both inside a mozilla::detail::MutexImpl which is a base class of mozilla::Mutex (or mozilla::OffTheBooksMutex).
Bug 1757100 only touched mozila::RWLock (which uses different functions like pthread_rwlock_rdlock), so I'm fairly sure it's not related.

Looking at the report, starting with the 2nd half, I can see:

#6 mozilla::TimelineConsumers::RemoveConsumer(nsDocShell*) /builds/worker/checkouts/gecko/docshell/base/timeline/TimelineConsumers.cpp:134:19

doing StaticMutexAutoLock lock(mozilla::TimelineConsumers::sMutex), and then calling observed.get()->ClearMarkers():

#5 mozilla::ObservedDocShell::ClearMarkers() /builds/worker/checkouts/gecko/docshell/base/timeline/ObservedDocShell.cpp:51:17

doing MutexAutoLock lock(this->MarkersStorage::mLock).

At a glance this seems reasonable to me, two chained functions that haven't been modified recently, this is likely the correct order.

In the 1st half of the report, things are more complex:

#24 non-virtual thunk to nsDocShell::PopProfileTimelineMarkers(JSContext*, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/docshell/base/nsDocShell.cpp
#23 nsDocShell::PopProfileTimelineMarkers(JSContext*, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/docshell/base/nsDocShell.cpp:2300:14
#22 mozilla::TimelineConsumers::PopMarkers(nsDocShell*, JSContext*, nsTArray<mozilla::dom::ProfileTimelineMarker>&) /builds/worker/checkouts/gecko/docshell/base/timeline/TimelineConsumers.cpp:268:25
#21 mozilla::ObservedDocShell::PopMarkers(JSContext*, nsTArray<mozilla::dom::ProfileTimelineMarker>&) /builds/worker/checkouts/gecko/docshell/base/timeline/ObservedDocShell.cpp:148:27

doing MutexAutoLock lock(this->MarkersStorage::mLock) (the one that was locked 2nd in the other half) and then calling a virtual AbstractTimelineMarker::AddDetails:

#20 mozilla::JavascriptTimelineMarker::AddDetails(JSContext*, mozilla::dom::ProfileTimelineMarker&) /builds/worker/checkouts/gecko/docshell/base/timeline/JavascriptTimelineMarker.h:75:11
#19 ToJSValue<mozilla::dom::RootedDictionary<mozilla::dom::ProfileTimelineStackFrame> > /builds/worker/workspace/obj-build/dist/include/mozilla/dom/ToJSValue.h:283:20
#18 mozilla::dom::ProfileTimelineStackFrame::ToObjectInternal(JSContext*, JS::MutableHandle<JS::Value>) const /builds/worker/workspace/obj-build/dom/bindings/ProfileTimelineMarkerBinding.cpp:292:33
#17 JS_NewPlainObject(JSContext*) /builds/worker/checkouts/gecko/js/src/jsapi.cpp:1850:10
#16 js::NewPlainObject(JSContext*, js::NewObjectKind) /builds/worker/checkouts/gecko/js/src/vm/PlainObject.cpp:166:10
#15 createWithShape /builds/worker/checkouts/gecko/js/src/vm/PlainObject-inl.h:36:23
#14 js::NativeObject::create(JSContext*, js::gc::AllocKind, js::gc::InitialHeap, JS::Handle<js::Shape*>, js::gc::AllocSite*) /builds/worker/checkouts/gecko/js/src/vm/NativeObject-inl.h:445:7
#13 JSObject* js::AllocateObject<(js::AllowGC)1>(JSContext*, js::gc::AllocKind, unsigned long, js::gc::InitialHeap, JSClass const*, js::gc::AllocSite*) /builds/worker/checkouts/gecko/js/src/gc/Allocator.cpp:79:28
#12 tryNewNurseryObject<js::CanGC> /builds/worker/checkouts/gecko/js/src/gc/Allocator.cpp:128:23
#11 js::gc::GCRuntime::minorGC(JS::GCReason, js::gcstats::PhaseKind) /builds/worker/checkouts/gecko/js/src/gc/GC.cpp:4109:3
#10 js::gc::GCRuntime::collectNursery(JS::GCOptions, JS::GCReason, js::gcstats::PhaseKind) /builds/worker/checkouts/gecko/js/src/gc/GC.cpp:4143:13
#9 js::Nursery::collect(JS::GCOptions, JS::GCReason) /builds/worker/checkouts/gecko/js/src/gc/Nursery.cpp:1091:11
#8 js::gcstats::Statistics::beginNurseryCollection(JS::GCReason) /builds/worker/checkouts/gecko/js/src/gc/Statistics.cpp:1112:5
#7 mozilla::CycleCollectedJSRuntime::GCNurseryCollectionCallback(JSContext*, JS::GCNurseryProgress, JS::GCReason) /builds/worker/checkouts/gecko/xpcom/base/CycleCollectedJSRuntime.cpp:1162:32
#6 mozilla::TimelineConsumers::IsEmpty() /builds/worker/checkouts/gecko/docshell/base/timeline/TimelineConsumers.cpp:147:23

doing StaticMutexAutoLock lock(mozilla::TimelineConsumers::sMutex) (the one that was locked 1st in the other half, that's the inversion).

So now we have ObservedDocShell::PopMarkers locking the MarkersStorage::mLock, and then calling JavascriptTimelineMarker::AddDetails that wants to create a JS object, which triggers a GC, which somehow ends up calling TimelineConsumers::IsEmpty where we attempt to lock TimelineConsumers::sMutex.
I'm afraid that's too much unknown code for me to analyze! (But I didn't see any recent changes in the code I looked at.)

Jon: I believe you're a GC expert, could you please look into this, see if these functions (#7 to #19) look correct, or have changed around 2022-03-04? (first report in autoland.)

My next bet would be around some of the classes that are involved (TimelineConsumers, ObservedDocShell, JavascriptTimelineMarker...), I'm not sure who would be best for these.

Comment 6

[Jon Coppeard (:jonco)]

The GC doesn't touch any of these locks so it's not likely to be related.

From the stack in the description is seems like the problem is that JavascriptTimelineMarker::AddDetails can trigger a minor GC which ends up calling back into TimelineConsumers::IsEmpty (via the CycleCollectedJSRuntime::GCNurseryCollectionCallback callback that is run at the start of minor GC). The code probably isn't expecting that.

AddDetails is called with a lock taken here: https://searchfox.org/mozilla-central/source/docshell/base/timeline/ObservedDocShell.cpp#59
IsEmpty takes a lock here: https://searchfox.org/mozilla-central/source/docshell/base/timeline/TimelineConsumers.cpp#147

Comment 7

[Intermittent Failures Robot]

27 failures in 3304 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 13
• mozilla-central: 10
• try: 4

Platform and build breakdown:

• linux1804-64-tsan-qr: 25
  • opt: 25
• windows7-32-qr: 1
  • opt: 1
• windows10-64-2004-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1758115&startday=2022-03-14&endday=2022-03-20&tree=all

Comment 8

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Thanks Jon.

Picking the next investigator:
Ted, you're the last person to touch the TimelineConsumers stuff, could you please have a sniff around, see if you can make sense of what's going wrong here? Your modifications were a long time ago compared to these failures, so it's probably something else, but any help would be appreciated, or if you could find another person who could help next.

Comment 9

[Intermittent Failures Robot]

11 failures in 3341 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1
• autoland: 9
• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-tsan-qr: 11
  • opt: 11

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1758115&startday=2022-03-21&endday=2022-03-27&tree=all

Comment 10

[Intermittent Failures Robot]

1 failures in 3159 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-tsan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1758115&startday=2022-04-18&endday=2022-04-24&tree=all

Comment 11

[Marian-Vasile Laza]

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

• linux1804-64-tsan-qr

Comment 12

[Intermittent Failures Robot]

45 failures in 3336 pushes (0.013 failures/push) were associated with this bug in the last 7 days.

This is the #22 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 28
• mozilla-central: 17

Platform and build breakdown:

• linux1804-64-tsan-qr: 45
  • opt: 45

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1758115&startday=2022-06-06&endday=2022-06-12&tree=all

Comment 13

[Marian-Vasile Laza]

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

• linux1804-64-tsan-qr

Comment 14

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

It's been a while without anyone looking, and failures are climbing -- though I didn't check them individually; there may be other deadlocks involved?
NI: Nika, could you please have a look, and/or find someone more suitable?

Comment 15

[Intermittent Failures Robot]

64 failures in 3170 pushes (0.02 failures/push) were associated with this bug in the last 7 days.

This is the #9 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 48
• mozilla-central: 16

Platform and build breakdown:

• linux1804-64-tsan-qr: 64
  • opt: 64

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1758115&startday=2022-06-13&endday=2022-06-19&tree=all

Comment 16

[Nika Layzell [:nika] (ni? for response)]

Looking at the failure log from comment 13, the cause of the issue is fairly clear:

The mutex TimelineConsumers::sMutex guards the members mActiveConsumers and mMarkersStores, so is locked when accessing those fields.

It appears that in the case of TimelineConsumers::RemoveConsumer, the lock is acquried for the full function (https://searchfox.org/mozilla-central/rev/c30349265c87047a324a471d2f39a216b6749262/docshell/base/timeline/TimelineConsumers.cpp#122-123), including the callback observed.get()->ClearMarkers(). That callback function acquires the other mutex mozilla::MarkersStorage::mLock which is used to guard its mOffTheMainThreadTimelineMarkers field (https://searchfox.org/mozilla-central/rev/c30349265c87047a324a471d2f39a216b6749262/docshell/base/timeline/ObservedDocShell.cpp#51).

Unfortunately, that lock is also held the other way around, when ObservedDocShell::PopMarkers acquires MarkersStorage::mLock (https://searchfox.org/mozilla-central/rev/c30349265c87047a324a471d2f39a216b6749262/docshell/base/timeline/ObservedDocShell.cpp#59), then calls AbstractTimelineMarker::AddDetails within that function (https://searchfox.org/mozilla-central/rev/c30349265c87047a324a471d2f39a216b6749262/docshell/base/timeline/ObservedDocShell.cpp#86). That method in particular performs a JS heap allocation, so can cause a JS garbage collection to occur while holding MarkersStorage::mLock, which in turn can cause the TimelineConsumers::sMutex mutex to be acquried within a cycle-collection callback.

This is unlikely to actually cause a deadlock, fortunately, thanks to ObservedDocShell generally being accessed from the main thread, but it's definitely still a bug which should be fixed.

We definitely shouldn't be holding mutexes like MarkersStorage::mLock across potential garbage-collection callsites. Based on the comments in the ObservedDocShell type it may be possible to hold the mutex only for the line where we access mOffTheMainThreadTimelineMarkers in PopMarkers (https://searchfox.org/mozilla-central/rev/c30349265c87047a324a471d2f39a216b6749262/docshell/base/timeline/ObservedDocShell.cpp#68), which would allow us to avoid that issue.

In general, I expect that the locking scopes for mutexes in this code should probably be re-checked, and the scopes should be reduced to make sure other issues like this don't happen in the future.

Comment 17

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Please let me clarify that I'm only involved here because a patch of mine was the initial suspect! I don't know the actual areas of concerns well, I'm trying to find the right component+owner to follow-up, so that it doesn't get forgotten.

Ni:Nika again, thanks for your analysis. If possible, could you please redirect this bug to the appropriate people? TIA.

Comment 18

[Intermittent Failures Robot]

17 failures in 534 pushes (0.032 failures/push) were associated with this bug yesterday.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• autoland: 13
• mozilla-central: 4

Platform and build breakdown:

• linux1804-64-tsan-qr: 17
  • opt: 17

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1758115&startday=2022-06-24&endday=2022-06-24&tree=all

Comment 19

[Cosmin Sabou [:CosminS]]

All latest failures here happen after helper_fission_animation_styling_in_transformed_oopif.html is started https://treeherder.mozilla.org/logviewer?job_id=382077528&repo=autoland&lineNumber=4070 and disabling the test on try resulted in no more failures.
Timothy, you were the last one to enable the test here https://hg.mozilla.org/integration/autoland/rev/c8be478a2054cb3a90f874d4d2a93d4903f7affe, would you be interested to see why this test is failing on ThreadSanitizer? It's on the disable-recommended bugs list. Thank you.

Comment 20

[Timothy Nikkel (:tnikkel)]

Sorry, I don't have any knowledge of the code that is going wrong.

Given comment 16 Dom: Navigation seems like a better component for this.

Comment 21

[Intermittent Failures Robot]

71 failures in 3075 pushes (0.023 failures/push) were associated with this bug in the last 7 days.

This is the #12 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 52
• mozilla-central: 18
• try: 1

Platform and build breakdown:

• linux1804-64-tsan-qr: 71
  • opt: 71

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1758115&startday=2022-06-20&endday=2022-06-26&tree=all

Comment 22

[Nika Layzell [:nika] (ni? for response)]

I'll just whip up a fix and post it, as it should be simple enough.

Comment 23

[Nika Layzell [:nika] (ni? for response)]

Attachment: Bug 1758115 - Part 1: Clean up locking in ObservedDocShell, r=smaug

This simplifies some of the locking in ObservedDocShell, annotates the mutex,
and reduces the scope of the problematic critical section.

Comment 24

[Nika Layzell [:nika] (ni? for response)]

Attachment: Bug 1758115 - Part 2: Streamline locking, initialization and shutdown for TimelineConsumers, r=smaug

The current implementation of TimelineConsumers contains some unnecessary
complexity due to how it is initialized as a singleton, and the need for it to
be initialized and used in a threadsafe way. This patch attempts to simplify it
by making all members static, and removing the need to explicitly observe
shutdown for cleanup.

In addition, this approach avoids the risk of the type being accessed from
off-main-thread during initialization or shutdown.

Depends on D150442

Comment 25

[Intermittent Failures Robot]

17 failures in 562 pushes (0.03 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 14
• mozilla-central: 3

Platform and build breakdown:

• linux1804-64-tsan-qr: 17
  • opt: 17

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1758115&startday=2022-06-27&endday=2022-06-27&tree=all

Comment 26

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/d982cbf3227f
Part 1: Clean up locking in ObservedDocShell, r=smaug
https://hg.mozilla.org/integration/autoland/rev/5df145bfd2ed
Part 2: Streamline locking, initialization and shutdown for TimelineConsumers, r=smaug

Comment 27

[Cristina Cozmuta (:CrissCozmuta)]

https://hg.mozilla.org/mozilla-central/rev/d982cbf3227f
https://hg.mozilla.org/mozilla-central/rev/5df145bfd2ed

Comment 28

[Intermittent Failures Robot]

24 failures in 3312 pushes (0.007 failures/push) were associated with this bug in the last 7 days.

This is the #37 most frequent failure this week.

Repository breakdown:

• autoland: 21
• mozilla-central: 3

Platform and build breakdown:

• linux1804-64-tsan-qr: 24
  • opt: 24

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1758115&startday=2022-06-27&endday=2022-07-03&tree=all