1650940 - Intermittent Assertion failure: aStream == mPipeOut, at /builds/worker/checkouts/gecko/dom/fetch/FetchStreamReader.cpp:192

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

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

---

[task 2020-07-06T22:05:56.222Z] 22:05:56 INFO - TEST-START | dom/workers/test/test_readableStream_when_closing.html
[task 2020-07-06T22:05:56.344Z] 22:05:56 INFO - GECKO(7147) | [7147, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /builds/worker/checkouts/gecko/parser/html/nsHtml5StreamParser.cpp, line 1131
[task 2020-07-06T22:05:56.503Z] 22:05:56 INFO - GECKO(7147) | [7147, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, nullptr) failed with result 0x804B000A (NS_ERROR_MALFORMED_URI): file /builds/worker/checkouts/gecko/extensions/permissions/Permission.cpp, line 46
[task 2020-07-06T22:05:56.504Z] 22:05:56 INFO - GECKO(7147) | [7147, Main Thread] WARNING: NS_ENSURE_TRUE(principal) failed: file /builds/worker/checkouts/gecko/extensions/permissions/Permission.cpp, line 58
[task 2020-07-06T22:05:56.702Z] 22:05:56 INFO - GECKO(7147) | [7147, StreamTrans #110] WARNING: A runnable was posted to a worker that is already shutting down!: file /builds/worker/checkouts/gecko/dom/workers/WorkerPrivate.cpp, line 1434
[task 2020-07-06T22:05:56.712Z] 22:05:56 INFO - GECKO(7147) | Assertion failure: aStream == mPipeOut, at /builds/worker/checkouts/gecko/dom/fetch/FetchStreamReader.cpp:192
[task 2020-07-06T22:05:56.712Z] 22:05:56 INFO - GECKO(7147) | #01: nsOutputStreamReadyEvent::Run() [xpcom/io/nsStreamUtils.cpp:184]
[task 2020-07-06T22:05:56.712Z] 22:05:56 INFO - GECKO(7147) | #02: mozilla::dom::(anonymous namespace)::ExternalRunnableWrapper::WorkerRun(JSContext*, mozilla::dom::WorkerPrivate*) [dom/workers/WorkerPrivate.cpp:181]
[task 2020-07-06T22:05:56.713Z] 22:05:56 INFO - GECKO(7147) | #03: mozilla::dom::WorkerRunnable::Run() [dom/workers/WorkerRunnable.cpp:370]
[task 2020-07-06T22:05:56.714Z] 22:05:56 INFO - GECKO(7147) | #04: mozilla::dom::(anonymous namespace)::WrappedControlRunnable::WorkerRun(JSContext*, mozilla::dom::WorkerPrivate*) [dom/workers/WorkerEventTarget.cpp:37]
[task 2020-07-06T22:05:56.718Z] 22:05:56 INFO - GECKO(7147) | #05: mozilla::dom::WorkerRunnable::Run() [dom/workers/WorkerRunnable.cpp:370]
[task 2020-07-06T22:05:56.720Z] 22:05:56 INFO - GECKO(7147) | #06: mozilla::dom::WorkerPrivate::ProcessAllControlRunnablesLocked() [dom/workers/WorkerPrivate.cpp:3528]
[task 2020-07-06T22:05:56.720Z] 22:05:56 INFO - GECKO(7147) | [7147, Main Thread] WARNING: A runnable was posted to a worker that is already shutting down!: file /builds/worker/checkouts/gecko/dom/workers/WorkerPrivate.cpp, line 1434
[task 2020-07-06T22:05:56.726Z] 22:05:56 INFO - GECKO(7147) | #07: mozilla::dom::WorkerPrivate::DoRunLoop(JSContext*) [dom/workers/WorkerPrivate.cpp:2884]
[task 2020-07-06T22:05:56.726Z] 22:05:56 INFO - GECKO(7147) | #08: mozilla::dom::workerinternals::(anonymous namespace)::WorkerThreadPrimaryRunnable::Run() [dom/workers/RuntimeService.cpp:2219]
[task 2020-07-06T22:05:56.730Z] 22:05:56 INFO - GECKO(7147) | #09: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1234]
[task 2020-07-06T22:05:56.731Z] 22:05:56 INFO - GECKO(7147) | #10: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/threads/nsThreadUtils.cpp:504]
[task 2020-07-06T22:05:56.732Z] 22:05:56 INFO - GECKO(7147) | #11: mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:332]
[task 2020-07-06T22:05:56.733Z] 22:05:56 INFO - GECKO(7147) | #12: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:316]
[task 2020-07-06T22:05:56.734Z] 22:05:56 INFO - GECKO(7147) | #13: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:292]
[task 2020-07-06T22:05:56.737Z] 22:05:56 INFO - GECKO(7147) | #14: nsThread::ThreadFunc(void*) [xpcom/threads/nsThread.cpp:449]
[task 2020-07-06T22:05:56.765Z] 22:05:56 INFO - GECKO(7147) | #15: _pt_root [nsprpub/pr/src/pthreads/ptthread.c:204]
[task 2020-07-06T22:05:56.765Z] 22:05:56 INFO - fix-stacks error: failed to read breakpad symbols dir /builds/worker/workspace/build/symbols/libpthread.so.0 for /lib/x86_64-linux-gnu/libpthread.so.0
[task 2020-07-06T22:05:56.765Z] 22:05:56 INFO - fix-stacks note: this is expected and harmless for system libraries on debug automation runs
[task 2020-07-06T22:05:56.765Z] 22:05:56 INFO - GECKO(7147) | #16: ??? [/lib/x86_64-linux-gnu/libpthread.so.0 + 0x76db]
[task 2020-07-06T22:05:56.765Z] 22:05:56 INFO - GECKO(7147) | #17: clone [/lib/x86_64-linux-gnu/libc.so.6 + 0x12188f]
[task 2020-07-06T22:05:56.765Z] 22:05:56 INFO - GECKO(7147) | #18: ??? (???:???)
[task 2020-07-06T22:05:56.765Z] 22:05:56 INFO - GECKO(7147) | ExceptionHandler::GenerateDump cloned child 7412
[task 2020-07-06T22:05:56.765Z] 22:05:56 INFO - GECKO(7147) | ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2020-07-06T22:05:56.765Z] 22:05:56 INFO - GECKO(7147) | ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2020-07-06T22:05:56.922Z] 22:05:56 INFO - TEST-INFO | Main app process: exit 11

