Closed Bug 1478850 Opened 6 years ago Closed 6 years ago

Intermittent dom/serviceworkers/test/test_fetch_event_with_thirdpartypref.html, dom/serviceworkers/test/test_fetch_event.html | application crashed [@ JS::ReadableStreamDefaultReaderRead(JSContext*, JS::Handle<JSObject*>)]

Categories

(Core :: DOM: Service Workers, defect, P1)

Product:
Core
Component:
DOM: Service Workers
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla65
Tracking Flags:
Tracking Status
firefox-esr60 --- unaffected
firefox63 --- wontfix
firefox64 --- wontfix
firefox65 --- fixed

People

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

References

(Blocks 1 open bug)

Details

(Keywords: crash, intermittent-failure)

Crash Data

Attachments

(2 files)

Bug 1478850 - Safely handle nuked wrappers as arguments to stream-related JSAPI entry points. r?tcampbell
47 bytes, text/x-phabricator-request
Details | Review
fix.patch
1.17 KB, patch
smaug
: review+
Details | Diff | Splinter Review 
Filed by: btara [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=190370625&repo=mozilla-inbound

https://queue.taskcluster.net/v1/task/YZ2TDzg5SyyNmSYeRVmbQQ/runs/0/artifacts/public/logs/live_backing.log

[task 2018-07-26T20:51:19.242Z] 20:51:19     INFO -  319 INFO TEST-PASS | dom/serviceworkers/test/test_fetch_event_with_thirdpartypref.html | Valid CORS request should receive valid response
[task 2018-07-26T20:51:19.242Z] 20:51:19     INFO -  320 INFO TEST-PASS | dom/serviceworkers/test/test_fetch_event_with_thirdpartypref.html | Response type should be CORS
[task 2018-07-26T20:51:19.243Z] 20:51:19     INFO -  321 INFO TEST-PASS | dom/serviceworkers/test/test_fetch_event_with_thirdpartypref.html | Response type should be opaque
[task 2018-07-26T20:51:19.243Z] 20:51:19     INFO -  322 INFO TEST-PASS | dom/serviceworkers/test/test_fetch_event_with_thirdpartypref.html | Status should be 0
[task 2018-07-26T20:51:19.244Z] 20:51:19     INFO -  323 INFO TEST-PASS | dom/serviceworkers/test/test_fetch_event_with_thirdpartypref.html | cors response body should match
[task 2018-07-26T20:51:19.244Z] 20:51:19     INFO -  324 INFO TEST-PASS | dom/serviceworkers/test/test_fetch_event_with_thirdpartypref.html | opaque response body should be empty
[task 2018-07-26T20:51:19.245Z] 20:51:19     INFO -  325 INFO TEST-PASS | dom/serviceworkers/test/test_fetch_event_with_thirdpartypref.html | load should be successful
[task 2018-07-26T20:51:19.245Z] 20:51:19     INFO -  326 INFO TEST-PASS | dom/serviceworkers/test/test_fetch_event_with_thirdpartypref.html | Redirect to real file should complete.
[task 2018-07-26T20:51:29.556Z] 20:51:29     INFO -  327 INFO TEST-PASS | dom/serviceworkers/test/test_fetch_event_with_thirdpartypref.html | synth+redirect+synth load should be successful
[task 2018-07-26T20:51:29.556Z] 20:51:29     INFO -  328 INFO TEST-PASS | dom/serviceworkers/test/test_fetch_event_with_thirdpartypref.html | load should have redirected+synthesized response
[task 2018-07-26T20:51:29.557Z] 20:51:29     INFO -  329 INFO TEST-PASS | dom/serviceworkers/test/test_fetch_event_with_thirdpartypref.html | worker load intercepted
[task 2018-07-26T20:51:50.701Z] 20:51:50     INFO -  INFO | automation.py | Application ran for: 0:10:07.699737
[task 2018-07-26T20:51:50.701Z] 20:51:50     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmp0WGXwgpidlog
[task 2018-07-26T20:51:51.324Z] 20:51:51     INFO -  /data/tombstones does not exist; tombstone check skipped
[task 2018-07-26T20:51:52.144Z] 20:51:52     INFO -  mozcrash Copy/paste: /usr/local/bin/linux64-minidump_stackwalk /tmp/tmpf7LkqC/72b1aacf-7582-1053-5efb-bf706170fb6c.dmp /builds/worker/workspace/build/symbols
[task 2018-07-26T20:52:01.275Z] 20:52:01     INFO -  mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/72b1aacf-7582-1053-5efb-bf706170fb6c.dmp
[task 2018-07-26T20:52:01.275Z] 20:52:01     INFO -  mozcrash Saved app info as /builds/worker/workspace/build/blobber_upload_dir/72b1aacf-7582-1053-5efb-bf706170fb6c.extra
[task 2018-07-26T20:52:01.278Z] 20:52:01  WARNING -  PROCESS-CRASH | dom/serviceworkers/test/test_fetch_event_with_thirdpartypref.html | application crashed [@ JS::ReadableStreamDefaultReaderRead(JSContext*, JS::Handle<JSObject*>)]
[task 2018-07-26T20:52:01.278Z] 20:52:01     INFO -  Crash dump filename: /tmp/tmpf7LkqC/72b1aacf-7582-1053-5efb-bf706170fb6c.dmp
[task 2018-07-26T20:52:01.279Z] 20:52:01     INFO -  Operating system: Android
[task 2018-07-26T20:52:01.279Z] 20:52:01     INFO -                    0.0.0 Linux 2.6.29-gea477bb #1 Wed Sep 26 11:04:45 PDT 2012 armv7l
[task 2018-07-26T20:52:01.279Z] 20:52:01     INFO -  CPU: arm
[task 2018-07-26T20:52:01.280Z] 20:52:01     INFO -       ARMv7 ARM Cortex-A8 features: swp,half,thumb,fastmult,vfpv2,edsp,neon,vfpv3
[task 2018-07-26T20:52:01.280Z] 20:52:01     INFO -       1 CPU
[task 2018-07-26T20:52:01.281Z] 20:52:01     INFO -  GPU: UNKNOWN
[task 2018-07-26T20:52:01.281Z] 20:52:01     INFO -  Crash reason:  SIGSEGV
[task 2018-07-26T20:52:01.281Z] 20:52:01     INFO -  Crash address: 0x0
[task 2018-07-26T20:52:01.281Z] 20:52:01     INFO -  Process uptime: not available
[task 2018-07-26T20:52:01.282Z] 20:52:01     INFO -  Thread 48 (crashed)
[task 2018-07-26T20:52:01.282Z] 20:52:01     INFO -   0  libxul.so!JS::ReadableStreamDefaultReaderRead(JSContext*, JS::Handle<JSObject*>) [RootingAPI.h:3268a54a7fab9e9565038d589229e9f2bf1cdff9 : 0 + 0x6]
[task 2018-07-26T20:52:01.283Z] 20:52:01     INFO -       r0 = 0x00000000    r1 = 0xb2b80778    r2 = 0xb2b80778    r3 = 0xb2b80778
[task 2018-07-26T20:52:01.283Z] 20:52:01     INFO -       r4 = 0x00000213    r5 = 0x60cfb060    r6 = 0x60cfb064    r7 = 0x60cfb038
[task 2018-07-26T20:52:01.283Z] 20:52:01     INFO -       r8 = 0x60cfb04c    r9 = 0x00000000   r10 = 0x60cfb058   r12 = 0x00000003
[task 2018-07-26T20:52:01.284Z] 20:52:01     INFO -       fp = 0x535384b1    sp = 0x60cfb020    lr = 0x55817ff7    pc = 0x55c2cf32
[task 2018-07-26T20:52:01.284Z] 20:52:01     INFO -      Found by: given as instruction pointer in context
[task 2018-07-26T20:52:01.285Z] 20:52:01     INFO -   1  libxul.so!mozilla::dom::FetchStreamReader::OnOutputStreamReady(nsIAsyncOutputStream*) [FetchStreamReader.cpp:3268a54a7fab9e9565038d589229e9f2bf1cdff9 : 201 + 0x3]
[task 2018-07-26T20:52:01.285Z] 20:52:01     INFO -       r4 = 0x5f013c80    r5 = 0x5f013ca0    r6 = 0x60cfb064    r7 = 0x60cfb0e0
[task 2018-07-26T20:52:01.286Z] 20:52:01     INFO -       r8 = 0x60cfb04c    r9 = 0x00000000   r10 = 0x60cfb058    fp = 0x535384b1
[task 2018-07-26T20:52:01.286Z] 20:52:01     INFO -       sp = 0x60cfb040    lr = 0x5473f7b3    pc = 0x5473f7b3
[task 2018-07-26T20:52:01.286Z] 20:52:01     INFO -      Found by: call frame info
[task 2018-07-26T20:52:01.287Z] 20:52:01     INFO -   2  libxul.so!nsOutputStreamReadyEvent::Run() [nsStreamUtils.cpp:3268a54a7fab9e9565038d589229e9f2bf1cdff9 : 193 + 0x3]
[task 2018-07-26T20:52:01.287Z] 20:52:01     INFO -       r4 = 0x60686210    r5 = 0x606861f0    r6 = 0x5bee7000    r7 = 0x60cfb0f0
[task 2018-07-26T20:52:01.287Z] 20:52:01     INFO -       r8 = 0x60cfb124    r9 = 0x80004005   r10 = 0x60cfb6df    fp = 0x5edb8030
[task 2018-07-26T20:52:01.288Z] 20:52:01     INFO -       sp = 0x60cfb0e8    lr = 0x53587c13    pc = 0x53587c13
[task 2018-07-26T20:52:01.288Z] 20:52:01     INFO -      Found by: call frame info
[task 2018-07-26T20:52:01.288Z] 20:52:01     INFO -   3  libxul.so!mozilla::dom::(anonymous namespace)::ExternalRunnableWrapper::WorkerRun(JSContext*, mozilla::dom::WorkerPrivate*) [WorkerPrivate.cpp:3268a54a7fab9e9565038d589229e9f2bf1cdff9 : 182 + 0x5]
[task 2018-07-26T20:52:01.288Z] 20:52:01     INFO -       r4 = 0x5bee7000    r5 = 0x00000001    r6 = 0x5bee7000    r7 = 0x60cfb100
[task 2018-07-26T20:52:01.289Z] 20:52:01     INFO -       r8 = 0x60cfb124    r9 = 0x80004005   r10 = 0x60cfb6df    fp = 0x5edb8030
[task 2018-07-26T20:52:01.289Z] 20:52:01     INFO -       sp = 0x60cfb0f8    lr = 0x54b6c83f    pc = 0x54b6c83f
[task 2018-07-26T20:52:01.289Z] 20:52:01     INFO -      Found by: call frame info
[task 2018-07-26T20:52:01.289Z] 20:52:01     INFO -   4  libxul.so!mozilla::dom::WorkerRunnable::Run() [WorkerRunnable.cpp:3268a54a7fab9e9565038d589229e9f2bf1cdff9 : 380 + 0x5]
[task 2018-07-26T20:52:01.290Z] 20:52:01     INFO -       r4 = 0x606865b0    r5 = 0x00000001    r6 = 0x5bee7000    r7 = 0x60cfb1e8
[task 2018-07-26T20:52:01.290Z] 20:52:01     INFO -       r8 = 0x60cfb124    r9 = 0x80004005   r10 = 0x60cfb6df    fp = 0x5edb8030
[task 2018-07-26T20:52:01.290Z] 20:52:01     INFO -       sp = 0x60cfb108    lr = 0x54b68875    pc = 0x54b68875
[task 2018-07-26T20:52:01.291Z] 20:52:01     INFO -      Found by: call frame info
[task 2018-07-26T20:52:01.291Z] 20:52:01     INFO -   5  libxul.so!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:3268a54a7fab9e9565038d589229e9f2bf1cdff9 : 1205 + 0x5]
[task 2018-07-26T20:52:01.291Z] 20:52:01     INFO -       r4 = 0x00000000    r5 = 0x5359ec81    r6 = 0x00000000    r7 = 0x60cfb6d0
[task 2018-07-26T20:52:01.291Z] 20:52:01     INFO -       r8 = 0x60cfb265    r9 = 0x60cfb268   r10 = 0x60cfb6df    fp = 0x5edb8030
[task 2018-07-26T20:52:01.292Z] 20:52:01     INFO -       sp = 0x60cfb1f0    lr = 0x535a58bf    pc = 0x535a58bf
Summary: Intermittent dom/serviceworkers/test/test_fetch_event_with_thirdpartypref.html | application crashed [@ JS::ReadableStreamDefaultReaderRead(JSContext*, JS::Handle<JSObject*>)] → Intermittent dom/serviceworkers/test/test_fetch_event_with_thirdpartypref.html, dom/serviceworkers/test/test_fetch_event.html | application crashed [@ JS::ReadableStreamDefaultReaderRead(JSContext*, JS::Handle<JSObject*>)]
I suspect that this bug is already fixed by bug 1387503. let's wait a couple of weeks to see if there is a lower number of crash reports.
This is what would happen if the argument `readerObj` is a nuked wrapper. We can easily make that a TypeError instead. Taking.
Assignee: nobody → jorendorff
Priority: P5 → P1
The patch did not fix the bug. I just submitted a diagnostic patch to try to learn more.
OK, the link in comment 24 has nine failures.

