Closed Bug 1415388 Opened 5 years ago Closed 5 years ago

Make sure the test_devtools_serviceworker_interception.html get all the timing markers related to service worker while there is an internal redirect

Categories

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

enhancement

Tracking

()

RESOLVED FIXED
mozilla59
Tracking Status
firefox59 --- fixed

People

(Reporter: tt, Assigned: tt)

References

(Blocks 1 open bug)

Details

Attachments

(3 files, 6 obsolete files)

15.02 KB, patch
Details | Diff | Splinter Review
8.58 KB, patch
Details | Diff | Splinter Review
4.30 KB, patch
Details | Diff | Splinter Review
Please refer to bug 1222008 comment 41.

While we are doing internal redirect (says channel A redirect to channel B), we basically copy the timing markers [1] to the new channel (channel B). At this moment, we haven't got the mHandleFetchEventEnd yet (It's marked in [2]). Then, in OnStopRequest, we notify the Necko observer [3] with the new channel (channel B) and the timing markers expcet the mHandleFetchEventEnd. After that, we finish the response and goes the place to record the mHandleFetchEventEnd [2] on the original channel (channel A).

Currently, test_devtools_serviceworker_interception.html is waitting for the channel A notify the Necko observer with the NS_HTTP_ON_STOP_REQUEST_TOPIC. Becuase of the consequence I mentioned above, the test will timeout. 

I feel like the simple solution for this is to notify the Necko observer while the original channel finish synthesized response if it has been done a real/interanl redirect.

I'm also thinking to add more scenarios (interanl/real redirect) to the test. And, maybe move the test to browser test?

Note: I suspect this issue, at least, has already happened on the opaque response (where the internal redirect happens) in non-e10s mode.

[1] https://searchfox.org/mozilla-central/source/netwerk/protocol/http/HttpBaseChannel.cpp#3662-3667
[2] https://searchfox.org/mozilla-central/source/dom/workers/ServiceWorkerEvents.cpp#215
[3] https://searchfox.org/mozilla-central/source/netwerk/protocol/http/InterceptedHttpChannel.cpp#1045
Blocks: 1222008
(In reply to Tom Tung [:tt] from comment #0)
> I feel like the simple solution for this is to notify the Necko observer
> while the original channel finish synthesized response if it has been done a
> real/interanl redirect.

I was wrong. If we do that, it will notify the Necko observer twice and make devtools harder to decide which channel they should listen.

Perphs, we should defer the time to notify the Necko observer pass the timings markers recorded later on the original channel to the new channel.

I'll try to write a browser test first.
I think the easiest way to do this would be to tie it to the OnStopRequest somehow.  That should only be fired once no matter how many redirects happens.  I think maybe devtools can listen for http-stop-request observer topic or something like that.
Sorry for the confusion...

I was misled due to the test which checks the responses by listening to "http-on-stop-request". If an observer is listening to this topic, we cannot guarantee that service worker has marked the mHandleFetchEventEnd.  

Devtools currently listens to the "service-worker-synthesized-response" topic [1] for collecting information related to service worker. That ensures the dev-tools can get all the timing markers related service workers from the intercetped channel. However, I'm a bit not sure about whether we really need to pour these timing markers over to the replacement channel since we notify the Necko observer with the original intercepted channel when finishing the synthesized response.

I feel like I should change the test to imitate the behavior in dev-tools [1] which listen to the "http-on-examine-response", "http-on-examine-cached-response", "http-on-modify-request" and "service-worker-synthesized-response" and then check the timing markers on the response.

[1] http://searchfox.org/mozilla-central/source/devtools/shared/webconsole/network-monitor.js#787-788
[2] http://searchfox.org/mozilla-central/source/netwerk/protocol/http/HttpBaseChannel.cpp#3662-3667
Summary: Make sure the devtools get all the timing markers related to service worker after the channel firing NS_HTTP_ON_STOP_REQUEST_TOPIC → Make sure the test_devtools_serviceworker_interception.html get all the timing markers related to service worker while there is an internal redirect
I believe I recently changed "service-worker-synthesized-response" to fire at the start of synthesis instead of when the body completes.  Maybe this is part of the problem here?  See bug 1390638.
(In reply to Ben Kelly [:bkelly] from comment #4)
> I believe I recently changed "service-worker-synthesized-response" to fire
> at the start of synthesis instead of when the body completes.  Maybe this is
> part of the problem here?  See bug 1390638.

Oh, that might be the issue I found because "http-on-stop-request" doesn't late enough to let HandleFetchEventEnd time be marked. Furthermore, we notify the Necko observer "http-on-stop-request" with the replacement channel after redirecting. But, we also want to notify the Necko observer with the intercepted channel since timing markers related to service workers are tracking on that channel.
(In reply to Tom Tung [:tt] from comment #5)
> (In reply to Ben Kelly [:bkelly] from comment #4)

Hi Ben,

Given the changes in bug 1390638, do you have any suggestion for dealing with the issue in comment #5? Should I tie the place for recording HandleFetchEventEndTime to the OnStopRequest like you said in comment#2? Or should I create another topic to notify when the body complete? Or something else?
Flags: needinfo?(bkelly)
Does this get easier if we copy service worker timing information forward for these redirects?

I would also be ok moving the final timing mark to be when OnStopRequest fires instead of just after.

Does that help at all?  (Sorry if I'm confused.  Trying to respond during a meeting at TPAC.)

Also, just to clarify, we want these intercepted channel that does an extra redirect to get the right URL exposed to only be a single entry in the network monitor, right?

This is opposed to an intercepted channel that returns a 30x which triggers a real new network request for the redirected location.  I think those get separate entries in devtools network monitor.
Flags: needinfo?(bkelly)
(In reply to Ben Kelly [:bkelly] from comment #8)
Thanks for the quick feedback!

I'll try to move the final timing mark to be when OnStopRequest(), if I don't misunderstand comment [0].

Please correct me if I misunderstand anything. Thanks!

[0] https://searchfox.org/mozilla-central/source/dom/workers/ServiceWorkerEvents.cpp#113-114

> Does this get easier if we copy service worker timing information forward
> for these redirects?

I feel like both solutions work fine for me, but I'm not so sure which one is better.

If we do that, for non-e10s mode, we need to make the intercepted channel hold the strong reference to the redirect channel [1] until setting the last service worker timing information. The reason is that we break the pointer on InterceptedHttpChannel::OnRedirectVerifyCallback and InterceptedHttpChannel::OnStopRequest. We need to have a way to get the redirect channel while copying the timing information after OnStopRequest.

I haven't finished investigating the e10s mode (InterceptedChannel/HttpChannelChild) yet, but I guess we need to do the similar things.

[1] https://searchfox.org/mozilla-central/source/netwerk/protocol/http/InterceptedHttpChannel.cpp#51
 
> I would also be ok moving the final timing mark to be when OnStopRequest
> fires instead of just after.

Do the OnStopRequest be called even when a network error happens? I'm a bit worried about if we can do the same thing in CancelChannelRunnable [2].

[2] https://searchfox.org/mozilla-central/source/dom/workers/ServiceWorkerEvents.cpp#115

> Does that help at all?  (Sorry if I'm confused.  Trying to respond during a
> meeting at TPAC.)

Yes, it does. Thanks for the quick feedback as always!

> Also, just to clarify, we want these intercepted channel that does an extra
> redirect to get the right URL exposed to only be a single entry in the
> network monitor, right?

Yes, I am thinking the internal redirect (respondWith() an opaque response in current implementation) should have one entry in the networker monitor.

> This is opposed to an intercepted channel that returns a 30x which triggers
> a real new network request for the redirected location.  I think those get
> separate entries in devtools network monitor.

To clarify as well, for the real redirect (if we decide to do bug 1222008), we probably want more than one entries, right?
(In reply to Tom Tung [:tt] from comment #9)
> To clarify as well, for the real redirect (if we decide to do bug 1222008),
Sorry, it's s/clarify as well/ensure I understand correctly/g
(In reply to Tom Tung [:tt] from comment #9)
> I'll try to move the final timing mark to be when OnStopRequest(), if I
> don't misunderstand comment [0].

I also need to redirect the service worker timing information to the redirect channel especially after SetupReplacementChannel()
Try to SetHandleFetchEventEnd() to the redirected channel if the internal redirect happens. Finish it in non-e10s mode, but sucks in e10s mode.

It seems that we don't pass the service worker timing information to the internal redirect channel (if there is no-IPC redirect) on SetupReplacementChannel() in e10s mode. (But we do it in non-e10s mode). The reason is that the created channel doesn't implement nsITimeChannel([1] for e10s, [2] for non-e10s). I will figure a way out to deal with it.

[1] https://searchfox.org/mozilla-central/source/netwerk/protocol/http/HttpChannelChild.cpp#1739
[2] https://searchfox.org/mozilla-central/source/netwerk/protocol/http/InterceptedHttpChannel.cpp#248-250
The alternative solution for avoiding this is to fire another topic to the observer rather than "service-worker-synthesized-response", so that we don't need to propagate the timing information from original timeChannl to the redirected channel.
I think maybe my idea to use the OnStopRequest() topic as the signal was wrong.

Can we do this?

1. Copy the timing data to the redirect channel if we are doing an "extra" redirect after interception for propagating the URL (and maybe resetting the channel).
2. Move the firing of the "service-worker-synthesized-response" observer topic into the channel code.  This would let us fire the topic if we follow a real-redirect fro a 30x status code or wait to fire the topic when we ultimately call OnStopRequest() for a synthetic response (even if we need to do a fake redirect first).  This would have to be implemented separately for e10s vs non-e10s of course.

I think if we can decide when to fire the topic in the channel we can properly handle the different redirect paths.  The ServiceWOrkerEvents.cpp code just doesn't have enough context to do it at the right time.

What do you think?
Flags: needinfo?(ttung)
(In reply to Ben Kelly [:bkelly] from comment #14)
> I think maybe my idea to use the OnStopRequest() topic as the signal was
> wrong.

You are right. I got the wrong channel on e10s mode.

> Can we do this?
> 
> 1. Copy the timing data to the redirect channel if we are doing an "extra"
> redirect after interception for propagating the URL (and maybe resetting the
> channel).

I thought we could do this and I did this for InterceptedHttpChannel (non-e10s mode), but I got the problem while I was trying to do this to InterceptedChannel. 

I tried to do things on both InterceptedHttpChannel and InterceptedChannel as follows:

1. Defer the time for removing the strong reference mRedirectChannel/mRedirect (because we need to propagate the timing data while onStopRequest is firing)
2. Record the last timing data (mHandleFetchEventEnd) on CompleteBody (because I want to ensure this finish while onStopRequest is firing)
3. Register an observe-function to observer service and listen the channel which firing the "http-on-stop-request" event.

The problem happens in step 3. The channel I got in step 3 for non-e10s mode is InterceptedHttpChannel but for e10s mode, it's HttpChannelChild. After that, I realized that InterceptedHttpChannel inherits HttpBaseChannel so that I can propagate timing data on redirect. However, for InterceptedChannel, we only redirect the data recored in HttpChannelChild, and thus I failed to propagate the timing data to the redirect channel. I have no idea how to get the interceptedChannel from the intercepted HttpChannelChild. (It seems we can only get the intercepted HttpChannelChild from the interceptedChannel->mChannel).

> 2. Move the firing of the "service-worker-synthesized-response" observer
> topic into the channel code.  This would let us fire the topic if we follow
> a real-redirect fro a 30x status code or wait to fire the topic when we
> ultimately call OnStopRequest() for a synthetic response (even if we need to
> do a fake redirect first).  This would have to be implemented separately for
> e10s vs non-e10s of course.

But, in the real-redirect for a 30x status code case, when should we record the HandleFetchEventEnd for the interceptedChannel?

Sorry if I don't understand clearly.

I imagine the timeline goes like below:
 
LaunchServiceWorkerStart End DispatchFetchEventStart End HandleFetchEventStart End?
          ^               ^              ^            ^           ^             ^
----------+---------------+--------------+------------+-----------+-------+-----+--------------->(timeline)                        
                                                                          |
                                    Fire the "service-worker-synthesized-response" (May even eariler than HandleFetchEventStart)

The read-redirect happens between firing the "service-worker-synthesized-response" and recording topic HandleFetchEventEnd.

If devtools examine the timing data while receiving the "service-worker-synthesized-response" topic, it will have a channel without timing for HandleFetchEventEnd.


> I think if we can decide when to fire the topic in the channel we can
> properly handle the different redirect paths.  The ServiceWOrkerEvents.cpp
> code just doesn't have enough context to do it at the right time.
> 
> What do you think

I'm thinking to register two observe-functions. The first listen to the "service-worker-synthesized-response" and the other one listen to the "http-on-stop-request". Then, record and hold the interceptChannl from the first observe-function. Finally, collect the timing data when getting the "http-on-stop-request". So that we only change a little implementation and ensure getting all the timing data from the intercetpedChannel.

But, if we do this for the real-redirect, we might get figure as follows (having two entries on devtools):

                                                                Redirect's timing data
                                                                          ^
----------+---------------+--------------+------------+-----------+-------+-----+--------------->(timeline)   
          |               |              |            |           |             |

LaunchServiceWorkerStart End DispatchFetchEventStart End HandleFetchEventStart End

I'm not sure whether it's strange or not.
Flags: needinfo?(ttung)
I guess I was thinking of moving the code not into InterceptedChannel.cpp, but all the way into HttpChannelChild.

So, copying the timing information in here for our "extra" redirects:

https://searchfox.org/mozilla-central/source/netwerk/protocol/http/HttpChannelChild.cpp#1730

And firing the observer topic in this conditional case for the 30x redirect:

https://searchfox.org/mozilla-central/source/netwerk/protocol/http/HttpChannelChild.cpp#3625

I think you can also call MaybeCallSynthesizedCallback() before following the 30x redirect to complete the body since it won't be read.  This might get the final timing marker for the fetch event handled there instead of waiting for the channel to be torn down.

And then also fire the observer topic in OnStopRequest() from here:

https://searchfox.org/mozilla-central/source/netwerk/protocol/http/HttpChannelChild.cpp#143

We can move HandleFetchEventEnd slightly earlier if that helps at all.

Does that help at all?  I think this will result in a single network monitor entry for our "extra" redirect, but two lines for a 30x status code redirect.

I have to admit I don't completely understand what you have tried so far, so I'm sorry if what I am suggesting is no different.  I'll try to look at this more tomorrow.  I have to head to bed now, though.
Flags: needinfo?(ttung)
(In reply to Ben Kelly [:bkelly] from comment #16)
I'll send a f? with my current approach to see if it's ok to do that.

> I guess I was thinking of moving the code not into InterceptedChannel.cpp,
> but all the way into HttpChannelChild.
> 
> So, copying the timing information in here for our "extra" redirects:
> 
> https://searchfox.org/mozilla-central/source/netwerk/protocol/http/
> HttpChannelChild.cpp#1730

I tried to do that, but I found the new channel doesn't implement the nsITimeChannel so that it won't be propagated to the new channel by SetupReplacementChannel() [1].

I could try to find out how to create a channel which both implements the nsITimeChannel and meets the current code's requirement.

[1] https://searchfox.org/mozilla-central/source/netwerk/protocol/http/HttpBaseChannel.cpp#3596-3668

> And firing the observer topic in this conditional case for the 30x redirect:
> 
> https://searchfox.org/mozilla-central/source/netwerk/protocol/http/
> HttpChannelChild.cpp#3625
> 
> I think you can also call MaybeCallSynthesizedCallback() before following
> the 30x redirect to complete the body since it won't be read.  This might
> get the final timing marker for the fetch event handled there instead of
> waiting for the channel to be torn down.
> 
> And then also fire the observer topic in OnStopRequest() from here:
> 
> https://searchfox.org/mozilla-central/source/netwerk/protocol/http/
> HttpChannelChild.cpp#143
> 
> We can move HandleFetchEventEnd slightly earlier if that helps at all.

Yeah, my current approach is to set HandleFetchEventEnd in BodyComplete[2].
[2] https://searchfox.org/mozilla-central/source/netwerk/protocol/http/HttpChannelChild.cpp#3798

> Does that help at all?  I think this will result in a single network monitor
> entry for our "extra" redirect, but two lines for a 30x status code redirect.
> 
> I have to admit I don't completely understand what you have tried so far, so
> I'm sorry if what I am suggesting is no different.  I'll try to look at this
> more tomorrow.  I have to head to bed now, though.

Sorry for not being able to explain this clearly... :(
Flags: needinfo?(ttung)
Hi Ben,

The attachment 8926792 [details] [diff] [review] moves the current chrome mochitest test to browser test so that we can verify whether the service worker timing data is recorded in both e10s mode and non-e10s mode.

This patch is applied above the attachment 8926792 [details] [diff] [review] and does the things below:

- Fire "service-worker-synthesized-response" sightly earlier. (on BodyComplete rather than in another thread)
- Add a test to verify behavior on internal redirect.
- Modify the test into two stages if the service worker is expected to hijack the request. First, listen to the "service-worker-synthesized-response" and seize the interceptedChannel. Finally, wait for "http-on-stop-request" firing, and checking the timing data on the interceptedChannel (caught on the previous stage).

If this approach is ok to you, I will change the logic in https://searchfox.org/mozilla-central/source/devtools/shared/webconsole/network-monitor.js in Bug 1353798.
Attachment #8927732 - Flags: feedback?(bkelly)
(In reply to Tom Tung [:tt] from comment #17)
> > I guess I was thinking of moving the code not into InterceptedChannel.cpp,
> > but all the way into HttpChannelChild.
> > 
> > So, copying the timing information in here for our "extra" redirects:
> > 
> > https://searchfox.org/mozilla-central/source/netwerk/protocol/http/
> > HttpChannelChild.cpp#1730
> 
> I tried to do that, but I found the new channel doesn't implement the
> nsITimeChannel so that it won't be propagated to the new channel by
> SetupReplacementChannel() [1].

Oh, I remember you saying that now in a previous comment.  I'm just really surprised.  Do you know what kind of concrete channel class is instantiated?  Its not an HttpChannelChild?

Maybe it doesn't matter now if you have figured out another path.  I need to look at your patch.

> > I have to admit I don't completely understand what you have tried so far, so
> > I'm sorry if what I am suggesting is no different.  I'll try to look at this
> > more tomorrow.  I have to head to bed now, though.
> 
> Sorry for not being able to explain this clearly... :(

Oh, its not your fault.  I just haven't had time while traveling to really sit down with the code while reading the comments here.  Sorry!
Comment on attachment 8927732 [details] [diff] [review]
Add a test to verify recording service worker timing data if there is an internal redirect

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

Sorry, I may still be a bit confused.

Where does this change "service-worker-synthesized-response"?  I don't see that in the patch.  Did you forgot to hg qref?

Also, while the changes seem ok to me, I'm not sure they have a huge impact here.  Moving the time capture out of CancelChannelRunnable and FinishResponse seems somewhat equivalent.  The FinishResponse runnable is not actually dispatched.  We call Run() synchronously in the current thread here:

https://searchfox.org/mozilla-central/source/dom/workers/ServiceWorkerEvents.cpp#260

I think adding test cases for this is very good, thank you.

::: dom/workers/ServiceWorkerEvents.cpp
@@ -111,5 @@
>    MOZ_ASSERT(NS_IsMainThread());
>  
> -  // TODO: When bug 1204254 is implemented, this time marker should be moved to
> -  // the point where the body of the network request is complete.
> -  mChannel->SetHandleFetchEventEnd(TimeStamp::Now());

I'm not sure about this one.  What if we end up triggering the CancelChannelRunnable from a case where this is no body complete?

Maybe pass a hint in to CancelChannelRunnable() constructor that says if the time stamp should be taken?  You can then have BodyComplete() do its own timestamp, but let other uses of CancelChannelRunnable also do the timestamp.
Attachment #8927732 - Flags: feedback?(bkelly)
(I'm marking this P1 since it blocks bug 1222008 which is also marked P1)
Priority: -- → P1
(In reply to Ben Kelly [:bkelly] from comment #20)
> Sorry, I may still be a bit confused.

Let me try to restate the problem I found and the solution I propose here.

The problem is that dev-tools (network-monitor.js) and this test cannot get all the timing data if there is an internal redirect. 

If dev-tools only listen to the "service-worker-synthesized-response" topic, it will get the intercepted channel which is seized by  RespondWithClosure [1] (Note 1). In these case, the timing for firing the "service-worker-synthesized-response" topic is too early to collect all the timing data.

[1] https://searchfox.org/mozilla-central/source/dom/workers/ServiceWorkerEvents.cpp#169

Note 1: I'm a bit confused here because the intercepted channel in the RespondWithClosure is never changed. So, I don't understand why we propagate the timing data in SetupReplacementChannel() [2].

[2] https://searchfox.org/mozilla-central/source/netwerk/protocol/http/HttpBaseChannel.cpp#3662-3667

If dev-tools only listen to the "http-on-stop-request" topic just like the test [3], it will catch the http channel which will be changed when the redirect happens (Note 2).
- For the InterceptedChannel object in the normal case (no redirect happen), it pours over its timing data to the http channel [4] after the fetching body is completed. Thus, the dev-tools can get the correct timing data from the http channel.
- But, for it in the redirect case, the mChannel held by InterceptedChannelBase [5] is wrong so that we save the timing data to the wrong channel.
- For the InterceptedHttpChannel object in the normal case, it's also a http channel and it's the channel reported to observer while firing the "http-on-stop-request". Thus, the dev-tools can get the correct timing data from it.
- But, for it in the redirect case, it pours overs its timng data to the redirect channel[2] and only the reidrect channel will fire the "http-on-stop-request" topic. Also, the timing HandleFetchEventEnd is recorded after redirect and we record the timing  HandleFetchEventEnd to the wrong channel. Therefore, dev-tool will get all the timing data except the timing  HandleFetchEventEnd.

Note 2: It makes sense to me for passing timing data in SetupReplacementChannel() in this case, because we need to ensure the new channel holds the correct data so that we can present them correctly on dev-tools.

[3] https://searchfox.org/mozilla-central/source/dom/workers/test/serviceworkers/test_devtools_serviceworker_interception.html#104
[4] https://searchfox.org/mozilla-central/source/netwerk/protocol/http/InterceptedChannel.cpp#144-165
[5] https://searchfox.org/mozilla-central/source/netwerk/protocol/http/InterceptedChannel.cpp#141

So, I have two different approaches to solve this issue.
Approach A: Don't change too much logic in dev-tools (network-monitor.js), make it be able to get every timing data from one channel 
- Propagate timing data to the redirect/new channel in every redirect and pass the timing HandleFetchEventEnd to the new channel
- Ensure the channel which fires the topic have all the timing data (Probably need to change the timing for firing the "service-worker-synthesized-response")

Approach B (the attachment 8927732 [details] [diff] [review]): Don't change too much logic in platfrom(ServiceWorkerEvent.cpp, InterceptedChannel.cpp, InterceptedHttpChannel.cpp, ... etc).
- Modify the test and logic in dev-tools to seize the interceptedChannel first, and then get its data after filling up all the timing data. (Note 3) 

I'm not sure which approach is better, but the approach B changes less code. Thus, I choose to approach B for now.

Note 3: It indicates that the dev-tools need to get the extra channel (intercetped channel) to get the service worker related timing data.
 
> Where does this change "service-worker-synthesized-response"?  I don't see
> that in the patch.  Did you forgot to hg qref?

Sorry for confusion. I tried it in the approach A, but I had a problem on pouring the original channel's timing data to the new channel while redirecting. Besides, it needs to extend the life time of reference [6] from the original channel to the new channel. (We remove the reference each time while OnRedirectVerifyCallback()/OnStopRequest() in ReleaseListener()). I'm not sure if it's a good idea to keep it longer.

[6] https://searchfox.org/mozilla-central/source/netwerk/protocol/http/InterceptedHttpChannel.cpp#51

> Also, while the changes seem ok to me, I'm not sure they have a huge impact
> here.  Moving the time capture out of CancelChannelRunnable and
> FinishResponse seems somewhat equivalent.  The FinishResponse runnable is
> not actually dispatched.  We call Run() synchronously in the current thread
> here:
> 
> https://searchfox.org/mozilla-central/source/dom/workers/ServiceWorkerEvents.
> cpp#260
> 
> I think adding test cases for this is very good, thank you.
> 
> ::: dom/workers/ServiceWorkerEvents.cpp
> @@ -111,5 @@
> >    MOZ_ASSERT(NS_IsMainThread());
> >  
> > -  // TODO: When bug 1204254 is implemented, this time marker should be moved to
> > -  // the point where the body of the network request is complete.
> > -  mChannel->SetHandleFetchEventEnd(TimeStamp::Now());
> 
> I'm not sure about this one.  What if we end up triggering the
> CancelChannelRunnable from a case where this is no body complete?

That is the one case I ignore. Thanks for catching it out!

> Maybe pass a hint in to CancelChannelRunnable() constructor that says if the
> time stamp should be taken?  You can then have BodyComplete() do its own
> timestamp, but let other uses of CancelChannelRunnable also do the timestamp.

Yeah, sounds reasonable. I'll try to do that.
(In reply to Ben Kelly [:bkelly] from comment #20)
I find out I somehow this part.

> Also, while the changes seem ok to me, I'm not sure they have a huge impact
> here.  Moving the time capture out of CancelChannelRunnable and
> FinishResponse seems somewhat equivalent.  The FinishResponse runnable is
> not actually dispatched.  We call Run() synchronously in the current thread
> here:
> 
> https://searchfox.org/mozilla-central/source/dom/workers/ServiceWorkerEvents.
> cpp#260

Oh, you catch my blind spot! I thought it's a dispatch, so I was afraid there is might be blocked for a while.

(In reply to Tom Tung [:tt] from comment #22)
> Yeah, sounds reasonable. I'll try to do that.

Thus, rather than adding a flag to ctor, I'll remove all the changes on ServiceWorkerEvent.cpp
Send the patch to review.

Hi Ben, 

Could you help me to review this? Thanks!
This patch only move the original chrome mochitest test to browser test. Thus, we can ensure the behavior in e10s mode.
Attachment #8926792 - Attachment is obsolete: true
Attachment #8928084 - Flags: review?(bkelly)
This patch is add a test to verify we can still get the timing data after an internal redirect.

It's approach B in comment 22. This patch only does two things and I list them below:

- Add an internal redirect test
- Modify the test logic for handling service worker intercepted request. Basically, catch the intercepted channel by listening to "service-worker-synthesized-response" and start to checking the data after getting "http-on-stop-request".

This indicates I need to modify the current logic to be the same as this test in network-monitor.js [1] as well. If you r+ this patch, I'll do it on Bug 1353798

Please feel free to cancel the request if you don't think this approach is appropriate or you think we should pass timing data to the final(redirect) channel.


[1] https://searchfox.org/mozilla-central/source/devtools/shared/webconsole/network-monitor.js
Attachment #8927732 - Attachment is obsolete: true
Attachment #8928085 - Flags: review?(bkelly)
Sorry I didn't get to the reviews here today.  My schedule was a bit disrupted because of a sick kid at home.

If I understand correctly, though, the proposal is to move the complexity of handling the timing information out of the network channel bits and in to the devtools bits.  That seems reasonable, I guess.

Would it be possible to go back to the simpler channel timing model once we move all interception logic to the parent?  Then we would only need to worry about InterceptedHttpChannel.  The HttpChannelChild complexity would be gone.

I'll do these reviews tomorrow.
(In reply to Ben Kelly [:bkelly] from comment #26)
> Sorry I didn't get to the reviews here today.  My schedule was a bit
> disrupted because of a sick kid at home.

Take care!

> If I understand correctly, though, the proposal is to move the complexity of
> handling the timing information out of the network channel bits and in to
> the devtools bits.  That seems reasonable, I guess.

Yeah, that's what I meant.

> Would it be possible to go back to the simpler channel timing model once we
> move all interception logic to the parent?  Then we would only need to worry
> about InterceptedHttpChannel.  The HttpChannelChild complexity would be gone.

It sounds like a good idea! Handling HttpChannelChild is rather complicated compared to InterceptedHttpChannel. I'll file a follow-up bug to track it.

> I'll do these reviews tomorrow.

Thanks!
Blocks: 1417294
Comment on attachment 8928084 [details] [diff] [review]
Bug 1415388 - P1: Move the test_devtools_serviceworker_interception to a browser test. r?bkelly

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

I'm assuming most of the inner test guts are just moved from the old test location.  Looks reasonable.

::: dom/workers/test/serviceworkers/browser_devtools_serviceworker_interception.js
@@ +12,5 @@
> +// XXXtt: We should be able to move this check to chrome process after we move
> +// the interception logic to chrome process.
> +async function checkObserverInContent(aInput) {
> +
> +async function checkTimeChannel(aURL, aIntercepted, aFetch) {

Can you indent this function or something?  Its a bit hard to see where the enclosing checkObserverInContent() function completes.  I don't even really understand why its nested, to be honest.  Could you just do all this logic directly in checkObserverInContent() without the extra function call?

@@ +108,5 @@
> +  swr.unregister();
> +}
> +
> +add_task(async function test_() {
> +  info("Setting the prefs to having multi-e10s enabled");

Is this correct?  The prefs seem to disable multi-e10s.
Attachment #8928084 - Flags: review?(bkelly) → review+
Comment on attachment 8928085 [details] [diff] [review]
Bug 1416629 - P2: Add a test to verify pass timing data correctlly after an internal redirect. r?bkelly

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

Thanks!
Attachment #8928085 - Flags: review?(bkelly) → review+
(In reply to Ben Kelly [:bkelly] from comment #28)
Thanks for the review! I'll address the commnet.

> :::
> dom/workers/test/serviceworkers/browser_devtools_serviceworker_interception.
> js
> @@ +12,5 @@
> > +// XXXtt: We should be able to move this check to chrome process after we move
> > +// the interception logic to chrome process.
> > +async function checkObserverInContent(aInput) {
> > +
> > +async function checkTimeChannel(aURL, aIntercepted, aFetch) {
> 
> Can you indent this function or something?  Its a bit hard to see where the
> enclosing checkObserverInContent() function completes.  I don't even really
> understand why its nested, to be honest.  Could you just do all this logic
> directly in checkObserverInContent() without the extra function call?

Sure, I'll do all the logic in checkObserverInContent(). 

I thought we are about to move the interception to the parent process and maybe move this check to the parent process soon. Therefore, we could just remove the checkObserverInContent() and  call checkTimeChannel() directly without changing the indent.

> @@ +108,5 @@
> > +  swr.unregister();
> > +}
> > +
> > +add_task(async function test_() {
> > +  info("Setting the prefs to having multi-e10s enabled");
> 
> Is this correct?  The prefs seem to disable multi-e10s.

Oh, that is a mistake I made, but I'm pretty sure it test the logic in InterceptedChannel.cpp. Because I printed the log to ensure that I test the right functions. I thought that is setting the max number of content process, but it's should be the max number of all the procees.
(In reply to Tom Tung [:tt] from comment #30)
> > @@ +108,5 @@
> > > +  swr.unregister();
> > > +}
> > > +
> > > +add_task(async function test_() {
> > > +  info("Setting the prefs to having multi-e10s enabled");
> > 
> > Is this correct?  The prefs seem to disable multi-e10s.
> 
> Oh, that is a mistake I made, but I'm pretty sure it test the logic in
> InterceptedChannel.cpp. Because I printed the log to ensure that I test the
> right functions. I thought that is setting the max number of content
> process, but it's should be the max number of all the procees.

That pref does be a limitation of the max number of the content processes, and I meant to do that because I open another tab for observing the channel. So, I don't want to have two tabs run in the different process. I'll modify the info to be "Setting the prefs to have e10s enabled"
Address the comment and modify the test name in the test
Attachment #8928084 - Attachment is obsolete: true
Attachment #8928802 - Flags: review+
Add an URL check for addInterceptedChannel to avoid bothering from other tests and move the URL check at the first of observer function.
Attachment #8928085 - Attachment is obsolete: true
Attachment #8928804 - Flags: review+
There are few failure on try, but the test passed on my MacBookPro and desktop(Ubuntu). I'll try to catah them by running the test in rr choas mode.
Attached patch Fix the issue on try (obsolete) — Splinter Review
I found I made two mistakes. One is I had forgotten to wait for the controller changes after post the claim message to the service worker. The other is that when an internal redirect happens, we should wait for the observer getting the http-on-stop-request twice so that the timing data is ensured to be saved to the timedChannel.
(In reply to Tom Tung [:tt] from comment #36)
> The
> other is that when an internal redirect happens, we should wait for the
> observer getting the http-on-stop-request twice so that the timing data is
> ensured to be saved to the timedChannel.

Wait, what?  How does OnStopRequest() fire twice?  I don't think that should happen.
(In reply to Ben Kelly [:bkelly] from comment #38)
> Wait, what?  How does OnStopRequest() fire twice?  I don't think that should
> happen.

Note that I was describing of getting "http-on-stop-request" topic twice from observer service in the content process.

HttpChannelChild fires the "http-on-stop-request" in HttpChannelChild::DoOnStopRequest()[1]. I noiced that the test receives the topic twice if there is an internal redirect. 

The first one is triggered from HttpChannelChild::OnStopRequest(). It won't trigger the BodyComplete() since it doesn't take the mSynthesizedCallback (the ownership of mSynthesizedCallback is transfer to InterceptStreamListener in HttpChannelChild::OnRedirectVerifyCallback() [2]).

The second one is triggered from InterceptStreamListener::OnStopRequest()[3] and the InterceptStreamListener is created if the there is an internal redirect. And, before it notifies the gHttpHandler with "http-on-stop-request", it calls BodyComplete()[4] where we save all the timing information to timedChannel.

[1] https://searchfox.org/mozilla-central/source/netwerk/protocol/http/HttpChannelChild.cpp#1211
[2] https://searchfox.org/mozilla-central/source/netwerk/protocol/http/HttpChannelChild.cpp#2170-2171
[3] https://searchfox.org/mozilla-central/source/netwerk/protocol/http/HttpChannelChild.cpp#143
[4] https://searchfox.org/mozilla-central/source/netwerk/protocol/http/HttpChannelChild.cpp#3798
(In reply to Tom Tung [:tt] from comment #37)
> re-push to try:
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=a2485e6ae1ccb52d28fd39ee3923d31735c297a0

FAIL | dom/workers/test/serviceworkers/browser_force_refresh.js | base load without cached load should only occur once 

It seems that I break the dom/workers/test/serviceworkers/browser_force_refresh.js. I'll rebase and push to try again (only test the browser test) to see if I really break this test.
Hmm, we should probably fix it so the topic only fires once in this case.  And just to clarify the end listener does not get two OnStopRequest() callbacks right?
(In reply to Ben Kelly [:bkelly] from comment #42)
> Hmm, we should probably fix it so the topic only fires once in this case. 
> And just to clarify the end listener does not get two OnStopRequest()
> callbacks right?

Do you mean the callback from the Necko chrome process? Then right, the first "http-on-stop-request" is fired because of IPC callback from Necko. The second "http-on-stop-request" topic (triggered by InterceptedStreamListener) is fire because of InputStreamPump [1]. 

[1] https://searchfox.org/mozilla-central/source/netwerk/base/nsInputStreamPump.cpp#704
But I don't think we should be running both the parent-side necko channel and the InputStreamPump at the same time.  It needs to be one or the other.  Otherwise we run the risk of duplicate OnStopRequest() calls to the external listener.  (And duplicate "http-on-stop-request" topic notifications.)

Can you walk me through how this happens?
(In reply to Ben Kelly [:bkelly] from comment #44)
> Can you walk me through how this happens?

Sure, but I feel like it's my fault that makes you cofused.

In the test case (internal redirect), it fetch a fake cross origin URL with no-cors mode on the tab (empty.html) and observe the channel with "http-on-stop-request" topic. Then, the registered service worker intercepts the request and responds with another fetch, which fetching a cross origin "hello" document in "no-cors" mode as well.

I expect to get two channel for "http-on-stop-request" for the corrss origin "hello" document from the observer. One is due to fetching on the service worker. The other is because the client document (empty.html) fetch an "internal-redirected" request. (But, I cannot understand that why is the second request I got in the test triggering from InputStreamPump rather than HttpChannelChild::OnStopRequest()). Other test case won't have the same problem because we won't do the internal redirect to them.

IIUC, we decide not showing the request/response from service worker on the controlling document, right? (Only showing the request/response from that document).

Thus, my solution for this is to ignore the first channel I got in "http-on-stop-request" for the internal redirect. 

I print the MOZ_LOG I got while testing the internal redirect and I list it below:

GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::OnStartRequest [this=0x19a2e9000]
GECKO(60038) | [Main Thread]: D/nsHttp   nsHttpChannel::OnStopRequest ChannelDisposition 2
GECKO(60038) | [Main Thread]: D/nsHttp nsHttpChannel::FinalizeCacheEntry [this=0x143304000]
GECKO(60038) | [Main Thread]: D/nsHttp nsHttpChannel::FinalizeCacheEntry [this=0x143304000] Is Strongly Framed
GECKO(60038) | [Main Thread]: D/nsHttp nsHttpChannel 0x143304000 calling OnStopRequest
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::DoOnStartRequest [this=0x19a2e9000]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelParentListener::OnStopRequest: [this=0x132274100 status=0]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelParent::OnStopRequest: [this=0x10ab31aa0 aRequest=0x143304050 status=0]
GECKO(60038) | [Main Thread]: D/nsHttp nsHttpChannel [this=0x143304000] SetWarningReporter [0x0]
GECKO(60038) | [Main Thread]: V/nsHttp HttpBackgroundChannelParent::OnStopRequest [this=0x130ab69d0 status=0]
GECKO(60038) | [Socket Thread]: V/nsHttp HttpBackgroundChannelChild::RecvOnTransportAndData [this=0x10fbda7e0]
GECKO(60038) | [Socket Thread]: V/nsHttp   > pending until OnStartRequest [offset=0 count=621]
GECKO(60038) | [Main Thread]: D/nsHttp nsHttpHandler::NotifyObservers [chan=0x143304050 event="http-on-stop-request"]

I didn't catch this one on the observing content process, so I assume it's on the chrome process.

GECKO(60038) | [Main Thread]: V/nsHttp HttpBaseChannel::RemoveAsNonTailRequest this=0x143304000, rc=0x13bf0b800, already added=1
GECKO(60038) | [IPDL Background]: V/nsHttp HttpBackgroundChannelParent::OnStopRequest [this=0x130ab69d0 status=0]
GECKO(60038) | [Main Thread]: D/nsHttp nsHttpChannel::CloseCacheEntry [this=0x143304000] mStatus=0 mCacheEntryIsWriteOnly=1
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::RetargetDeliveryTo [this=0x19a2e9000, aNewTarget=0x106407488]
GECKO(60038) | [Main Thread]: V/nsHttp HttpBaseChannel::DoApplyContentConversions [this=0x19a2e9028]
GECKO(60038) | [Socket Thread]: V/nsHttp HttpBackgroundChannelChild::RecvOnStopRequest [this=0x10fbda7e0]
GECKO(60038) | [Socket Thread]: V/nsHttp   > pending until OnStartRequest [status=0]
GECKO(60038) | [Socket Thread]: V/nsHttp HttpBackgroundChannelChild::OnStartRequestReceived [this=0x10fbda7e0]
GECKO(60038) | [Socket Thread]: V/nsHttp HttpBackgroundChannelChild::RecvOnTransportAndData [this=0x10fbda7e0]
GECKO(60038) | [Socket Thread]: D/nsHttp HttpChannelChild::ProcessOnTransportAndData [this=0x19a2e9000]
GECKO(60038) | [Socket Thread]: V/nsHttp HttpBackgroundChannelChild::RecvOnStopRequest [this=0x10fbda7e0]
GECKO(60038) | [Socket Thread]: D/nsHttp HttpChannelChild::ProcessOnStopRequest [this=0x19a2e9000]
GECKO(60038) | [StreamTrans #2]: D/nsHttp HttpChannelChild::OnTransportAndData [this=0x19a2e9000]
GECKO(60038) | [StreamTrans #2]: D/nsHttp HttpChannelChild::DoOnDataAvailable [this=0x19a2e9000]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::DoOnStatus [this=0x19a2e9000]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::DoOnProgress [this=0x19a2e9000]
GECKO(60038) | [Main Thread]: V/nsHttp nsHttpResponseHead::ParseVersion [version=HTTP/1.1 404 Not Found]
GECKO(60038) | [Main Thread]: V/nsHttp Have status line [version=11 status=404 statusText=Not Found]
GECKO(60038) | [Main Thread]: V/nsHttp ParseContentType [type=text/html;charset=utf-8]

Start NonIPCRedirect here.

GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::BeginNonIPCRedirect [this=0x19a2e8000]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::SetupRedirect [this=0x19a2e8000]
GECKO(60038) | [Main Thread]: D/nsHttp nsHttpHandler::NewProxiedChannel [proxyInfo=0x0]
GECKO(60038) | [Main Thread]: V/nsHttp Creating HttpBaseChannel @0x19a2eb028
GECKO(60038) | [Main Thread]: D/nsHttp Creating HttpChannelChild @0x19a2eb000
GECKO(60038) | [Main Thread]: V/nsHttp HttpBaseChannel::Init [this=0x19a2eb028]
GECKO(60038) | [Main Thread]: V/nsHttp host=example.com port=-1
GECKO(60038) | [Main Thread]: V/nsHttp uri=http://example.com/browser/dom/workers/test/serviceworkers/hello.html
GECKO(60038) | [Main Thread]: V/nsHttp HttpBaseChannel::SetupReplacementChannel [this=0x19a2e8028 newChannel=0x19a2eb078 preserveMethod=1]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::SetRequestHeader [this=0x19a2eb000]
GECKO(60038) | [Main Thread]: V/nsHttp HttpBaseChannel::SetRequestHeader [this=0x19a2eb028 header="Referer" value="http://mochi.test:8888/browser/dom/workers/test/serviceworkers/empty.html" merge=0]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::SetRequestHeader [this=0x19a2eb000]
GECKO(60038) | [Main Thread]: V/nsHttp HttpBaseChannel::SetRequestHeader [this=0x19a2eb028 header="Accept" value="*/*" merge=0]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::SetPriority 0x19a2eb000 p=0
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::SetRequestHeader [this=0x19a2eb000]
GECKO(60038) | [Main Thread]: V/nsHttp HttpBaseChannel::SetRequestHeader [this=0x19a2eb028 header="origin" value="http://mochi.test:8888" merge=0]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::SetRequestHeader [this=0x19a2eb000]
GECKO(60038) | [Main Thread]: V/nsHttp HttpBaseChannel::SetRequestHeader [this=0x19a2eb028 header="Referer" value="http://mochi.test:8888/browser/dom/workers/test/serviceworkers/empty.html" merge=0]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::OnStopRequest [this=0x19a2e9000 status=0]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::DoPreOnStopRequest [this=0x19a2e9000 status=0]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::DoOnStopRequest [this=0x19a2e9000]
GECKO(60038) | [Main Thread]: D/nsHttp nsHttpHandler::NotifyObservers [chan=0x19a2e9078 event="http-on-stop-request"]

This is the first "http-on-stop-request" with the expected URL I got in the test.

GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::CleanupBackgroundChannel [this=0x19a2e9000 bgChild=0x10fbda7e0]
GECKO(60038) | [Socket Thread]: V/nsHttp HttpBackgroundChannelChild::OnChannelClosed [this=0x10fbda7e0]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelParent::CleanupBackgroundChannel [this=0x10ab31aa0 bgParent=0x130ab69d0]
GECKO(60038) | [Main Thread]: V/nsHttp HttpBackgroundChannelParent::OnChannelClosed [this=0x130ab69d0]
GECKO(60038) | [IPDL Background]: V/nsHttp HttpBackgroundChannelParent::DeleteRunnable [this=0x130ab69d0]
GECKO(60038) | [IPDL Background]: V/nsHttp HttpBackgroundChannelParent::ActorDestroy [this=0x130ab69d0]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelParent::OnBackgroundParentDestroyed [this=0x10ab31aa0]
GECKO(60038) | [Socket Thread]: V/nsHttp HttpBackgroundChannelChild::ActorDestroy[this=0x10fbda7e0]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::SetRequestHeader [this=0x19a2eb000]
GECKO(60038) | [Main Thread]: V/nsHttp HttpBaseChannel::SetRequestHeader [this=0x19a2eb028 header="accept" value="*/*" merge=0]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::SetRequestHeader [this=0x19a2eb000]
GECKO(60038) | [Main Thread]: V/nsHttp HttpBaseChannel::SetRequestHeader [this=0x19a2eb028 header="origin" value="http://mochi.test:8888" merge=0]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::RecvDeleteSelf [this=0x19a2e9000]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::OnRedirectVerifyCallback [this=0x19a2e8000]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::Redirect3Complete [this=0x19a2e8000]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::FinishRedirectSetup [this=0x19a2eb000]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelParent::CleanupBackgroundChannel [this=0x10ab31aa0 bgParent=0x0]
GECKO(60038) | [Main Thread]: D/nsHttp nsHttpChannel [this=0x143304000] SetWarningReporter [0x0]
GECKO(60038) | [Main Thread]: D/nsHttp Destroying HttpChannelParent [this=0x10ab31aa0]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelParent::CleanupBackgroundChannel [this=0x10ab31aa0 bgParent=0x0]
GECKO(60038) | [Main Thread]: D/nsHttp nsHttpChannel [this=0x143304000] SetWarningReporter [0x0]
GECKO(60038) | [Main Thread]: V/nsHttp HttpBaseChannel::SetApplyConversion [this=0x19a2eb028 value=0]
GECKO(60038) | [Main Thread]: D/nsStreamPump nsInputStreamPump::OnInputStreamReady [this=0x19922a560]
GECKO(60038) | [Main Thread]: D/nsStreamPump   OnStateStart [this=0x19922a560]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::DoOnStartRequest [this=0x19a2eb000]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::RetargetDeliveryTo [this=0x19a2eb000, aNewTarget=0x106407488]
GECKO(60038) | [Main Thread]: V/nsHttp HttpBaseChannel::DoApplyContentConversions [this=0x19a2eb028]
GECKO(60038) | [Main Thread]: V/nsHttp not applying conversion per mApplyConversion
GECKO(60038) | [Main Thread]: D/nsStreamPump   OnStateTransfer [this=0x19922a560]
GECKO(60038) | [Main Thread]: D/nsStreamPump   Available returned [stream=0x1993d88b0 rv=0 avail=621]
GECKO(60038) | [Main Thread]: D/nsStreamPump   calling OnDataAvailable [offset=0 count=621(621)]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::DoOnStatus [this=0x19a2eb000]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::DoOnProgress [this=0x19a2eb000]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::DoOnDataAvailable [this=0x19a2eb000]
GECKO(60038) | [Main Thread]: D/nsStreamPump   OnStateStop [this=0x19922a560 status=0]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::DoPreOnStopRequest [this=0x19a2eb000 status=0]
GECKO(60038) | [Main Thread]: D/nsHttp HttpChannelChild::DoOnStopRequest [this=0x19a2eb000]
GECKO(60038) | [Main Thread]: D/nsHttp nsHttpHandler::NotifyObservers [chan=0x19a2eb078 event="http-on-stop-request"]

This is the second "http-on-stop-request" with the expected URL I got in the test. Note that the address of this channel is different from the previous one.
(In reply to Tom Tung [:tt] from comment #45)
> "internal-redirected" request. (But, I cannot understand that why is the
> second request I got in the test triggering from InputStreamPump rather than
> HttpChannelChild::OnStopRequest()). 

Sorry for confusion, please ignore this question. I thought everything for the response is done after HttpChannelChild::OnStopRequest(), but we need to read the stream out and propograte it to the response to the controlling document.
Hi Ben,

Could you help me to review this patch? Thanks!

I put the changes in comment #36 comment #40, comment #45, and comment #46. 

Please feel free to cancel the request if you don't agree with the explanation in comment #45
Attachment #8929372 - Attachment is obsolete: true
Attachment #8930030 - Flags: review?(bkelly)
(In reply to Tom Tung [:tt] from comment #45)
> In the test case (internal redirect), it fetch a fake cross origin URL with
> no-cors mode on the tab (empty.html) and observe the channel with
> "http-on-stop-request" topic. Then, the registered service worker intercepts
> the request and responds with another fetch, which fetching a cross origin
> "hello" document in "no-cors" mode as well.
> 
> I expect to get two channel for "http-on-stop-request" for the corrss origin
> "hello" document from the observer. One is due to fetching on the service
> worker. The other is because the client document (empty.html) fetch an
> "internal-redirected" request. (But, I cannot understand that why is the
> second request I got in the test triggering from InputStreamPump rather than
> HttpChannelChild::OnStopRequest()). Other test case won't have the same
> problem because we won't do the internal redirect to them.

Ohhhh... I think I understand now.  I thought you were saying you had one nsIChannel and two http-on-stop-request notifications.  But we really have two nsIChannel objects.  One for the "outer" window request and one for the "inner" service worker request.  Ok, that makes sense.

> IIUC, we decide not showing the request/response from service worker on the
> controlling document, right? (Only showing the request/response from that
> document).

I'm not 100% sure I understand this question.  Ideally I think network panel should show:

1. A line for the "outer" window request.  This includes interception timing information.
2. A line for the "inner" service worker request.  This does not include interception timing information (because its not intercepted).

The line for (1) should completely encompass the line for (2) when the service worker does something like `evt.respondWith(fetch(url))`.

Does that help?
Comment on attachment 8930030 [details] [diff] [review]
Bug 1415388 - P3: Fix the issues on try. r?bkelly

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

r=me assuming that this is really dealing with an ordering problem as I postulate below.  If the internal redirect is creating a new "http-on-stop-request" notification that did not exist before then we probably need to dig into why.

::: dom/workers/test/serviceworkers/browser_devtools_serviceworker_interception.js
@@ +20,5 @@
>    let interceptedChannel = null;
> +
> +  // When an internal redirect happens, the DoOnStopRequest(), where notifies
> +  // the observer with "http-on-stop-request" topic, will be called twice. And,
> +  // the timing data is saved at the second time, so we must wait for it.

This comment is confusing to me given your previous comment in the bug.  If the reason we are getting two "http-on-stop-request" notifications is because there are two channels for the outer window and the inner service worker fetch, why does the internal redirect matter at all here?

Are there always two "http-on-stop-request" notifications and the internal redirect just changes the order that they are received in?

@@ +21,5 @@
> +
> +  // When an internal redirect happens, the DoOnStopRequest(), where notifies
> +  // the observer with "http-on-stop-request" topic, will be called twice. And,
> +  // the timing data is saved at the second time, so we must wait for it.
> +  let waitForSecondOnStopReuqest = aInput.redirect;

nit: s/Reuqest/Request/
Attachment #8930030 - Flags: review?(bkelly) → review+
(In reply to Ben Kelly [:bkelly] from comment #48)
> Ohhhh... I think I understand now.  I thought you were saying you had one
> nsIChannel and two http-on-stop-request notifications.  But we really have
> two nsIChannel objects.  One for the "outer" window request and one for the
> "inner" service worker request.  Ok, that makes sense.

Yes, that's what I meant. Sorry for the confusion. 

> I'm not 100% sure I understand this question.  Ideally I think network panel
> should show:
> 
> 1. A line for the "outer" window request.  This includes interception timing
> information.
> 2. A line for the "inner" service worker request.  This does not include
> interception timing information (because its not intercepted).
> 
> The line for (1) should completely encompass the line for (2) when the
> service worker does something like `evt.respondWith(fetch(url))`.
> 
> Does that help?

Oh, I see. Yes, that does help! Thanks!

(In reply to Ben Kelly [:bkelly] from comment #49)
> r=me assuming that this is really dealing with an ordering problem as I
> postulate below.  If the internal redirect is creating a new
> "http-on-stop-request" notification that did not exist before then we
> probably need to dig into why.

Thanks for the review!

> :::
> dom/workers/test/serviceworkers/browser_devtools_serviceworker_interception.
> js
> @@ +20,5 @@
> >    let interceptedChannel = null;
> > +
> > +  // When an internal redirect happens, the DoOnStopRequest(), where notifies
> > +  // the observer with "http-on-stop-request" topic, will be called twice. And,
> > +  // the timing data is saved at the second time, so we must wait for it.
> 
> This comment is confusing to me given your previous comment in the bug.  If
> the reason we are getting two "http-on-stop-request" notifications is
> because there are two channels for the outer window and the inner service
> worker fetch, why does the internal redirect matter at all here?

Sorry for the confusion. The test filters the channel via whether response.URL is the same as the request.URL (I believe we may need to change it after bug 1222008). Thus, I bump into this problem after adding a test for internal redirect.

> Are there always two "http-on-stop-request" notifications and the internal
> redirect just changes the order that they are received in?

Yes, but I can distinguish them by the URI of the channel, since they are testing that a service worker intercepts a request (fake.html) and responds with different URL (hello.html). Furthermore, we have not propagated the URL to the response yet (except the internal redirect), so I always got two channels in different for the other tests by catching the "http-on-stop-request" notification.

> @@ +21,5 @@
> > +
> > +  // When an internal redirect happens, the DoOnStopRequest(), where notifies
> > +  // the observer with "http-on-stop-request" topic, will be called twice. And,
> > +  // the timing data is saved at the second time, so we must wait for it.
> > +  let waitForSecondOnStopReuqest = aInput.redirect;
> 
> nit: s/Reuqest/Request/

Sure.
Address the comment
Attachment #8930030 - Attachment is obsolete: true
Attachment #8930323 - Flags: review+
try looks good
Keywords: checkin-needed
https://hg.mozilla.org/integration/mozilla-inbound/rev/051a59c4a53a6434c25c2460155c549f69fedd24
Bug 1415388 - P1: Move the test_devtools_serviceworker_interception to a browser test. r=bkelly

https://hg.mozilla.org/integration/mozilla-inbound/rev/39d8372dd2e7dd853c09d922a206f0fd3d09be49
Bug 1415388 - P2: Add a test to verify pass timing data correctlly after an internal redirect. r=bkelly

https://hg.mozilla.org/integration/mozilla-inbound/rev/d28a3ef4867908a8024ba705c1773c82c92171b8
Bug 1415388 - P3: Fix the issues on try. r=bkelly
Keywords: checkin-needed
You need to log in before you can comment on or make changes to this bug.