Closed Bug 1790025 Opened 4 years ago Closed 2 years ago

Intermittent Hit MOZ_CRASH(FetchStreamReader not thread-safe) at /builds/worker/checkouts/gecko/xpcom/base/nsISupportsImpl.cpp:43

Categories

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

Product:
Core
Component:
DOM: Streams
Type:
defect

Tracking

()

Status:
RESOLVED WORKSFORME

People

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

References

Details

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

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

[task 2022-09-09T11:33:32.176Z] 11:33:32     INFO - TEST-START | dom/tests/mochitest/fetch/test_readableStreams.html
[task 2022-09-09T11:33:34.329Z] 11:33:34     INFO - GECKO(5404) | Hit MOZ_CRASH(FetchStreamReader not thread-safe) at /builds/worker/checkouts/gecko/xpcom/base/nsISupportsImpl.cpp:43
[task 2022-09-09T11:33:34.332Z] 11:33:34     INFO - GECKO(5404) | #01: nsAutoOwningThread::AssertCurrentThreadOwnsMe(char const*) const [xpcom/base/nsISupportsImpl.cpp:43]
[task 2022-09-09T11:33:34.335Z] 11:33:34     INFO - GECKO(5404) | #02: mozilla::dom::FetchStreamReader::Release() [dom/fetch/FetchStreamReader.cpp:33]
[task 2022-09-09T11:33:34.338Z] 11:33:34     INFO - GECKO(5404) | #03: mozilla::detail::MaybeStorage<CallbackHolder::CallbackHolder(nsIAsyncOutputStream*, nsIOutputStreamCallback*, unsigned int, nsIEventTarget*)::{lambda()#1}, false>::~MaybeStorage() [mfbt/Maybe.h:269]
[task 2022-09-09T11:33:34.341Z] 11:33:34     INFO - GECKO(5404) | #04: NS_NewCancelableRunnableFunction<CallbackHolder::CallbackHolder(nsIAsyncOutputStream*, nsIOutputStreamCallback*, unsigned int, nsIEventTarget*)::{lambda()#1}>(char const*, CallbackHolder::CallbackHolder(nsIAsyncOutputStream*, nsIOutputStreamCallback*, unsigned int, nsIEventTarget*)::{lambda()#1}&&)::FuncCancelableRunnable::~FuncCancelableRunnable() [xpcom/threads/nsThreadUtils.h:662]
[task 2022-09-09T11:33:34.342Z] 11:33:34     INFO - GECKO(5404) | #05: mozilla::Runnable::Release() [xpcom/threads/nsThreadUtils.cpp:61]
[task 2022-09-09T11:33:34.345Z] 11:33:34     INFO - GECKO(5404) | #06: mozilla::dom::(anonymous namespace)::ExternalRunnableWrapper::~ExternalRunnableWrapper() [dom/workers/WorkerPrivate.cpp:188]
[task 2022-09-09T11:33:34.347Z] 11:33:34     INFO - GECKO(5404) | #07: mozilla::dom::WorkerRunnable::Release() [dom/workers/WorkerRunnable.cpp:209]
[task 2022-09-09T11:33:34.349Z] 11:33:34     INFO - GECKO(5404) | #08: mozilla::dom::(anonymous namespace)::ExternalRunnableWrapper::Release() [dom/workers/WorkerPrivate.cpp:185]
[task 2022-09-09T11:33:34.350Z] 11:33:34     INFO - GECKO(5404) | #09: mozilla::dom::WorkerEventTarget::Dispatch(already_AddRefed<nsIRunnable>, unsigned int) [mfbt/RefPtr.h:0]
[task 2022-09-09T11:33:34.352Z] 11:33:34     INFO - GECKO(5404) | #10: CallbackHolder::Notify() [xpcom/io/nsPipe3.cpp:117]
[task 2022-09-09T11:33:34.353Z] 11:33:34     INFO - GECKO(5404) | #11: nsPipeEvents::~nsPipeEvents() [xpcom/io/nsPipe3.cpp:1155]
[task 2022-09-09T11:33:34.354Z] 11:33:34     INFO - GECKO(5404) | #12: nsPipe::AdvanceReadCursor(nsPipeReadState&, unsigned int) [xpcom/io/nsPipe3.cpp:0]
[task 2022-09-09T11:33:34.355Z] 11:33:34     INFO - GECKO(5404) | #13: AutoReadSegment::~AutoReadSegment() [xpcom/io/nsPipe3.cpp:0]
[task 2022-09-09T11:33:34.357Z] 11:33:34     INFO - GECKO(5404) | #14: nsPipeInputStream::ReadSegments(nsresult (*)(nsIInputStream*, void*, char const*, unsigned int, unsigned int, unsigned int*), void*, unsigned int, unsigned int*) [xpcom/io/nsPipe3.cpp:1328]
[task 2022-09-09T11:33:34.359Z] 11:33:34     INFO - GECKO(5404) | #15: mozilla::dom::MutableBlobStreamListener::OnDataAvailable(nsIRequest*, nsIInputStream*, unsigned long, unsigned int) [dom/file/MutableBlobStreamListener.cpp:0]
[task 2022-09-09T11:33:34.361Z] 11:33:34     INFO - GECKO(5404) | #16: nsInputStreamPump::OnStateTransfer() [netwerk/base/nsInputStreamPump.cpp:562]
[task 2022-09-09T11:33:34.363Z] 11:33:34     INFO - GECKO(5404) | #17: nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream*) [netwerk/base/nsInputStreamPump.cpp:404]
[task 2022-09-09T11:33:34.364Z] 11:33:34     INFO - GECKO(5404) | #18: {virtual override thunk({offset(-24)}, nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream*))} [netwerk/base/nsInputStreamPump.cpp:0]
[task 2022-09-09T11:33:34.366Z] 11:33:34     INFO - GECKO(5404) | #19: NS_NewCancelableRunnableFunction<CallbackHolder::CallbackHolder(nsIAsyncInputStream*, nsIInputStreamCallback*, unsigned int, nsIEventTarget*)::{lambda()#1}>(char const*, CallbackHolder::CallbackHolder(nsIAsyncInputStream*, nsIInputStreamCallback*, unsigned int, nsIEventTarget*)::{lambda()#1}&&)::FuncCancelableRunnable::Run() [xpcom/threads/nsThreadUtils.h:653]
[task 2022-09-09T11:33:34.368Z] 11:33:34     INFO - GECKO(5404) | #20: nsThreadPool::Run() [xpcom/threads/nsThreadPool.cpp:312]
[task 2022-09-09T11:33:34.371Z] 11:33:34     INFO - GECKO(5404) | #21: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1200]
[task 2022-09-09T11:33:34.373Z] 11:33:34     INFO - GECKO(5404) | #22: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/threads/nsThreadUtils.cpp:465]
[task 2022-09-09T11:33:34.374Z] 11:33:34     INFO - GECKO(5404) | #23: mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:301]
[task 2022-09-09T11:33:34.376Z] 11:33:34     INFO - GECKO(5404) | #24: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:0]
[task 2022-09-09T11:33:34.378Z] 11:33:34     INFO - GECKO(5404) | #25: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:357]
[task 2022-09-09T11:33:34.379Z] 11:33:34     INFO - GECKO(5404) | #26: nsThread::ThreadFunc(void*) [xpcom/threads/nsThread.cpp:386]
[task 2022-09-09T11:33:34.396Z] 11:33:34     INFO - GECKO(5404) | #27: _pt_root [nsprpub/pr/src/pthreads/ptthread.c:204]
[task 2022-09-09T11:33:34.498Z] 11:33:34     INFO - GECKO(5404) | #28: set_alt_signal_stack_and_start(PthreadCreateParams*) [toolkit/crashreporter/pthread_create_interposer/pthread_create_interposer.cpp:80]
[task 2022-09-09T11:33:34.501Z] 11:33:34     INFO - GECKO(5404) | #29: ??? [/lib/x86_64-linux-gnu/libpthread.so.0 + 0x76db]
[task 2022-09-09T11:33:34.505Z] 11:33:34     INFO - GECKO(5404) | #30: clone [/lib/x86_64-linux-gnu/libc.so.6 + 0x121a3f]
[task 2022-09-09T11:33:34.507Z] 11:33:34     INFO - GECKO(5404) | #31: ??? (???:???)
Group: dom-core-security
Component: XPCOM → DOM: Streams