*   In seven cases, the object being passed to JS::ReadableStreamDefaultReaderRead
    is an Array, according to the log. For example:
    https://treeherder.mozilla.org/logviewer.html#?job_id=212546013&repo=try&lineNumber=6070
    https://treeherder.mozilla.org/logviewer.html#?job_id=212546104&repo=try&lineNumber=6139
    https://treeherder.mozilla.org/logviewer.html#?job_id=212546016&repo=try&lineNumber=6218

*   In one case, the object is a Promise.
    https://treeherder.mozilla.org/logviewer.html#?job_id=212546345&repo=try&lineNumber=5724

*   In the other case, the object is from a different compartment. We check that before checking the type,
    so I didn't get the object's class in the log for this one. But my guess is, same bug, different symptom.
    https://treeherder.mozilla.org/logviewer.html#?job_id=212546326&repo=try&lineNumber=1892

The reader comes from FetchStreamReader::mReader. FetchStreamReader's constructor default-constructs mReader, which initializes it to null. mReader is only ever assigned the result of JS::ReadableStreamGetReader.

Is JS::ReadableStreamGetReader really returning a Reader most of the time, but then an Array sometimes, and other objects other times... on Android only? I went and checked the source code just in case. This is impossible.

That leaves a few possibilities, all undefined behavior:

1.  Somehow mReader isn't really being initialized; the FetchStreamReader constructor isn't being called, or it's got a bug.

2.  This FetchStreamReader has been freed, and another object has been allocated at the same address, overwriting mReader. So we're chasing a dangling FetchStreamReader pointer to get here.

3.  The Reader object has been GC'd, and another object has been allocated at the same address, overwriting it with an Array, Promise, or something else. This means the Heap<JSObject*> FetchStreamReader::mReader isn't keeping the reader object rooted for some reason.

4.  The FetchStreamReader object is getting tenured (moved from the nursery by GC), but FetchStreamReader::mReader isn't being updated for some reason.

I can add more diagnostic output to distinguish these cases.
Cleaning the NI. Jason is working on this issue.
Flags: needinfo?(amarchesini)
+  LOG("FetchStreamReader::OnOutputStreamReady in\n");

Would be nice if you can add a "%p, this" here. I suspect that we are just reading random data here.

https://taskcluster-artifacts.net/Y5zSMorOQuG5gyE_uWUjVA/0/public/logs/live_backing.log

Here we see:

[task 2018-11-19T18:39:08.761Z] 18:39:08     INFO -  11-19 10:38:29.561 F/MOZ_Assert( 2887): FetchStreamReader::OnOutputStreamReady in
[task 2018-11-19T18:39:08.761Z] 18:39:08     INFO -  11-19 10:38:29.581 F/MOZ_Assert( 2887):   OnOutputStreamReady: FetchStreamReader::mReader is 0x655b93a0

That pointer is completely unknown. We've never allocated a reader in that address.
Attached patch fix.patch — — Splinter Review 
Could be just this missing?
Attachment #9026435 - Flags: review?(jorendorff)
Attachment #9026435 - Flags: review?(jorendorff) → review?(bugs)
Assignee: jorendorff → amarchesini
Attachment #9026435 - Flags: review?(bugs) → review+
Pushed by amarchesini@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/6ce084069f38
FetchStreamReader must call HoldJSObject()/DropJSObjects, r=smaug
Pushed by jorendorff@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/b4bc0fa77a1e
Safely handle nuked wrappers as arguments to stream-related JSAPI entry points. r=tcampbell
https://hg.mozilla.org/mozilla-central/rev/6ce084069f38
Status: NEW → RESOLVED
Closed: 6 years ago
status-firefox65: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla65
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: