Open Bug 1615725 Opened 4 years ago Updated 11 months ago

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

Categories

(Toolkit :: Storage, defect, P5)

defect

Tracking

()

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug, Blocks 1 open bug)

Details

(Keywords: intermittent-failure, Whiteboard: [retriggered])

Crash Data

Attachments

(1 file)

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=288982535&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/GGlOSIU2Qr-YACPfrSQeRQ/runs/0/artifacts/public/logs/live_backing.log


[task 2020-02-14T18:48:45.524Z] 18:48:45     INFO -  TEST-PASS | netwerk/test/unit/test_bug248970_cache.js | check_data/< - [check_data/< : 119] "test content" == "test content"
[task 2020-02-14T18:48:45.524Z] 18:48:45     INFO -  (xpcshell/head.js) | test check_entries pending (2)
[task 2020-02-14T18:48:45.524Z] 18:48:45     INFO -  (xpcshell/head.js) | test do_test_finished pending (3)
[task 2020-02-14T18:48:45.524Z] 18:48:45     INFO -  (xpcshell/head.js) | test check_entries finished (3)
[task 2020-02-14T18:48:45.524Z] 18:48:45     INFO -  (xpcshell/head.js) | test finished (2)
[task 2020-02-14T18:48:45.524Z] 18:48:45     INFO -  (xpcshell/head.js) | test do_test_finished finished (1)
[task 2020-02-14T18:48:45.525Z] 18:48:45     INFO -  exiting test
[task 2020-02-14T18:48:45.525Z] 18:48:45     INFO -  PID 18444 | ==================
[task 2020-02-14T18:48:45.525Z] 18:48:45     INFO -  PID 18444 | WARNING: ThreadSanitizer: data race (pid=18444)
[task 2020-02-14T18:48:45.525Z] 18:48:45     INFO -  PID 18444 |   Write of size 8 at 0x7b3800020070 by thread T10:
[task 2020-02-14T18:48:45.525Z] 18:48:45     INFO -  PID 18444 |     #0 free /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/tsan/rtl/tsan_interceptors.cc:706:3 (xpcshell+0x55eb8)
[task 2020-02-14T18:48:45.525Z] 18:48:45     INFO -  PID 18444 |     #1 operator delete /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/cxxalloc.h:51:10 (libxul.so+0x18c9873)
[task 2020-02-14T18:48:45.525Z] 18:48:45     INFO -  PID 18444 |     #2 mozilla::storage::Connection::Release() /builds/worker/workspace/build/src/storage/mozStorageConnection.cpp:557:5 (libxul.so+0x18c9873)
[task 2020-02-14T18:48:45.525Z] 18:48:45     INFO -  PID 18444 |     #3 Release /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RefPtr.h:50:40 (libxul.so+0x18d1a91)
[task 2020-02-14T18:48:45.525Z] 18:48:45     INFO -  PID 18444 |     #4 Release /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RefPtr.h:381:36 (libxul.so+0x18d1a91)
[task 2020-02-14T18:48:45.526Z] 18:48:45     INFO -  PID 18444 |     #5 assign_assuming_AddRef /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RefPtr.h:69:7 (libxul.so+0x18d1a91)
[task 2020-02-14T18:48:45.526Z] 18:48:45     INFO -  PID 18444 |     #6 operator= /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RefPtr.h:168:5 (libxul.so+0x18d1a91)
[task 2020-02-14T18:48:45.526Z] 18:48:45     INFO -  PID 18444 |     #7 Revoke /builds/worker/workspace/build/src/obj-firefox/dist/include/nsThreadUtils.h:785:24 (libxul.so+0x18d1a91)
[task 2020-02-14T18:48:45.526Z] 18:48:45     INFO -  PID 18444 |     #8 Revoke /builds/worker/workspace/build/src/obj-firefox/dist/include/nsThreadUtils.h:1226:15 (libxul.so+0x18d1a91)
[task 2020-02-14T18:48:45.526Z] 18:48:45     INFO -  PID 18444 |     #9 ~RunnableMethodImpl /builds/worker/workspace/build/src/obj-firefox/dist/include/nsThreadUtils.h:1187:35 (libxul.so+0x18d1a91)
[task 2020-02-14T18:48:45.526Z] 18:48:45     INFO -  PID 18444 |     #10 mozilla::detail::RunnableMethodImpl<mozilla::storage::Connection*, nsresult (mozilla::storage::Connection::*)(), true, (mozilla::RunnableKind)0>::~RunnableMethodImpl() /builds/worker/workspace/build/src/obj-firefox/dist/include/nsThreadUtils.h:1187:33 (libxul.so+0x18d1a91)
[task 2020-02-14T18:48:45.526Z] 18:48:45     INFO -  PID 18444 |     #11 mozilla::Runnable::Release() /builds/worker/workspace/build/src/xpcom/threads/nsThreadUtils.cpp:54:1 (libxul.so+0xa62ebb)
[task 2020-02-14T18:48:45.526Z] 18:48:45     INFO -  PID 18444 |     #12 ~nsCOMPtr_base /builds/worker/workspace/build/src/obj-firefox/dist/include/nsCOMPtr.h:330:7 (libxul.so+0xa6e777)
[task 2020-02-14T18:48:45.526Z] 18:48:45     INFO -  PID 18444 |     #13 nsThread::ProcessNextEvent(bool, bool*) /builds/worker/workspace/build/src/xpcom/threads/nsThread.cpp:1234:3 (libxul.so+0xa6e777)
[task 2020-02-14T18:48:45.526Z] 18:48:45     INFO -  PID 18444 |     #14 NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/workspace/build/src/xpcom/threads/nsThreadUtils.cpp:481:10 (libxul.so+0xa73272)
[task 2020-02-14T18:48:45.526Z] 18:48:45     INFO -  PID 18444 |     #15 mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) /builds/worker/workspace/build/src/ipc/glue/MessagePump.cpp:332:5 (libxul.so+0x12af068)
[task 2020-02-14T18:48:45.527Z] 18:48:45     INFO -  PID 18444 |     #16 RunInternal /builds/worker/workspace/build/src/ipc/chromium/src/base/message_loop.cc:315:10 (libxul.so+0x12422cc)
[task 2020-02-14T18:48:45.527Z] 18:48:45     INFO -  PID 18444 |     #17 RunHandler /builds/worker/workspace/build/src/ipc/chromium/src/base/message_loop.cc:308:3 (libxul.so+0x12422cc)
[task 2020-02-14T18:48:45.527Z] 18:48:45     INFO -  PID 18444 |     #18 MessageLoop::Run() /builds/worker/workspace/build/src/ipc/chromium/src/base/message_loop.cc:290:3 (libxul.so+0x12422cc)
[task 2020-02-14T18:48:45.527Z] 18:48:45     INFO -  PID 18444 |     #19 nsThread::ThreadFunc(void*) /builds/worker/workspace/build/src/xpcom/threads/nsThread.cpp:464:10 (libxul.so+0xa6adb5)
[task 2020-02-14T18:48:45.527Z] 18:48:45     INFO -  PID 18444 |     #20 _pt_root /builds/worker/workspace/build/src/nsprpub/pr/src/pthreads/ptthread.c:201:5 (libnspr4.so+0x46a4f)
[task 2020-02-14T18:48:45.527Z] 18:48:45     INFO -  PID 18444 |   Previous atomic write of size 4 at 0x7b3800020074 by main thread (mutexes: write M389133966982084776):
[task 2020-02-14T18:48:45.527Z] 18:48:45     INFO -  PID 18444 |     #0 __tsan_atomic32_compare_exchange_val /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/tsan/rtl/tsan_interface_atomic.cc:844:3 (xpcshell+0xa851a)
[task 2020-02-14T18:48:45.527Z] 18:48:45     INFO -  PID 18444 |     #1 compare_exchange_strong /builds/worker/fetches/clang/bin/../lib/gcc/x86_64-unknown-linux-gnu/7.4.0/../../../../include/c++/7.4.0/bits/atomic_base.h:477:9 (libxul.so+0x18c9898)
[task 2020-02-14T18:48:45.527Z] 18:48:45     INFO -  PID 18444 |     #2 compareExchange /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/Atomics.h:236:17 (libxul.so+0x18c9898)
[task 2020-02-14T18:48:45.527Z] 18:48:45     INFO -  PID 18444 |     #3 compareExchange /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/Atomics.h:359:12 (libxul.so+0x18c9898)
[task 2020-02-14T18:48:45.527Z] 18:48:45     INFO -  PID 18444 |     #4 compareExchange /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/Atomics.h:543:18 (libxul.so+0x18c9898)
[task 2020-02-14T18:48:45.528Z] 18:48:45     INFO -  PID 18444 |     #5 mozilla::storage::Connection::Release() /builds/worker/workspace/build/src/storage/mozStorageConnection.cpp:521:21 (libxul.so+0x18c9898)
[task 2020-02-14T18:48:45.528Z] 18:48:45     INFO -  PID 18444 |     #6 Release /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RefPtr.h:50:40 (libxul.so+0x18e3857)
[task 2020-02-14T18:48:45.528Z] 18:48:45     INFO -  PID 18444 |     #7 Release /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RefPtr.h:381:36 (libxul.so+0x18e3857)
[task 2020-02-14T18:48:45.528Z] 18:48:45     INFO -  PID 18444 |     #8 ~RefPtr /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RefPtr.h:81:7 (libxul.so+0x18e3857)
[task 2020-02-14T18:48:45.528Z] 18:48:45     INFO -  PID 18444 |     #9 mozilla::storage::Service::unregisterConnection(mozilla::storage::Connection*) /builds/worker/workspace/build/src/storage/mozStorageService.cpp:288:1 (libxul.so+0x18e3857)
[task 2020-02-14T18:48:45.528Z] 18:48:45     INFO -  PID 18444 |     #10 mozilla::storage::Connection::Release() /builds/worker/workspace/build/src/storage/mozStorageConnection.cpp:550:24 (libxul.so+0x18c99e5)
[task 2020-02-14T18:48:45.528Z] 18:48:45     INFO -  PID 18444 |     #11 assign_assuming_AddRef /builds/worker/workspace/build/src/obj-firefox/dist/include/nsCOMPtr.h:366:7 (libxul.so+0xe9df24)
[task 2020-02-14T18:48:45.528Z] 18:48:45     INFO -  PID 18444 |     #12 assign_assuming_AddRef /builds/worker/workspace/build/src/obj-firefox/dist/include/nsCOMPtr.h:389:20 (libxul.so+0xe9df24)
[task 2020-02-14T18:48:45.528Z] 18:48:45     INFO -  PID 18444 |     #13 operator= /builds/worker/workspace/build/src/obj-firefox/dist/include/nsCOMPtr.h:685:5 (libxul.so+0xe9df24)
[task 2020-02-14T18:48:45.528Z] 18:48:45     INFO -  PID 18444 |     #14 nsOfflineCacheDevice::Shutdown() /builds/worker/workspace/build/src/netwerk/cache/nsDiskCacheDeviceSQL.cpp:1365:7 (libxul.so+0xe9df24)
[task 2020-02-14T18:48:45.529Z] 18:48:45     INFO -  PID 18444 |     #15 nsCacheService::OnProfileShutdown() /builds/worker/workspace/build/src/netwerk/cache/nsCacheService.cpp:1337:18 (libxul.so+0xe9bdf6)
[task 2020-02-14T18:48:45.530Z] 18:48:45     INFO -  PID 18444 |     #16 nsCacheProfilePrefObserver::Observe(nsISupports*, char const*, char16_t const*) /builds/worker/workspace/build/src/netwerk/cache/nsCacheService.cpp:191:5 (libxul.so+0xe9b247)
[task 2020-02-14T18:48:45.530Z] 18:48:45     INFO -  PID 18444 |     #17 nsObserverList::NotifyObservers(nsISupports*, char const*, char16_t const*) /builds/worker/workspace/build/src/xpcom/ds/nsObserverList.cpp:65:19 (libxul.so+0x9d9153)
[task 2020-02-14T18:48:45.531Z] 18:48:45     INFO -  PID 18444 |     #18 nsObserverService::NotifyObservers(nsISupports*, char const*, char16_t const*) /builds/worker/workspace/build/src/xpcom/ds/nsObserverService.cpp:292:19 (libxul.so+0x9dc000)
[task 2020-02-14T18:48:45.532Z] 18:48:45     INFO -  PID 18444 |     #19 NS_InvokeByIndex /builds/worker/workspace/build/src/xpcom/reflect/xptcall/md/unix/xptcinvoke_asm_x86_64_unix.S:106 (libxul.so+0xa8ef65)
[task 2020-02-14T18:48:45.532Z] 18:48:45     INFO -  PID 18444 |     #20 XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) /builds/worker/workspace/build/src/js/xpconnect/src/XPCWrappedNativeJSOps.cpp:947:10 (libxul.so+0x188cc91)
[task 2020-02-14T18:48:45.532Z] 18:48:45     INFO -  PID 18444 |     #21 CallJSNative /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:477:13 (libxul.so+0x6457508)
[task 2020-02-14T18:48:45.533Z] 18:48:45     INFO -  PID 18444 |     #22 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:569:12 (libxul.so+0x6457508)
[task 2020-02-14T18:48:45.534Z] 18:48:45     INFO -  PID 18444 |     #23 InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:632:10 (libxul.so+0x645851b)
[task 2020-02-14T18:48:45.535Z] 18:48:45     INFO -  PID 18444 |     #24 js::CallFromStack(JSContext*, JS::CallArgs const&) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:636:10 (libxul.so+0x64583f0)
[task 2020-02-14T18:48:45.536Z] 18:48:45     INFO -  PID 18444 |     #25 js::jit::DoCallFallback(JSContext*, js::jit::BaselineFrame*, js::jit::ICCall_Fallback*, unsigned int, JS::Value*, JS::MutableHandle<JS::Value>) /builds/worker/workspace/build/src/js/src/jit/BaselineIC.cpp:2910:10 (libxul.so+0x6ca149e)
[task 2020-02-14T18:48:45.538Z] 18:48:45     INFO -  PID 18444 |     #26 <null> <null> (0x7fce2bbbde88)
[task 2020-02-14T18:48:45.538Z] 18:48:45     INFO -  PID 18444 |     #27 Interpret(JSContext*, js::RunState&) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:1935:17 (libxul.so+0x643bb81)
[task 2020-02-14T18:48:45.539Z] 18:48:45     INFO -  PID 18444 |     #28 js::RunScript(JSContext*, js::RunState&) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:449:10 (libxul.so+0x643a61b)
[task 2020-02-14T18:48:45.540Z] 18:48:45     INFO -  PID 18444 |     #29 js::ExecuteKernel(JSContext*, JS::Handle<JSScript*>, JSObject&, JS::Value const&, js::AbstractFramePtr, JS::Value*) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:825:13 (libxul.so+0x6459c67)
[task 2020-02-14T18:48:45.540Z] 18:48:45     INFO -  PID 18444 |     #30 js::Execute(JSContext*, JS::Handle<JSScript*>, JSObject&, JS::Value*) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:858:10 (libxul.so+0x6459fbd)
[task 2020-02-14T18:48:45.541Z] 18:48:45     INFO -  PID 18444 |     #31 EvaluateSourceBuffer<mozilla::Utf8Unit> /builds/worker/workspace/build/src/js/src/vm/CompilationAndEvaluation.cpp:568:10 (libxul.so+0x65c17e0)
[task 2020-02-14T18:48:45.542Z] 18:48:45     INFO -  PID 18444 |     #32 JS::EvaluateDontInflate(JSContext*, JS::ReadOnlyCompileOptions const&, JS::SourceText<mozilla::Utf8Unit>&, JS::MutableHandle<JS::Value>) /builds/worker/workspace/build/src/js/src/vm/CompilationAndEvaluation.cpp:600:10 (libxul.so+0x65c17e0)
[task 2020-02-14T18:48:45.542Z] 18:48:45     INFO -  PID 18444 |     #33 ProcessArgs /builds/worker/workspace/build/src/js/xpconnect/src/XPCShellImpl.cpp:1001:11 (libxul.so+0x1879307)
[task 2020-02-14T18:48:45.543Z] 18:48:45     INFO -  PID 18444 |     #34 XRE_XPCShellMain(int, char**, char**, XREShellData const*) /builds/worker/workspace/build/src/js/xpconnect/src/XPCShellImpl.cpp:1401:14 (libxul.so+0x1879307)
[task 2020-02-14T18:48:45.548Z] 18:48:45     INFO -  PID 18444 |     #35 mozilla::BootstrapImpl::XRE_XPCShellMain(int, char**, char**, XREShellData const*) /builds/worker/workspace/build/src/toolkit/xre/Bootstrap.cpp:54:12 (libxul.so+0x63302bb)
[task 2020-02-14T18:48:45.549Z] 18:48:45     INFO -  PID 18444 |     #36 main /builds/worker/workspace/build/src/js/xpconnect/shell/xpcshell.cpp:66:27 (xpcshell+0xc82d6)
[task 2020-02-14T18:48:45.549Z] 18:48:45     INFO -  PID 18444 |   Mutex M389133966982084776 is already destroyed.
[task 2020-02-14T18:48:45.549Z] 18:48:45     INFO -  PID 18444 |   Thread T10 'Cache I/O' (tid=18455, running) created by main thread at:
[task 2020-02-14T18:48:45.550Z] 18:48:45     INFO -  PID 18444 |     #0 pthread_create /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/tsan/rtl/tsan_interceptors.cc:967:3 (xpcshell+0x5714b)
[task 2020-02-14T18:48:45.550Z] 18:48:45     INFO -  PID 18444 |     #1 _PR_CreateThread /builds/worker/workspace/build/src/nsprpub/pr/src/pthreads/ptthread.c:458:14 (libnspr4.so+0x3dc53)
[task 2020-02-14T18:48:45.551Z] 18:48:45     INFO -  PID 18444 |     #2 PR_CreateThread /builds/worker/workspace/build/src/nsprpub/pr/src/pthreads/ptthread.c:533:12 (libnspr4.so+0x32152)
[task 2020-02-14T18:48:45.551Z] 18:48:45     INFO -  PID 18444 |     #3 nsThread::Init(nsTSubstring<char> const&) /builds/worker/workspace/build/src/xpcom/threads/nsThread.cpp:670:8 (libxul.so+0xa6c24a)
[task 2020-02-14T18:48:45.552Z] 18:48:45     INFO -  PID 18444 |     #4 nsThreadManager::NewNamedThread(nsTSubstring<char> const&, unsigned int, nsIThread**) /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp:621:12 (libxul.so+0xa72975)
[task 2020-02-14T18:48:45.552Z] 18:48:45     INFO -  PID 18444 |     #5 NS_NewNamedThread(nsTSubstring<char> const&, nsIThread**, nsIRunnable*, unsigned int) /builds/worker/workspace/build/src/xpcom/threads/nsThreadUtils.cpp:139:57 (libxul.so+0xa74a68)
[task 2020-02-14T18:48:45.552Z] 18:48:45     INFO -  PID 18444 |     #6 NS_NewNamedThread<10> /builds/worker/workspace/build/src/obj-firefox/dist/include/nsThreadUtils.h:65:10 (libxul.so+0xe9b4ec)
[task 2020-02-14T18:48:45.553Z] 18:48:45     INFO -  PID 18444 |     #7 nsCacheService::Init() /builds/worker/workspace/build/src/netwerk/cache/nsCacheService.cpp:488:8 (libxul.so+0xe9b4ec)
[task 2020-02-14T18:48:45.553Z] 18:48:45     INFO -  PID 18444 |     #8 nsCacheService::Create(nsISupports*, nsID const&, void**) /builds/worker/workspace/build/src/netwerk/cache/nsCacheService.cpp:599:22 (libxul.so+0xe9f642)
[task 2020-02-14T18:48:45.554Z] 18:48:45     INFO -  PID 18444 |     #9 nsCacheServiceConstructor(nsISupports*, nsID const&, void**) /builds/worker/workspace/build/src/netwerk/build/nsNetModule.cpp:79:10 (libxul.so+0x1231f45)
[task 2020-02-14T18:48:45.554Z] 18:48:45     INFO -  PID 18444 |     #10 mozilla::xpcom::CreateInstanceImpl(mozilla::xpcom::ModuleID, nsISupports*, nsID const&, void**) /builds/worker/workspace/build/src/obj-firefox/xpcom/components/StaticComponents.cpp:8281:27 (libxul.so+0xa3a80a)
[task 2020-02-14T18:48:45.554Z] 18:48:45     INFO -  PID 18444 |     #11 mozilla::xpcom::StaticModule::CreateInstance(nsISupports*, nsID const&, void**) const /builds/worker/workspace/build/src/obj-firefox/xpcom/components/StaticComponents.cpp:11204:10 (libxul.so+0xa31120)
[task 2020-02-14T18:48:45.555Z] 18:48:45     INFO -  PID 18444 |     #12 CreateInstance /builds/worker/workspace/build/src/xpcom/components/nsComponentManager.cpp:219:46 (libxul.so+0xa4840d)
[task 2020-02-14T18:48:45.555Z] 18:48:45     INFO -  PID 18444 |     #13 nsComponentManagerImpl::GetServiceLocked((anonymous namespace)::MutexLock&, (anonymous namespace)::EntryWrapper&, nsID const&, void**) /builds/worker/workspace/build/src/xpcom/components/nsComponentManager.cpp:1372:17 (libxul.so+0xa4840d)
[task 2020-02-14T18:48:45.556Z] 18:48:45     INFO -  PID 18444 |     #14 nsComponentManagerImpl::GetService(nsID const&, nsID const&, void**) /builds/worker/workspace/build/src/xpcom/components/nsComponentManager.cpp:1424:10 (libxul.so+0xa4323c)
[task 2020-02-14T18:48:45.556Z] 18:48:45     INFO -  PID 18444 |     #15 CallGetService /builds/worker/workspace/build/src/xpcom/components/nsComponentManagerUtils.cpp:51:43 (libxul.so+0xa4b82b)
[task 2020-02-14T18:48:45.557Z] 18:48:45     INFO -  PID 18444 |     #16 nsGetServiceByCID::operator()(nsID const&, void**) const /builds/worker/workspace/build/src/xpcom/components/nsComponentManagerUtils.cpp:220:21 (libxul.so+0xa4b82b)
[task 2020-02-14T18:48:45.557Z] 18:48:45     INFO -  PID 18444 |     #17 nsCOMPtr_base::assign_from_gs_cid(nsGetServiceByCID, nsID const&) /builds/worker/workspace/build/src/xpcom/base/nsCOMPtr.cpp:64:7 (libxul.so+0x9925a0)
[task 2020-02-14T18:48:45.557Z] 18:48:45     INFO -  PID 18444 |     #18 nsCOMPtr /builds/worker/workspace/build/src/obj-firefox/dist/include/nsCOMPtr.h:600:5 (libxul.so+0xe91704)
[task 2020-02-14T18:48:45.557Z] 18:48:45     INFO -  PID 18444 |     #19 nsApplicationCacheService::nsApplicationCacheService() /builds/worker/workspace/build/src/netwerk/cache/nsApplicationCacheService.cpp:26:36 (libxul.so+0xe91704)
[task 2020-02-14T18:48:45.558Z] 18:48:45     INFO -  PID 18444 |     #20 mozilla::xpcom::CreateInstanceImpl(mozilla::xpcom::ModuleID, nsISupports*, nsID const&, void**) /builds/worker/workspace/build/src/obj-firefox/xpcom/components/StaticComponents.cpp:8743:52 (libxul.so+0xa3af8b)
[task 2020-02-14T18:48:45.558Z] 18:48:45     INFO -  PID 18444 |     #21 mozilla::xpcom::StaticModule::CreateInstance(nsISupports*, nsID const&, void**) const /builds/worker/workspace/build/src/obj-firefox/xpcom/components/StaticComponents.cpp:11204:10 (libxul.so+0xa31120)
[task 2020-02-14T18:48:45.558Z] 18:48:45     INFO -  PID 18444 |     #22 CreateInstance /builds/worker/workspace/build/src/xpcom/components/nsComponentManager.cpp:219:46 (libxul.so+0xa4840d)
[task 2020-02-14T18:48:45.559Z] 18:48:45     INFO -  PID 18444 |     #23 nsComponentManagerImpl::GetServiceLocked((anonymous namespace)::MutexLock&, (anonymous namespace)::EntryWrapper&, nsID const&, void**) /builds/worker/workspace/build/src/xpcom/components/nsComponentManager.cpp:1372:17 (libxul.so+0xa4840d)
[task 2020-02-14T18:48:45.559Z] 18:48:45     INFO -  PID 18444 |     #24 nsComponentManagerImpl::GetServiceByContractID(char const*, nsID const&, void**) /builds/worker/workspace/build/src/xpcom/components/nsComponentManager.cpp:1559:10 (libxul.so+0xa43475)
[task 2020-02-14T18:48:45.559Z] 18:48:45     INFO -  PID 18444 |     #25 CallGetService(char const*, nsID const&, void**) /builds/worker/workspace/build/src/xpcom/components/nsComponentManagerUtils.cpp:61:43 (libxul.so+0xa4b4dd)
[task 2020-02-14T18:48:45.560Z] 18:48:45     INFO -  PID 18444 |     #26 xpc::CIGSHelper(JSContext*, unsigned int, JS::Value*, bool) /builds/worker/workspace/build/src/js/xpconnect/src/XPCJSID.cpp:512:10 (libxul.so+0x1870a8b)
[task 2020-02-14T18:48:45.560Z] 18:48:45     INFO -  PID 18444 |     #27 xpc::CID_GetService(JSContext*, unsigned int, JS::Value*) /builds/worker/workspace/build/src/js/xpconnect/src/XPCJSID.cpp:537:10 (libxul.so+0x1870717)
[task 2020-02-14T18:48:45.560Z] 18:48:45     INFO -  PID 18444 |     #28 CallJSNative /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:477:13 (libxul.so+0x6457508)
[task 2020-02-14T18:48:45.560Z] 18:48:45     INFO -  PID 18444 |     #29 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:569:12 (libxul.so+0x6457508)
[task 2020-02-14T18:48:45.561Z] 18:48:45     INFO -  PID 18444 |     #30 InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:632:10 (libxul.so+0x645851b)
[task 2020-02-14T18:48:45.561Z] 18:48:45     INFO -  PID 18444 |     #31 CallFromStack /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:636:10 (libxul.so+0x644a3c8)
[task 2020-02-14T18:48:45.561Z] 18:48:45     INFO -  PID 18444 |     #32 Interpret(JSContext*, js::RunState&) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:3049:16 (libxul.so+0x644a3c8)
[task 2020-02-14T18:48:45.562Z] 18:48:45     INFO -  PID 18444 |     #33 js::RunScript(JSContext*, js::RunState&) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:449:10 (libxul.so+0x643a61b)
[task 2020-02-14T18:48:45.562Z] 18:48:45     INFO -  PID 18444 |     #34 js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:604:13 (libxul.so+0x645796e)
[task 2020-02-14T18:48:45.562Z] 18:48:45     INFO -  PID 18444 |     #35 InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:632:10 (libxul.so+0x645851b)
[task 2020-02-14T18:48:45.563Z] 18:48:45     INFO -  PID 18444 |     #36 js::CallFromStack(JSContext*, JS::CallArgs const&) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:636:10 (libxul.so+0x64583f0)
[task 2020-02-14T18:48:45.564Z] 18:48:45     INFO -  PID 18444 |     #37 js::jit::DoCallFallback(JSContext*, js::jit::BaselineFrame*, js::jit::ICCall_Fallback*, unsigned int, JS::Value*, JS::MutableHandle<JS::Value>) /builds/worker/workspace/build/src/js/src/jit/BaselineIC.cpp:2910:10 (libxul.so+0x6ca149e)
[task 2020-02-14T18:48:45.565Z] 18:48:45     INFO -  PID 18444 |     #38 <null> <null> (0x7fce2bbbde88)
[task 2020-02-14T18:48:45.566Z] 18:48:45     INFO -  PID 18444 |     #39 Interpret(JSContext*, js::RunState&) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:1935:17 (libxul.so+0x643bb81)
[task 2020-02-14T18:48:45.567Z] 18:48:45     INFO -  PID 18444 |     #40 js::RunScript(JSContext*, js::RunState&) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:449:10 (libxul.so+0x643a61b)
[task 2020-02-14T18:48:45.568Z] 18:48:45     INFO -  PID 18444 |     #41 js::ExecuteKernel(JSContext*, JS::Handle<JSScript*>, JSObject&, JS::Value const&, js::AbstractFramePtr, JS::Value*) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:825:13 (libxul.so+0x6459c67)
[task 2020-02-14T18:48:45.568Z] 18:48:45     INFO -  PID 18444 |     #42 js::Execute(JSContext*, JS::Handle<JSScript*>, JSObject&, JS::Value*) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:858:10 (libxul.so+0x6459fbd)
[task 2020-02-14T18:48:45.569Z] 18:48:45     INFO -  PID 18444 |     #43 EvaluateSourceBuffer<mozilla::Utf8Unit> /builds/worker/workspace/build/src/js/src/vm/CompilationAndEvaluation.cpp:568:10 (libxul.so+0x65c17e0)
[task 2020-02-14T18:48:45.570Z] 18:48:45     INFO -  PID 18444 |     #44 JS::EvaluateDontInflate(JSContext*, JS::ReadOnlyCompileOptions const&, JS::SourceText<mozilla::Utf8Unit>&, JS::MutableHandle<JS::Value>) /builds/worker/workspace/build/src/js/src/vm/CompilationAndEvaluation.cpp:600:10 (libxul.so+0x65c17e0)
[task 2020-02-14T18:48:45.571Z] 18:48:45     INFO -  PID 18444 |     #45 ProcessArgs /builds/worker/workspace/build/src/js/xpconnect/src/XPCShellImpl.cpp:1001:11 (libxul.so+0x1879307)
[task 2020-02-14T18:48:45.572Z] 18:48:45     INFO -  PID 18444 |     #46 XRE_XPCShellMain(int, char**, char**, XREShellData const*) /builds/worker/workspace/build/src/js/xpconnect/src/XPCShellImpl.cpp:1401:14 (libxul.so+0x1879307)
[task 2020-02-14T18:48:45.574Z] 18:48:45     INFO -  PID 18444 |     #47 mozilla::BootstrapImpl::XRE_XPCShellMain(int, char**, char**, XREShellData const*) /builds/worker/workspace/build/src/toolkit/xre/Bootstrap.cpp:54:12 (libxul.so+0x63302bb)
[task 2020-02-14T18:48:45.575Z] 18:48:45     INFO -  PID 18444 |     #48 main /builds/worker/workspace/build/src/js/xpconnect/shell/xpcshell.cpp:66:27 (xpcshell+0xc82d6)
[task 2020-02-14T18:48:45.576Z] 18:48:45     INFO -  PID 18444 | SUMMARY: ThreadSanitizer: data race /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/cxxalloc.h:51:10 in operator delete
[task 2020-02-14T18:48:45.577Z] 18:48:45     INFO -  PID 18444 | ==================
[task 2020-02-14T18:48:45.578Z] 18:48:45     INFO -  <<<<<<<
[task 2020-02-14T18:48:45.578Z] 18:48:45     INFO -  TEST-START | netwerk/test/unit/test_fallback_no-cache-entry_canceled.js
Component: Memory Allocator → Storage
Product: Core → Toolkit
Blocks: tsan