Comment 1

[Intermittent Failures Robot]

1 failures in 5265 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 1

Platform breakdown:

• linux1804-64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1650940&startday=2020-07-06&endday=2020-07-12&tree=all

Comment 2

[Jens Stutte [:jstutte]]

We expect the input stream to be the same we already know. BTW, this seems to be the same for most implementations of OnOutputStreamReady but this special case, which makes me feel a bit unsure, if we really need this parameter in general.

I see no obvious cause for this, though. Maybe it is totally unrelated, but I see a GC running on the main thread while this happens.

Comment 3

[Andrea Marchesini [:baku]]

I would wait until we see more crashes. As far as I know, nothing has changed on the outputStream lately, and that code follows that the XPCOM IDL says: "aStream The stream whose asyncWait method was called."
https://searchfox.org/mozilla-central/rev/af5cff556a9482d7aa2267a82f2ccfaf18e797e9/xpcom/io/nsIAsyncOutputStream.idl#97-102

Comment 4

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 5

[Intermittent Failures Robot]

1 failures in 4618 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux1804-64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1650940&startday=2020-08-03&endday=2020-08-09&tree=all

Comment 6

[Intermittent Failures Robot]

1 failures in 3760 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1

Platform breakdown:

• linux1804-64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1650940&startday=2020-09-14&endday=2020-09-20&tree=all

Comment 7

[Alexandru Michis [:malexandru]]

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=340043640&repo=mozilla-central&lineNumber=128668

Comment 8

[Intermittent Failures Robot]

1 failures in 3061 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1650940&startday=2021-05-17&endday=2021-05-23&tree=all

Comment 9

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 10

[Alexandru Michis [:malexandru]]

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=343843410&repo=autoland&lineNumber=143755

Comment 11

[Intermittent Failures Robot]

1 failures in 3115 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1650940&startday=2021-06-21&endday=2021-06-27&tree=all

Comment 12

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 13

[Intermittent Failures Robot]

1 failures in 3375 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1

Platform and build breakdown:

• linux1804-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1650940&startday=2021-09-13&endday=2021-09-19&tree=all

Comment 14

[Cristian Tuns]

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=352814073&repo=mozilla-esr91&lineNumber=148667

Comment 15

[Intermittent Failures Robot]

3 failures in 3376 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-esr91: 1
• autoland: 1
• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-qr: 3
  • debug: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1650940&startday=2021-09-27&endday=2021-10-03&tree=all

Comment 16

[Intermittent Failures Robot]

1 failures in 3315 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64-2004-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1650940&startday=2021-10-11&endday=2021-10-17&tree=all

Comment 17

[Intermittent Failures Robot]

1 failures in 2845 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1650940&startday=2021-10-25&endday=2021-10-31&tree=all

Comment 18

[Jens Stutte [:jstutte]]

(In reply to Jens Stutte [:jstutte] from comment #2)

We expect the input stream to be the same we already know. BTW, this seems to be the same for most implementations of OnOutputStreamReady but this special case, which makes me feel a bit unsure, if we really need this parameter in general.

I see no obvious cause for this, though. Maybe it is totally unrelated, but I see a GC running on the main thread while this happens.

(In reply to Andrea Marchesini [:baku] from comment #3)

I would wait until we see more crashes. As far as I know, nothing has changed on the outputStream lately, and that code follows that the XPCOM IDL says: "aStream The stream whose asyncWait method was called."
https://searchfox.org/mozilla-central/rev/af5cff556a9482d7aa2267a82f2ccfaf18e797e9/xpcom/io/nsIAsyncOutputStream.idl#97-102

It's still there. We are coming from nsOutputStreamReadyEvent thus we know that mStream is not null and we even hold a strong reference to it in this event. Given the few places we manipulate mPipeOut I must assume, we somehow executed FetchStreamReader::CloseAndRelease while this event was in flight. We might want to move this assert after the explicit check if we are already closed?

Comment 19

[Intermittent Failures Robot]

2 failures in 3259 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1
• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-qr: 1
  • debug: 1
• windows10-64-2004-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1650940&startday=2021-11-15&endday=2021-11-21&tree=all

Comment 20

[Intermittent Failures Robot]

1 failures in 3170 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1650940&startday=2021-11-29&endday=2021-12-05&tree=all

Comment 21

[Intermittent Failures Robot]

1 failures in 3263 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1650940&startday=2021-12-13&endday=2021-12-19&tree=all

Comment 22

[Jens Stutte [:jstutte]]

(In reply to Jens Stutte [:jstutte] from comment #18)

I must assume, we somehow executed FetchStreamReader::CloseAndRelease while this event was in flight. We might want to move this assert after the explicit check if we are already closed?

So bug 1128959 comment 105 actually suggest the very same:

I think we should check mStreamClosed here before doing anything. Its possible the StreamReady runnable is in the event queue when the stream is closed. We should short-circuit any further action here.

Then the asserts should just move after the check here.

Comment 23

[Jens Stutte [:jstutte]]

Attachment: Bug 1650940: Only assert FetchStreamReader members in OnOutputStreamReady if we are not closed. r?smaug

Comment 24

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/d5746efda226
Only assert FetchStreamReader members in OnOutputStreamReady if we are not closed. r=smaug

Comment 25

[Marian-Vasile Laza]

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