Closed Bug 1691557 Opened 3 years ago Closed 2 years ago

Intermittent SUMMARY: ThreadSanitizer: data race /builds/worker/checkouts/gecko/dom/workers/RuntimeService.cpp:1101:55 in mozilla::dom::workerinternals::RuntimeService::GetService()

Categories

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

defect

Tracking

()

RESOLVED FIXED
99 Branch
Tracking Status
firefox99 --- fixed

People

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

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

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


[task 2021-02-08T17:26:59.835Z] 17:26:59     INFO - GECKO(2910) |   Thread T8 'Shutdow~minator' (tid=3129, running) created by main thread at:
[task 2021-02-08T17:26:59.835Z] 17:26:59     INFO - GECKO(2910) |     #0 pthread_create /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/tsan/rtl/tsan_interceptors_posix.cpp:966:3 (firefox+0x5669b)
[task 2021-02-08T17:26:59.835Z] 17:26:59     INFO - GECKO(2910) |     #1 _PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:458:14 (libnspr4.so+0x3c3f3)
[task 2021-02-08T17:26:59.835Z] 17:26:59     INFO - GECKO(2910) |     #2 PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:533:12 (libnspr4.so+0x30d15)
[task 2021-02-08T17:26:59.835Z] 17:26:59     INFO - GECKO(2910) |     #3 CreateSystemThread /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:103:7 (libxul.so+0x67d3da5)
[task 2021-02-08T17:26:59.835Z] 17:26:59     INFO - GECKO(2910) |     #4 StartWatchdog /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:442:7 (libxul.so+0x67d3da5)
[task 2021-02-08T17:26:59.835Z] 17:26:59     INFO - GECKO(2910) |     #5 Start /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:383:3 (libxul.so+0x67d3da5)
[task 2021-02-08T17:26:59.835Z] 17:26:59     INFO - GECKO(2910) |     #6 mozilla::nsTerminator::Observe(nsISupports*, char const*, char16_t const*) /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:493:5 (libxul.so+0x67d3da5)
[task 2021-02-08T17:26:59.835Z] 17:26:59     INFO - GECKO(2910) |     #7 nsObserverList::NotifyObservers(nsISupports*, char const*, char16_t const*) /builds/worker/checkouts/gecko/xpcom/ds/nsObserverList.cpp:70:19 (libxul.so+0xb18433)
[task 2021-02-08T17:26:59.835Z] 17:26:59     INFO - GECKO(2910) |     #8 nsObserverService::NotifyObservers(nsISupports*, char const*, char16_t const*) /builds/worker/checkouts/gecko/xpcom/ds/nsObserverService.cpp:287:19 (libxul.so+0xb1b66d)
[task 2021-02-08T17:26:59.835Z] 17:26:59     INFO - GECKO(2910) |     #9 nsAppStartup::Quit(unsigned int, int, bool*) /builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp:446:19 (libxul.so+0x66de895)
[task 2021-02-08T17:26:59.835Z] 17:26:59     INFO - GECKO(2910) |     #10 NS_InvokeByIndex /builds/worker/checkouts/gecko/xpcom/reflect/xptcall/md/unix/xptcinvoke_asm_x86_64_unix.S:101 (libxul.so+0xbdf9d5)
[task 2021-02-08T17:26:59.835Z] 17:26:59     INFO - GECKO(2910) |     #11 XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNativeJSOps.cpp:925:10 (libxul.so+0x1aa4350)
[task 2021-02-08T17:26:59.836Z] 17:26:59     INFO - GECKO(2910) |     #12 CallJSNative /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:435:13 (libxul.so+0x6930e09)
[task 2021-02-08T17:26:59.836Z] 17:26:59     INFO - GECKO(2910) |     #13 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:526:12 (libxul.so+0x6930e09)
[task 2021-02-08T17:26:59.837Z] 17:26:59     INFO - GECKO(2910) |     #14 InternalCall /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:579:10 (libxul.so+0x693208e)
[task 2021-02-08T17:26:59.838Z] 17:26:59     INFO - GECKO(2910) |     #15 js::CallFromStack(JSContext*, JS::CallArgs const&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:583:10 (libxul.so+0x693208e)
[task 2021-02-08T17:26:59.838Z] 17:26:59     INFO - GECKO(2910) |     #16 js::jit::DoCallFallback(JSContext*, js::jit::BaselineFrame*, js::jit::ICCall_Fallback*, unsigned int, JS::Value*, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/js/src/jit/BaselineIC.cpp:1841:10 (libxul.so+0x712fd38)
[task 2021-02-08T17:26:59.839Z] 17:26:59     INFO - GECKO(2910) |     #17 <null> <null> (0x7fb153469b08)
[task 2021-02-08T17:26:59.839Z] 17:26:59     INFO - GECKO(2910) |     #18 js::RunScript(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:395:32 (libxul.so+0x6918e4e)
[task 2021-02-08T17:26:59.839Z] 17:26:59     INFO - GECKO(2910) |     #19 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:551:13 (libxul.so+0x69316a0)
[task 2021-02-08T17:26:59.840Z] 17:26:59     INFO - GECKO(2910) |     #20 InternalCall /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:579:10 (libxul.so+0x6932236)
[task 2021-02-08T17:26:59.841Z] 17:26:59     INFO - GECKO(2910) |     #21 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:596:8 (libxul.so+0x6932236)
[task 2021-02-08T17:26:59.842Z] 17:26:59     INFO - GECKO(2910) |     #22 JS::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/js/src/jsapi.cpp:2861:10 (libxul.so+0x6df515e)
[task 2021-02-08T17:26:59.842Z] 17:26:59     INFO - GECKO(2910) |     #23 mozilla::dom::MessageListener::ReceiveMessage(mozilla::dom::BindingCallContext&, JS::Handle<JS::Value>, mozilla::dom::ReceiveMessageArgument const&, JS::MutableHandle<JS::Value>, mozilla::ErrorResult&) /builds/worker/workspace/obj-build/dom/bindings/MessageManagerBinding.cpp:6309:8 (libxul.so+0x29723cd)
[task 2021-02-08T17:26:59.842Z] 17:26:59     INFO - GECKO(2910) |     #24 ReceiveMessage /builds/worker/workspace/obj-build/dist/include/mozilla/dom/MessageManagerBinding.h:783:12 (libxul.so+0x4717252)
[task 2021-02-08T17:26:59.843Z] 17:26:59     INFO - GECKO(2910) |     #25 mozilla::dom::JSActor::CallReceiveMessage(JSContext*, mozilla::dom::JSActorMessageMeta const&, JS::Handle<JS::Value>, JS::MutableHandle<JS::Value>, mozilla::ErrorResult&) /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSActor.cpp:271:22 (libxul.so+0x4717252)
[task 2021-02-08T17:26:59.844Z] 17:26:59     INFO - GECKO(2910) |     #26 ReceiveMessage /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSActor.cpp:284:3 (libxul.so+0x4719f9c)
[task 2021-02-08T17:26:59.844Z] 17:26:59     INFO - GECKO(2910) |     #27 mozilla::dom::JSActorManager::ReceiveRawMessage(mozilla::dom::JSActorMessageMeta const&, mozilla::Maybe<mozilla::dom::ipc::StructuredCloneData>&&, mozilla::Maybe<mozilla::dom::ipc::StructuredCloneData>&&) /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSActorManager.cpp:182:14 (libxul.so+0x4719f9c)
[task 2021-02-08T17:26:59.845Z] 17:26:59     INFO - GECKO(2910) |     #28 mozilla::dom::WindowGlobalParent::RecvRawMessage(mozilla::dom::JSActorMessageMeta const&, mozilla::Maybe<mozilla::dom::ClonedMessageData> const&, mozilla::Maybe<mozilla::dom::ClonedMessageData> const&) /builds/worker/checkouts/gecko/dom/ipc/WindowGlobalParent.cpp:469:3 (libxul.so+0x470b4a5)
[task 2021-02-08T17:26:59.846Z] 17:26:59     INFO - GECKO(2910) |     #29 mozilla::dom::PWindowGlobalParent::OnMessageReceived(IPC::Message const&) /builds/worker/workspace/obj-build/ipc/ipdl/PWindowGlobalParent.cpp:687:62 (libxul.so+0x19188c3)
[task 2021-02-08T17:26:59.846Z] 17:26:59     INFO - GECKO(2910) |     #30 mozilla::dom::PContentParent::OnMessageReceived(IPC::Message const&) /builds/worker/workspace/obj-build/ipc/ipdl/PContentParent.cpp:6685:32 (libxul.so+0x15fde95)
[task 2021-02-08T17:26:59.846Z] 17:26:59     INFO - GECKO(2910) |     #31 mozilla::ipc::MessageChannel::DispatchAsyncMessage(mozilla::ipc::ActorLifecycleProxy*, IPC::Message const&) /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:2153:25 (libxul.so+0x14b907b)
[task 2021-02-08T17:26:59.846Z] 17:26:59     INFO - GECKO(2910) |     #32 mozilla::ipc::MessageChannel::DispatchMessage(IPC::Message&&) /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:2077:9 (libxul.so+0x14b745c)
[task 2021-02-08T17:26:59.846Z] 17:26:59     INFO - GECKO(2910) |     #33 mozilla::ipc::MessageChannel::RunMessage(mozilla::ipc::MessageChannel::MessageTask&) /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1925:3 (libxul.so+0x14b803a)
[task 2021-02-08T17:26:59.847Z] 17:26:59     INFO - GECKO(2910) |     #34 mozilla::ipc::MessageChannel::MessageTask::Run() /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1956:13 (libxul.so+0x14b8641)
[task 2021-02-08T17:26:59.848Z] 17:26:59     INFO - GECKO(2910) |     #35 mozilla::RunnableTask::Run() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:472:16 (libxul.so+0xba3b52)
[task 2021-02-08T17:26:59.848Z] 17:26:59     INFO - GECKO(2910) |     #36 mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:753:26 (libxul.so+0xba1a58)
[task 2021-02-08T17:26:59.849Z] 17:26:59     INFO - GECKO(2910) |     #37 mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:611:15 (libxul.so+0xba03d6)
[task 2021-02-08T17:26:59.849Z] 17:26:59     INFO - GECKO(2910) |     #38 mozilla::TaskController::ProcessPendingMTTask(bool) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:395:36 (libxul.so+0xba0674)
[task 2021-02-08T17:26:59.849Z] 17:26:59     INFO - GECKO(2910) |     #39 operator() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:136:37 (libxul.so+0xba6cda)
[task 2021-02-08T17:26:59.849Z] 17:26:59     INFO - GECKO(2910) |     #40 mozilla::detail::RunnableFunction<mozilla::TaskController::InitializeInternal()::$_4>::Run() /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.h:534:5 (libxul.so+0xba6cda)
[task 2021-02-08T17:26:59.850Z] 17:26:59     INFO - GECKO(2910) |     #41 nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1158:16 (libxul.so+0xbb7af6)
[task 2021-02-08T17:26:59.851Z] 17:26:59     INFO - GECKO(2910) |     #42 NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:548:10 (libxul.so+0xbbdb12)
[task 2021-02-08T17:26:59.851Z] 17:26:59     INFO - GECKO(2910) |     #43 mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:109:5 (libxul.so+0x14bcaf0)
[task 2021-02-08T17:26:59.852Z] 17:26:59     INFO - GECKO(2910) |     #44 RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:335:10 (libxul.so+0x14477cc)
[task 2021-02-08T17:26:59.852Z] 17:26:59     INFO - GECKO(2910) |     #45 RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:328:3 (libxul.so+0x14477cc)
[task 2021-02-08T17:26:59.853Z] 17:26:59     INFO - GECKO(2910) |     #46 MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:310:3 (libxul.so+0x14477cc)
[task 2021-02-08T17:26:59.854Z] 17:26:59     INFO - GECKO(2910) |     #47 nsBaseAppShell::Run() /builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp:137:27 (libxul.so+0x4b6df16)
[task 2021-02-08T17:26:59.854Z] 17:26:59     INFO - GECKO(2910) |     #48 nsAppStartup::Run() /builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp:271:30 (libxul.so+0x66de0a8)
[task 2021-02-08T17:26:59.854Z] 17:26:59     INFO - GECKO(2910) |     #49 XREMain::XRE_mainRun() /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5246:22 (libxul.so+0x67f88cf)
[task 2021-02-08T17:26:59.855Z] 17:26:59     INFO - GECKO(2910) |     #50 XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5438:8 (libxul.so+0x67f97f8)
[task 2021-02-08T17:26:59.855Z] 17:26:59     INFO - GECKO(2910) |     #51 XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5501:21 (libxul.so+0x67f9c74)
[task 2021-02-08T17:26:59.855Z] 17:26:59     INFO - GECKO(2910) |     #52 mozilla::BootstrapImpl::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/Bootstrap.cpp:45:12 (libxul.so+0x6804312)
[task 2021-02-08T17:26:59.857Z] 17:26:59     INFO - GECKO(2910) |     #53 do_main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:220:22 (firefox+0xc7c80)
[task 2021-02-08T17:26:59.857Z] 17:26:59     INFO - GECKO(2910) |     #54 main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:344:16 (firefox+0xc7c80)
[task 2021-02-08T17:26:59.858Z] 17:26:59     INFO - GECKO(2910) | SUMMARY: ThreadSanitizer: data race /builds/worker/checkouts/gecko/dom/workers/RuntimeService.cpp:1101:55 in mozilla::dom::workerinternals::RuntimeService::GetService()
[task 2021-02-08T17:26:59.858Z] 17:26:59     INFO - GECKO(2910) | ==================
[task 2021-02-08T17:33:09.845Z] 17:33:09     INFO - Buffered messages finished
[task 2021-02-08T17:33:09.845Z] 17:33:09    ERROR - TEST-UNEXPECTED-TIMEOUT | Last test finished | application timed out after 370 seconds with no output
[task 2021-02-08T17:33:09.845Z] 17:33:09    ERROR - Force-terminating active process(es).```

Start of the ThreadSanitizer warning message:

[task 2021-02-08T17:26:59.826Z] 17:26:59     INFO - GECKO(2910) | WARNING: ThreadSanitizer: data race (pid=2910)
[task 2021-02-08T17:26:59.827Z] 17:26:59     INFO - GECKO(2910) |   Read of size 8 at 0x7fb1e7ef5530 by thread T8:
[task 2021-02-08T17:26:59.827Z] 17:26:59     INFO - GECKO(2910) |     #0 mozilla::dom::workerinternals::RuntimeService::GetService() /builds/worker/checkouts/gecko/dom/workers/RuntimeService.cpp:1101:55 (libxul.so+0x472fed6)
[task 2021-02-08T17:26:59.827Z] 17:26:59     INFO - GECKO(2910) |     #1 mozilla::(anonymous namespace)::RunWatchdog(void*) /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:215:9 (libxul.so+0x67d3ae4)
[task 2021-02-08T17:26:59.828Z] 17:26:59     INFO - GECKO(2910) |     #2 _pt_root /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:201:5 (libnspr4.so+0x4524b)
[task 2021-02-08T17:26:59.829Z] 17:26:59     INFO - GECKO(2910) |   Previous write of size 8 at 0x7fb1e7ef5530 by main thread:
[task 2021-02-08T17:26:59.829Z] 17:26:59     INFO - GECKO(2910) |     [failed to restore the stack]
[task 2021-02-08T17:26:59.829Z] 17:26:59     INFO - GECKO(2910) |   As if synchronized via sleep:
[task 2021-02-08T17:26:59.833Z] 17:26:59     INFO - GECKO(2910) |     #0 usleep /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/tsan/rtl/tsan_interceptors_posix.cpp:356:3 (firefox+0x53df6)
[task 2021-02-08T17:26:59.834Z] 17:26:59     INFO - GECKO(2910) |     #1 mozilla::(anonymous namespace)::RunWatchdog(void*) /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:177:5 (libxul.so+0x67d3a88)
[task 2021-02-08T17:26:59.834Z] 17:26:59     INFO - GECKO(2910) |     #2 _pt_root /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:201:5 (libnspr4.so+0x4524b)
[task 2021-02-08T17:26:59.835Z] 17:26:59     INFO - GECKO(2910) |   Location is global 'mozilla::dom::workerinternals::(anonymous namespace)::gRuntimeService' of size 8 at 0x7fb1e7ef5530 (libxul.so+0x00000ba7e530)

Unfortunately, there is no stack trace for the previous write, but it's likely it's from the dtor of RuntimeService at https://searchfox.org/mozilla-central/rev/7067bbd8194f4346ec59d77c33cd88f06763e090/dom/workers/RuntimeService.cpp#1079.

Flags: needinfo?(jstutte)

(In reply to Simon Giesecke [:sg] [he/him] from comment #2)

Unfortunately, there is no stack trace for the previous write, but it's likely it's from the dtor of RuntimeService at https://searchfox.org/mozilla-central/rev/7067bbd8194f4346ec59d77c33cd88f06763e090/dom/workers/RuntimeService.cpp#1079.

Yes, that seems likely. We are getting there late during shutdown and the watchdog triggers around the deconstruction of the RuntimeService. gRuntimeService is intended to be a self reference to this singleton, but being a non-atomic raw pointer can lead to this situation (and could even lead to a UAF during the shutdown timer handling). The entire life-cycle of RuntimeService should be improved, because gRuntimeService == nullptr can currently mean two things:

  1. The instance has not yet been initialized (as of GetOrCreateService)
  2. The instance has been shut down. It might be the case that we should check for hanging workers only earlier and not after sShutdownNotified ?

Unfortunately it is difficult to search for real-world crashes there, because RunWatchdog crashes often and most of the times legitimately.

Blocks: tsan

During shutdown gRuntimeService can be accessed from a different thread while it gets destroyed. There should be not too much penalty having this atomic, even if it is for an edge case only.

Assignee: nobody → jstutte
Status: NEW → ASSIGNED
Pushed by jstutte@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/a72af1093403
Make gRuntimeService atomic. r=dom-worker-reviewers,jesup
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → 99 Branch
See Also: → 1757513

The remaining failures seem to be only happening on ESR.

Flags: needinfo?(jstutte)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: