Closed Bug 1724817 Opened 4 years ago Closed 10 months ago

Intermittent SUMMARY: ThreadSanitizer: data race /builds/worker/workspace/obj-build/dist/include/mozilla/ipc/GeckoChildProcessHost.h:128:50 in GetChildProcessHandle

Categories

(Core :: IPC, defect, P5)

Product:
Core
Component:
IPC
Type:
defect

Tracking

()

Status:
RESOLVED DUPLICATE of bug 1763625

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Blocks 1 open bug)

Details

(Keywords: csectype-race, intermittent-failure, sec-moderate)

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

[task 2021-08-09T21:58:04.761Z] 21:58:04     INFO - TEST-START | toolkit/components/telemetry/tests/browser/browser_DynamicScalars.js
[task 2021-08-09T21:58:04.879Z] 21:58:04     INFO - GECKO(3695) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-08-09T21:58:07.469Z] 21:58:07     INFO - GECKO(3695) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-08-09T21:58:07.473Z] 21:58:07     INFO - GECKO(3695) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-08-09T21:58:08.461Z] 21:58:08     INFO - GECKO(3695) | ==================
[task 2021-08-09T21:58:08.463Z] 21:58:08     INFO - GECKO(3695) | WARNING: ThreadSanitizer: data race (pid=3695)
[task 2021-08-09T21:58:08.464Z] 21:58:08     INFO - GECKO(3695) |   Read of size 4 at 0x7b4800337d7c by main thread (mutexes: write M749140204498462656):
[task 2021-08-09T21:58:08.465Z] 21:58:08     INFO - GECKO(3695) |     #0 GetChildProcessHandle /builds/worker/workspace/obj-build/dist/include/mozilla/ipc/GeckoChildProcessHost.h:128:50 (libxul.so+0xbc6b61)
[task 2021-08-09T21:58:08.465Z] 21:58:08     INFO - GECKO(3695) |     #1 operator() /builds/worker/checkouts/gecko/xpcom/base/MemoryTelemetry.cpp:327:29 (libxul.so+0xbc6b61)
[task 2021-08-09T21:58:08.468Z] 21:58:08     INFO - GECKO(3695) |     #2 std::_Function_handler<void (mozilla::ipc::GeckoChildProcessHost*), mozilla::MemoryTelemetry::GatherTotalMemory()::$_2>::_M_invoke(std::_Any_data const&, mozilla::ipc::GeckoChildProcessHost*&&) /builds/worker/fetches/sysroot-x86_64-linux-gnu/usr/lib/gcc/x86_64-linux-gnu/7.5.0/../../../../include/c++/7.5.0/bits/std_function.h:316:2 (libxul.so+0xbc6b61)
[task 2021-08-09T21:58:08.469Z] 21:58:08     INFO - GECKO(3695) |     #3 operator() /builds/worker/fetches/sysroot-x86_64-linux-gnu/usr/lib/gcc/x86_64-linux-gnu/7.5.0/../../../../include/c++/7.5.0/bits/std_function.h:706:14 (libxul.so+0x157c67c)
[task 2021-08-09T21:58:08.477Z] 21:58:08     INFO - GECKO(3695) |     #4 mozilla::ipc::GeckoChildProcessHost::GetAll(std::function<void (mozilla::ipc::GeckoChildProcessHost*)> const&) /builds/worker/checkouts/gecko/ipc/glue/GeckoChildProcessHost.cpp:1765:5 (libxul.so+0x157c67c)
[task 2021-08-09T21:58:08.478Z] 21:58:08     INFO - GECKO(3695) |     #5 mozilla::MemoryTelemetry::GatherTotalMemory() /builds/worker/checkouts/gecko/xpcom/base/MemoryTelemetry.cpp:325:3 (libxul.so+0xbaed2d)
[task 2021-08-09T21:58:08.479Z] 21:58:08     INFO - GECKO(3695) |     #6 mozilla::MemoryTelemetry::GatherReports(std::function<void ()> const&) /builds/worker/checkouts/gecko/xpcom/base/MemoryTelemetry.cpp:223:5 (libxul.so+0xbae68d)
[task 2021-08-09T21:58:08.481Z] 21:58:08     INFO - GECKO(3695) |     #7 (anonymous namespace)::TelemetryImpl::GatherMemory(JSContext*, mozilla::dom::Promise**) /builds/worker/checkouts/gecko/toolkit/components/telemetry/core/Telemetry.cpp:1709:26 (libxul.so+0x6a21627)
[task 2021-08-09T21:58:08.482Z] 21:58:08     INFO - GECKO(3695) |     #8 NS_InvokeByIndex /builds/worker/checkouts/gecko/xpcom/reflect/xptcall/md/unix/xptcinvoke_asm_x86_64_unix.S:101 (libxul.so+0xcc2c95)
[task 2021-08-09T21:58:08.482Z] 21:58:08     INFO - GECKO(3695) |     #9 XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCWrappedNativeJSOps.cpp:921:10 (libxul.so+0x1bbd840)
[task 2021-08-09T21:58:08.483Z] 21:58:08     INFO - GECKO(3695) |     #10 CallJSNative /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:402:13 (libxul.so+0x6c68e64)
[task 2021-08-09T21:58:08.484Z] 21:58:08     INFO - GECKO(3695) |     #11 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:489:12 (libxul.so+0x6c68e64)
[task 2021-08-09T21:58:08.484Z] 21:58:08     INFO - GECKO(3695) |     #12 InternalCall /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:549:10 (libxul.so+0x6c5ece6)
[task 2021-08-09T21:58:08.485Z] 21:58:08     INFO - GECKO(3695) |     #13 CallFromStack /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:553:10 (libxul.so+0x6c5ece6)
[task 2021-08-09T21:58:08.486Z] 21:58:08     INFO - GECKO(3695) |     #14 Interpret(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:3242:16 (libxul.so+0x6c5ece6)
[task 2021-08-09T21:58:08.486Z] 21:58:08     INFO - GECKO(3695) |     #15 js::RunScript(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:371:13 (libxul.so+0x6c52536)
[task 2021-08-09T21:58:08.487Z] 21:58:08     INFO - GECKO(3695) |     #16 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:521:13 (libxul.so+0x6c696c1)
[task 2021-08-09T21:58:08.488Z] 21:58:08     INFO - GECKO(3695) |     #17 InternalCall /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:549:10 (libxul.so+0x6c6a153)
[task 2021-08-09T21:58:08.489Z] 21:58:08     INFO - GECKO(3695) |     #18 js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:566:8 (libxul.so+0x6c6a153)
[task 2021-08-09T21:58:08.490Z] 21:58:08     INFO - GECKO(3695) |     #19 js::CallSelfHostedFunction(JSContext*, JS::Handle<js::PropertyName*>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/js/src/vm/SelfHosting.cpp:1546:10 (libxul.so+0x6f88780)
[task 2021-08-09T21:58:08.490Z] 21:58:08     INFO - GECKO(3695) |     #20 js::jit::InterpretResume(JSContext*, JS::Handle<JSObject*>, JS::Value*, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/js/src/jit/VMFunctions.cpp:1327:10 (libxul.so+0x7494669)
[task 2021-08-09T21:58:08.491Z] 21:58:08     INFO - GECKO(3695) |     #21 <null> <null> (0x7f32f6503940)
[task 2021-08-09T21:58:08.492Z] 21:58:08     INFO - GECKO(3695) |     #22 js::RunScript(JSContext*, js::RunState&) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:361:32 (libxul.so+0x6c5246b)
[task 2021-08-09T21:58:08.493Z] 21:58:08     INFO - GECKO(3695) |     #23 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:521:13 (libxul.so+0x6c696c1)
[task 2021-08-09T21:58:08.494Z] 21:58:08     INFO - GECKO(3695) |     #24 InternalCall /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:549:10 (libxul.so+0x6c6a153)
[task 2021-08-09T21:58:08.495Z] 21:58:08     INFO - GECKO(3695) |     #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:566:8 (libxul.so+0x6c6a153)
[task 2021-08-09T21:58:08.497Z] 21:58:08     INFO - GECKO(3695) |     #26 js::CallSelfHostedFunction(JSContext*, JS::Handle<js::PropertyName*>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/js/src/vm/SelfHosting.cpp:1546:10 (libxul.so+0x6f88780)
[task 2021-08-09T21:58:08.498Z] 21:58:08     INFO - GECKO(3695) |     #27 AsyncFunctionResume(JSContext*, JS::Handle<js::AsyncFunctionGeneratorObject*>, ResumeKind, JS::Handle<JS::Value>) /builds/worker/checkouts/gecko/js/src/vm/AsyncFunction.cpp:127:8 (libxul.so+0x6d81719)
[task 2021-08-09T21:58:08.500Z] 21:58:08     INFO - GECKO(3695) |     #28 js::AsyncFunctionAwaitedFulfilled(JSContext*, JS::Handle<js::AsyncFunctionGeneratorObject*>, JS::Handle<JS::Value>) /builds/worker/checkouts/gecko/js/src/vm/AsyncFunction.cpp:158:10 (libxul.so+0x6d81477)
[task 2021-08-09T21:58:08.501Z] 21:58:08     INFO - GECKO(3695) |     #29 AsyncFunctionPromiseReactionJob /builds/worker/checkouts/gecko/js/src/builtin/Promise.cpp:1700:12 (libxul.so+0x6e1f715)
[task 2021-08-09T21:58:08.502Z] 21:58:08     INFO - GECKO(3695) |     #30 PromiseReactionJob(JSContext*, unsigned int, JS::Value*) /builds/worker/checkouts/gecko/js/src/builtin/Promise.cpp:1856:12 (libxul.so+0x6e1f715)
[task 2021-08-09T21:58:08.503Z] 21:58:08     INFO - GECKO(3695) |     #31 CallJSNative /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:402:13 (libxul.so+0x6c68e64)
[task 2021-08-09T21:58:08.505Z] 21:58:08     INFO - GECKO(3695) |     #32 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:489:12 (libxul.so+0x6c68e64)
[task 2021-08-09T21:58:08.506Z] 21:58:08     INFO - GECKO(3695) |     #33 InternalCall /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:549:10 (libxul.so+0x6c6a153)
[task 2021-08-09T21:58:08.507Z] 21:58:08     INFO - GECKO(3695) |     #34 js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) /builds/worker/checkouts/gecko/js/src/vm/Interpreter.cpp:566:8 (libxul.so+0x6c6a153)
[task 2021-08-09T21:58:08.508Z] 21:58:08     INFO - GECKO(3695) |     #35 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+0x6da7db1)
[task 2021-08-09T21:58:08.509Z] 21:58:08     INFO - GECKO(3695) |     #36 mozilla::dom::PromiseJobCallback::Call(mozilla::dom::BindingCallContext&, JS::Handle<JS::Value>, mozilla::ErrorResult&) /builds/worker/workspace/obj-build/dom/bindings/PromiseBinding.cpp:34:8 (libxul.so+0x2c423eb)
[task 2021-08-09T21:58:08.509Z] 21:58:08     INFO - GECKO(3695) |     #37 Call /builds/worker/workspace/obj-build/dist/include/mozilla/dom/PromiseBinding.h:89:12 (libxul.so+0xb9e5ee)
[task 2021-08-09T21:58:08.510Z] 21:58:08     INFO - GECKO(3695) |     #38 Call /builds/worker/workspace/obj-build/dist/include/mozilla/dom/PromiseBinding.h:102:12 (libxul.so+0xb9e5ee)
[task 2021-08-09T21:58:08.510Z] 21:58:08     INFO - GECKO(3695) |     #39 mozilla::PromiseJobRunnable::Run(mozilla::AutoSlowOperation&) /builds/worker/checkouts/gecko/xpcom/base/CycleCollectedJSContext.cpp:212:18 (libxul.so+0xb9e5ee)
[task 2021-08-09T21:58:08.511Z] 21:58:08     INFO - GECKO(3695) |     #40 mozilla::CycleCollectedJSContext::PerformMicroTaskCheckPoint(bool) /builds/worker/checkouts/gecko/xpcom/base/CycleCollectedJSContext.cpp:647:17 (libxul.so+0xb8af5a)
[task 2021-08-09T21:58:08.512Z] 21:58:08     INFO - GECKO(3695) |     #41 mozilla::CycleCollectedJSContext::AfterProcessTask(unsigned int) /builds/worker/checkouts/gecko/xpcom/base/CycleCollectedJSContext.cpp:462:3 (libxul.so+0xb8b887)
[task 2021-08-09T21:58:08.512Z] 21:58:08     INFO - GECKO(3695) |     #42 XPCJSContext::AfterProcessTask(unsigned int) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCJSContext.cpp:1485:28 (libxul.so+0x1b8668f)
[task 2021-08-09T21:58:08.513Z] 21:58:08     INFO - GECKO(3695) |     #43 nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1185:24 (libxul.so+0xc96bba)
[task 2021-08-09T21:58:08.514Z] 21:58:08     INFO - GECKO(3695) |     #44 NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:466:10 (libxul.so+0xc9d632)
[task 2021-08-09T21:58:08.514Z] 21:58:08     INFO - GECKO(3695) |     #45 mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:107:5 (libxul.so+0x15ac410)
[task 2021-08-09T21:58:08.515Z] 21:58:08     INFO - GECKO(3695) |     #46 RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:331:10 (libxul.so+0x152631c)
[task 2021-08-09T21:58:08.515Z] 21:58:08     INFO - GECKO(3695) |     #47 RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:324:3 (libxul.so+0x152631c)
[task 2021-08-09T21:58:08.516Z] 21:58:08     INFO - GECKO(3695) |     #48 MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:306:3 (libxul.so+0x152631c)
[task 2021-08-09T21:58:08.517Z] 21:58:08     INFO - GECKO(3695) |     #49 nsBaseAppShell::Run() /builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp:137:27 (libxul.so+0x4cc2f16)
[task 2021-08-09T21:58:08.517Z] 21:58:08     INFO - GECKO(3695) |     #50 nsAppStartup::Run() /builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp:274:30 (libxul.so+0x6a13bb8)
[task 2021-08-09T21:58:08.518Z] 21:58:08     INFO - GECKO(3695) |     #51 XREMain::XRE_mainRun() /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5295:22 (libxul.so+0x6b2fd3a)
[task 2021-08-09T21:58:08.519Z] 21:58:08     INFO - GECKO(3695) |     #52 XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5487:8 (libxul.so+0x6b30a87)
[task 2021-08-09T21:58:08.519Z] 21:58:08     INFO - GECKO(3695) |     #53 XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5546:21 (libxul.so+0x6b31024)
[task 2021-08-09T21:58:08.524Z] 21:58:08     INFO - GECKO(3695) |     #54 mozilla::BootstrapImpl::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/Bootstrap.cpp:45:12 (libxul.so+0x6b3b592)
[task 2021-08-09T21:58:08.524Z] 21:58:08     INFO - GECKO(3695) |     #55 do_main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:225:22 (firefox+0xca340)
[task 2021-08-09T21:58:08.525Z] 21:58:08     INFO - GECKO(3695) |     #56 main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:378:16 (firefox+0xca340)
[task 2021-08-09T21:58:08.526Z] 21:58:08     INFO - GECKO(3695) |   Previous write of size 4 at 0x7b4800337d7c by thread T4:
<...>
[task 2021-08-09T21:58:08.560Z] 21:58:08     INFO - GECKO(3695) |   Mutex M749140204498462656 is already destroyed.
[task 2021-08-09T21:58:08.561Z] 21:58:08     INFO - GECKO(3695) |   Thread T4 'IPC I/O Parent' (tid=3705, running) created by main thread at:
[task 2021-08-09T21:58:08.562Z] 21:58:08     INFO - GECKO(3695) |     #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-08-09T21:58:08.564Z] 21:58:08     INFO - GECKO(3695) |     #1 CreateThread /builds/worker/checkouts/gecko/ipc/chromium/src/base/platform_thread_posix.cc:123:14 (libxul.so+0x152e197)
[task 2021-08-09T21:58:08.564Z] 21:58:08     INFO - GECKO(3695) |     #2 PlatformThread::Create(unsigned long, PlatformThread::Delegate*, unsigned long*) /builds/worker/checkouts/gecko/ipc/chromium/src/base/platform_thread_posix.cc:134:10 (libxul.so+0x152e197)
[task 2021-08-09T21:58:08.565Z] 21:58:08     INFO - GECKO(3695) |     #3 base::Thread::StartWithOptions(base::Thread::Options const&) /builds/worker/checkouts/gecko/ipc/chromium/src/base/thread.cc:93:8 (libxul.so+0x15376a1)
[task 2021-08-09T21:58:08.565Z] 21:58:08     INFO - GECKO(3695) |     #4 NS_InitXPCOM /builds/worker/checkouts/gecko/xpcom/build/XPCOMInit.cpp:318:9 (libxul.so+0xcd45ac)
[task 2021-08-09T21:58:08.566Z] 21:58:08     INFO - GECKO(3695) |     #5 ScopedXPCOMStartup::Initialize(bool) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:1717:8 (libxul.so+0x6b25bcd)
[task 2021-08-09T21:58:08.566Z] 21:58:08     INFO - GECKO(3695) |     #6 XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5476:22 (libxul.so+0x6b30a71)
[task 2021-08-09T21:58:08.567Z] 21:58:08     INFO - GECKO(3695) |     #7 XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5546:21 (libxul.so+0x6b31024)
[task 2021-08-09T21:58:08.567Z] 21:58:08     INFO - GECKO(3695) |     #8 mozilla::BootstrapImpl::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/Bootstrap.cpp:45:12 (libxul.so+0x6b3b592)
[task 2021-08-09T21:58:08.568Z] 21:58:08     INFO - GECKO(3695) |     #9 do_main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:225:22 (firefox+0xca340)
[task 2021-08-09T21:58:08.572Z] 21:58:08     INFO - GECKO(3695) |     #10 main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:378:16 (firefox+0xca340)
[task 2021-08-09T21:58:08.573Z] 21:58:08     INFO - GECKO(3695) | SUMMARY: ThreadSanitizer: data race /builds/worker/workspace/obj-build/dist/include/mozilla/ipc/GeckoChildProcessHost.h:128:50 in GetChildProcessHandle
[task 2021-08-09T21:58:08.578Z] 21:58:08     INFO - GECKO(3695) | ==================
[task 2021-08-09T21:58:08.578Z] 21:58:08     INFO - GECKO(3695) | Exiting due to channel error.
[task 2021-08-09T21:58:08.579Z] 21:58:08     INFO - GECKO(3695) | Exiting due to channel error.
[task 2021-08-09T21:58:08.579Z] 21:58:08     INFO - GECKO(3695) | Exiting due to channel error.
[task 2021-08-09T21:58:08.580Z] 21:58:08     INFO - GECKO(3695) | Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: Receive IPC close with reason=AbnormalShutdown (t=15.696) Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: Receive IPC close with reason=AbnormalShutdown (t=5.07616) Exiting due to channel error.
[task 2021-08-09T21:58:08.580Z] 21:58:08     INFO - GECKO(3695) | Exiting due to channel error.
[task 2021-08-09T21:58:09.562Z] 21:58:09     INFO - GECKO(3695) | Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: Receive IPC close with reason=AbnormalShutdown (t=2.57259)
[task 2021-08-09T21:58:09.562Z] 21:58:09     INFO - TEST-INFO | Main app process: killed by SIGIOT
[task 2021-08-09T21:58:09.563Z] 21:58:09     INFO - Buffered messages logged at 21:58:04
[task 2021-08-09T21:58:09.564Z] 21:58:09     INFO - Entering test bound test_setup
[task 2021-08-09T21:58:09.564Z] 21:58:09     INFO - Leaving test bound test_setup
[task 2021-08-09T21:58:09.564Z] 21:58:09     INFO - Entering test bound test_recording
[task 2021-08-09T21:58:09.565Z] 21:58:09     INFO - Buffered messages logged at 21:58:05
[task 2021-08-09T21:58:09.571Z] 21:58:09     INFO - TEST-PASS | toolkit/components/telemetry/tests/browser/browser_DynamicScalars.js | The new tab must spawn its own process - 
[task 2021-08-09T21:58:09.572Z] 21:58:09     INFO - Buffered messages logged at 21:58:07
[task 2021-08-09T21:58:09.572Z] 21:58:09     INFO - TEST-PASS | toolkit/components/telemetry/tests/browser/browser_DynamicScalars.js | The scalars must contain the 'dynamic' process section - 
[task 2021-08-09T21:58:09.573Z] 21:58:09     INFO - TEST-PASS | toolkit/components/telemetry/tests/browser/browser_DynamicScalars.js | Dynamic scalars registered before a process spawns must be present. - 
[task 2021-08-09T21:58:09.573Z] 21:58:09     INFO - TEST-PASS | toolkit/components/telemetry/tests/browser/browser_DynamicScalars.js | The dynamic scalar must contain the expected value. - 
[task 2021-08-09T21:58:09.573Z] 21:58:09     INFO - TEST-PASS | toolkit/components/telemetry/tests/browser/browser_DynamicScalars.js | The dynamic scalar must not be updated after being expired. - 
[task 2021-08-09T21:58:09.574Z] 21:58:09     INFO - TEST-PASS | toolkit/components/telemetry/tests/browser/browser_DynamicScalars.js | Dynamic scalars registered after a process spawns must be present. - 
[task 2021-08-09T21:58:09.574Z] 21:58:09     INFO - TEST-PASS | toolkit/components/telemetry/tests/browser/browser_DynamicScalars.js | The dynamic scalar must contain the expected value. - 
[task 2021-08-09T21:58:09.575Z] 21:58:09     INFO - TEST-PASS | toolkit/components/telemetry/tests/browser/browser_DynamicScalars.js | The keyed scalars must contain the 'dynamic' process section - 
[task 2021-08-09T21:58:09.575Z] 21:58:09     INFO - TEST-PASS | toolkit/components/telemetry/tests/browser/browser_DynamicScalars.js | Dynamic keyed scalars registered after a process spawns must be present. - 
[task 2021-08-09T21:58:09.576Z] 21:58:09     INFO - TEST-PASS | toolkit/components/telemetry/tests/browser/browser_DynamicScalars.js | The dynamic keyed scalar must contain the expected value. - 
[task 2021-08-09T21:58:09.576Z] 21:58:09     INFO - Leaving test bound test_recording
[task 2021-08-09T21:58:09.577Z] 21:58:09     INFO - Entering test bound test_aggregation
[task 2021-08-09T21:58:09.577Z] 21:58:09     INFO - Buffered messages finished
[task 2021-08-09T21:58:09.577Z] 21:58:09    ERROR - TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/browser/browser_DynamicScalars.js | application terminated with exit code -6
[task 2021-08-09T21:58:09.578Z] 21:58:09     INFO - runtests.py | Application ran for: 0:00:26.419574
[task 2021-08-09T21:58:09.578Z] 21:58:09     INFO - zombiecheck | Reading PID log: /tmp/tmpehgl600wpidlog
[task 2021-08-09T21:58:09.579Z] 21:58:09     INFO - ==> process 3695 launched child process 3710
[task 2021-08-09T21:58:09.579Z] 21:58:09     INFO - ==> process 3695 launched child process 3772
[task 2021-08-09T21:58:09.580Z] 21:58:09     INFO - ==> process 3695 launched child process 3790
[task 2021-08-09T21:58:09.580Z] 21:58:09     INFO - ==> process 3695 launched child process 3843
[task 2021-08-09T21:58:09.580Z] 21:58:09     INFO - ==> process 3695 launched child process 3879
[task 2021-08-09T21:58:09.580Z] 21:58:09     INFO - ==> process 3695 launched child process 3903
[task 2021-08-09T21:58:09.581Z] 21:58:09     INFO - ==> process 3695 launched child process 3925
[task 2021-08-09T21:58:09.581Z] 21:58:09     INFO - ==> process 3695 launched child process 3953
[task 2021-08-09T21:58:09.582Z] 21:58:09     INFO - zombiecheck | Checking for orphan process with PID: 3843
[task 2021-08-09T21:58:09.582Z] 21:58:09     INFO - zombiecheck | Checking for orphan process with PID: 3879
[task 2021-08-09T21:58:09.583Z] 21:58:09     INFO - zombiecheck | Checking for orphan process with PID: 3790
[task 2021-08-09T21:58:09.583Z] 21:58:09     INFO - zombiecheck | Checking for orphan process with PID: 3953
[task 2021-08-09T21:58:09.583Z] 21:58:09     INFO - zombiecheck | Checking for orphan process with PID: 3925
[task 2021-08-09T21:58:09.584Z] 21:58:09     INFO - zombiecheck | Checking for orphan process with PID: 3772
[task 2021-08-09T21:58:09.584Z] 21:58:09     INFO - zombiecheck | Checking for orphan process with PID: 3710
[task 2021-08-09T21:58:09.585Z] 21:58:09     INFO - zombiecheck | Checking for orphan process with PID: 3903
[task 2021-08-09T21:58:09.585Z] 21:58:09     INFO - Stopping web server
[task 2021-08-09T21:58:09.590Z] 21:58:09     INFO - Server shut down.
[task 2021-08-09T21:58:09.610Z] 21:58:09     INFO - Web server killed.
[task 2021-08-09T21:58:09.610Z] 21:58:09     INFO - Stopping web socket server
[task 2021-08-09T21:58:09.630Z] 21:58:09     INFO - Stopping ssltunnel
[task 2021-08-09T21:58:09.652Z] 21:58:09  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2021-08-09T21:58:09.652Z] 21:58:09     INFO - runtests.py | Running tests: end.

