1759616 - Intermittent SUMMARY: ThreadSanitizer: data race /builds/worker/workspace/obj-build/dist/include/mozilla/cxxalloc.h:51:10 in operator delete

Status: RESOLVED DUPLICATE of bug 1713773

(Core :: XPCOM, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-03-14T23:22:10.584Z] 23:22:10     INFO - TEST-START | /html/semantics/embedded-content/the-iframe-element/iframe_sandbox_allow_script.html
[task 2022-03-14T23:22:10.611Z] 23:22:10     INFO - Closing window 51dcb830-16ad-410a-811a-e8314a516ebd
[task 2022-03-14T23:22:47.072Z] 23:22:47     INFO - PID 5236 | ==================
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 | WARNING: ThreadSanitizer: data race (pid=8793)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |   Write of size 8 at 0x7b4c0000ffd0 by main thread:
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #0 free /builds/worker/fetches/llvm-project/compiler-rt/lib/tsan/rtl/tsan_interceptors_posix.cpp:714:3 (firefox+0x5908a)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #1 operator delete /builds/worker/workspace/obj-build/dist/include/mozilla/cxxalloc.h:51:10 (libxul.so+0xfb5edd)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #2 nsThread::~nsThread() /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:590:23 (libxul.so+0xfb5edd)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #3 nsThread::Release() /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:178:1 (libxul.so+0xfb3d77)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #4 Release /builds/worker/workspace/obj-build/dist/include/mozilla/RefPtr.h:50:40 (libxul.so+0xfbdd7b)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #5 Release /builds/worker/workspace/obj-build/dist/include/mozilla/RefPtr.h:381:36 (libxul.so+0xfbdd7b)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #6 ~RefPtr /builds/worker/workspace/obj-build/dist/include/mozilla/RefPtr.h:81:7 (libxul.so+0xfbdd7b)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #7 Destruct /builds/worker/workspace/obj-build/dist/include/nsTArray.h:642:45 (libxul.so+0xfbdd7b)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #8 DestructRange /builds/worker/workspace/obj-build/dist/include/nsTArray.h:2403:7 (libxul.so+0xfbdd7b)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #9 ClearAndRetainStorage /builds/worker/workspace/obj-build/dist/include/nsTArray.h:1479:5 (libxul.so+0xfbdd7b)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #10 ~nsTArray_Impl /builds/worker/workspace/obj-build/dist/include/nsTArray.h:1034:7 (libxul.so+0xfbdd7b)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #11 nsThreadManager::Shutdown() /builds/worker/checkouts/gecko/xpcom/threads/nsThreadManager.cpp:456:3 (libxul.so+0xfbdd7b)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #12 mozilla::ShutdownXPCOM(nsIServiceManager*) /builds/worker/checkouts/gecko/xpcom/build/XPCOMInit.cpp:670:28 (libxul.so+0xff9c0e)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #13 NS_ShutdownXPCOM /builds/worker/checkouts/gecko/xpcom/build/XPCOMInit.cpp:582:10 (libxul.so+0xff99c5)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #14 XRE_TermEmbedding() /builds/worker/checkouts/gecko/toolkit/xre/nsEmbedFunctions.cpp:226:3 (libxul.so+0x72c4339)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #15 mozilla::ipc::ScopedXREEmbed::Stop() /builds/worker/checkouts/gecko/ipc/glue/ScopedXREEmbed.cpp:90:5 (libxul.so+0x1a25d4f)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #16 mozilla::dom::ContentProcess::CleanUp() /builds/worker/checkouts/gecko/dom/ipc/ContentProcess.cpp:181:44 (libxul.so+0x4b180fc)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #17 XRE_InitChildProcess(int, char**, XREChildData const*) /builds/worker/checkouts/gecko/toolkit/xre/nsEmbedFunctions.cpp:733:16 (libxul.so+0x72c4abc)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #18 mozilla::BootstrapImpl::XRE_InitChildProcess(int, char**, XREChildData const*) /builds/worker/checkouts/gecko/toolkit/xre/Bootstrap.cpp:67:12 (libxul.so+0x72cc8a2)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #19 content_process_main /builds/worker/checkouts/gecko/browser/app/../../ipc/contentproc/plugin-container.cpp:57:28 (firefox+0xd0297)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #20 main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:327:18 (firefox+0xd0297)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |   Previous read of size 8 at 0x7b4c0000ffd0 by thread T4:
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #0 get /builds/worker/workspace/obj-build/dist/include/mozilla/RefPtr.h:286:27 (libxul.so+0xfb1e6a)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #1 EventQueue /builds/worker/checkouts/gecko/xpcom/threads/nsThread.h:230:66 (libxul.so+0xfb1e6a)
[task 2022-03-14T23:22:47.079Z] 23:22:47     INFO - PID 5236 |     #2 IsNSThread /builds/worker/checkouts/gecko/xpcom/threads/nsThreadManager.cpp:559:20 (libxul.so+0xfb1e6a)
[task 2022-03-14T23:22:47.080Z] 23:22:47     INFO - PID 5236 |     #3 NS_SetCurrentThreadName(char const*) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:478:30 (libxul.so+0xfb1e6a)
[task 2022-03-14T23:22:47.080Z] 23:22:47     INFO - PID 5236 |     #4 WatchdogMain(void*) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCJSContext.cpp:476:3 (libxul.so+0x1b408ec)
[task 2022-03-14T23:22:47.084Z] 23:22:47     INFO - PID 5236 |     #5 _pt_root /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:201:5 (libnspr4.so+0x44fad)
[task 2022-03-14T23:22:47.084Z] 23:22:47     INFO - PID 5236 |   Thread T4 'JS Watchdog' (tid=8802, running) created by main thread at:
[task 2022-03-14T23:22:47.084Z] 23:22:47     INFO - PID 5236 |     #0 pthread_create /builds/worker/fetches/llvm-project/compiler-rt/lib/tsan/rtl/tsan_interceptors_posix.cpp:977:3 (firefox+0x5a16d)
[task 2022-03-14T23:22:47.084Z] 23:22:47     INFO - PID 5236 |     #1 _PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:458:14 (libnspr4.so+0x3c1a5)
[task 2022-03-14T23:22:47.084Z] 23:22:47     INFO - PID 5236 |     #2 PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:533:12 (libnspr4.so+0x30cf5)
[task 2022-03-14T23:22:47.085Z] 23:22:47     INFO - PID 5236 |     #3 Watchdog::Init() /builds/worker/checkouts/gecko/js/xpconnect/src/XPCJSContext.cpp:170:17 (libxul.so+0x1b407a8)
[task 2022-03-14T23:22:47.085Z] 23:22:47     INFO - PID 5236 |     #4 StartWatchdog /builds/worker/checkouts/gecko/js/xpconnect/src/XPCJSContext.cpp:412:16 (libxul.so+0x1b40566)
[task 2022-03-14T23:22:47.085Z] 23:22:47     INFO - PID 5236 |     #5 WatchdogManager::RefreshWatchdog() /builds/worker/checkouts/gecko/js/xpconnect/src/XPCJSContext.cpp:385:9 (libxul.so+0x1b40566)
[task 2022-03-14T23:22:47.085Z] 23:22:47     INFO - PID 5236 |     #6 WatchdogManager::RegisterContext(XPCJSContext*) /builds/worker/checkouts/gecko/js/xpconnect/src/XPCJSContext.cpp:304:5 (libxul.so+0x1b28f31)
[task 2022-03-14T23:22:47.085Z] 23:22:47     INFO - PID 5236 |     #7 XPCJSContext::XPCJSContext() /builds/worker/checkouts/gecko/js/xpconnect/src/XPCJSContext.cpp:1111:21 (libxul.so+0x1b28e24)
[task 2022-03-14T23:22:47.085Z] 23:22:47     INFO - PID 5236 |     #8 XPCJSContext::NewXPCJSContext() /builds/worker/checkouts/gecko/js/xpconnect/src/XPCJSContext.cpp:1420:28 (libxul.so+0x1b2a1bf)
[task 2022-03-14T23:22:47.085Z] 23:22:47     INFO - PID 5236 |     #9 InitJSContext /builds/worker/checkouts/gecko/js/xpconnect/src/nsXPConnect.cpp:84:25 (libxul.so+0x1b6b973)
[task 2022-03-14T23:22:47.085Z] 23:22:47     INFO - PID 5236 |     #10 xpc::InitializeJSContext() /builds/worker/checkouts/gecko/js/xpconnect/src/nsXPConnect.cpp:99:35 (libxul.so+0x1b6b973)
[task 2022-03-14T23:22:47.085Z] 23:22:47     INFO - PID 5236 |     #11 NS_InitXPCOM /builds/worker/checkouts/gecko/xpcom/build/XPCOMInit.cpp:506:5 (libxul.so+0xff92c8)
[task 2022-03-14T23:22:47.085Z] 23:22:47     INFO - PID 5236 |     #12 XRE_InitEmbedding2(nsIFile*, nsIFile*, nsIDirectoryServiceProvider*) /builds/worker/checkouts/gecko/toolkit/xre/nsEmbedFunctions.cpp:200:8 (libxul.so+0x72c42a7)
[task 2022-03-14T23:22:47.085Z] 23:22:47     INFO - PID 5236 |     #13 mozilla::ipc::ScopedXREEmbed::Start() /builds/worker/checkouts/gecko/ipc/glue/ScopedXREEmbed.cpp (libxul.so+0x1a25f14)
[task 2022-03-14T23:22:47.086Z] 23:22:47     INFO - PID 5236 |     #14 mozilla::dom::ContentProcess::Init(int, char**) /builds/worker/checkouts/gecko/dom/ipc/ContentProcess.cpp:157:13 (libxul.so+0x4b1802f)
[task 2022-03-14T23:22:47.086Z] 23:22:47     INFO - PID 5236 |     #15 XRE_InitChildProcess(int, char**, XREChildData const*) /builds/worker/checkouts/gecko/toolkit/xre/nsEmbedFunctions.cpp:695:21 (libxul.so+0x72c4a81)
[task 2022-03-14T23:22:47.086Z] 23:22:47     INFO - PID 5236 |     #16 mozilla::BootstrapImpl::XRE_InitChildProcess(int, char**, XREChildData const*) /builds/worker/checkouts/gecko/toolkit/xre/Bootstrap.cpp:67:12 (libxul.so+0x72cc8a2)
[task 2022-03-14T23:22:47.087Z] 23:22:47     INFO - PID 5236 |     #17 content_process_main /builds/worker/checkouts/gecko/browser/app/../../ipc/contentproc/plugin-container.cpp:57:28 (firefox+0xd0297)
[task 2022-03-14T23:22:47.087Z] 23:22:47     INFO - PID 5236 |     #18 main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:327:18 (firefox+0xd0297)
[task 2022-03-14T23:22:47.087Z] 23:22:47     INFO - PID 5236 | SUMMARY: ThreadSanitizer: data race /builds/worker/workspace/obj-build/dist/include/mozilla/cxxalloc.h:51:10 in operator delete
[task 2022-03-14T23:22:47.088Z] 23:22:47     INFO - PID 5236 | ==================
[task 2022-03-14T23:22:47.838Z] 23:22:47     INFO - 
[task 2022-03-14T23:22:47.839Z] 23:22:47     INFO - TEST-UNEXPECTED-NOTRUN | /html/semantics/embedded-content/the-iframe-element/iframe_sandbox_allow_script.html | iframe_sandbox_allow_scripts - expected PASS
[task 2022-03-14T23:22:47.843Z] 23:22:47     INFO - TEST-UNEXPECTED-TIMEOUT | /html/semantics/embedded-content/the-iframe-element/iframe_sandbox_allow_script.html | expected OK
[task 2022-03-14T23:22:47.843Z] 23:22:47     INFO - TEST-INFO took 37260ms
[task 2022-03-14T23:22:47.850Z] 23:22:47     INFO - PID 5236 | 1647300167849	Marionette	INFO	Stopped listening on port 60359
[task 2022-03-14T23:22:49.517Z] 23:22:49     INFO - PID 5236 | ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-14T23:22:49.902Z] 23:22:49     INFO - PID 5236 | ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PTexture::Msg_Destroy) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-14T23:22:49.903Z] 23:22:49     INFO - PID 5236 | ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PTexture::Msg_Destroy) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-14T23:22:49.904Z] 23:22:49     INFO - PID 5236 | ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-14T23:22:54.866Z] 23:22:54     INFO - Browser exited with return code 0
[task 2022-03-14T23:22:54.868Z] 23:22:54     INFO - Closing logging queue
[task 2022-03-14T23:22:54.869Z] 23:22:54     INFO - queue closed
[task 2022-03-14T23:22:54.940Z] 23:22:54     INFO - INFO | runtests.py | TSan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2022-03-14T23:22:54.941Z] 23:22:54     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox --marionette about:blank -profile /tmp/tmpwppt_qvu
[task 2022-03-14T23:22:54.955Z] 23:22:54     INFO - PID 5534 | 1647299248095	Marionette	INFO	Marionette enabled
[task 2022-03-14T23:22:54.956Z] 23:22:54     INFO - PID 5534 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /tmp/tmpv3h2tdbc/search.json.mozlz4", (void 0)))
[task 2022-03-14T23:22:54.956Z] 23:22:54     INFO - PID 5534 | 1647299278752	Marionette	INFO	Listening on port 56462
[task 2022-03-14T23:22:54.957Z] 23:22:54     INFO - PID 5534 | ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-14T23:22:54.957Z] 23:22:54     INFO - PID 5534 | ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-14T23:22:54.958Z] 23:22:54     INFO - PID 5534 | ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-14T23:22:54.958Z] 23:22:54     INFO - PID 5534 | ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-14T23:22:54.959Z] 23:22:54     INFO - PID 5534 | ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-14T23:22:54.960Z] 23:22:54     INFO - PID 5534 | 1647299638172	addons.xpi	ERROR	System addon update list error Error: Failed downloading XML, status: 0, reason: error
[task 2022-03-14T23:22:54.960Z] 23:22:54     INFO - Starting runner
[task 2022-03-14T23:22:58.342Z] 23:22:58     INFO - TEST-START | /html/semantics/embedded-content/the-iframe-element/iframe_sandbox_allow_top_navigation-1.html

Comment 1

[Andrew McCreight [:mccr8]]

It looks like thread manager shutdown is racing with starting up the watchdog thread. Seems pretty unexploitable.

Comment 2

[Jens Stutte [:jstutte]]

The race reported here seems no longer possible. It was probably fixed as a side effect of bug 1713773 (Part 1: "Simplify nsThreadManager shutdown", landed 2022-04-12), which removed the racing code path.

The race was between:

• Main thread (nsThreadManager::Shutdown): collecting all TLS-referenced nsThread wrappers into a local nsTArray<RefPtr<nsThread>> and freeing them when the array went out of scope
• JS Watchdog thread (WatchdogMain→NS_SetCurrentThreadName→IsNSThread): reading its own nsThread wrapper's EventQueue() member via TLS

The watchdog thread creates an nsThread wrapper via NS_GetCurrentThread() early in WatchdogMain. During content process shutdown, the old nsThreadManager::Shutdown() would steal the TLS reference for all threads (via dont_AddRef into a local array + clearing mHasTLSEntry), dropping the last reference and freeing the nsThread — while the watchdog could still be reading from it.

Bug 1713773 removed that entire block. In current code. nsThread TLS references are only released by the NSPR TLS destructor when the owning thread actually exits, which for the watchdog happens when ~XPCJSContext calls StopWatchdog() → PR_JoinThread(). The nsThread wrapper is guaranteed alive for the full lifetime of its thread.

Closing as fixed by bug 1713773.