Sorry for the delay!

I finally found some time to test this, but the patch is not synced
with latest head. Could you please rebase it, thanks!

Honza

You will very likely be faster than me ;) Won't get to this sooner than next week, if then.

Andrea, I would use some help with rebasing the patch here. I managed to hg rebase it, but there is a too big conflict at hunk [1]. The purpose was to mark the channel as 'classified from tracking.' Right now, after patch [2], I can't see where to put that particular NS_SetRequestBlockingReason call.

Can you please navigate me to the right place? Also, could it just be added as another case: at [3]?

Thanks!

[1] https://bugzilla.mozilla.org/attachment.cgi?id=9019083&action=diff#a/netwerk/base/nsChannelClassifier.cpp_sec2
[2] https://hg.mozilla.org/mozilla-central/rev/0cc5e8d1a09d
[3] https://bugzilla.mozilla.org/attachment.cgi?id=9019083&action=diff#a/netwerk/base/nsChannelClassifier.cpp_sec3

(note for me: fastblock has been removed from httpchan at https://hg.mozilla.org/mozilla-central/diff/dd23df519c7e/netwerk/protocol/http/nsHttpChannel.cpp)

I haven't checked what the patch does in the detail. I just converted it to the new codebase.

Thanks for the rebase Andrea!

I was testing the patch on my machine and the new nsILoadInfo.requestBlockingReason is always set to 0 for me.

Here is what I am doing:

1. Open DevTools Toolbox and Select the Network panel
2. Load https://googlesamples.github.io/web-fundamentals/fundamentals/security/prevent-mixed-content/active-mixed-content.html
3. Check out your system console for logs:

I created logs in:

• onStartRequest
  https://searchfox.org/mozilla-central/rev/5c8ea961d04767db723a0a15e3a8f7fbca154129/devtools/server/actors/network-monitor/network-response-listener.js#202

• onStopRequest
  https://searchfox.org/mozilla-central/rev/5c8ea961d04767db723a0a15e3a8f7fbca154129/devtools/server/actors/network-monitor/network-response-listener.js#320

I did something as follows when logging the value:

console.log(channel.loadInfo.requestBlockingReason);

Does the patch work for you?
Or am I doing something wrong?

Honza

thanks :baku!

• added also mixed content blocking (was missing in v1)

Honza, please check this one again.

Thanks for the update!

I just tested the new patch with:
https://googlesamples.github.io/web-fundamentals/fundamentals/security/prevent-mixed-content/active-mixed-content.html

...and I am still only seeing 0 when reading channel.loadInfo.requestBlockingReason for all requests executed by the page.

The Console panel is showing that the page generates mixed content messages, so there should be some non-zero results.

Honza

I am attaching a patch I am using for logging.
If you apply the patch on top of the platform/api patch and load the page (mentioned in the previous comment), you should see logs in the system console (there is always 0 for me).

Honza

Requests reporting 0 are not blocked.

Mixed content blocking happens at the time of asyncOpen, it makes asyncOpen fail, so then there is no onStart/StopRequest (and I don't know where from the _createNetworkEvent call comes). To handle this is beyond the scope of this bug, the information hangs of off the channel's load info (on child), though.

The patch works as it has to.

Thanks for the update!

Here is another test case I have:
http://janodvarko.cz/tests/bugzilla/1493599/

1. Load the page, enable the Network panel
2. Click the button on the page
3. CORS request is executed and blocked, this error appears in the Console panel:
   Cross-Origin Request Blocked: The Same Origin Policy disallows reading the remote resource at https://www.google.com/. (Reason: CORS header ‘Access-Control-Allow-Origin’ missing).

But, the blocked reason is always 0 for me.

Is this similar to the case above? (with mixed content)

Honza

​

Probably. At which point do you read the blocked reason value?

The Network panel (backend) is using nsIHttpActivityDistributor and listening for ACTIVITY_SUBTYPE_REQUEST_HEADER event. When this event happens the patch reads channel.loadInfo.requestBlockingReason flag and prints it using console.log.

There is also custom response listener (nsIRequestObserver) set at the same time (ACTIVITY_SUBTYPE_REQUEST_HEADER fired) through nsITraceableChannel. The patch reads channel.loadInfo.requestBlockingReason flag and prints it when onStartRequest and onStopRequest happens.

Honza

(In reply to Jan Honza Odvarko [:Honza] (need-info? me) from comment #16)

The Network panel (backend) is using nsIHttpActivityDistributor and listening for ACTIVITY_SUBTYPE_REQUEST_HEADER event.

This happens ONLY when we decide to do a network request for the channel (either when there is no cached content, it's bypassed by flags, has to be revalidated or when we race cache and network) but NOT when we go from the cache.

My patch add the info at CheckRequestApproved, called (between else) from here:
https://searchfox.org/mozilla-central/rev/60c4067b1cbb0f94d7dc2d7cdfa27ed579817fee/netwerk/protocol/http/nsCORSListenerProxy.cpp#423

But this gets called from inside nsContentSecurityManager::doContentSecurityCheck called from AsyncOpen. At that moment you definitely don't know about that channel.

Hence, we may need to invent a new http-on-* notification for such cases.

Err! No, we add the CORS proxy from doContentSecurityCheck, but CheckRequestApproved is called from OnStartRequest, so this should just work.

(In reply to Honza Bambas (:mayhemer) from comment #17)

(In reply to Jan Honza Odvarko [:Honza] (need-info? me) from comment #16)

The Network panel (backend) is using nsIHttpActivityDistributor and listening for ACTIVITY_SUBTYPE_REQUEST_HEADER event.

This happens ONLY when we decide to do a network request for the channel (either when there is no cached content, it's bypassed by flags, has to be revalidated or when we race cache and network) but NOT when we go from the cache.

Note that I have cache disabled when testing this API.

Err! No, we add the CORS proxy from doContentSecurityCheck, but CheckRequestApproved is called from OnStartRequest, so this should just work.

I can see that LogBlockedRequest is called with CORSMissingAllowOrigin (in CheckRequestApproved, C++), but when reading channel.loadInfo.requestBlockingReason later in onStart/StopRequest (JS) it says 0.
(this happens when I am using my test case: http://janodvarko.cz/tests/bugzilla/1493599/)

Honza

Putting back to the triage pool, I have more important bugs assigned to me right now.

Baku, could you help get this over the hump?

I think what we need is a new "on-http-failed-open" notification triggered somewhere from [1]. If it's enough to be triggered on the child process, it's easy to do. If it has to be propagated to the parent in this form (i.e. via the necko code), then we have way more work to do.

[1] https://searchfox.org/mozilla-central/rev/cb7faaf6b4ad2528390186f1ce64618dea71031e/netwerk/protocol/http/HttpChannelChild.cpp#2548

Hi Jan, dev-tools run on the parent process. Can dev-tools get notification form a child process? I just want to know how much wotk it will be to implement comment #22.

@Alex, can you please look at the previous comment @23, thanks!

Honza

Most of the inspection work in done from the parent process, but we had to also start listening from the content process because of service workers (We might stop doing that with the newest SW implementation, that I don't know yet).

So, you have a good example of observer service message being listened either from the parent process and/or the content process over here:
https://searchfox.org/mozilla-central/source/devtools/server/actors/network-monitor/network-observer.js#200-212

Hopefully, this event is for notifying about a new request and not about augmenting the information of one being already inspected in the parent process? As I don't think we have anything already augmenting parent process inspection with data from the content process.

(In reply to Alexandre Poirot [:ochameau] from comment #25)

Most of the inspection work in done from the parent process, but we had to also start listening from the content process because of service workers (We might stop doing that with the newest SW implementation, that I don't know yet).

So, you have a good example of observer service message being listened either from the parent process and/or the content process over here:
https://searchfox.org/mozilla-central/source/devtools/server/actors/network-monitor/network-observer.js#200-212

Hopefully, this event is for notifying about a new request and not about augmenting the information of one being already inspected in the parent process? As I don't think we have anything already augmenting parent process inspection with data from the content process.

This will be a new request. The request is blocked so it will not get any other notification.

:mayhemer -- can you pick this back up? It's now blocking a devtools feature from shipping.

(In reply to Selena Deckelmann :selenamarie :selena use ni? pronoun: she from comment #27)

:mayhemer -- can you pick this back up? It's now blocking a devtools feature from shipping.

Absolutely.

(In reply to Honza Bambas (:mayhemer) from comment #29)

Created attachment 9050329 [details]
Bug 1493599 - Expose reason of security blocking on nsILoadInfo and add new http observer notification for failed asyncOpens, r=honza,dragana

This patch adds a new notification for all failed httpchannelchild::asyncopen. it only fires on the child process. this is still just a wip, I wrote a stub for observing this new notification in the dev tool's net observer which should be updated by Honza or someone from the dev team.

please let me know how this works for you.

@tanhengyeow: can you please test the patch, thanks!

Honza

(In reply to Jan Honza Odvarko [:Honza] (always need-info? me) from comment #31)

@tanhengyeow: can you please test the patch, thanks!

Honza

Please note that the patch needs some additional code to be added at _httpFailedOpening in network-observer.js. I didn't know how to go on from that point.

Hi :Honza

I pulled the patch, built the code (without artifact builds mode on), and tested the patch. Apart from a missing comma, I got this error when trying to open Devtools:

JavaScript error: resource://devtools/client/framework/attach-thread.js, line 79: TypeError: threadClient is undefined
console.error: "Exception while opening the toolbox" "Protocol error (unknownError): error occurred while processing 'startListeners: [Exception... \"Component returned failure code: 0x80004001 (NS_ERROR_NOT_IMPLEMENTED) [nsIObserverService.addObserver]\"  nsresult: \"0x80004001 (NS_ERROR_NOT_IMPLEMENTED)\"  location: \"JS frame :: resource://devtools/server/actors/network-monitor/network-observer.js :: init :: line 211\"  data: no]\nStack: init@resource://devtools/server/actors/network-monitor/network-observer.js:211:20\ninitialize@resource://devtools/server/actors/network-monitor.js:48:19\ncls@resource://devtools/shared/protocol.js:1254:25\nstartListeners@resource://devtools/server/actors/webconsole.js:617:13\nAsync*onPacket@resource://devtools/server/main.js:1291:58\nreceiveMessage@resource://devtools/shared/transport/child-transport.js:66:16\nMessageListener.receiveMessage*_addListener@resource://devtools/shared/transport/child-transport.js:40:14\nready@resource://devtools/shared/transport/child-transport.js:57:10\n_onConnection@resource://devtools/server/main.js:880:15\nconnectToParent@resource://devtools/server/main.js:296:17\nonConnect<@resource://devtools/server/startup/frame.js:59:35\nexports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:109:22\nMessageListener.receiveMessage*@resource://devtools/server/startup/frame.js:80:5\n@resource://devtools/server/startup/frame.js:160:5\nLine: 211, column: 0" "Protocol error (unknownError): error occurred while processing 'startListeners: [Exception... \"Component returned failure code: 0x80004001 (NS_ERROR_NOT_IMPLEMENTED) [nsIObserverService.addObserver]\"  nsresult: \"0x80004001 (NS_ERROR_NOT_IMPLEMENTED)\"  location: \"JS frame :: resource://devtools/server/actors/network-monitor/network-observer.js :: init :: line 211\"  data: no]\nStack: init@resource://devtools/server/actors/network-monitor/network-observer.js:211:20\ninitialize@resource://devtools/server/actors/network-monitor.js:48:19\ncls@resource://devtools/shared/protocol.js:1254:25\nstartListeners@resource://devtools/server/actors/webconsole.js:617:13\nAsync*onPacket@resource://devtools/server/main.js:1291:58\nreceiveMessage@resource://devtools/shared/transport/child-transport.js:66:16\nMessageListener.receiveMessage*_addListener@resource://devtools/shared/transport/child-transport.js:40:14\nready@resource://devtools/shared/transport/child-transport.js:57:10\n_onConnection@resource://devtools/server/main.js:880:15\nconnectToParent@resource://devtools/server/main.js:296:17\nonConnect<@resource://devtools/server/startup/frame.js:59:35\nexports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:109:22\nMessageListener.receiveMessage*@resource://devtools/server/startup/frame.js:80:5\n@resource://devtools/server/startup/frame.js:160:5\nLine: 211, column: 0"
undefined

As :mayhemer stated in the previous comment, I think additional code needs to be included "at _httpFailedOpening in network-observer.js" for it to be working so that we can test the patch properly. Still figuring out what to add, but thought I would give early feedback here first.

@tanhengyeow: thanks for testing!

I see, let's wait till :mayhemer has an updated version.

Honza

So, I fixed the two glitches, but adding dump() into the observer method doesn't show anything for me in the text console (maybe just because child process are not allowed to)

Can you please retest?

Hi :mayhemer

I tested your new patch with steps from comment 14. The Disable cache option is checked in network panel as well.

I'm logging the output using the code from the patch highlighted in comment 12.

The results are all 0 to me, here's a snippet of the output I see:

console.log: "---> blocked reason 0, url: https://www.google.com/\n"
console.log: "---> blocked reason 0, url: https://www.google.com/\n"
console.log: "---> blocked reason 0, url: http://ocsp.pki.goog/GTSGIAG3\n"
console.log: "---> blocked reason onStartRequest 0, url: http://ocsp.pki.goog/GTSGIAG3\n"
console.log: "---> blocked reason onStopRequest 0, url: http://ocsp.pki.goog/GTSGIAG3\n"
console.log: "---> blocked reason onStartRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStartRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStopRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStopRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason 0, url: https://www.google.com/\n"
console.log: "---> blocked reason 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStartRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStartRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStopRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStopRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason 0, url: https://www.google.com/\n"
console.log: "---> blocked reason 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStartRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStartRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStopRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStopRequest 0, url: https://www.google.com/\n"

(In reply to Heng Yeow (:tanhengyeow) from comment #36)

Hi :mayhemer

I tested your new patch with steps from comment 14. The Disable cache option is checked in network panel as well.

I'm logging the output using the code from the patch highlighted in comment 12.

The results are all 0 to me, here's a snippet of the output I see:

console.log: "---> blocked reason 0, url: https://www.google.com/\n"
console.log: "---> blocked reason 0, url: https://www.google.com/\n"
console.log: "---> blocked reason 0, url: http://ocsp.pki.goog/GTSGIAG3\n"
console.log: "---> blocked reason onStartRequest 0, url: http://ocsp.pki.goog/GTSGIAG3\n"
console.log: "---> blocked reason onStopRequest 0, url: http://ocsp.pki.goog/GTSGIAG3\n"
console.log: "---> blocked reason onStartRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStartRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStopRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStopRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason 0, url: https://www.google.com/\n"
console.log: "---> blocked reason 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStartRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStartRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStopRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStopRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason 0, url: https://www.google.com/\n"
console.log: "---> blocked reason 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStartRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStartRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStopRequest 0, url: https://www.google.com/\n"
console.log: "---> blocked reason onStopRequest 0, url: https://www.google.com/\n"

I have no idea what you are doing, but if you are using the patch from comment 12, then it will definitely not work.

You have to fill in the part in network-observer.js, _httpFailedOpening. There is a comment: // ...
Only there you can see the reason.

Hi :mayhemer

In my previous comment, I'm testing the patch with this test site, http://janodvarko.cz/tests/bugzilla/1493599/ as mentioned in comment 14.

The snippet of the output was logged in my terminal console by applying the patch from comment 12.

You have to fill in the part in network-observer.js, _httpFailedOpening. There is a comment: // ...
Only there you can see the reason.

I tried to log statements in the _httpFailedOpening function, but it is not triggered at all when tested with the test site, which meant logging statements won't show.

I placed debugger statement in that function as well, tested with the test site and confirmed that the function wasn't run at all.

We might need a different test method, or perhaps it is not reading the interface properly.

Just double checked that I am triggering the new notification from HttpChannelChild::AsyncOpen - let you know this happens ONLY on the content (child) process(es). I also confirmed that when no devtools window is open, there is no listener registered for the notification. When I open devtools in exactly one window there is then exactly one observer to the notification and it's being called. Honza O. has confirmed for me that my new code in network-observer.js that listens to that notification is correct and hence that it should trigger as expected. So I'm not sure what's happening and I'm not sure I can help more, I don't know the guts of network-observer at all - the problem must be there. Please ask Honza O for more help.

Mu comment 39 (and comment 37 actually too - I missed you are suddenly testing something the original test case now) is about the test case from comment 11.

The test case from comment 14 is doing something else. It tests CORS blocked request and that should be visible asynchronously (in OnStartRequest). Hence, checking with the logging patch from comment 12 was correct.

I'm going to look into it a bit more now.

OK, so for the test case from comment 14 I can see the following (added logging to where we set the blocking reason):

2019-03-15 10:57:49.989000 UTC - [Child 9404: Main Thread]: D/nsHttp HttpChannelChild::OnStartRequest [this=000001EFF28FF000]
2019-03-15 10:57:49.989000 UTC - [Child 9404: Main Thread]: V/loadinfo LoadInfo::SetRequestBlockingReason 000001EFF53BE370 0
2019-03-15 10:57:49.989000 UTC - [Child 9404: Main Thread]: D/nsHttp HttpChannelChild::DoOnStartRequest [this=000001EFF28FF000]
2019-03-15 10:57:49.989000 UTC - [Child 9404: Main Thread]: V/loadinfo LoadInfo::SetRequestBlockingReason 000001EFF53BE370 1005
2019-03-15 10:57:49.990000 UTC - [Child 9404: Main Thread]: D/nsHttp HttpChannelChild::Cancel [this=000001EFF28FF000, status=805303f4]
2019-03-15 10:57:49.990000 UTC - [Child 9404: Main Thread]: D/nsHttp HttpChannelChild::Cancel [this=000001EFF28FF000, status=805303f4]

The reason 1005 is from here:

 	xul.dll!mozilla::net::LoadInfo::SetRequestBlockingReason(1005) Line 1394	C++
 	xul.dll!NS_SetRequestBlockingReason(0x000001bd9b6f09b0, 1005) Line 2835	C++
 	xul.dll!NS_SetRequestBlockingReason(0x000001bda000c078, 1005) Line 2829	C++
 	xul.dll!LogBlockedRequest(0x000001bda000c078, 0x00007ff96c0d9d41, 0x0000000000000000, 1005, 0x000001bda000c078) Line 67	C++
 	xul.dll!nsCORSListenerProxy::CheckRequestApproved(0x000001bda000c078) Line 571	C++
 	xul.dll!nsCORSListenerProxy::OnStartRequest(0x000001bda000c078) Line 424	C++
	xul.dll!mozilla::net::HttpChannelChild::DoOnStartRequest(0x000001bda000c078, 0x0000000000000000) Line 668	C++
 	xul.dll!mozilla::net::HttpChannelChild::OnStartRequest(NS_OK, {...}, true, {...}, {...}, false, true, 0, 0, 0, {...}, {...}, {...}, {...}, 0, {...}, 0, true, {...}) Line 599	C++
 	xul.dll!mozilla::net::StartRequestEvent::Run() Line 438	C++
 	xul.dll!mozilla::net::ChannelEventQueue::RunOrEnqueue(0x000001bd9d0c8000, false) Line 211	C++
 	xul.dll!mozilla::net::HttpChannelChild::RecvOnStartRequest(NS_OK, {...}, true, {...}, {...}, false, true, 0, 0, 0, {...}, {...}, {...}, {...}, 0, 0, {...}, 0, true, {...}) Line 500	C++

To explain: blocking doesn't happen on the parent process, but solely on the content process. nsCORSListenerProxy intercepts the OnStartRequest call and sets the reason on the load info prior to calling the outer listener, which is an XHR in case devtools net monitor is not open.

When devtools are open, it is exactly the same! Apparently, you are observing only the channel on the parent process where the blocking doesn't happen at all and therefor there can't be any reason exposed.

You must observe onStartRequest on the child process (only?) to catch the blocking reason.

I think you should file a new bug for the devtools parts. This but should be dedicated only to the platform changes and the stub changes to expose the new failed-open notification.

(In reply to Honza Bambas (:mayhemer) from comment #42)

I think you should file a new bug for the devtools parts. This but should be dedicated only to the platform changes and the stub changes to expose the new failed-open notification.

There is already bug 1157817 that covers the DevTools part.

Honza

From Comment 41:

To explain: blocking doesn't happen on the parent process, but solely on the content process. nsCORSListenerProxy intercepts the OnStartRequest call and sets the reason on the load info prior to calling the outer listener, which is an XHR in case devtools net monitor is not open.
When devtools are open, it is exactly the same! Apparently, you are observing only the channel on the parent process where the blocking doesn't happen at all and therefor there can't be any reason exposed.
You must observe onStartRequest on the child process (only?) to catch the blocking reason.

Hi :ochameau

Do you have any idea how we can listen to child/content processes on the devtools side? I tried to find the logs (reproduced from Comment 36) in the browser toolbox as well as browser content toolbox but wasn't able to find any.

I've been testing this using the following STRs

1. Apply patch from Honza Bambas (needs minor rebasing on top of m-c)
2. Apply the attached 'logging' patch. There are logs from both child/parent process. There is a log from _httpFailedOpening (child process) and _createNetworkEvent (parent process)
3. Load http://janodvarko.cz/tests/bugzilla/1493599/ & open the Network panel
4. Click the button on the page to generate blocked request.
5. There is no log from _httpFailedOpening
6. Try loading https://poc.miki.it/strict-dynamic-tests/
7. There are many logs from _httpFailedOpening, but requestBlockingReason is always set to 0

@mayhemer: is there anything I am doing wrong?

Honza

c45

@mayhemer: did you have time to look at my comment?

It would be great it we can land this in 68.

Honza

(In reply to Jan Honza Odvarko [:Honza] (always need-info? me) from comment #45)

Created attachment 9057473 [details] [diff] [review]
blocked-reason-logging.patch

I've been testing this using the following STRs

1. Apply patch from Honza Bambas (needs minor rebasing on top of m-c)
2. Apply the attached 'logging' patch. There are logs from both child/parent process. There is a log from _httpFailedOpening (child process) and _createNetworkEvent (parent process)
3. Load http://janodvarko.cz/tests/bugzilla/1493599/ & open the Network panel
4. Click the button on the page to generate blocked request.
5. There is no log from _httpFailedOpening

because the only request to https://www.google.com/ is not blocked.

6. Try loading https://poc.miki.it/strict-dynamic-tests/
7. There are many logs from _httpFailedOpening, but requestBlockingReason is always set to 0

you found another case: CSP policy. adding it now.

@mayhemer: Thanks for the update, but I am seeing conflicts when applying the patch on the latest m-c

Update: issue fixed on my side

Honza

The patch works for me, thanks :mayhemer for working on this!

Honza

https://hg.mozilla.org/mozilla-central/rev/8f9398c8c37d

I can confirm that the new platform API introduced in this bug is working as expected.
Thanks,
Honza

Since it requires a custom build + based on the above comment updating the status of this issue.
A quick check with STR from comment 14 revealed no issues.