Although the caller in this case is telemetry, the problem might happen down with GetChildProcessHandle() more generically. The full log link has both stacks.

Group: core-security → dom-core-security
Component: Telemetry → IPC
Keywords: csectype-race, sec-moderate
Product: Toolkit → Core
Blocks: tsan

From the stacks, it looks like the main thread is gathering a memory report, which does ipc::GeckoChildProcessHost::GetAll(). The other thread in the race is the 'IPC I/O Parent' thread, so maybe a process host is being created or destroyed at the same time.

From the read, it looks like this is a race on GeckoChildProcessHost::mChildProcessHandle. This failure showed up on Linux. GeckoChildProcessHost::OpenPrivilegedHandle() is the only place on Linux that I can see that can write to that field.

From looking at the code, GeckoChildProcessHost objects are added the list traversed by GetAll when they're constructed, so they can be observed before or (in this case) during the promise resolution that happens in GeckoChildProcessHost::AsyncLaunch. (The callback provided to GetAll is invoked while holding a mutex against changes to the list, so a well-behaved callback can't race with GeckoChildProcessHost destruction.)

I'll need to look at the various GetChildProcessHandle callers more to get an idea of what can happen here. It's mostly from inside other parts of process handling, which hopefully is synchronized correctly but maybe not; and then there are MemoryTelemetry::GatherTotalMemory and ChromeUtils::RequestProcInfo, where occasional temporary inconsistency might not be a big problem.

See Also: → 1745562

Looks like this is still happening a few times a week.

I don't see any instances of this in the available orange-factor time window. Did it stop? Or just morph somewhere else?

Flags: needinfo?(jld)

I believe this member is now guarded by a mutex since bug 1763625, so this bug shouldn't exist anymore.

Status: NEW → RESOLVED
Closed: 10 months ago
Duplicate of bug: 1763625
Flags: needinfo?(jld)
Resolution: --- → DUPLICATE
Group: dom-core-security
You need to log in before you can comment on or make changes to this bug.