It looks like the main thread is inside the if (1 == count) { branch while thread T10 is already deleting this. This could lead to a use-after-free crash on shutdown. And indeed we have two such crashes in crash-stats, with an uaf pattern.

Crash Signature: [@ mozilla::storage::Connection::Release]
This is an automated crash issue comment:

Summary: ThreadSanitizer: data race [@ __tsan_atomic32_compare_exchange_val] vs. [@ free]
Build version: autoland revision 27fc34dc2e4d0c0a9d8fbc3cb7526198af650103

For detailed crash information, see attachment.

Marco, can you find an owner for this? I think this can cause shutdown crashes and it should be easy to diagnose from the TSan report.

Flags: needinfo?(mak)

Andrew, you cleaned up most of this code originally, would you have time to have a look at it? Off-hand comment 1 sounds correct, we should probably not reduce mRefCnt until we are done (but then we risk multiple threads executing the == 1 code), or use a classical kungFuDeathGrip trick when we enter the == 1 code, or a mutex. Wdyt?
I'm still a bit puzzled that we have to do this manual refcounting. It was added in bug 702815, but there must be a better way than this black magic.

Flags: needinfo?(mak) → needinfo?(bugmail)

Short Proposal

Let's get rid of the connection list and their consumers that is the source of all of these nightmares.

Long Proposal

We currently use the connection list in:

  1. Service::CollectReports to generate reports for about:memory. The list does accumulate per-connection usages in totalConnSize and subtracts them off of sqlite3_memory_used to derive an "other" variable for data that can't be attributed to specific connections.
  2. In Service::minimizeMemory to induce PRAGMA shrink_memory to be invoked.
  3. In Service::Observe for "xpcom-shutdown-threads to wait for the connections to shutdown at a stage of shutdown where there should no longer be any connections in existence.

The nightmares get extra complicated because these methods can end up transferring the ownership of the connection from whatever thread actually owned it to the main thread. And the connections all have failsafe connection closing when they get destroyed.

We have ThreadSafeWeakPtr since Bug 1404742 in late 2017, which could potentially reduce some of the refcounting insanity, but still has the fundamental problem of ownership being transferred across threads unless every operation forces the other threads to block until the main thread is done doing whatever it was doing.

I would propose that we address the above 3 use-cases like this:

  1. Make the subsystems that use mozStorage connections responsible for reporting their own memory on the thread on which they own it. The connections can provide helpers. This would potentially require extra engineering for the "other" bin that has a data dependency on the per-connection data. This seems like a fixup the memory reporting subsystem might help out with by letting reports indicate that they're providing attribution that describes specific usages inside an over-arching allocation block.
  2. Make subsystems responsible for shrinking their own memory usage. This was always an ugly hack.
  3. Make subsystems responsible for cleaning up their own storage connections. Now that we have nsIAsyncShutdown and no legacy extensions, every subsystem that uses storage should absolutely be using a shutdown blocker. As discussed elsewhere, I think storage connections should actually be taking these blockers and verifying that the connection isn't trying to be opened after the start of its phase. (This will require minor nsIAsyncShutdown enhancements that we really want anyways.)

I can do the ripping out stuff in the short term, but not anything to help replace what was ripped out beyond just making all SQLite memory reported to about:memory as other.

Is this a reasonable plan? Should I take the bug and plan to file a follow-up to put things back together?

Flags: needinfo?(bugmail)

Let's discuss!

(In reply to Andrew Sutherland [:asuth] (he/him) from comment #15)

  1. Make the subsystems that use mozStorage connections responsible for reporting their own memory on the thread on which they own it. The connections can provide helpers.

Consumers should already be reporting their caches/memory usage unrelated to Sqlite, and Sqlite its own use. I'm not sure what additionally they should be measuring related to Sqlite.
To put it in a different perspective, what is inside "sqlite/other" today? heap clownshoes? It sounds like it may also account for leaked connection data, that Sqlite itself is not tracking anymore, at least according to https://bugzilla.mozilla.org/show_bug.cgi?id=703143#c1 ...
I'm not sure how we could delegate that to consumers?

  1. Make subsystems responsible for shrinking their own memory usage. This was always an ugly hack.

Yes, though it would end up being the same boilerplate repeated over and over, every consumer should listen for the memory pressure notification, and we risk they won't. At that point it would be safer to make each connection listen and do its own cleanup. The problem is that we can't use the observer service, we'd need a thread-safe messaging system.

  1. Make subsystems responsible for cleaning up their own storage connections. Now that we have nsIAsyncShutdown and no legacy extensions, every subsystem that uses storage should absolutely be using a shutdown blocker. As discussed elsewhere, I think storage connections should actually be taking these blockers and verifying that the connection isn't trying to be opened after the start of its phase. (This will require minor nsIAsyncShutdown enhancements that we really want anyways.)

That sounds good to me, though the current system is pretty much ensuring consumers behave properly (as you said, we check that there are no leftover connections at shutdown threads)... we'd still want some debug-only system to check that, I guess?

I got other fancy thoughts.

If we don't want to lose memory info, we could make each connection report its memory usage once an hour (low priority, maybe background task) to the Service, also report value when the connection is ready and 0 when it's closed. When the memory collection happens, the service just uses cached data, it will be an approximation.

Maybe stop obeying memory-pressure completely. Our Sqlite connections use a small fixed amount of memory that we control, and it manages its memory pool: "If a memory allocation ever fails (that is to say, if malloc() or realloc() ever return NULL) then SQLite will recover gracefully. SQLite will first attempt to free memory from unpinned cache pages then retry the allocation request. ". On my profile that boils down to 50MB or such, it may not make a difference even if a part of it gets freed. If a consumer (like Places) has connections with a larger cache we could indeed just provide an API to free up memory. Sqlite.jsm being on the main thread could also do that internally, so for example the urlbar connection (that uses a larger cache) would get it automatically.

For leaked connection, could we store a connection id when a connection is created, and notify the service when a connection goes away? Then instead of keeping references to the connections, we just MOZ_DIAGNOSTIC_ASSERT if an id was not closed.

Summary: Intermittent PID 18444 | SUMMARY: ThreadSanitizer: data race /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/cxxalloc.h:51:10 in operator delete → Intermittent SUMMARY: ThreadSanitizer: data race /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/cxxalloc.h:51:10 in operator delete
Whiteboard: [retriggered]
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: