use alt data to cache wasm code compiled from Response

REOPENED
Assigned to
(NeedInfo from)

Status

()

enhancement
REOPENED
9 months ago
3 days ago

People

(Reporter: luke, Assigned: luke, NeedInfo)

Tracking

(Blocks 1 bug, {leave-open})

unspecified
mozilla67
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox67 affected)

Details

Attachments

(19 attachments, 2 obsolete attachments)

2.37 KB, patch
Details | Diff | Splinter Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
18.99 KB, patch
baku
: review+
Details | Diff | Splinter Review
920 bytes, patch
baku
: review+
Details | Diff | Splinter Review
9.16 KB, patch
lth
: review+
Details | Diff | Splinter Review
19.48 KB, patch
Details | Diff | Splinter Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
Assignee

Description

9 months ago
Since WebAssembly.{compileStreaming,instantiateStreaming} both take a Response, we have a link back to the original cache entry, so we can use the alt-data API (currently used by the JS bytecode cache) to cache machine code.  Later with wasm-esm integration (https://github.com/WebAssembly/esm-integration/tree/master/proposals/esm-integration), we could additionally plug in via the nsScriptLoader.

This is intended to subsume the explicit IDB caching which was recently removed from the wasm spec (bug 1469395) and beat the implicit asm.js caching we do in dom/asmjscache.  The core (de)serialization machinery is still present (and actively used by asm.js caching).

The existing wasm streaming support this would build on is FetchUtil::StreamResponseToJS:
  https://searchfox.org/mozilla-central/source/dom/fetch/FetchUtil.cpp#530
and the alt-data interface we need to use is nsICacheInfoChannel, which lets us get a stream for the serialized module.

It looks like we'll need some modest changes to the alt-data API: bug 1487100.  In the meantime, we can get something sorta-working by unconditionally setting the preferred alt-data-type "wasm" in fetch().

When alt-data is implemented for the DOM Cache API (bug 1336199), this same support should Just Work for DOM Cache / ServiceWorker which would perhaps provide access to larger quota and lower churn.
Assignee

Updated

9 months ago
Depends on: 1487475
Assignee

Updated

9 months ago
Depends on: 1330661
Assignee

Updated

7 months ago
Depends on: 1500203
Assignee

Comment 1

6 months ago
Ok, so I finally started to play around with the awesome new functionality added by bug 1487100.

Valentin: this tiny patch requests alt-data for "application/wasm", which I would expect to attach an nsICacheInfoChannel to the InternalRequest.  The fprintf() before AsyncOpen2() shows I'm calling PreferAlternativeDataType() for the fetch() in question, but the fprintf() on the consuming end indicates there is not an nsICacheInfoChannel.

I fully expect I'm doing something silly or expecting to find the nsICacheInfoChannel in the wrong place.  Can you see anything wrong?

I'm using https://lukewagner.github.io/wasm-mime-type to test this path.
Assignee: nobody → luke
Flags: needinfo?(valentin.gosu)
I think Nicolas can help here.
Flags: needinfo?(valentin.gosu) → needinfo?(nicolas.b.pierron)
Comment on attachment 9025507 [details] [diff] [review]
request-alt-data-for-wasm (test)

Review of attachment 9025507 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/fetch/FetchDriver.cpp
@@ +755,5 @@
>    } else {
> +    nsCOMPtr<nsICacheInfoChannel> cic = do_QueryInterface(chan);
> +    if (cic) {
> +      fprintf(stderr, "### PREFERRING for %s !\n", url.get());
> +      cic->PreferAlternativeDataType(NS_LITERAL_CSTRING("wasm"), NS_LITERAL_CSTRING("application/wasm"));

I do not know much of this code base, but …

My guess would be that you have to create an AlternativeDataStreamListener (as done as few lines above) and set the mAltDataListener field in order to pipe the input stream of the nsICacheInfoChannel through the fetch API.
Forwarding the need-info to Ben Kelly as he reviewed this implementation and might know better where to patch the default case for setting the preferred alternated data type.
Flags: needinfo?(nicolas.b.pierron) → needinfo?(ben)
Just heard that Ben left Mozilla, so based on Nathan feedback, I will re-forward to Andrew / Andrea.
Flags: needinfo?(bugmail)
Flags: needinfo?(ben)
Flags: needinfo?(amarchesini)
I think Eden is working on the alternate stream support in Cache API and may also have input here.
Yes, I'm going to redirect to Eden for his expertise here.
Flags: needinfo?(bugmail) → needinfo?(echuang)
Flags: needinfo?(amarchesini)
Assignee

Comment 8

6 months ago
Learning a bit more, I see I was misunderstanding how this was supposed to work.
Flags: needinfo?(echuang)
Assignee

Comment 9

5 months ago
To summarize, given an InternalResponse, it's not currently possible to write the alt-data output stream because there is no way to get the nsICacheInfoChannel (if there is one).

Discussing options with baku at the all-hands:
 - One option would be to set InternalResponse::mCacheInfoChannel not just when the alt-data cache entry *already* exists, but also when the content-type specified by preferAlternativeDataTypes() matches, so that alt-data can be written.
 - Another option would be to change the nsIInputStream body produced by fetch() so that one could QI it to something providing the nsICacheInfoChannel.  (Maybe this allows killing InternalResponse::mCacheInfoChannel altogether?)
Flags: needinfo?(amarchesini)
Flags: needinfo?(amarchesini)
Assignee: luke → amarchesini

Comment 13

3 months ago
Pushed by amarchesini@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/1e97c3573ce6
Expose nsICacheInfoChannel in Respose object for wasm content-type, r=valentin,nbp
https://hg.mozilla.org/integration/autoland/rev/a8406df01e95
nsICacheInfoChannel.preferAlternativeDataType() should expose alt-data as optional if required, r=valentin
https://hg.mozilla.org/integration/autoland/rev/831ac8c662c0
nsICacheInfoChannel.preferAlternativeDataType() should expose alt-data as optional if required - tests, r=valentin
Flags: needinfo?(amarchesini)

Comment 15

3 months ago
Pushed by amarchesini@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/6179d66e457f
Expose nsICacheInfoChannel in Respose object for wasm content-type, r=valentin,nbp
https://hg.mozilla.org/integration/autoland/rev/94e827a2e0d1
nsICacheInfoChannel.preferAlternativeDataType() should expose alt-data as optional if required, r=valentin
https://hg.mozilla.org/integration/autoland/rev/834182e86ef2
nsICacheInfoChannel.preferAlternativeDataType() should expose alt-data as optional if required - tests, r=valentin

Comment 16

3 months ago
bugherder
Status: NEW → RESOLVED
Last Resolved: 3 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla67
Assignee

Comment 17

3 months ago

Oops, that should've probably been leave-open :) With baku's patch landed, I just have to write a final patch plugging these two things together.

Assignee: amarchesini → luke
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Assignee

Comment 18

3 months ago

Almost done, but the current issue I'm running into is that OpenAlternativeOutputStream() asserts NS_IsMainThread() (HttpChannelChild.cpp:3083) and the ideal time to call OpenAlternativeOutputStream() is on a random helper thread when wasm tier-2 compilation completes. How hard is this limitation to remove?

Flags: needinfo?(amarchesini)
Assignee

Comment 19

3 months ago

Another question: is there any way to indicate failure to write the alt-data file, after OpenAlternativeOutputStream() succeeds? The only current usage in ScriptLoader.cpp makes a single Write() and implicitly assumes:

  • the Write() writes the entire payload atomically
  • calling Close() if Write() fails is correctly interpreted as failure

Are both these assumptions valid? This seems a bit fragile; is there any other way to signal failure to write given only an nsIOutputStream. I'm not too familiar with streams; maybe dropping the last refcount on the nsIOutputStream without having called Close()?

Noticing that CacheFileOutputStream is an nsIAsyncOutputStream, which has CloseWithStatus(), which is a way to indicate failure, I tried writing a patch that propagates the nsIAsyncOutputStream all the way into openAlternativeOutputStream()'s signature, but I ran into trouble with AltDataOutputStreamChild, which is not an nsIAsyncOutputStream.

(In reply to Luke Wagner [:luke] from comment #18)

How hard is this limitation to remove?

At the moment, PHttpChannel is managed by PNecko which is managed by PContent and all of this is main-thread only.
This is hard to be changed soon-ish.

Another question: is there any way to indicate failure to write the alt-data file, after OpenAlternativeOutputStream() succeeds?

You can do several write() calls and then a final close(). If a writing operation, on the parent side fails, the information is propagated asynchronously back to the child actor. Any following writing/flushing/closing op will report the known error.

If you want to propagate an error from the child actor, this is not supported. And yes, using nsIAsyncOutputStream seems a good solution. The missing piece is that we need to inform CacheEntry about this failure. NI Valentin for this part.

Flags: needinfo?(amarchesini) → needinfo?(valentin.gosu)

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

If you want to propagate an error from the child actor, this is not supported. And yes, using nsIAsyncOutputStream seems a good solution. The missing piece is that we need to inform CacheEntry about this failure. NI Valentin for this part.

I agree, we need to implement nsIAsyncOutputStream for AltDataOutputStreamChild

Flags: needinfo?(valentin.gosu)

I agree, we need to implement nsIAsyncOutputStream for AltDataOutputStreamChild

And we also need to introduce a way to abort the writing operation in CacheEntry. Does this already exist?

Flags: needinfo?(valentin.gosu)

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

I agree, we need to implement nsIAsyncOutputStream for AltDataOutputStreamChild

And we also need to introduce a way to abort the writing operation in CacheEntry. Does this already exist?

Clearing the alt-data should already be done when calling CloseWithStatus(error).

https://searchfox.org/mozilla-central/rev/dbddac86aadf1d4871fb350bbe66db43728a9f81/netwerk/cache2/CacheFileOutputStream.cpp#186,218

Flags: needinfo?(valentin.gosu)
Assignee

Comment 25

3 months ago

(In reply to Andrea Marchesini [:baku] from comment #20)
Thanks!

(In reply to Luke Wagner [:luke] from comment #18)
At the moment, PHttpChannel is managed by PNecko which is managed by PContent and all of this is main-thread only.
This is hard to be changed soon-ish.

Ok, makes sense, I can fix it on my end. So after dispatching a runnable to the main thread to open the alt-data stream, because the nsIOutputStream is blocking, I probably need to dispatch to some background thread to do the Write(), right? Is there any utility service to do this that doesn't introduce an extra copy (b/c this is possibly a many-MB payload)? Otherwise, I'd probably just dispatch my same runnable to some background thread where I can do the synchronous Write(); what's a good thread pool to use for this?

Flags: needinfo?(amarchesini)
Flags: needinfo?(amarchesini)

Luke and I discussed this issue on IRC.

Assignee

Comment 27

3 months ago
Posted patch close-with-status (obsolete) — Splinter Review

With nsIAsyncOutputStream present everywhere (thanks baku!), this patch changes the static return type of openAlternativeOutputStream() to return an nsIAsyncOutputStream. This allows me to remove the aforementioned sketchy assumptions in ScriptLoader.cpp so that we CloseWithStatus(NS_OK) iff the output was written successfully.

Attachment #9047165 - Flags: review?(amarchesini)
Assignee

Comment 28

3 months ago

(Tweaked)

Attachment #9047165 - Attachment is obsolete: true
Attachment #9047165 - Flags: review?(amarchesini)
Attachment #9047166 - Flags: review?(amarchesini)
Assignee

Comment 29

3 months ago

The current JSBC code seems to make this assumption...

Attachment #9047167 - Flags: review?(amarchesini)

Comment 30

3 months ago
Pushed by amarchesini@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/169c6e292149
AltDataOutputStreamChild must be nsIAsyncOutputStream, r=valentin
Comment on attachment 9047166 [details] [diff] [review]
close-with-status

Review of attachment 9047166 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/script/ScriptLoader.cpp
@@ +2880,5 @@
>      return;
>    }
>    MOZ_ASSERT(output);
> +
> +  {

Write a comment saying that this block is done just to call Close() before releasing bytecodefailed.

::: netwerk/base/nsICacheInfoChannel.idl
@@ +151,5 @@
>     * The consumer may choose to replace the saved alt representation.
>     * Opening the output stream will fail if there are any open input streams
> +   * reading the already saved alt representation. After successfully opening
> +   * an output stream, the client must signal failure to write a complete
> +   * alternative representation via CloseWithStatus(NS_ERROR_*).

No, this is wrong. After successfully opening an output stream, the client must signal _success_ to write a complete alternative rappresentation via CloseWithStatus(NS_OK). If an error is passed as argument, the alternative stream is be aborted and the data not saved.
Attachment #9047166 - Flags: review?(amarchesini) → review+
Comment on attachment 9047167 [details] [diff] [review]
assert-write-length

Review of attachment 9047167 [details] [diff] [review]:
-----------------------------------------------------------------

This is OK, but in theory, nothing guarantees that a nsIOutputStream::Write() writes the whole buffer. It could write only part of it and then ask you to call ::AsyncWait(). It's an nsIAsyncOutputStream in the end, right?
Attachment #9047167 - Flags: review?(amarchesini) → review+
Assignee

Comment 33

3 months ago

(In reply to Andrea Marchesini [:baku] from comment #32)
Right, I agree, but the code is already written with this assumption; the alternative would be to generalize it with a loop, but it's never used (or testable) then.

Assignee

Comment 34

3 months ago

This patch hands over ownership of the Vector<uint8> so the callee can hold onto it when dispatching to the main thread to write the cache file.

Attachment #9047245 - Flags: review?(lhansen)
Assignee

Comment 35

3 months ago

This patch (which applies on top of the other 3) creates the wasm alt-data stream and writes it to that alt-data output stream. The patch doesn't implement reading wasm alt-data, though; it just ignores the alt-data and reads the unfiltered body as before. IIUC, because deliverAltData is set to false, this should still Just Work, and for small wasm modules it does.

But for big wasm modules, the unfiltered body produces bytes that are neither the original response nor the serialized bytes. A simple tester app that shows this is: https://lukewagner.github.io/test-streaming/

If you apply my patches and click "Compile Small" twice, it works both times. But if you click "Compile Big" twice, it fails reliably the second and all future times until the cache is cleared. (Note you need to wait for the "### Stored optimized encoding" printf() to know that the alt-data was written; this can take a while in debug builds.)

The "Print" buttons print the bytes of the fetch() as an ArrayBuffer. For "Print Small", we see the same bytes before and after "Compile Small". However, "Print Big" shows different bytes before and after.

So something weird is happening for large (~34mb) alt-data. Any ideas?

Flags: needinfo?(amarchesini)
Comment on attachment 9047245 [details] [diff] [review]
pass-bytes-ownership

Review of attachment 9047245 [details] [diff] [review]:
-----------------------------------------------------------------

Some of the formatting changes will likely be undone by clang-format when it rides over the code base again.
Attachment #9047245 - Flags: review?(lhansen) → review+

Comment 37

3 months ago
bugherder
Status: REOPENED → RESOLVED
Last Resolved: 3 months ago3 months ago
Resolution: --- → FIXED
Assignee

Updated

3 months ago
Status: RESOLVED → REOPENED
Keywords: leave-open
Resolution: FIXED → ---

Comment 38

3 months ago
Pushed by lwagner@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/bd4cd4017fd4
Use CloseWithStatus in ScriptLoader.cpp to indicate failure (r=baku)

Comment 39

3 months ago
Pushed by lwagner@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/27986829a160
MOZ_RELEASE_ASSERT existing implicit assumption about alt-data Write() in ScriptLoader.cpp (r=baku)

First of all, sorry for the delay. I have seen the patch landed, is this NI still valid?

Flags: needinfo?(amarchesini) → needinfo?(luke)

Comment 43

2 months ago
Pushed by lwagner@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/1e5191f8b8b5
Baldr: pass ownership of optimized encoding bytes (r=lth)
Assignee

Comment 44

2 months ago

Thanks and no worries; I've been distracted away from this patch too. As of comment 43, all the pre-req patches have been pushed and so the patch in comment 35 applies to inbound tip. I just tried again and the same issues still appears.

Flags: needinfo?(luke) → needinfo?(amarchesini)
Assignee

Comment 45

2 months ago

Different question: it looks like getAltDataInputStream() doesn't guarantee that the given aReceiver is called in all cases: it's only called if the stream is successfully opened and thus there is no way to detect and report the error case. Is there something I'm missing here?

Another question: before getAltDataInputStream() is called, will the parent have already speculatively started sending bytes to the child for the original input stream? Or, does it wait until the child process actually requests it?

Assignee

Comment 46

2 months ago

(In reply to Luke Wagner [:luke] from comment #45)

Different question: it looks like getAltDataInputStream() doesn't guarantee that the given aReceiver is called in all cases: it's only called if the stream is successfully opened and thus there is no way to detect and report the error case.

FWIW, a really ideal interface would be for getAltDataInputStream() to synchronously return the new nsIInputStream and signal parent or IPC errors by having the stream fail with an error. That way the JSStreamConsumer can be Start()ed with an nsIInputStream in both the cached and uncached cases.

Comment 49

2 months ago
Pushed by amarchesini@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/f2860ee8dd24
nsHttpChannel should return the Content-Length even when alt-data is available if not delivered, r=valentin

Luke, I submitted a fix. When that will be in m-c, can you check all again and, in case, resolve this bug as fixed?
We also need a test for this issue. Thanks!

Flags: needinfo?(amarchesini) → needinfo?(luke)
Assignee

Comment 52

2 months ago

Works great, thanks!

Flags: needinfo?(luke)

Luke and I discussed how to remove the async aspect of getAltDataInputStream(). The idea is to send the alt-data stream from parent to child in a delay-start mode. See https://searchfox.org/mozilla-central/rev/a7315d78417179b151fef6108f2bce14786ba64d/ipc/glue/IPCStreamUtils.h

This would work. My only concern is that we need to send 1 stream for each preferred alt-data stream. Probably this is fine, but I want to check it more before implementing it.

Assignee

Comment 54

2 months ago

Thanks! Since there can only be 1 alt-data file, even if multiple alt-data-types were preferred, it seems like we'd only need to send over the at-most-1 stream that matched nsICacheInfoChannel.alternateDataType.

Comment 57

2 months ago
Pushed by amarchesini@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/0ee68b246224
nsICacheInfoChannel.originalInputStream as attribute, r=valentin
https://hg.mozilla.org/integration/autoland/rev/74ae5929e387
nsICacheInfoChannel.alternativeDataInputStream as attribute, r=valentin

Backed out 2 changesets (Bug 1487113) for causing xpcshell failure in netwerk/test/unit_ipc/test_alt-data_cross_process_wrap.js CLOSED TREE

Failure: https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=testfailed%2Cbusted%2Cexception&classifiedState=unclassified&selectedJob=237282804

Log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=237282804&repo=autoland&lineNumber=2103

[task 2019-04-01T09:49:47.482Z] 09:49:47 INFO - TEST-START | security/manager/ssl/tests/unit/test_validity.js
[task 2019-04-01T09:49:48.286Z] 09:49:48 INFO - TEST-PASS | security/manager/ssl/tests/unit/test_validity.js | took 801ms
[task 2019-04-01T09:49:48.287Z] 09:49:48 INFO - Retrying tests that failed when run in parallel.
[task 2019-04-01T09:49:48.295Z] 09:49:48 INFO - TEST-START | netwerk/test/unit_ipc/test_alt-data_cross_process_wrap.js
[task 2019-04-01T09:54:48.293Z] 09:54:48 WARNING - TEST-UNEXPECTED-TIMEOUT | netwerk/test/unit_ipc/test_alt-data_cross_process_wrap.js | Test timed out
[task 2019-04-01T09:54:48.295Z] 09:54:48 INFO - TEST-INFO took 300000ms
[task 2019-04-01T09:54:48.296Z] 09:54:48 INFO - >>>>>>>
[task 2019-04-01T09:54:48.298Z] 09:54:48 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2019-04-01T09:54:48.300Z] 09:54:48 INFO - (xpcshell/head.js) | test pending (2)
[task 2019-04-01T09:54:48.302Z] 09:54:48 INFO - (xpcshell/head.js) | test pending (3)
[task 2019-04-01T09:54:48.308Z] 09:54:48 INFO - (xpcshell/head.js) | test run in child pending (4)
[task 2019-04-01T09:54:48.308Z] 09:54:48 INFO - (xpcshell/head.js) | test MAIN run_test finished (4)
[task 2019-04-01T09:54:48.309Z] 09:54:48 INFO - running event loop
[task 2019-04-01T09:54:48.310Z] 09:54:48 INFO - "CONSOLE_MESSAGE: (info) No chrome package registered for chrome://branding/locale/brand.properties"
[task 2019-04-01T09:54:48.310Z] 09:54:48 INFO - CHILD-TEST-STARTED
[task 2019-04-01T09:54:48.311Z] 09:54:48 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2019-04-01T09:54:48.311Z] 09:54:48 INFO - (xpcshell/head.js) | test pending (2)
[task 2019-04-01T09:54:48.312Z] 09:54:48 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2019-04-01T09:54:48.312Z] 09:54:48 INFO - running event loop
[task 2019-04-01T09:54:48.313Z] 09:54:48 INFO - "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "/builds/worker/workspace/build/tests/xpcshell/head.js" line: 352}]"
[task 2019-04-01T09:54:48.313Z] 09:54:48 INFO - "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "/builds/worker/workspace/build/tests/xpcshell/head.js" line: 352}]"
[task 2019-04-01T09:54:48.314Z] 09:54:48 INFO - TEST-PASS | netwerk/test/unit_ipc/test_alt-data_cross_process_wrap.js | undefined assertion name - 13 == 13
[task 2019-04-01T09:54:48.315Z] 09:54:48 INFO - TEST-PASS | netwerk/test/unit_ipc/test_alt-data_cross_process_wrap.js | readServerContent - [readServerContent : 96] "response body" == "response body"
[task 2019-04-01T09:54:48.315Z] 09:54:48 INFO - TEST-PASS | netwerk/test/unit_ipc/test_alt-data_cross_process_wrap.js | readServerContent - [readServerContent : 97] "" == ""
[task 2019-04-01T09:54:48.316Z] 09:54:48 INFO - (xpcshell/head.js) | test pending (2)
[task 2019-04-01T09:54:48.317Z] 09:54:48 INFO - (xpcshell/head.js) | test flushAndOpenAltChannel pending (3)
[task 2019-04-01T09:54:48.318Z] 09:54:48 INFO - (xpcshell/head.js) | test finished (3)
[task 2019-04-01T09:54:48.318Z] 09:54:48 INFO - (xpcshell/head.js) | test finished (3)
[task 2019-04-01T09:54:48.319Z] 09:54:48 INFO - (xpcshell/head.js) | test pending (3)
[task 2019-04-01T09:54:48.320Z] 09:54:48 INFO - (xpcshell/head.js) | test flushAndOpenAltChannel finished (3)
[task 2019-04-01T09:54:48.321Z] 09:54:48 INFO - (xpcshell/head.js) | test finished (2)
[task 2019-04-01T09:54:48.321Z] 09:54:48 INFO - TEST-PASS | netwerk/test/unit_ipc/test_alt-data_cross_process_wrap.js | undefined assertion name - 10 == 10
[task 2019-04-01T09:54:48.322Z] 09:54:48 INFO - TEST-PASS | netwerk/test/unit_ipc/test_alt-data_cross_process_wrap.js | readAltContent - [readAltContent : 131] true == true
[task 2019-04-01T09:54:48.322Z] 09:54:48 INFO - TEST-PASS | netwerk/test/unit_ipc/test_alt-data_cross_process_wrap.js | readAltContent - [readAltContent : 132] "text/binary" == "text/binary"
[task 2019-04-01T09:54:48.323Z] 09:54:48 INFO - TEST-PASS | netwerk/test/unit_ipc/test_alt-data_cross_process_wrap.js | readAltContent - [readAltContent : 133] "!@#$%^&()" == "!@#$%^&()"
[task 2019-04-01T09:54:48.324Z] 09:54:48 INFO - (xpcshell/head.js) | test pending (2)
[task 2019-04-01T09:54:48.324Z] 09:54:48 INFO - (xpcshell/head.js) | test finished (2)
[task 2019-04-01T09:54:48.325Z] 09:54:48 INFO - TEST-PASS | netwerk/test/unit_ipc/test_alt-data_cross_process_wrap.js | load_channel - [load_channel : 31] "http://localhost:33545/content" == true
[task 2019-04-01T09:54:48.325Z] 09:54:48 INFO - TEST-PASS | netwerk/test/unit_ipc/test_alt-data_cross_process_wrap.js | undefined assertion name - 13 == 13
[task 2019-04-01T09:54:48.325Z] 09:54:48 INFO - TEST-PASS | netwerk/test/unit_ipc/test_alt-data_cross_process_wrap.js | readTextData - [readTextData : 48] "" == ""
[task 2019-04-01T09:54:48.325Z] 09:54:48 INFO - TEST-PASS | netwerk/test/unit_ipc/test_alt-data_cross_process_wrap.js | readTextData - [readTextData : 49] "response body" == "response body"
[task 2019-04-01T09:54:48.326Z] 09:54:48 INFO - (xpcshell/head.js) | test pending (2)
[task 2019-04-01T09:54:48.326Z] 09:54:48 WARNING - TEST-UNEXPECTED-FAIL | netwerk/test/unit_ipc/test_alt-data_cross_process_wrap.js | - NS_ERROR_NOT_AVAILABLE: Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsICacheInfoChannel.openAlternativeOutputStream]
[task 2019-04-01T09:54:48.327Z] 09:54:48 INFO - readTextData/<@/builds/worker/workspace/build/tests/xpcshell/tests/netwerk/test/unit_ipc/test_alt-data_cross_process_wrap.js:54:17
[task 2019-04-01T09:54:48.328Z] 09:54:48 INFO - run@/builds/worker/workspace/build/tests/xpcshell/head.js:688:9
[task 2019-04-01T09:54:48.328Z] 09:54:48 INFO - _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:227:6
[task 2019-04-01T09:54:48.329Z] 09:54:48 INFO - _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:529:5

Flags: needinfo?(luke)

Comment 59

2 months ago
Backout by shindli@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/16b03064b09d
Backed out 2 changesets for causing xpcshell failure in netwerk/test/unit_ipc/test_alt-data_cross_process_wrap.js CLOSED TREE
Assignee

Comment 60

2 months ago

redirecting ni? to author. btw, thanks for the patch baku!

Flags: needinfo?(luke) → needinfo?(amarchesini)

I discussed this issue with Valentin. The problem seems to be that if we retrieve the alt-data inputstream from a CacheEntry, then we are not able to obtain the output stream too. This means that, if we already have an alt-data, and with my patch, the inputStream is available from nsIHttpChannel, it's not possible to overwrite the data writing into the output stream.

Can you confirm this? Is it something we can fix it in necko?

Flags: needinfo?(amarchesini) → needinfo?(valentin.gosu)

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

Can you confirm this? Is it something we can fix it in necko?

That is correct, and I don't think there's a way to fix it in necko without a major rewrite of the cache.

The reason for this is that each CacheFile keeps track of inputStreams and outputStreams to it to allow multiple readers from the cache entry. So for example if one load of a.html is in progress, then another load of a.html can simply stream it from the cache, while the first load is writing it from the network. But a third load can't overwrite that entry while other inputStreams are opened to it - this is why we can't overwrite the alt-data while we already have an alt-data inputStream still open.

Flags: needinfo?(valentin.gosu)
Assignee

Comment 63

2 months ago

Independent of above, I have a working patch stack and so I'm writing tests and I ran into a weird case: if I Response.clone(), and then compile both Responses (either at the same time or in sequence), both have an nsICacheInfoChannel which claims matching alt-data, but the second Response's nsIInputStream is empty (specifically, on the first call to nsPipeInputStream::AsyncWait(), Status(mon) == NS_BASE_STREAM_CLOSED and so onInputStreamReady() is synchronously called with nsIInputStream::Available() returning 0). Maybe simple bug?

Flags: needinfo?(amarchesini)

Can you give me a test + your patch? I'll work on a fix.

Flags: needinfo?(amarchesini) → needinfo?(luke)
Assignee

Comment 69

2 months ago

Ok, thanks! If you apply these patches (and/or review them; I think they're ready :), which are based on your two unlanded patches, then the mochitest dom/promise/tests/test_webassembly_compile.html has two tests, compileCachedBothClonesHitCache and compileCachedCacheThroughClone, that hit this case and crash/fail (you can isolate them by commenting out everything else in the final tests array at the end of the file).

Flags: needinfo?(luke)

Comment 70

a month ago
Pushed by lwagner@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/c910aaceb2aa
Use NS_MakeSyncNonBlockingInputStream in JSStreamConsumer (r=baku)
https://hg.mozilla.org/integration/mozilla-inbound/rev/d078014dcad1
Baldr: correctly deserialize name section index (r=lth)
https://hg.mozilla.org/integration/mozilla-inbound/rev/bd5eba0629e6
Baldr: add logging/testing functions for (de)serialization (r=lth)
Assignee

Comment 72

a month ago

(Note: now just one patch to apply to tip to test the failure in the new test_webassembly_compile.html mochitest. Edit: oops, in addition to the two patches that were backed out in comment 59.)

Flags: needinfo?(amarchesini)
Assignee

Updated

a month ago
Blocks: 1545131
Assignee

Comment 74

a month ago

One interesting thing I noticed is that, without bug 1545131, the alt data entry for web.autocad.com is 148mb. When attempting to store this, nsICacheInfoChannel::OpenAlternativeOutputStream() succeeds (with the declared length of 148mb), which is a bit surprising; from the comment, it seemed like this would fail since the cache file is way beyond the size limit.

I just landed a couple of new patches. If/when they will be in m-c, Luke, can you test again if there are issues with your code?

Flags: needinfo?(amarchesini) → needinfo?(luke)

Comment 78

4 days ago
Pushed by amarchesini@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e6f579752678
nsICacheInfoChannel.originalInputStream as attribute, r=valentin
https://hg.mozilla.org/integration/autoland/rev/dce59b615568
nsICacheInfoChannel.alternativeDataInputStream as attribute, r=valentin

Comment 79

3 days ago
Backout by dvarga@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/3a8b999553a4
Backed out 2 changesets for mochitest failure at dom/base/test/test_script_loader_js_cache.html.

Backed out 2 changesets (Bug 1487113) for mochitest failure at dom/base/test/test_script_loader_js_cache.html.

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception&searchStr=mochitest-e10s&revision=dce59b6155685fb271e2affd84e5e4b44e0ec8d5&selectedJob=247375112

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=247375112&repo=autoland&lineNumber=4102
and
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=247399578&repo=autoland&lineNumber=2451

Backout link: https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception&classifiedState=unclassified&searchStr=tp6m&revision=3a8b999553a4e672b7895b8c8aabd458afbbe3a1

[task 2019-05-20T16:34:55.323Z] 16:34:55     INFO -  1686 INFO TEST-OK | dom/serviceworkers/test/test_scopes.html | took 220ms
[task 2019-05-20T16:34:55.323Z] 16:34:55     INFO -  1687 INFO TEST-START | dom/serviceworkers/test/test_script_loader_intercepted_js_cache.html
[task 2019-05-20T16:34:55.323Z] 16:34:55     INFO -  1688 INFO TEST-UNEXPECTED-FAIL | dom/serviceworkers/test/test_script_loader_intercepted_js_cache.html | Test for saving and loading bytecode in/from the necko cache - Test for saving and loading bytecode in/from the necko cache: assert_equals: [4] ScriptLoadRequest status after same SRI hash expected "bytecode_exec" but got "fallback_bytecode_saved"
[task 2019-05-20T16:34:55.323Z] 16:34:55     INFO -  1689 INFO TEST-PASS | dom/serviceworkers/test/test_script_loader_intercepted_js_cache.html | Test for saving and loading bytecode in/from the necko cache - Test for saving and loading bytecode in/from the necko cache: Elided 1 passes or known failures.
[task 2019-05-20T16:34:55.323Z] 16:34:55     INFO -  1690 INFO TEST-OK | dom/serviceworkers/test/test_script_loader_intercepted_js_cache.html | took 300ms
[task 2019-05-20T16:34:55.323Z] 16:34:55     INFO -  1691 INFO TEST-START | dom/serviceworkers/test/test_service_worker_allowed.html
[task 2019-05-20T16:34:55.323Z] 16:34:55     INFO -  Buffered messages logged at 16:34:48
[task 2019-05-20T16:34:55.323Z] 16:34:55     INFO -  1692 INFO TEST-PASS | dom/serviceworkers/test/test_service_worker_allowed.html | Registration should fail
[task 2019-05-20T16:34:55.324Z] 16:34:55     INFO -  1693 INFO TEST-PASS | dom/serviceworkers/test/test_service_worker_allowed.html | Registration should fail
[task 2019-05-20T16:34:55.324Z] 16:34:55     INFO -  1694 INFO TEST-PASS | dom/serviceworkers/test/test_service_worker_allowed.html | Registration should fail
[task 2019-05-20T16:34:55.324Z] 16:34:55     INFO -  1695 INFO TEST-PASS | dom/serviceworkers/test/test_service_worker_allowed.html | Registration should finish successfully
[task 2019-05-20T16:34:55.324Z] 16:34:55     INFO -  1696 INFO TEST-PASS | dom/serviceworkers/test/test_service_worker_allowed.html | Registration should finish successfully
[task 2019-05-20T16:34:55.324Z] 16:34:55     INFO -  Buffered messages finished
[task 2019-05-20T16:34:55.324Z] 16:34:55     INFO -  1697 INFO TEST-UNEXPECTED-FAIL | dom/serviceworkers/test/test_service_worker_allowed.html | This test left a service worker registered without cleaning it up
[task 2019-05-20T16:34:55.324Z] 16:34:55     INFO -      SimpleTest.ok@SimpleTest/SimpleTest.js:275:18
[task 2019-05-20T16:34:55.324Z] 16:34:55     INFO -      afterCleanup@SimpleTest/SimpleTest.js:1190:28
[task 2019-05-20T16:34:55.324Z] 16:34:55     INFO -      executeCleanupFunction@SimpleTest/SimpleTest.js:1230:13
[task 2019-05-20T16:34:55.324Z] 16:34:55     INFO -      SimpleTest.finish@SimpleTest/SimpleTest.js:1249:5
[task 2019-05-20T16:34:55.324Z] 16:34:55     INFO -  1698 INFO TEST-UNEXPECTED-FAIL | dom/serviceworkers/test/test_service_worker_allowed.html | Left over worker: http://mochi.test:8888/tests/dom/serviceworkers/test/fetch.js (scope: http://mochi.test:8888/tests/dom/serviceworkers/test/)
[task 2019-05-20T16:34:55.325Z] 16:34:55     INFO -      SimpleTest.ok@SimpleTest/SimpleTest.js:275:18
[task 2019-05-20T16:34:55.325Z] 16:34:55     INFO -      afterCleanup@SimpleTest/SimpleTest.js:1192:32
[task 2019-05-20T16:34:55.325Z] 16:34:55     INFO -      executeCleanupFunction@SimpleTest/SimpleTest.js:1230:13
[task 2019-05-20T16:34:55.325Z] 16:34:55     INFO -      SimpleTest.finish@SimpleTest/SimpleTest.js:1249:5
[task 2019-05-20T18:33:15.121Z] 18:33:15     INFO -  SUMMARY: AddressSanitizer: heap-use-after-free /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/ipc/ProtocolUtils.h:305:39 in Manager
[task 2019-05-20T18:33:15.121Z] 18:33:15     INFO -  Shadow bytes around the buggy address:
[task 2019-05-20T18:33:15.121Z] 18:33:15     INFO -    0x0c2c8001db20: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[task 2019-05-20T18:33:15.122Z] 18:33:15     INFO -    0x0c2c8001db30: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[task 2019-05-20T18:33:15.122Z] 18:33:15     INFO -    0x0c2c8001db40: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[task 2019-05-20T18:33:15.122Z] 18:33:15     INFO -    0x0c2c8001db50: 00 00 00 00 00 02 fa fa fa fa fa fa fa fa fa fa
[task 2019-05-20T18:33:15.123Z] 18:33:15     INFO -    0x0c2c8001db60: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
[task 2019-05-20T18:33:15.123Z] 18:33:15     INFO -  =>0x0c2c8001db70: fd fd[fd]fd fd fd fd fd fd fd fd fd fd fd fd fd
[task 2019-05-20T18:33:15.123Z] 18:33:15     INFO -    0x0c2c8001db80: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
[task 2019-05-20T18:33:15.124Z] 18:33:15     INFO -    0x0c2c8001db90: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
[task 2019-05-20T18:33:15.124Z] 18:33:15     INFO -    0x0c2c8001dba0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
[task 2019-05-20T18:33:15.124Z] 18:33:15     INFO -    0x0c2c8001dbb0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fa
[task 2019-05-20T18:33:15.124Z] 18:33:15     INFO -    0x0c2c8001dbc0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
[task 2019-05-20T18:33:15.124Z] 18:33:15     INFO -  Shadow byte legend (one shadow byte represents 8 application bytes):
[task 2019-05-20T18:33:15.125Z] 18:33:15     INFO -    Addressable:           00
[task 2019-05-20T18:33:15.125Z] 18:33:15     INFO -    Partially addressable: 01 02 03 04 05 06 07
[task 2019-05-20T18:33:15.125Z] 18:33:15     INFO -    Heap left redzone:       fa
[task 2019-05-20T18:33:15.126Z] 18:33:15     INFO -    Freed heap region:       fd
[task 2019-05-20T18:33:15.127Z] 18:33:15     INFO -    Stack left redzone:      f1
[task 2019-05-20T18:33:15.128Z] 18:33:15     INFO -    Stack mid redzone:       f2
[task 2019-05-20T18:33:15.128Z] 18:33:15     INFO -    Stack right redzone:     f3
[task 2019-05-20T18:33:15.128Z] 18:33:15     INFO -    Stack after return:      f5
[task 2019-05-20T18:33:15.129Z] 18:33:15     INFO -    Stack use after scope:   f8
[task 2019-05-20T18:33:15.129Z] 18:33:15     INFO -    Global redzone:          f9
[task 2019-05-20T18:33:15.129Z] 18:33:15     INFO -    Global init order:       f6
[task 2019-05-20T18:33:15.129Z] 18:33:15     INFO -    Poisoned by user:        f7
[task 2019-05-20T18:33:15.129Z] 18:33:15     INFO -    Container overflow:      fc
[task 2019-05-20T18:33:15.130Z] 18:33:15     INFO -    Array cookie:            ac
[task 2019-05-20T18:33:15.130Z] 18:33:15     INFO -    Intra object redzone:    bb
[task 2019-05-20T18:33:15.130Z] 18:33:15     INFO -    ASan internal:           fe
[task 2019-05-20T18:33:15.130Z] 18:33:15     INFO -    Left alloca redzone:     ca
[task 2019-05-20T18:33:15.131Z] 18:33:15     INFO -    Right alloca redzone:    cb
[task 2019-05-20T18:33:15.132Z] 18:33:15     INFO -    Shadow gap:              cc
[task 2019-05-20T18:33:15.132Z] 18:33:15     INFO -  ==1433==ABORTING
[task 2019-05-20T18:33:15.169Z] 18:33:15     INFO -  Exiting due to channel error.
[task 2019-05-20T18:36:23.496Z] 18:36:23     INFO - TEST-UNEXPECTED-ERROR | telemetry/marionette/tests/client/test_search_counts_across_sessions.py TestSearchCounts.test_search_counts | IOError: Process has been unexpectedly closed (Exit code: 1) (Reason: Process unexpectedly quit without restarting (exit code: 1))
Flags: needinfo?(amarchesini)

The "fallback_bytecode_saved" state is a summary of a trace of events made with TRACE_FOR_TEST macro in the ScriptLoader.cpp file.

[task 2019-05-20T16:34:55.323Z] 16:34:55 INFO - 1688 INFO TEST-UNEXPECTED-FAIL | dom/serviceworkers/test/test_script_loader_intercepted_js_cache.html | Test for saving and loading bytecode in/from the necko cache - Test for saving and loading bytecode in/from the necko cache: assert_equals: [4] ScriptLoadRequest status after same SRI hash expected "bytecode_exec" but got "fallback_bytecode_saved"

In this case, the difference is that we took the unexpected RestartLoad function, cause by a failure while decoding the first bytes of the saved alternate data.

You should be able to get more information by running the test case with the environment variable MOZ_LOG=ScriptLoader:5,SRI:5.
Feel free to contact me if you need any help understanding the test case.

Attachment #9066047 - Attachment is obsolete: true

I really don't like the 2 patches I proposed. I have a better approach.

Flags: needinfo?(amarchesini)

BTW, I wonder if it's time to clean up this bug and file a separate one. It's getting hard to understand which patches are landed, what is not and what is needed for testing.

You need to log in before you can comment on or make changes to this bug.