<a class="header-button" href="https://bugzilla.mozilla.org/home" title="Go to home page"> Bugzilla

Andrew McCreight [:mccr8]

Comment 4

•

2 years ago

Kagami - any thoughts? Unfortunately no backtraces, but all the off-main-thread accesses are on StreamTrans threads. Is this on the DOM side of Fetch, or the Networking side? Looks like the DOM side to me

Sec bug - modifying the refcnt of an object on another thread than the creating/owning thread is dangerous if it's not thread-safe. It might be some sort of race where a ref is left and gets released on the "wrong" thread.

Group: network-core-security

Severity: S4 → S2

Flags: needinfo?(krosylight)

Priority: P5 → P2

Updated

•

2 years ago

Keywords: csectype-race, sec-moderate

Assignee

Comment 5

•

2 years ago

StreamTrans threads are AFAICT for nsStreamTransportService that is used by NS_MakeAsyncNonBlockingInputStream which again is used by NonAsyncInputToReadableStreamAlgorithms. But AFAIK that service never directly grabs FetchStreamReader. 🤔

Flags: needinfo?(krosylight)

Assignee

Comment 6

•

2 years ago

Tried adding MOZ_DIAGNOSTIC_ASSERT(mOwningEventTarget->IsOnCurrentThread()); here and there in FetchStreamReader methods but I see no crash, so at least nothing calls any methods from non-owning thread. Hmm.

Assignee

Comment 7

•

2 years ago

But CI disagrees; https://treeherder.mozilla.org/jobs?repo=try&revision=e6bf7a2d96d3e90cd34c9ae64df2a550ae80690a&selectedTaskRun=LO2dxD7QRuOC_sXUa4ChkA.0

[task 2023-07-06T13:01:39.392Z] 13:01:39     INFO - PROCESS-CRASH | MOZ_DIAGNOSTIC_ASSERT(mOwningEventTarget->IsOnCurrentThread()) [@ mozilla::dom::FetchStreamReader::CloseAndRelease] | dom/tests/mochitest/fetch/test_readableStreams.html 
[task 2023-07-06T13:01:39.393Z] 13:01:39     INFO - Process type: content
[task 2023-07-06T13:01:39.394Z] 13:01:39     INFO - Process pid: None
[task 2023-07-06T13:01:39.394Z] 13:01:39     INFO - Mozilla crash reason: MOZ_DIAGNOSTIC_ASSERT(mOwningEventTarget->IsOnCurrentThread())
[task 2023-07-06T13:01:39.394Z] 13:01:39     INFO - Crash dump filename: /tmp/tmpsou9lj44.mozrunner/minidumps/7449ae08-3244-f6e6-cc42-d31a25460d47.dmp
[task 2023-07-06T13:01:39.394Z] 13:01:39     INFO - Operating system: Linux
[task 2023-07-06T13:01:39.394Z] 13:01:39     INFO -                   4.4.0-1014-aws #14taskcluster1-Ubuntu SMP Tue Apr 3 10:27:00 UTC 2018
[task 2023-07-06T13:01:39.395Z] 13:01:39     INFO - CPU: amd64
[task 2023-07-06T13:01:39.395Z] 13:01:39     INFO -      family 6 model 85 stepping 7
[task 2023-07-06T13:01:39.395Z] 13:01:39     INFO -      2 CPUs
[task 2023-07-06T13:01:39.396Z] 13:01:39     INFO - Linux Ubuntu 18.04 - bionic (Ubuntu 18.04.6 LTS)
[task 2023-07-06T13:01:39.397Z] 13:01:39     INFO - 
[task 2023-07-06T13:01:39.397Z] 13:01:39     INFO - Crash reason:  SIGSEGV / SEGV_MAPERR
[task 2023-07-06T13:01:39.397Z] 13:01:39     INFO - Crash address: 0x0
[task 2023-07-06T13:01:39.398Z] 13:01:39     INFO - Crashing instruction: `mov dword [0x0], 0x80`
[task 2023-07-06T13:01:39.398Z] 13:01:39     INFO - Memory accessed by instruction:
[task 2023-07-06T13:01:39.399Z] 13:01:39     INFO -   0. Address: 0x0000000000000000
[task 2023-07-06T13:01:39.399Z] 13:01:39     INFO -      Size: 4
[task 2023-07-06T13:01:39.400Z] 13:01:39     INFO - Process uptime: not available
[task 2023-07-06T13:01:39.400Z] 13:01:39     INFO - 
[task 2023-07-06T13:01:39.401Z] 13:01:39     INFO - Thread 24 DOM Worker (crashed)
[task 2023-07-06T13:01:39.401Z] 13:01:39     INFO -  0  libxul.so!mozilla::dom::FetchStreamReader::CloseAndRelease(JSContext*, nsresult) [FetchStreamReader.cpp:e6bf7a2d96d3e90cd34c9ae64df2a550ae80690a : 128 + 0x0]
[task 2023-07-06T13:01:39.401Z] 13:01:39     INFO -      rax = 0x00007f25c5fed10a    rdx = 0x0000000000000000
[task 2023-07-06T13:01:39.402Z] 13:01:39     INFO -      rcx = 0x000055b428a28f98    rbx = 0x00007f25bcafc220
[task 2023-07-06T13:01:39.403Z] 13:01:39     INFO -      rsi = 0x00007f25dc4348b0    rdi = 0x00007f25dc433680
[task 2023-07-06T13:01:39.403Z] 13:01:39     INFO -      rbp = 0x00007f25bbbfe230    rsp = 0x00007f25bbbfe190
[task 2023-07-06T13:01:39.404Z] 13:01:39     INFO -       r8 = 0x00007f25dc4348b0     r9 = 0x00007f25bbbff700
[task 2023-07-06T13:01:39.404Z] 13:01:39     INFO -      r10 = 0x0000000000000002    r11 = 0x0000000000000000
[task 2023-07-06T13:01:39.405Z] 13:01:39     INFO -      r12 = 0x00007f25bbbfe280    r13 = 0x0000000000000000
[task 2023-07-06T13:01:39.405Z] 13:01:39     INFO -      r14 = 0x0000000080470002    r15 = 0x0000000000000000
[task 2023-07-06T13:01:39.405Z] 13:01:39     INFO -      rip = 0x00007f25caf88767
[task 2023-07-06T13:01:39.406Z] 13:01:39     INFO -     Found by: given as instruction pointer in context
[task 2023-07-06T13:01:39.407Z] 13:01:39     INFO -  1  libxul.so!mozilla::dom::FetchStreamReader::~FetchStreamReader() [FetchStreamReader.cpp:e6bf7a2d96d3e90cd34c9ae64df2a550ae80690a : 116 + 0xb]
[task 2023-07-06T13:01:39.407Z] 13:01:39     INFO -      rbx = 0x00007f25bcafc220    rbp = 0x00007f25bbbfe250
[task 2023-07-06T13:01:39.407Z] 13:01:39     INFO -      rsp = 0x00007f25bbbfe240    r12 = 0x00007f25bbbfe280
[task 2023-07-06T13:01:39.408Z] 13:01:39     INFO -      r13 = 0x0000000000000000    r14 = 0x00007f25bbbfe320
[task 2023-07-06T13:01:39.408Z] 13:01:39     INFO -      r15 = 0x00007f25bbbfe328    rip = 0x00007f25caf883cb
[task 2023-07-06T13:01:39.408Z] 13:01:39     INFO -     Found by: call frame info
[task 2023-07-06T13:01:39.409Z] 13:01:39     INFO -  2  libxul.so!mozilla::dom::FetchStreamReader::DeleteCycleCollectable() [FetchStreamReader.cpp:e6bf7a2d96d3e90cd34c9ae64df2a550ae80690a : 33]
[task 2023-07-06T13:01:39.410Z] 13:01:39     INFO -     Found by: inlining
[task 2023-07-06T13:01:39.410Z] 13:01:39     INFO -  3  libxul.so!mozilla::dom::FetchStreamReader::cycleCollection::DeleteCycleCollectable(void*) [FetchStreamReader.h:e6bf7a2d96d3e90cd34c9ae64df2a550ae80690a : 27 + 0x7]
[task 2023-07-06T13:01:39.411Z] 13:01:39     INFO -      rbx = 0x00007f25bcafc220    rbp = 0x00007f25bbbfe270
[task 2023-07-06T13:01:39.411Z] 13:01:39     INFO -      rsp = 0x00007f25bbbfe260    r12 = 0x00007f25bbbfe280
[task 2023-07-06T13:01:39.413Z] 13:01:39     INFO -      r13 = 0x0000000000000000    r14 = 0x00007f25bbbfe320
[task 2023-07-06T13:01:39.413Z] 13:01:39     INFO -      r15 = 0x00007f25bbbfe328    rip = 0x00007f25caf9452f
[task 2023-07-06T13:01:39.414Z] 13:01:39     INFO -     Found by: call frame info
[task 2023-07-06T13:01:39.414Z] 13:01:39     INFO -  4  libxul.so!SnowWhiteKiller::MaybeKillObject(SnowWhiteKiller::SnowWhiteObject&) [nsCycleCollector.cpp:e6bf7a2d96d3e90cd34c9ae64df2a550ae80690a : 2486 + 0xc]
[task 2023-07-06T13:01:39.414Z] 13:01:39     INFO -      rbx = 0x00007f25bd040048    rbp = 0x00007f25bbbfe2b0
[task 2023-07-06T13:01:39.415Z] 13:01:39     INFO -      rsp = 0x00007f25bbbfe280    r12 = 0x00007f25bbbfe280
[task 2023-07-06T13:01:39.415Z] 13:01:39     INFO -      r13 = 0x0000000000000000    r14 = 0x00007f25bbbfe320
[task 2023-07-06T13:01:39.416Z] 13:01:39     INFO -      r15 = 0x00007f25bbbfe328    rip = 0x00007f25c8be6b1e
[task 2023-07-06T13:01:39.416Z] 13:01:39     INFO -     Found by: call frame info

DOM Worker? Does it mean it somehow got the reference from the main thread? 🤔

Comment 8

•

2 years ago

Eden - any thoughts?

Flags: needinfo?(echuang)

Comment 9

•

2 years ago

I'd ping asuth as well but I think he's on PTO

Comment 10

•

2 years ago

Triggered a pernosco run of Kagami's test

Comment 11

•

2 years ago

Didn't repro in Pernosco; trying a few more from different tests that failed in the Try

https://pernos.co/debug/Ug5nchAkUD4G8b6KhbCWrw/index.html
https://pernos.co/debug/qltGx_8aC9qx_Omln1TYXw/index.html

Comment 12

•

2 years ago

Flags: needinfo?(krosylight)

Comment 13

•

2 years ago

•

Edited

FYI, OnCurrentThread() returned false because the SnowWhite CC killer ran after mWorkerPrivate->RunShutdownTasks(), which nulls out the mWorkerPrivate, which is used for OnCurrentThread(). The object was freed on the same thread it was allocated on, so this Try run failure is a false positive

Assignee

Comment 14

•

2 years ago

FYI, OnCurrentThread() returned false because the SnowWhite CC killer ran after mWorkerPrivate->RunShutdownTasks(), which nulls out the mWorkerPrivate, which is used for OnCurrentThread(). The object was freed on the same thread it was allocated on, so this Try run failure is a false positive

I wonder all my Try crashes are false positive in that case, as all failures are from ::CloseAndRelease AFAICT 😬. Any idea how to prevent such false positive?

Flags: needinfo?(krosylight) → needinfo?(rjesup)

Assignee

Updated

•

2 years ago

Duplicate of this bug: 1835096

Comment 16

•

2 years ago

The problem is that this code can run after worker shutdown has gotten past the point where you can safely do this test (OnCurrentThread). You need to do the test in some other manner (record the thread at create and compare on destruction, for example)

Flags: needinfo?(rjesup)

Assignee

Comment 17

•

2 years ago

Tried using PR_GetCurrentThread() and now I see nothing interesting in the CI. Hmm. https://treeherder.mozilla.org/jobs?repo=try&revision=6bb11b076bebe43565a4d50efbd319561e585e9a

Andrew McCreight [:mccr8]

Assignee

Comment 18

•

2 years ago

I was to replace this class but I think I should understand what's happening here before doing that.

Blocks: 1825763

Updated

•

2 years ago

Duplicate of this bug: 1843531

Valentin Gosu [:valentin] (he/him)

Updated

•

1 years ago

Duplicate of this bug: 1843840

Assignee

Updated

•

1 years ago

Duplicate of this bug: 1844917

Assignee

Updated

•

1 years ago

Duplicate of this bug: 1846876

Assignee

Comment 23

•

1 years ago

https://bugzilla.mozilla.org/show_bug.cgi?id=1846876#c0 has the stack:

[task 2023-08-02T23:09:26.534Z] 23:09:26     INFO -  5  libxul.so!~(lambda at /builds/worker/checkouts/gecko/xpcom/io/nsPipe3.cpp:84:35) [nsPipe3.cpp:4e8d25555f9d9253daae12f37e70b494fe6bc018 : 84]
[task 2023-08-02T23:09:26.534Z] 23:09:26     INFO -     Found by: inlining
[task 2023-08-02T23:09:26.534Z] 23:09:26     INFO -  6  libxul.so!~MaybeStorage [Maybe.h:4e8d25555f9d9253daae12f37e70b494fe6bc018 : 269]
[task 2023-08-02T23:09:26.534Z] 23:09:26     INFO -     Found by: inlining
[task 2023-08-02T23:09:26.534Z] 23:09:26     INFO -  7  libxul.so!NS_NewCancelableRunnableFunction<CallbackHolder::CallbackHolder(nsIAsyncOutputStream*, nsIOutputStreamCallback*, unsigned int, nsIEventTarget*)::{lambda()#1}>(char const*, CallbackHolder::CallbackHolder(nsIAsyncOutputStream*, nsIOutputStreamCallback*, unsigned int, nsIEventTarget*)::{lambda()#1}&&)::FuncCancelableRunnable::~FuncCancelableRunnable() [nsThreadUtils.h:4e8d25555f9d9253daae12f37e70b494fe6bc018 : 679 + 0x3a]
[task 2023-08-02T23:09:26.535Z] 23:09:26     INFO -      rbx = 0x00007f5c1befd380    rbp = 0x00007f5c1e5bd4e0
[task 2023-08-02T23:09:26.535Z] 23:09:26     INFO -      rsp = 0x00007f5c1e5bd4d0    r12 = 0x0000000000000008
[task 2023-08-02T23:09:26.535Z] 23:09:26     INFO -      r13 = 0x0000000000004000    r14 = 0x00007f5c1c6e0920
[task 2023-08-02T23:09:26.535Z] 23:09:26     INFO -      r15 = 0x00007f5c1be0d2b0    rip = 0x00007f5c2c77845f
[task 2023-08-02T23:09:26.535Z] 23:09:26     INFO -     Found by: call frame info
[task 2023-08-02T23:09:26.535Z] 23:09:26     INFO -  8  libxul.so!NS_NewCancelableRunnableFunction<CallbackHolder::CallbackHolder(nsIAsyncOutputStream*, nsIOutputStreamCallback*, unsigned int, nsIEventTarget*)::{lambda()#1}>(char const*, CallbackHolder::CallbackHolder(nsIAsyncOutputStream*, nsIOutputStreamCallback*, unsigned int, nsIEventTarget*)::{lambda()#1}&&)::FuncCancelableRunnable::~FuncCancelableRunnable() [nsThreadUtils.h:4e8d25555f9d9253daae12f37e70b494fe6bc018 : 679 + 0x14]
[task 2023-08-02T23:09:26.535Z] 23:09:26     INFO -      rbx = 0x00007f5c1befd380    rbp = 0x00007f5c1e5bd500
[task 2023-08-02T23:09:26.535Z] 23:09:26     INFO -      rsp = 0x00007f5c1e5bd4f0    r12 = 0x0000000000000008
[task 2023-08-02T23:09:26.535Z] 23:09:26     INFO -      r13 = 0x0000000000004000    r14 = 0x00007f5c1c6e0920
[task 2023-08-02T23:09:26.536Z] 23:09:26     INFO -      r15 = 0x00007f5c1be0d2b0    rip = 0x00007f5c2c7784d5
[task 2023-08-02T23:09:26.536Z] 23:09:26     INFO -     Found by: call frame info

This looks a lot related to bug 1839703?

Comment 24

•

1 years ago

And blob again.

[task 2023-08-02T23:09:26.544Z] 23:09:26     INFO - 26  libxul.so!mozilla::dom::MutableBlobStreamListener::OnDataAvailable(nsIRequest*, nsIInputStream*, unsigned long, unsigned int) + 0x39
[task 2023-08-02T23:09:26.544Z] 23:09:26     INFO -      rbx = 0x00007f5c1c6cc090    rbp = 0x00007f5c1e5bd6d0
[task 2023-08-02T23:09:26.544Z] 23:09:26     INFO -      rsp = 0x00007f5c1e5bd6c0    r12 = 0x00007f5c1c6cc130
[task 2023-08-02T23:09:26.544Z] 23:09:26     INFO -      r13 = 0x00007f5c1befd560    r14 = 0x00007f5c1c6defc8
[task 2023-08-02T23:09:26.544Z] 23:09:26     INFO -      r15 = 0x000000000000f000    rip = 0x00007f5c30540bea

Comment 25

•

1 years ago

Thanks Kagami - can you take this bug, since it seems like this is in the Streams side, not the networking side?

Flags: needinfo?(krosylight)

Assignee

Comment 26

•

1 years ago

I can take, but any help is much welcome because I'm still not sure where the problem is. Most probably somewhere in Blob, but can't exclude XPCOM stream things either.

Assignee: nobody → krosylight

Flags: needinfo?(krosylight)

Comment 27

•

1 years ago

sure!

Component: DOM: Networking → DOM: Streams

Whiteboard: [necko-monitor]

Assignee

Comment 28

•

1 year ago

•

Edited

Is there a way to see this is still happening?

Edit: The intermittent failures bot stopped reporting any intermittents, could this be a temporary issue caused by something else?
Edit 2: But there have been some recent duplicates, hmm.
Edit 3: https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2023-08-10&endday=2023-08-17&tree=trunk&bug=1844917 has some reports from yesterday.

Assignee

Comment 29

•

1 year ago

Some early investigation:

https://bugzilla.mozilla.org/show_bug.cgi?id=1846876#c0 says it's from https://searchfox.org/mozilla-central/rev/d81e60336d9f498ad3985491dc17c2b77969ade4/dom/tests/mochitest/fetch/common_readableStreams.js#124, which is basically testing a worker (as it's from workify() per the log) that runs:

new Worker(URL.createObjectURL(new Blob([`
  const BIG_BUFFER_SIZE = 1000000;

  function makeBuffer(size) {
    let buffer = new Uint8Array(size);
    buffer.fill(42);

    let value = 0;
    for (let i = 0; i < 1000000; i += 1000) {
      buffer.set([++value % 255], i);
    }

    return buffer;
  }

  let buffer = makeBuffer(BIG_BUFFER_SIZE);

  new Response(
    new ReadableStream({
      start: controller => {
        controller.enqueue(buffer);
        controller.close();
      },
    })
  ).blob();
`])));

This creates MutableBlobStreamListener here: https://searchfox.org/mozilla-central/rev/d81e60336d9f498ad3985491dc17c2b77969ade4/dom/base/BodyConsumer.cpp#551

This listener is called by StreamTrans thread regardless of whether the above code is ran by main or worker thread. I think it's no good to use a separate thread here at least for this situation, but anyway I guess that's fine. What's not fine is that the call sometimes goes all the way down to delete the callback and thus releases the lambda-captured reference of FetchStreamReader, which generally only happens in the owning thread.

I'll dig further tomorrow.

Assignee

Comment 30

•

1 year ago

So far all failures have been from Android, is there any related worker issue on Android you can think of, Andrew?

Flags: needinfo?(bugmail)

Assignee

Comment 31

•

1 year ago

Actually never mind, bug 1846876 was from Linux. Still interesting that the majority is from Android.

Flags: needinfo?(bugmail)

Jens Stutte [:jstutte]

Comment 32

•

1 year ago

The main high level difference on Android is that we do not have fission enabled (as apparently also on the try instances you linked in comment 28), which might influence thread and process layout and what not in general. It could be interesting to check if we regularly run android tests also with fission enabled and if we see the issue there, too, or not.

Assignee

Comment 33

•

1 year ago

Thanks, testing with fission disabled might help then.

Still looking at the stack in https://bugzilla.mozilla.org/show_bug.cgi?id=1846876#c0 and the local behavior.

[task 2023-08-02T23:09:26.539Z] 23:09:26     INFO - 16  libxul.so!mozilla::dom::(anonymous namespace)::ExternalRunnableWrapper::Release() [WorkerPrivate.cpp:4e8d25555f9d9253daae12f37e70b494fe6bc018 : 193 + 0x22]
[task 2023-08-02T23:09:26.539Z] 23:09:26     INFO -      rbx = 0x00007f5c1c6e0930    rbp = 0x00007f5c1e5bd540
[task 2023-08-02T23:09:26.539Z] 23:09:26     INFO -      rsp = 0x00007f5c1e5bd540    r12 = 0x0000000000000008
[task 2023-08-02T23:09:26.539Z] 23:09:26     INFO -      r13 = 0x0000000000004000    r14 = 0x00007f5c1c6e0920
[task 2023-08-02T23:09:26.539Z] 23:09:26     INFO -      r15 = 0x00007f5c1be0d2b0    rip = 0x00007f5c31eda5d0
[task 2023-08-02T23:09:26.539Z] 23:09:26     INFO -     Found by: call frame info
[task 2023-08-02T23:09:26.540Z] 23:09:26     INFO - 17  libxul.so!Release [RefPtr.h:4e8d25555f9d9253daae12f37e70b494fe6bc018 : 54]
[task 2023-08-02T23:09:26.540Z] 23:09:26     INFO -     Found by: inlining
[task 2023-08-02T23:09:26.540Z] 23:09:26     INFO - 18  libxul.so!Release [RefPtr.h:4e8d25555f9d9253daae12f37e70b494fe6bc018 : 420]
[task 2023-08-02T23:09:26.540Z] 23:09:26     INFO -     Found by: inlining
[task 2023-08-02T23:09:26.540Z] 23:09:26     INFO - 19  libxul.so!~RefPtr [RefPtr.h:4e8d25555f9d9253daae12f37e70b494fe6bc018 : 85]
[task 2023-08-02T23:09:26.540Z] 23:09:26     INFO -     Found by: inlining
[task 2023-08-02T23:09:26.540Z] 23:09:26     INFO - 20  libxul.so!mozilla::dom::WorkerEventTarget::Dispatch(already_AddRefed<nsIRunnable>, unsigned int) [WorkerEventTarget.cpp:4e8d25555f9d9253daae12f37e70b494fe6bc018 : 128 + 0x8]
[task 2023-08-02T23:09:26.541Z] 23:09:26     INFO -      rbx = 0x00007f5c1c6e0930    rbp = 0x00007f5c1e5bd570
[task 2023-08-02T23:09:26.541Z] 23:09:26     INFO -      rsp = 0x00007f5c1e5bd550    r12 = 0x0000000000000008
[task 2023-08-02T23:09:26.541Z] 23:09:26     INFO -      r13 = 0x0000000000004000    r14 = 0x00007f5c1c6e0920
[task 2023-08-02T23:09:26.541Z] 23:09:26     INFO -      r15 = 0x00007f5c1be0d2b0    rip = 0x00007f5c31e92cef
[task 2023-08-02T23:09:26.541Z] 23:09:26     INFO -     Found by: call frame info

Line 128 of WorkerEventTarget is the end of the block where WorkerRunnable is released after failing to be dispatched: https://searchfox.org/mozilla-central/rev/d7a8eadc28298c31381119cbf25c8ba14b8712b3/dom/workers/WorkerEventTarget.cpp#119-128

Presumably at this point the refcount of the runnable goes down to 0 and releases the lambda captured references, which causes this issue. I wonder this is related to Eden's recent WorkerRunnable refactoring?

Comment 34

•

1 year ago

I'd like to try getting a minimal repro for this based on comment #29 and comment #33, but not sure how the dispatch can fail during an actively running test, as at that point the worker should not be dying. Any idea?

Flags: needinfo?(bugmail)

Comment 35

•

1 year ago

I requested a pernosco self-serve on the task from https://bugzilla.mozilla.org/show_bug.cgi?id=1846876#c0 and got:
https://pernos.co/debug/8IWAeSqgbkVQ4qZ6AHindA/index.html

I haven't dug in yet, but am letting needinfo be cleared because this hopefully can help unblock you bug-wise. (Timeline-wise I know we both have the all-hands imminently.) I'll try and add some journal notes and comments here today.

Flags: needinfo?(bugmail)

Assignee

Comment 36

•

1 year ago

Thanks! Something I forget frequently 🙂

Nothing hits line 125, which means there's no dispatch failure actually.

Assignee

Comment 37

•

1 year ago

There are two destruct-after-dispatch in the session:

From StreamTrans (that caused the crash): https://pernos.co/debug/8IWAeSqgbkVQ4qZ6AHindA/index.html#f{m[Ex6v,gQ_,t[Aes,CkI_,f{e[Ex6v,gQ_,s{aa+N+5oAA,bARk,uA7ZtVw,oA7k4iQ___/
From Timer: https://pernos.co/debug/8IWAeSqgbkVQ4qZ6AHindA/index.html#f{m[EwnD,gQ_,t[Ado,Ci8_,f{e[EwnD,gQ_,s{aa+N+5oAA,bARk,uA7ZtVw,oA7k4iQ___/

What does this really mean? Does Dispatch call waits until the runnable actually runs, or is it being destructed before running?

Comment 38

•

1 year ago

•

Edited

This may be a case where the runnable should be going out of its way to drop references in its run method (on the worker thread) instead of assuming that it will be destroyed on the thread it ran on? Like the interleaving might be:

STS thread: We call dispatch on runnable R, yield control.
Worker thread: completely runs the runnable R to completion and drops its refcount on R.
STS thread: we resume control and drop our refcount on R, explosions.

Assignee

Comment 39

•

1 year ago

Sounds like keeping STS busy can repro this issue, and bingo, this is the minimal repro. The numbers can be smaller on slower systems as 20 workers and 1M buffer size causes crash on my Surface Pro 7 but not on my Threadripper desktop. A bad minimal repro in that sense.

for (const i of new Array(200).fill(0)) {
  new Worker(URL.createObjectURL(new Blob([`
    const BIG_BUFFER_SIZE = 100000000;

    function makeBuffer(size) {
      let buffer = new Uint8Array(size);
      buffer.fill(42);

      let value = 0;
      for (let i = 0; i < BIG_BUFFER_SIZE; i += 1000) {
        buffer.set([++value % 255], i);
      }

      return buffer;
    }

    let buffer = makeBuffer(BIG_BUFFER_SIZE);

    new Response(
      new ReadableStream({
        start: controller => {
          controller.enqueue(buffer);
          controller.close();
        },
      })
    ).blob().then(() => console.log('finished'));
  `])));
}

Assignee

Comment 40

•

1 year ago

Attached file 1836607.html — Details

Comment 41

•

1 year ago

•

Edited

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

This may be a case where the runnable should be going out of its way to drop references in its run method (on the worker thread) instead of assuming that it will be destroyed on the thread it ran on?

I phrased this badly. A better take is that we have a 2-part systemic bug in workers where step 1 is we wrap the runnable and retain a reference to the wrapper on the dispatching thread. In general, the right way for runnable dispatch to work is that we transfer ownership into the dispatch queue in the success case by moving the existing strong refcount (and this is not that).

RefPtr<WorkerRunnable> r =
    mWorkerPrivate->MaybeWrapAsWorkerRunnable(runnable.forget());
if (r->Dispatch()) {
  return NS_OK;

The 2nd part of the bug is that ExternalRunnable does not drop its mWrappedRunnable in Run and Cancel, but it totally could and that can be our fix here, perhaps.

virtual bool WorkerRun(JSContext* aCx,
                       WorkerPrivate* aWorkerPrivate) override {
  nsresult rv = mWrappedRunnable->Run();
  if (NS_FAILED(rv)) {
    if (!JS_IsExceptionPending(aCx)) {
      Throw(aCx, rv);
    }
    return false;
  }
  return true;
}

nsresult Cancel() override {
  nsCOMPtr<nsIDiscardableRunnable> doomed =
      do_QueryInterface(mWrappedRunnable);
  if (doomed) {
    doomed->OnDiscard();
  }
  return NS_OK;
}

The caveat is that if the runnable is already a WorkerRunnable we just give it back and those WorkerRunnables are still on the hook to make sure they drop everything in their WorkerRun/Cancel methods.

Our short/medium-term plans are to eliminate the wrapping which can avoid all the WorkerRunnable awkwardness and we can just be dispatching to a normal-ish event queue, but we can't do that on this bug.

Eden Chuang[:edenchuang]

Comment 42

•

1 year ago

I am curious whether dropping the mWrappedRunnable of ExternalWorkerRunnable fixes the bug.

It looks like FetchStreamReader is supposed to be released on the Worker thread, but it got released on the STS thread, then we hit the assertion.

I don't see caller methods of WorkerPrivate::MaybeWrapAsWorkerRunnable() propagate the runnable out after dispatch. So the only owner of ExternalWrappedRunnable should be the corresponding event queue after out of the scope of these caller methods. And then ExternalWrappedRunnable should be destroyed once it finishes its Run().

One possible situation is the runnable is still hold by other RefPtr/nsCOMPtr after dispatching.

nsCOMPtr<nsIRunnable> runnableA;
nsCOMPtr<nsIRunnable> runnableB = runnableA; // This increase the Ref count of the runnable.
WorkerEventTarget::Dispatch(runnableB.forget); // runnableA is still valid.

//... After ExternalRunnableWrapper execution finish on worker thread ...

runnableA = nullptr;  // if some resources releasing should be on the worker thread, we meet problem.

But I am not sure how CallbackHolder causes the situation.

Flags: needinfo?(echuang)

Assignee

Comment 43

•

1 year ago

(In reply to Eden Chuang[:edenchuang] from comment #42)

I don't see caller methods of WorkerPrivate::MaybeWrapAsWorkerRunnable() propagate the runnable out after dispatch. So the only owner of ExternalWrappedRunnable should be the corresponding event queue after out of the scope of these caller methods. And then ExternalWrappedRunnable should be destroyed once it finishes its Run().

Given the crash happens in WorkerEventTarget::Dispatch(), I think comment #38 better explains the situation. Somehow the runnable finishes to run on the worker thread before STS thread releases its reference, which causes CallbackHolder to be released in a wrong thread. Keeping STS thread busy indeed causes the crash reliably, see comment #39 and comment #40.

And dropping mWrappedRunnable early fixes the issue at least for my repro. I'll submit the patch.

Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)

Assignee

Comment 44

•

1 year ago

Attached file Bug 1836607 - Drop mWrappedRunnable early r=asuth,edenchuang — Details

Pulsebot

Comment 45

•

1 year ago

Pushed by krosylight@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/a552ec363a4e Drop mWrappedRunnable early r=asuth

Comment 46

•

1 year ago

https://hg.mozilla.org/mozilla-central/rev/a552ec363a4e

Group: network-core-security → core-security-release

Status: NEW → RESOLVED

Closed: 1 year ago

status-firefox119: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → 119 Branch

Comment 47

•

1 year ago

Do we know what caused this to start happening? Bug 1800659 or something else?

status-firefox117: --- → wontfix

status-firefox118: --- → wontfix

Flags: needinfo?(krosylight)

Assignee

Comment 48

•

1 year ago

This reproduces on the earliest available debug build (2022-09-21, mozilla-central 7c0a787f) so I'd bet it's something older than bug 1800659.

Flags: needinfo?(krosylight)

Updated

•

1 year ago

status-firefox-esr102: --- → wontfix

status-firefox-esr115: --- → affected

tracking-firefox119: --- → +

tracking-firefox-esr115: --- → 119+

Comment 49

•

1 year ago

(In reply to Ryan VanderMeulen [:RyanVM] from comment #47)

Do we know what caused this to start happening? Bug 1800659 or something else?

Building on Kagami's reply, the failure to drop for worker runnables has always been there. That said, if the event target being used for the stream stuff changed from the WorkerThread to the HybridEventTarget, that would have changed the runnable from not being wrapped to being wrapped. This would happen in cases where use of GetCurrentSerialEventTarget() on the worker (which returns the thread right now) was changed to instead use nsIGlobalObject::EventTargetFor (which returns the hybrid event target).

https://phabricator.services.mozilla.com/D172038 is the most likely commit that I could find with the tooling available.

Andrei Vaida [:avaida]

Updated

•

1 year ago

QA Whiteboard: [post-critsmash-triage]

Flags: qe-verify-

Comment 50

•

1 year ago

Please attach a rebased patch and nominate for ESR115 approval when you get a chance.

Flags: needinfo?(krosylight)

Assignee

Comment 51

•

1 year ago

Attached file Bug 1836607 - Drop mWrappedRunnable early r=asuth,edenchuang — Details

Assignee

Comment 52

•

1 year ago

•

Edited

Comment on attachment 9356565 [details]
Bug 1836607 - Drop mWrappedRunnable early r=asuth,edenchuang

ESR Uplift Approval Request

If this is not a sec:{high,crit} bug, please state case for ESR consideration: sec-moderate, but a potential cause for bug 1845412 which is sec-high
User impact if declined: Non-thread-safe destruction may potentially cause UAF on other thread.
Fix Landed on Version: 119
Risk to taking this patch: Low
Why is the change risky/not risky? (and alternatives if risky): The patch is fairly simple, it just nullifies the runnable field early enough after using it.

Flags: needinfo?(krosylight)

Attachment #9356565 - Flags: approval-mozilla-esr115?

Assignee

Updated

•

1 year ago

Attachment #9353692 - Flags: approval-mozilla-esr115?

Updated

•

1 year ago

Attachment #9353692 - Flags: approval-mozilla-esr115?

https://hg.mozilla.org/releases/mozilla-esr115/rev/8c9a876fd94a

Comment 53

•

1 year ago

Comment on attachment 9356565 [details]
Bug 1836607 - Drop mWrappedRunnable early r=asuth,edenchuang

Approved for 115.4esr.

Attachment #9356565 - Flags: approval-mozilla-esr115? → approval-mozilla-esr115+

Pulsebot

Comment 54

•

1 year ago

uplift