Not sure how controllable it is.

Maybe the dispatch of a runnable is failing? Any ideas, Matthew?

Flags: needinfo?(mgaudet)
Keywords: csectype-race, sec-moderate

My extra StrongWorkerRef coverage in bug 1770630 for FetchStreamReader would seem to have been insufficient. It looks like this is the STS still having some lingering stream machinery trying to finish cleanup on the worker but the worker is gone. Based on the buffered log messages (which are provided after the crash), the failing test is the worker-ified test_nonNativeStream and its follow-on "_continue" variant that does the actual reading that's found in the source right after that.

Assignee: nobody → bugmail
Status: NEW → ASSIGNED
Depends on: 1770630

(I'll leave this with Andrew who did the heavy lifting for Bug 1770630 )

Flags: needinfo?(mgaudet)

FetchStreamReader thread safety issues are still showing up on TreeHerder. I came across this one.

See Also: → 1728042

Those 5 failures are from bug 1728042 which seems to have turned into the place where all MOZ_Crash()es in TSan end up.

The most recent log from orange factor is https://treeherder.mozilla.org/logviewer?job_id=414339676&repo=autoland&lineNumber=34167 and the stack identifies a situation that will be resolved by the patches on bug 1800659 landing. Specifically, the stack identifies a case where:

  • FetchStreamReader is trying to dispatch a runnable to a worker from the StreamTransportService thread pool.
  • The dispatch is failing and this results in the FetchStreamReader being freed on the STS thread, which it does not like because it is not threadsafe, this generates the assertion.
  • Because the dispatch method passes the !mWorkerPrivate case we presume this to mean that the worker's status is >= Closing. Bug 1800659 changes our dispatch constraint to allow dispatch through Canceling, only preventing dispatch at > Canceling which means that as long as FetchStreamReader is properly holding a WorkerRef, things will be fine. So as an amendment to comment 2, in this case we believe the WorkerRef situation is probably fine (noting that things may have improved since comment 2 thanks to cleanups performed by Nika and Kagami), it's just the worker dispatch footgun that we're imminently fixing.
Depends on: 1800659

Bug 1800659 landed 9 months ago and apparently there are no new instances here at least for the last 4 months.

Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → WORKSFORME
Group: dom-core-security
You need to log in before you can comment on or make changes to this bug.