Closed Bug 1710990 Opened 2 years ago Closed 2 years ago

Intermittent SUMMARY: ThreadSanitizer: lock-order-inversion (potential deadlock) /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/sys/unix/mutex.rs:63:17 in std::sys::unix::mutex::Mutex::lock::h174542705dc79b0a

Categories

(Data Platform and Tools :: Glean: SDK, defect, P1)

defect

Tracking

(Not tracked)

RESOLVED FIXED

People

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

References

Details

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

Attachments

(2 files)

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


[task 2021-05-13T03:59:56.880Z] 03:59:56     INFO - TEST-OK | dom/media/test/test_background_video_no_suspend_disabled.html | took 16994ms
[task 2021-05-13T03:59:56.984Z] 03:59:56     INFO - TEST-START | dom/media/test/test_background_video_no_suspend_not_in_tree.html
[task 2021-05-13T04:00:00.239Z] 04:00:00     INFO - GECKO(1577) | ==================
[task 2021-05-13T04:00:00.239Z] 04:00:00     INFO - GECKO(1577) | WARNING: ThreadSanitizer: lock-order-inversion (potential deadlock) (pid=1577)
[task 2021-05-13T04:00:00.241Z] 04:00:00     INFO - GECKO(1577) |   Cycle in lock order graph: M93303508762776160 (0x000000000000) => M110754957319156608 (0x000000000000) => M93303508762776160
[task 2021-05-13T04:00:00.248Z] 04:00:00     INFO - GECKO(1577) |   Mutex M110754957319156608 acquired here while holding mutex M93303508762776160 in thread T69:
[task 2021-05-13T04:00:00.248Z] 04:00:00     INFO - GECKO(1577) |     #0 pthread_mutex_lock /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/tsan/../sanitizer_common/sanitizer_common_interceptors.inc:4233:3 (firefox+0x755a6)
[task 2021-05-13T04:00:00.248Z] 04:00:00     INFO - GECKO(1577) |     #1 std::sys::unix::mutex::Mutex::lock::h174542705dc79b0a /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/sys/unix/mutex.rs:63:17 (libxul.so+0x7eaba49)
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |     #2 std::sys_common::mutex::MovableMutex::raw_lock::hbd4bc7cfaf1d174d /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/sys_common/mutex.rs:76:18 (libxul.so+0x7eaba49)
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |     #3 std::sync::mutex::Mutex$LT$T$GT$::lock::h667aff80d33df854 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/sync/mutex.rs:263:13 (libxul.so+0x7eaba49)
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |     #4 glean_core::scheduler::schedule::h1a498c6dd0dfcfab /builds/worker/checkouts/gecko/third_party/rust/glean-core/src/scheduler.rs:79:9 (libxul.so+0x7eaba49)
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |     #5 glean_core::Glean::start_metrics_ping_scheduler::h4c50677e6327a76f /builds/worker/checkouts/gecko/third_party/rust/glean-core/src/lib.rs:1028:13 (libxul.so+0x7eaba49)
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |     #6 glean::initialize_internal::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::hc43e103982a94a2a /builds/worker/checkouts/gecko/third_party/rust/glean/src/lib.rs:315:17 (libxul.so+0x7e32b53)
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |     #7 glean::with_glean_mut::ha6fae43c6bf291b7 /builds/worker/checkouts/gecko/third_party/rust/glean/src/lib.rs:152:5 (libxul.so+0x7e32b53)
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |     #8 glean::initialize_internal::_$u7b$$u7b$closure$u7d$$u7d$::h6d68cc88b094bdc8 /builds/worker/checkouts/gecko/third_party/rust/glean/src/lib.rs:235:13 (libxul.so+0x7e32b53)
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |     #9 std::sys_common::backtrace::__rust_begin_short_backtrace::hd0e9c2a50d8feb3c /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/sys_common/backtrace.rs:125:18 (libxul.so+0x7e32b53)
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |     #10 std::thread::Builder::spawn_unchecked::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::h47723f4acb1560d2 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/thread/mod.rs:474:17 (libxul.so+0x7e2cc5a)
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |     #11 _$LT$std..panic..AssertUnwindSafe$LT$F$GT$$u20$as$u20$core..ops..function..FnOnce$LT$$LP$$RP$$GT$$GT$::call_once::hb83920a8a032194e /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/panic.rs:322:9 (libxul.so+0x7e2cc5a)
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |     #12 std::panicking::try::do_call::haf1060a7bfe17895 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/panicking.rs:381:40 (libxul.so+0x7e2cc5a)
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |     #13 std::panicking::try::h562a96f9d72440bb /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/panicking.rs:345:19 (libxul.so+0x7e2cc5a)
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |     #14 std::panic::catch_unwind::he58824fdc6229a5f /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/panic.rs:396:14 (libxul.so+0x7e2cc5a)
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |     #15 std::thread::Builder::spawn_unchecked::_$u7b$$u7b$closure$u7d$$u7d$::hcd92938ebae846fe /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/thread/mod.rs:473:30 (libxul.so+0x7e2cc5a)
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |     #16 core::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::hb3902ffd1a962a71 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/core/src/ops/function.rs:227:5 (libxul.so+0x7e2cc5a)
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |     #17 _$LT$alloc..boxed..Box$LT$F$C$A$GT$$u20$as$u20$core..ops..function..FnOnce$LT$Args$GT$$GT$::call_once::hb4d0520786147807 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/alloc/src/boxed.rs:1307:9 (libxul.so+0x82ce636)
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |     #18 _$LT$alloc..boxed..Box$LT$F$C$A$GT$$u20$as$u20$core..ops..function..FnOnce$LT$Args$GT$$GT$::call_once::h7b3e75c823aaab91 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/alloc/src/boxed.rs:1307:9 (libxul.so+0x82ce636)
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |     #19 std::sys::unix::thread::Thread::new::thread_start::h4b687605f586dc2f /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/sys/unix/thread.rs:71:17 (libxul.so+0x82ce636)
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |     Hint: use TSAN_OPTIONS=second_deadlock_stack=1 to get more informative warning message
[task 2021-05-13T04:00:00.249Z] 04:00:00     INFO - GECKO(1577) |   Mutex M93303508762776160 acquired here while holding mutex M110754957319156608 in thread T72:
[task 2021-05-13T04:00:00.250Z] 04:00:00     INFO - GECKO(1577) |     #0 pthread_mutex_lock /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/tsan/../sanitizer_common/sanitizer_common_interceptors.inc:4233:3 (firefox+0x755a6)
[task 2021-05-13T04:00:00.250Z] 04:00:00     INFO - GECKO(1577) |     #1 std::sys::unix::mutex::Mutex::lock::h174542705dc79b0a /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/sys/unix/mutex.rs:63:17 (libxul.so+0x7eadfd2)
[task 2021-05-13T04:00:00.251Z] 04:00:00     INFO - GECKO(1577) |     #2 std::sys_common::mutex::MovableMutex::raw_lock::hbd4bc7cfaf1d174d /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/sys_common/mutex.rs:76:18 (libxul.so+0x7eadfd2)
[task 2021-05-13T04:00:00.251Z] 04:00:00     INFO - GECKO(1577) |     #3 std::sync::mutex::Mutex$LT$T$GT$::lock::h4b8867b9b30cb60a /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/sync/mutex.rs:263:13 (libxul.so+0x7eadfd2)
[task 2021-05-13T04:00:00.251Z] 04:00:00     INFO - GECKO(1577) |     #4 glean_core::scheduler::start_scheduler::_$u7b$$u7b$closure$u7d$$u7d$::h92797724dc734335 /builds/worker/checkouts/gecko/third_party/rust/glean-core/src/scheduler.rs:214:41 (libxul.so+0x7eadfd2)
[task 2021-05-13T04:00:00.252Z] 04:00:00     INFO - GECKO(1577) |     #5 std::sys_common::backtrace::__rust_begin_short_backtrace::h53e16fe614e5c18b /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/sys_common/backtrace.rs:125:18 (libxul.so+0x7eadfd2)
[task 2021-05-13T04:00:00.252Z] 04:00:00     INFO - GECKO(1577) |     #6 std::thread::Builder::spawn_unchecked::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::ha0771ad4d4fd90c2 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/thread/mod.rs:474:17 (libxul.so+0x7ead373)
[task 2021-05-13T04:00:00.253Z] 04:00:00     INFO - GECKO(1577) |     #7 _$LT$std..panic..AssertUnwindSafe$LT$F$GT$$u20$as$u20$core..ops..function..FnOnce$LT$$LP$$RP$$GT$$GT$::call_once::h81ba965e2a1ac362 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/panic.rs:322:9 (libxul.so+0x7ead373)
[task 2021-05-13T04:00:00.253Z] 04:00:00     INFO - GECKO(1577) |     #8 std::panicking::try::do_call::h8f7a16434a52275b /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/panicking.rs:381:40 (libxul.so+0x7ead373)
[task 2021-05-13T04:00:00.254Z] 04:00:00     INFO - GECKO(1577) |     #9 std::panicking::try::h38ec2a37bc5c14e2 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/panicking.rs:345:19 (libxul.so+0x7ead373)
[task 2021-05-13T04:00:00.254Z] 04:00:00     INFO - GECKO(1577) |     #10 std::panic::catch_unwind::h4510edd8fc850779 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/panic.rs:396:14 (libxul.so+0x7ead373)
[task 2021-05-13T04:00:00.255Z] 04:00:00     INFO - GECKO(1577) |     #11 std::thread::Builder::spawn_unchecked::_$u7b$$u7b$closure$u7d$$u7d$::h2ae1ddd1ea8d82b7 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/thread/mod.rs:473:30 (libxul.so+0x7ead373)
[task 2021-05-13T04:00:00.255Z] 04:00:00     INFO - GECKO(1577) |     #12 core::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::h94bf70315d78cd2b /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/core/src/ops/function.rs:227:5 (libxul.so+0x7ead373)
[task 2021-05-13T04:00:00.256Z] 04:00:00     INFO - GECKO(1577) |     #13 _$LT$alloc..boxed..Box$LT$F$C$A$GT$$u20$as$u20$core..ops..function..FnOnce$LT$Args$GT$$GT$::call_once::hb4d0520786147807 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/alloc/src/boxed.rs:1307:9 (libxul.so+0x82ce636)
[task 2021-05-13T04:00:00.256Z] 04:00:00     INFO - GECKO(1577) |     #14 _$LT$alloc..boxed..Box$LT$F$C$A$GT$$u20$as$u20$core..ops..function..FnOnce$LT$Args$GT$$GT$::call_once::h7b3e75c823aaab91 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/alloc/src/boxed.rs:1307:9 (libxul.so+0x82ce636)
[task 2021-05-13T04:00:00.257Z] 04:00:00     INFO - GECKO(1577) |     #15 std::sys::unix::thread::Thread::new::thread_start::h4b687605f586dc2f /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/sys/unix/thread.rs:71:17 (libxul.so+0x82ce636)
[task 2021-05-13T04:00:00.257Z] 04:00:00     INFO - GECKO(1577) |   Thread T69 (tid=1760, finished) created by main thread at:
[task 2021-05-13T04:00:00.258Z] 04:00:00     INFO - GECKO(1577) |     #0 pthread_create /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/tsan/rtl/tsan_interceptors_posix.cpp:965:3 (firefox+0x577eb)
[task 2021-05-13T04:00:00.258Z] 04:00:00     INFO - GECKO(1577) |     #1 std::sys::unix::thread::Thread::new::he0fcb8382fb479a0 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/sys/unix/thread.rs:50:19 (libxul.so+0x82ce205)
[task 2021-05-13T04:00:00.259Z] 04:00:00     INFO - GECKO(1577) |     #2 std::thread::Builder::spawn_unchecked::hb2c783a915f843f1 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/thread/mod.rs:498:22 (libxul.so+0x7b89dd2)
[task 2021-05-13T04:00:00.259Z] 04:00:00     INFO - GECKO(1577) |     #3 std::thread::Builder::spawn::hc8270c9aae8bca21 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/thread/mod.rs:381:18 (libxul.so+0x7b89dd2)
[task 2021-05-13T04:00:00.260Z] 04:00:00     INFO - GECKO(1577) |     #4 glean::initialize_internal::h571fca6700bf5e50 /builds/worker/checkouts/gecko/third_party/rust/glean/src/lib.rs:188:23 (libxul.so+0x7b89dd2)
[task 2021-05-13T04:00:00.260Z] 04:00:00     INFO - GECKO(1577) |     #5 glean::initialize::h035339834c1020dd /builds/worker/checkouts/gecko/third_party/rust/glean/src/lib.rs:176:5 (libxul.so+0x7b89dd2)
[task 2021-05-13T04:00:00.261Z] 04:00:00     INFO - GECKO(1577) |     #6 fog_init /builds/worker/checkouts/gecko/toolkit/components/glean/src/lib.rs:159:5 (libxul.so+0x7b89dd2)
[task 2021-05-13T04:00:00.261Z] 04:00:00     INFO - GECKO(1577) |     #7 mozilla::FOG::InitializeFOG(nsTSubstring<char> const&, nsTSubstring<char> const&) /builds/worker/checkouts/gecko/toolkit/components/glean/xpcom/FOG.cpp:65:10 (libxul.so+0x677a1c1)
[task 2021-05-13T04:00:00.262Z] 04:00:00     INFO - GECKO(1577) |     #8 mozilla::FOG::InitializeFOG(nsTSubstring<char> const&, nsTSubstring<char> const&) /builds/worker/checkouts/gecko/toolkit/components/glean/xpcom/FOG.cpp:65:10 (libxul.so+0x677a1c1)
[task 2021-05-13T04:00:00.262Z] 04:00:00     INFO - GECKO(1577) |     #9 mozilla::FOG::InitializeFOG(nsTSubstring<char> const&, nsTSubstring<char> const&) /builds/worker/checkouts/gecko/toolkit/components/glean/xpcom/FOG.cpp:65:10 (libxul.so+0x677a1c1)
[task 2021-05-13T04:00:00.263Z] 04:00:00     INFO - GECKO(1577) |     #10 NS_InvokeByIndex /builds/worker/checkouts/gecko/xpcom/reflect/xptcall/md/unix/xptcinvoke_asm_x86_64_unix.S:101 (libxul.so+0xc06c05)
[task 2021-05-13T04:00:00.263Z] 04:00:00     INFO - GECKO(1577) |     #11 XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNativeJSOps.cpp:925:10 (libxul.so+0x1a4f190)
[task 2021-05-13T04:00:00.264Z] 04:00:00     INFO - GECKO(1577) |     #12 CallJSNative /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:427:13 (libxul.so+0x6aaf5f4)
[task 2021-05-13T04:00:00.264Z] 04:00:00     INFO - GECKO(1577) |     #13 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:512:12 (libxul.so+0x6aaf5f4)
[task 2021-05-13T04:00:00.265Z] 04:00:00     INFO - GECKO(1577) |     #14 InternalCall /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:572:10 (libxul.so+0x6aa5350)
[task 2021-05-13T04:00:00.265Z] 04:00:00     INFO - GECKO(1577) |     #15 CallFromStack /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:576:10 (libxul.so+0x6aa5350)
[task 2021-05-13T04:00:00.266Z] 04:00:00     INFO - GECKO(1577) |     #16 Interpret(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:3227:16 (libxul.so+0x6aa5350)
[task 2021-05-13T04:00:00.266Z] 04:00:00     INFO - GECKO(1577) |     #17 js::RunScript(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:396:13 (libxul.so+0x6a9887c)
[task 2021-05-13T04:00:00.267Z] 04:00:00     INFO - GECKO(1577) |     #18 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:544:13 (libxul.so+0x6aafe51)
[task 2021-05-13T04:00:00.267Z] 04:00:00     INFO - GECKO(1577) |     #19 InternalCall /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:572:10 (libxul.so+0x6ab08e3)
[task 2021-05-13T04:00:00.268Z] 04:00:00     INFO - GECKO(1577) |     #20 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+0x6ab08e3)
[task 2021-05-13T04:00:00.268Z] 04:00:00     INFO - GECKO(1577) |     #21 js::jit::InvokeFunction(JSContext*, JS::Handle<JSObject*>, bool, bool, unsigned int, JS::Value*, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/js/src/jit/VMFunctions.cpp:760:10 (libxul.so+0x72de10e)
[task 2021-05-13T04:00:00.269Z] 04:00:00     INFO - GECKO(1577) |     #22 js::jit::InvokeFromInterpreterStub(JSContext*, js::jit::InterpreterStubExitFrameLayout*) /builds/worker/checkouts/gecko/js/src/jit/VMFunctions.cpp:784:8 (libxul.so+0x72de6a2)
[task 2021-05-13T04:00:00.269Z] 04:00:00     INFO - GECKO(1577) |     #23 <null> <null> (0x7fbb46dbedf4)
[task 2021-05-13T04:00:00.270Z] 04:00:00     INFO - GECKO(1577) |     #24 js::RunScript(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:386:32 (libxul.so+0x6a987ae)
[task 2021-05-13T04:00:00.270Z] 04:00:00     INFO - GECKO(1577) |     #25 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:544:13 (libxul.so+0x6aafe51)
[task 2021-05-13T04:00:00.270Z] 04:00:00     INFO - GECKO(1577) |     #26 InternalCall /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:572:10 (libxul.so+0x6ab08e3)
[task 2021-05-13T04:00:00.271Z] 04:00:00     INFO - GECKO(1577) |     #27 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+0x6ab08e3)
[task 2021-05-13T04:00:00.272Z] 04:00:00     INFO - GECKO(1577) |     #28 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:2796:10 (libxul.so+0x6f54091)
[task 2021-05-13T04:00:00.272Z] 04:00:00     INFO - GECKO(1577) |     #29 mozilla::dom::IdleRequestCallback::Call(mozilla::dom::BindingCallContext&, JS::Handle<JS::Value>, mozilla::dom::IdleDeadline&, mozilla::ErrorResult&) /builds/worker/workspace/obj-build/dom/bindings/WindowBinding.cpp:871:8 (libxul.so+0x2ef1e8c)
[task 2021-05-13T04:00:00.273Z] 04:00:00     INFO - GECKO(1577) |     #30 Call /builds/worker/workspace/obj-build/dist/include/mozilla/dom/WindowBinding.h:782:12 (libxul.so+0x243ea7c)
[task 2021-05-13T04:00:00.273Z] 04:00:00     INFO - GECKO(1577) |     #31 Call /builds/worker/workspace/obj-build/dist/include/mozilla/dom/WindowBinding.h:795:12 (libxul.so+0x243ea7c)
[task 2021-05-13T04:00:00.273Z] 04:00:00     INFO - GECKO(1577) |     #32 mozilla::dom::(anonymous namespace)::IdleDispatchRunnable::Run() /builds/worker/checkouts/gecko/dom/base/ChromeUtils.cpp:426:17 (libxul.so+0x243ea7c)
[task 2021-05-13T04:00:00.274Z] 04:00:00     INFO - GECKO(1577) |     #33 mozilla::RunnableTask::Run() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:482:16 (libxul.so+0xbedb87)
[task 2021-05-13T04:00:00.274Z] 04:00:00     INFO - GECKO(1577) |     #34 mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:766:26 (libxul.so+0xbcaafa)
[task 2021-05-13T04:00:00.275Z] 04:00:00     INFO - GECKO(1577) |     #35 mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:644:15 (libxul.so+0xbc933f)
[task 2021-05-13T04:00:00.275Z] 04:00:00     INFO - GECKO(1577) |     #36 mozilla::TaskController::ProcessPendingMTTask(bool) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:405:36 (libxul.so+0xbc9424)
[task 2021-05-13T04:00:00.276Z] 04:00:00     INFO - GECKO(1577) |     #37 operator() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:138:37 (libxul.so+0xbf17e7)
[task 2021-05-13T04:00:00.276Z] 04:00:00     INFO - GECKO(1577) |     #38 mozilla::detail::RunnableFunction<mozilla::TaskController::InitializeInternal()::$_0>::Run() /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.h:534:5 (libxul.so+0xbf17e7)
[task 2021-05-13T04:00:00.277Z] 04:00:00     INFO - GECKO(1577) |     #39 nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1159:16 (libxul.so+0xbdb8f0)
[task 2021-05-13T04:00:00.277Z] 04:00:00     INFO - GECKO(1577) |     #40 NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:548:10 (libxul.so+0xbe2872)
[task 2021-05-13T04:00:00.278Z] 04:00:00     INFO - GECKO(1577) |     #41 mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:85:21 (libxul.so+0x14a9a8d)
[task 2021-05-13T04:00:00.278Z] 04:00:00     INFO - GECKO(1577) |     #42 RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:335:10 (libxul.so+0x1433c9c)
[task 2021-05-13T04:00:00.279Z] 04:00:00     INFO - GECKO(1577) |     #43 RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:328:3 (libxul.so+0x1433c9c)
[task 2021-05-13T04:00:00.279Z] 04:00:00     INFO - GECKO(1577) |     #44 MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:310:3 (libxul.so+0x1433c9c)
[task 2021-05-13T04:00:00.280Z] 04:00:00     INFO - GECKO(1577) |     #45 nsBaseAppShell::Run() /builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp:137:27 (libxul.so+0x4b00ac6)
[task 2021-05-13T04:00:00.280Z] 04:00:00     INFO - GECKO(1577) |     #46 nsAppStartup::Run() /builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp:273:30 (libxul.so+0x685b548)
[task 2021-05-13T04:00:00.281Z] 04:00:00     INFO - GECKO(1577) |     #47 XREMain::XRE_mainRun() /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5367:22 (libxul.so+0x6976b4a)
[task 2021-05-13T04:00:00.281Z] 04:00:00     INFO - GECKO(1577) |     #48 XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5565:8 (libxul.so+0x6977897)
[task 2021-05-13T04:00:00.282Z] 04:00:00     INFO - GECKO(1577) |     #49 XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5624:21 (libxul.so+0x6977e34)
[task 2021-05-13T04:00:00.282Z] 04:00:00     INFO - GECKO(1577) |     #50 mozilla::BootstrapImpl::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/Bootstrap.cpp:45:12 (libxul.so+0x69823f2)
[task 2021-05-13T04:00:00.283Z] 04:00:00     INFO - GECKO(1577) |     #51 do_main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:224:22 (firefox+0xca6e0)
[task 2021-05-13T04:00:00.283Z] 04:00:00     INFO - GECKO(1577) |     #52 main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:351:16 (firefox+0xca6e0)
[task 2021-05-13T04:00:00.283Z] 04:00:00     INFO - GECKO(1577) |   Thread T72 'glean.mps' (tid=1763, running) created by thread T69 at:
[task 2021-05-13T04:00:00.284Z] 04:00:00     INFO - GECKO(1577) |     #0 pthread_create /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/tsan/rtl/tsan_interceptors_posix.cpp:965:3 (firefox+0x577eb)
[task 2021-05-13T04:00:00.285Z] 04:00:00     INFO - GECKO(1577) |     #1 std::sys::unix::thread::Thread::new::he0fcb8382fb479a0 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/sys/unix/thread.rs:50:19 (libxul.so+0x82ce205)
[task 2021-05-13T04:00:00.285Z] 04:00:00     INFO - GECKO(1577) |     #2 std::thread::Builder::spawn_unchecked::h5f7279cd735d2c4c /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/thread/mod.rs:498:22 (libxul.so+0x7eaccb3)
[task 2021-05-13T04:00:00.286Z] 04:00:00     INFO - GECKO(1577) |     #3 std::thread::Builder::spawn::h4df9b69da38ce389 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/thread/mod.rs:381:18 (libxul.so+0x7eaccb3)
[task 2021-05-13T04:00:00.286Z] 04:00:00     INFO - GECKO(1577) |     #4 glean_core::scheduler::start_scheduler::h98743f5a8be90088 /builds/worker/checkouts/gecko/third_party/rust/glean-core/src/scheduler.rs:192:5 (libxul.so+0x7eaccb3)
[task 2021-05-13T04:00:00.287Z] 04:00:00     INFO - GECKO(1577) |     #5 _$LT$glean_core..scheduler..GleanMetricsPingScheduler$u20$as$u20$glean_core..scheduler..MetricsPingScheduler$GT$::start_scheduler::h9ec5fd5c81b13a22 /builds/worker/checkouts/gecko/third_party/rust/glean-core/src/scheduler.rs:68:9 (libxul.so+0x7eaccb3)
[task 2021-05-13T04:00:00.287Z] 04:00:00     INFO - GECKO(1577) |     #6 glean_core::scheduler::schedule_internal::h283252857677744d /builds/worker/checkouts/gecko/third_party/rust/glean-core/src/scheduler.rs (libxul.so+0x7eac4ce)
[task 2021-05-13T04:00:00.288Z] 04:00:00     INFO - GECKO(1577) |     #7 glean_core::scheduler::schedule::h1a498c6dd0dfcfab /builds/worker/checkouts/gecko/third_party/rust/glean-core/src/scheduler.rs:87:5 (libxul.so+0x7eac4ce)
[task 2021-05-13T04:00:00.288Z] 04:00:00     INFO - GECKO(1577) |     #8 glean_core::Glean::start_metrics_ping_scheduler::h4c50677e6327a76f /builds/worker/checkouts/gecko/third_party/rust/glean-core/src/lib.rs:1028:13 (libxul.so+0x7eac4ce)
[task 2021-05-13T04:00:00.289Z] 04:00:00     INFO - GECKO(1577) |     #9 glean::initialize_internal::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::hc43e103982a94a2a /builds/worker/checkouts/gecko/third_party/rust/glean/src/lib.rs:315:17 (libxul.so+0x7e32b53)
[task 2021-05-13T04:00:00.290Z] 04:00:00     INFO - GECKO(1577) |     #10 glean::with_glean_mut::ha6fae43c6bf291b7 /builds/worker/checkouts/gecko/third_party/rust/glean/src/lib.rs:152:5 (libxul.so+0x7e32b53)
[task 2021-05-13T04:00:00.290Z] 04:00:00     INFO - GECKO(1577) |     #11 glean::initialize_internal::_$u7b$$u7b$closure$u7d$$u7d$::h6d68cc88b094bdc8 /builds/worker/checkouts/gecko/third_party/rust/glean/src/lib.rs:235:13 (libxul.so+0x7e32b53)
[task 2021-05-13T04:00:00.291Z] 04:00:00     INFO - GECKO(1577) |     #12 std::sys_common::backtrace::__rust_begin_short_backtrace::hd0e9c2a50d8feb3c /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/sys_common/backtrace.rs:125:18 (libxul.so+0x7e32b53)
[task 2021-05-13T04:00:00.292Z] 04:00:00     INFO - GECKO(1577) |     #13 std::thread::Builder::spawn_unchecked::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::h47723f4acb1560d2 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/thread/mod.rs:474:17 (libxul.so+0x7e2cc5a)
[task 2021-05-13T04:00:00.295Z] 04:00:00     INFO - GECKO(1577) |     #14 _$LT$std..panic..AssertUnwindSafe$LT$F$GT$$u20$as$u20$core..ops..function..FnOnce$LT$$LP$$RP$$GT$$GT$::call_once::hb83920a8a032194e /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/panic.rs:322:9 (libxul.so+0x7e2cc5a)
[task 2021-05-13T04:00:00.295Z] 04:00:00     INFO - GECKO(1577) |     #15 std::panicking::try::do_call::haf1060a7bfe17895 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/panicking.rs:381:40 (libxul.so+0x7e2cc5a)
[task 2021-05-13T04:00:00.296Z] 04:00:00     INFO - GECKO(1577) |     #16 std::panicking::try::h562a96f9d72440bb /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/panicking.rs:345:19 (libxul.so+0x7e2cc5a)
[task 2021-05-13T04:00:00.296Z] 04:00:00     INFO - GECKO(1577) |     #17 std::panic::catch_unwind::he58824fdc6229a5f /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/panic.rs:396:14 (libxul.so+0x7e2cc5a)
[task 2021-05-13T04:00:00.296Z] 04:00:00     INFO - GECKO(1577) |     #18 std::thread::Builder::spawn_unchecked::_$u7b$$u7b$closure$u7d$$u7d$::hcd92938ebae846fe /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/thread/mod.rs:473:30 (libxul.so+0x7e2cc5a)
[task 2021-05-13T04:00:00.296Z] 04:00:00     INFO - GECKO(1577) |     #19 core::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::hb3902ffd1a962a71 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/core/src/ops/function.rs:227:5 (libxul.so+0x7e2cc5a)
[task 2021-05-13T04:00:00.296Z] 04:00:00     INFO - GECKO(1577) |     #20 _$LT$alloc..boxed..Box$LT$F$C$A$GT$$u20$as$u20$core..ops..function..FnOnce$LT$Args$GT$$GT$::call_once::hb4d0520786147807 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/alloc/src/boxed.rs:1307:9 (libxul.so+0x82ce636)
[task 2021-05-13T04:00:00.297Z] 04:00:00     INFO - GECKO(1577) |     #21 _$LT$alloc..boxed..Box$LT$F$C$A$GT$$u20$as$u20$core..ops..function..FnOnce$LT$Args$GT$$GT$::call_once::h7b3e75c823aaab91 /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/alloc/src/boxed.rs:1307:9 (libxul.so+0x82ce636)
[task 2021-05-13T04:00:00.297Z] 04:00:00     INFO - GECKO(1577) |     #22 std::sys::unix::thread::Thread::new::thread_start::h4b687605f586dc2f /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/sys/unix/thread.rs:71:17 (libxul.so+0x82ce636)
[task 2021-05-13T04:00:00.297Z] 04:00:00     INFO - GECKO(1577) | SUMMARY: ThreadSanitizer: lock-order-inversion (potential deadlock) /builds/worker/fetches/rustc/lib/rustlib/src/rust/library/std/src/sys/unix/mutex.rs:63:17 in std::sys::unix::mutex::Mutex::lock::h174542705dc79b0a
[task 2021-05-13T04:00:00.297Z] 04:00:00     INFO - GECKO(1577) | ==================
[task 2021-05-13T04:00:00.323Z] 04:00:00     INFO - GECKO(1577) | Exiting due to channel error.
[task 2021-05-13T04:00:00.324Z] 04:00:00     INFO - GECKO(1577) | Exiting due to channel error.
[task 2021-05-13T04:00:00.324Z] 04:00:00     INFO - GECKO(1577) | Exiting due to channel error.
[task 2021-05-13T04:00:00.328Z] 04:00:00     INFO - GECKO(1577) | Exiting due to channel error.
[task 2021-05-13T04:00:00.329Z] 04:00:00     INFO - GECKO(1577) | Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: Receive IPC close with reason=AbnormalShutdown (t=79.7103) Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: Receive IPC close with reason=AbnormalShutdown (t=90.9123) Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: Receive IPC close with reason=AbnormalShutdown (t=83.2464) [Child 1682, MediaDecoderStateMachine #1] WARNING: Decoder=7b5800075600 Decode error: NS_ERROR_OUT_OF_MEMORY (0x8007000e) - mozilla::MediaResult mozilla::FFmpegVideoDecoder<57>::CreateImage(int64_t, int64_t, int64_t, MediaDataDecoder::DecodedData &) const: image allocation error: file /builds/worker/checkouts/gecko/dom/media/MediaDecoderStateMachine.cpp:3498
[task 2021-05-13T04:00:00.348Z] 04:00:00     INFO - GECKO(1577) | Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: Receive IPC close with reason=AbnormalShutdown (t=90.2173) [Child 1682, MediaDecoderStateMachine #1] WARNING: Decoder=7b5800075600 Decode error: NS_ERROR_OUT_OF_MEMORY (0x8007000e) - mozilla::MediaResult mozilla::FFmpegVideoDecoder<57>::CreateImage(int64_t, int64_t, int64_t, MediaDataDecoder::DecodedData &) const: image allocation error: file /builds/worker/checkouts/gecko/dom/media/MediaDecoderStateMachine.cpp:3498
[task 2021-05-13T04:00:00.378Z] 04:00:00     INFO - GECKO(1577) | [Child 1682, MediaDecoderStateMachine #1] WARNING: Decoder=7b5800075600 Decode error: NS_ERROR_OUT_OF_MEMORY (0x8007000e) - mozilla::MediaResult mozilla::FFmpegVideoDecoder<57>::CreateImage(int64_t, int64_t, int64_t, MediaDataDecoder::DecodedData &) const: image allocation error: file /builds/worker/checkouts/gecko/dom/media/MediaDecoderStateMachine.cpp:3498
[task 2021-05-13T04:00:00.412Z] 04:00:00     INFO - GECKO(1577) | [Child 1682, MediaDecoderStateMachine #1] WARNING: Decoder=7b5800075600 Decode error: NS_ERROR_OUT_OF_MEMORY (0x8007000e) - mozilla::MediaResult mozilla::FFmpegVideoDecoder<57>::CreateImage(int64_t, int64_t, int64_t, MediaDataDecoder::DecodedData &) const: image allocation error: file /builds/worker/checkouts/gecko/dom/media/MediaDecoderStateMachine.cpp:3498
[task 2021-05-13T04:00:00.445Z] 04:00:00     INFO - GECKO(1577) | [Child 1682, MediaDecoderStateMachine #1] WARNING: Decoder=7b5800075600 Decode error: NS_ERROR_OUT_OF_MEMORY (0x8007000e) - mozilla::MediaResult mozilla::FFmpegVideoDecoder<57>::CreateImage(int64_t, int64_t, int64_t, MediaDataDecoder::DecodedData &) const: image allocation error: file /builds/worker/checkouts/gecko/dom/media/MediaDecoderStateMachine.cpp:3498
[task 2021-05-13T04:00:00.478Z] 04:00:00     INFO - GECKO(1577) | [Child 1682, MediaDecoderStateMachine #1] WARNING: Decoder=7b5800075600 Decode error: NS_ERROR_OUT_OF_MEMORY (0x8007000e) - mozilla::MediaResult mozilla::FFmpegVideoDecoder<57>::CreateImage(int64_t, int64_t, int64_t, MediaDataDecoder::DecodedData &) const: image allocation error: file /builds/worker/checkouts/gecko/dom/media/MediaDecoderStateMachine.cpp:3498
[task 2021-05-13T04:00:00.512Z] 04:00:00     INFO - GECKO(1577) | [Child 1682, MediaDecoderStateMachine #1] WARNING: Decoder=7b5800075600 Decode error: NS_ERROR_OUT_OF_MEMORY (0x8007000e) - mozilla::MediaResult mozilla::FFmpegVideoDecoder<57>::CreateImage(int64_t, int64_t, int64_t, MediaDataDecoder::DecodedData &) const: image allocation error: file /builds/worker/checkouts/gecko/dom/media/MediaDecoderStateMachine.cpp:3498
[task 2021-05-13T04:00:00.545Z] 04:00:00     INFO - GECKO(1577) | [Child 1682, MediaDecoderStateMachine #1] WARNING: Decoder=7b5800075600 Decode error: NS_ERROR_OUT_OF_MEMORY (0x8007000e) - mozilla::MediaResult mozilla::FFmpegVideoDecoder<57>::CreateImage(int64_t, int64_t, int64_t, MediaDataDecoder::DecodedData &) const: image allocation error: file /builds/worker/checkouts/gecko/dom/media/MediaDecoderStateMachine.cpp:3498
[task 2021-05-13T04:00:00.578Z] 04:00:00     INFO - GECKO(1577) | [Child 1682, MediaDecoderStateMachine #1] WARNING: Decoder=7b5800075600 Decode error: NS_ERROR_OUT_OF_MEMORY (0x8007000e) - mozilla::MediaResult mozilla::FFmpegVideoDecoder<57>::CreateImage(int64_t, int64_t, int64_t, MediaDataDecoder::DecodedData &) const: image allocation error: file /builds/worker/checkouts/gecko/dom/media/MediaDecoderStateMachine.cpp:3498
[task 2021-05-13T04:00:01.403Z] 04:00:01     INFO - TEST-INFO | Main app process: killed by SIGIOT
[task 2021-05-13T04:00:01.403Z] 04:00:01     INFO - Buffered messages logged at 03:59:57```

This started to fail in a bunch on this merge. Retriggers were green and also backfills and retriggers on autoland were the same.
Christian, could you please have a look at what determined these to fail all at once? Could the changes in https://bugzilla.mozilla.org/show_bug.cgi?id=1458339#c13 have something to do with it? Thank you.

Flags: needinfo?(choller)

Chris, could you help us out with this one?
Could the glean updates in Bug 1672951 cause this?
Thank you.

Flags: needinfo?(chutten)

It is entirely possible that the updates brought in a lock order inversion. Running TSan isn't in my standard repertoire of checks to perform on an update, so it may have slipped. Certainly that stack suggests it's the SDK update. I'll investigate.

(Note to self: update the docs with instructions on running TSan as part of this work)

Assignee: nobody → chutten
Status: NEW → ASSIGNED
Component: Sanitizers → Glean: SDK
Flags: needinfo?(chutten)
Priority: P5 → P1
Product: Core → Data Platform and Tools

Be aware the next central push wasn't affected and the issue also hadn't been observed on autoland. Might depend on the build.

Code inspection on the relevant parts of the stack suggests the order problem is between the Global Glean and the MPS' condvar. When we start the MPS we hold Glean and acquire the condvar. When the MPS triggers over we hold the condvar and acquire Glean.

I'll confirm in a moment if it's reproducible on a local TSan build (once it finishes building).

Seems as though the "correct" order is 1) hold Glean 2) acquire condvar since it is the Global Glean that controls the MPS (not the other way around). Now to see if the MPS' trigger can invert its order easily or not.

Pushed by chutten@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/c7e5d737d3ef
Update Glean SDK to v38.0.1 r=janerik
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.