1405375 - MOZ_CRASH("Close() called on closed channel!") via StreamFilterParent::Close (tab crash)

Status: VERIFIED FIXED

(WebExtensions :: Request Handling, defect, P1)

Description

[Rob Wu [:robwu]]

This bug was filed from the Socorro interface and is 
report bp-7711d704-3851-4e6a-b459-2720d0171003.
=============================================================

Also: bp-cbe5fa3a-5fcd-4dc1-bb05-1daa20171003

Calling close() on a resumed StreamFilter returned by webRequest.filterResponseData caused the tab to crash. I cannot get a reliable reproduction case, but by reading the code I have eventually found a plausible reason for the crash (see second half of this report).

The circumstances of the crashes are:

1. Extension calls webRequest.filterResponseData at webRequest.onBeforeRequest.
2. At filter.onstart, the filter is suspended and filter.write is called once.
3. Asynchronously (after the server has closed the connection), filter.resume() is called.
4. At filter.ondata and filter.onstop, filter.close() is called.

In terms of code:

filter = browser.webRequest.filterResponseData(requestId);
filter.onstart = () => {
  filter.suspend();
  filter.write(array buffer with 100 bytes of random data);
};
filter.ondata = filter.onstop = () => {
    filter.close();
};
// Asynchronously, after server has closed the connection:
filter.resume();



The crash is an assertion error at mozilla::ipc::MessageChannel::Close [1].
I can imagine the assertion being triggered if StreamFilterParent::Destroy [2] is somehow called twice. E.g. if StreamFilterParent::RecvClose called twice.

StreamFilterParent::RecvClose is called in response to SendClose(), which is guarded on mState [3].
The logic SEEMS solid. However, I have found that StreamFilterChild::MaybeStopRequest can change the state from State:Closing to State::FinishedTransferringData, which prevents the guard from working properly.

I believe that this crash is caused by the following sequence of actions:

1. Server sends one reply.
2. Extension calls filter.suspend() at filter.onstart.
3. Data is buffered in StreamFilterChild::mBufferedData.

4. Server closes connection.
5. StreamFilterChild::RecvStopRequest is triggered. This sets mReceivedOnStop = true.
6. StreamFilterChild::MaybeStopRequest is called, but returns early because mBufferedData is not empty [4].

7. Extension calls filter.resume()
8. StreamFilterChild::Resume calls StreamFilterChild::FlushBufferedData, which removes the an element from mBufferedData.
8. StreamFilterChild::EmitData [5] is called for this piece of data.
9. StreamFilterChild::EmitData fires filter.ondata, the extension calls filter.close(), handled by [3].
   -> mState = State::Closing (was: State::FinishedTransferringData).
   -> SendClose() is called.
   -> mBufferedData is emptied, if it was not already the case after step 8.
10. StreamFilterChild::EmitData then calls StreamFilterChild::MaybeStopRequest.
11. StreamFilterChild::MaybeStopRequest will now continue because mReceivedOnStop is true (step 5) mBufferedData is empty (step 8).
12. mState is currently State::Closing, so we proceed to the default label in the switch block [6].
   -> mState = State::FinishedTransferringData (was: State::Closing from step 9)
13. filter.onstop is fired, and the extension calls filter.close(), handled by [3].
   -> mState = State::Closing (was State::FinishedTransferringData from step 12).
   -> SendClose() is called.

14. StreamFilterParent::RecvClose is called TWICE because of step 9 and 13.
   -> Destroy() is called twice.
   -> Assertion is triggered -> CRASH.


For extensions, the work-around to this bug is to not synchronously call filter.close() in filter.ondata.



[1] https://searchfox.org/mozilla-central/rev/a4702203522745baff21e519035b6c946b7d710d/ipc/glue/MessageChannel.cpp#2720
[2] https://searchfox.org/mozilla-central/rev/a4702203522745baff21e519035b6c946b7d710d/ipc/glue/ProtocolUtils.cpp#662
[3] https://searchfox.org/mozilla-central/rev/a4702203522745baff21e519035b6c946b7d710d/toolkit/components/extensions/webrequest/StreamFilterChild.cpp#167-175

[4] https://searchfox.org/mozilla-central/rev/a4702203522745baff21e519035b6c946b7d710d/toolkit/components/extensions/webrequest/StreamFilterChild.cpp#255-257
[5] https://searchfox.org/mozilla-central/rev/a4702203522745baff21e519035b6c946b7d710d/toolkit/components/extensions/webrequest/StreamFilterChild.cpp#458-466
[6] https://searchfox.org/mozilla-central/rev/a4702203522745baff21e519035b6c946b7d710d/toolkit/components/extensions/webrequest/StreamFilterChild.cpp#263-277

Comment 1

[Rob Wu [:robwu]]

Attachment: webreqforceclose.xpi

Test case. It is not guaranteed to trigger the crash (since that is sensitive to delivery of messages over IPC), but it can be used to show that the filter state unexpectedly changes.

1. Load extension at about:debugging.
2. Visit example.com and wait a few seconds for the server to have sent everything. Alternatively, use netcat and answer:
HTTP/1.1 200 ok
content-length: 1

x<enter>
3. Click on the extension button to trigger filter.resume().
4. Look at the console


The following messages are shown with Firefox 58.0a1 build ID 20170926100259.

webRequest.onBeforeRequest
filter.onstart
Now close the connection and click on the browserAction button to resume.
Calling filter.resume() while in state suspended
ondata in state transferringdata
filter.onstop
"filter.status must be "closed", but is "finishedtransferringdata" - https://bugzil.la/1405375"

The last message is a failing console.assert in the background page and shows that despite calling filter.close() in filter.ondata, the filter.status is not closed in filter.onstop.

Comment 2

[Rob Wu [:robwu]]

The fact that the state machine makes an unexpected transition can potentially have severe consequences, so I recommend to fix this bug and uplift the patch to 57.

Comment 3

[Rob Wu [:robwu]]

The "Part 4" patch from bug 1405286 seems to fix this bug in Firefox 58 (the patch prevents the bug from happening by avoiding the Closing -> FinishedTransferringData transition in step 12 of my initial report).

https://hg.mozilla.org/integration/mozilla-inbound/rev/8ded456b65770dcfa0e4fc7d63d81a826d50702d

Shouldn't you uplift part 4 of that bug too? The patch consists of only adding two lines of non-test code and fixes an invalid state transition + crash.

Comment 4

[Kris Maglione [:kmag]]

Thanks.

(In reply to Rob Wu [:robwu] from comment #3)
> Shouldn't you uplift part 4 of that bug too? The patch consists of only
> adding two lines of non-test code and fixes an invalid state transition +
> crash.

No. We're severely limited in what we're allowed to uplift at this point, and this issue can easily be worked around by anyone who happens to run into it.

Comment 5

[CosminB]

Attachment: 1405375.zip

I can reproduce this issue on Firefox 57.0 (20171112125346) under Win 7 64-bit.

The message described in comment 1 is displayed in the browser console.

This issue is verified as fixed on Firefox 59.0a1 (20171127100433) and Firefox 58.0b7 (20171127135700) under Win 7 64-bit and Mac OS X 10.13.1 the issue is fixed. 

The following logs are no longer displayed in the browser console:
 filter.onstop
"filter.status must be "closed", but is "finishedtransferringdata" - https://bugzil.la/1405375"

Please see the attached screenshots.