Closed Bug 1421803 Opened 3 years ago Closed 3 years ago

ThreatHit requests are sent too early

Categories

(Toolkit :: Safe Browsing, defect, P1)

defect

Tracking

()

RESOLVED FIXED
mozilla59
Tracking Status
firefox59 --- fixed

People

(Reporter: francois, Assigned: francois)

References

Details

(Whiteboard: pwphish-threathit)

Attachments

(1 file)

I added a bunch of log messages and found that ThreatHit calls fail:

[Main Thread]: D/nsChannelClassifier nsChannelClassifier[0x7f68f93546c0]::SendThreatHitReport BEFORE SERVICE LOOKUP
[Main Thread]: D/nsChannelClassifier nsChannelClassifier[0x7f68f93546c0]::SendThreatHitReport BEFORE SERVICE CALL
[Main Thread]: D/UrlClassifierDbService nsUrlClassifierDBService[0x7f68b90397c0]::SendThreatHitReport
[Parent 8981, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /home/francois/devel/mozilla-unified/netwerk/base/nsChannelClassifier.cpp, line 1126

right here: https://searchfox.org/mozilla-central/rev/7a8c667bdd2a4a32746c9862356e199627c0896d/netwerk/base/nsChannelClassifier.cpp#1121

That failure code is NS_ERROR_FAILURE and comes from here: https://searchfox.org/mozilla-central/rev/7a8c667bdd2a4a32746c9862356e199627c0896d/toolkit/components/url-classifier/nsUrlClassifierDBService.cpp#2049

and so the problem is that the channel hasn't received a provider via SetMatchedInfo(). Commenting out the other return statements reveals that the channel doesn't have a provider, listname or fullhash set.

It appears that this is due to SetMatchedInfo() getting called after SendThreatHit():

[Main Thread]: D/nsChannelClassifier nsChannelClassifier::SendThreatHitReport START
[Main Thread]: D/nsChannelClassifier nsChannelClassifier::SendThreatHitReport BEFORE SERVICE LOOKUP
[Main Thread]: D/nsChannelClassifier nsChannelClassifier::SendThreatHitReport BEFORE SERVICE CALL
[Main Thread]: D/UrlClassifierDbService nsUrlClassifierDBService::SendThreatHitReport cannot get provider: NS_OK
[Main Thread]: D/UrlClassifierDbService nsUrlClassifierDBService::SendThreatHitReport cannot get listname
[Main Thread]: D/UrlClassifierDbService nsUrlClassifierDBService::SendThreatHitReport cannot get fullhash
[Main Thread]: D/nsChannelClassifier nsChannelClassifier::SendThreatHitReport CALL returned NS_ERROR_FAILURE
[Parent 4600, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /home/francois/devel/mozilla-unified/netwerk/base/nsChannelClassifier.cpp, line 1138
[Main Thread]: D/nsChannelClassifier nsChannelClassifier[0x7f0962d371c0]: resuming channel 0x7f09656ec050 from OnClassifyComplete
[Main Thread]: D/nsChannelClassifier ***** SET MATCHED INFO: (goog-malware-proto, google4) *****
Comment on attachment 8933102 [details]
Bug 1421803 - Send ThreatHit requests and telemetry at the right time.

https://reviewboard.mozilla.org/r/204076/#review209558

::: toolkit/components/url-classifier/nsUrlClassifierHashCompleter.js
(Diff revision 1)
>        // FullHashResponse.
>        onCompleteHashFound: (aCompleteHash,
>                              aTableNames,
>                              aPerHashCacheDuration) => {
>          log("V4 fullhash response complete hash found callback: " +
> -            JSON.stringify(aCompleteHash) + ", " +

Logging this to the console can hang the terminal due to the presence of control characters in the binary output.
Comment on attachment 8933102 [details]
Bug 1421803 - Send ThreatHit requests and telemetry at the right time.

https://reviewboard.mozilla.org/r/204076/#review209642

Hi francois,
I am not familiar with the design here, could you help check my comment below?
Thanks!

::: netwerk/base/nsChannelClassifier.cpp:834
(Diff revision 2)
>    }
>  
> +  if (aErrorCode == NS_ERROR_MALWARE_URI ||
> +      aErrorCode == NS_ERROR_PHISHING_URI ||
> +      aErrorCode == NS_ERROR_UNWANTED_URI ||
> +      aErrorCode == NS_ERROR_HARMFUL_URI) {

Not sure if this is a concern, moving SendThreatHitReport here means we are doing it in child side instead of parent side.

I am not familiar with the design here, please correct me if anything wrong.

Right now we will call SetMatchedInfo twice for the same child channel (none for parent), one from [1], another via IPC call parentChannel->SetClassifierMatchedInfo[2]. So that's why we call SendThreathitReport fail in parent.

Another approach could be move the |classifiedChannel->SetMatchedInfo|
to the beginning of this function and remove the  parentChannel->SetClassifierMatchedInfo.
Then we will have both SetMatchInfo for child channel[3] and parent channel[4].
In this case, then don't have to move the SendThreatHitReport inside SetBlockedContent.

But maybe I miss the point why we added |parentChannel->SetClassifierMatchedInfo| in the first place.


[1] https://searchfox.org/mozilla-central/source/netwerk/base/nsChannelClassifier.cpp#828
[2] https://searchfox.org/mozilla-central/source/netwerk/base/nsChannelClassifier.cpp#819
[3] https://searchfox.org/mozilla-central/source/netwerk/protocol/http/HttpChannelChild.cpp#1197
[4] https://searchfox.org/mozilla-central/source/netwerk/base/nsChannelClassifier.cpp#1157

::: toolkit/components/url-classifier/nsUrlClassifierDBService.cpp:1973
(Diff revision 2)
>  NS_IMETHODIMP
> -ThreatHitReportListener::OnStartRequest(nsIRequest* aRequest, nsISupports* aContext)
> +ThreatHitReportListener::OnStartRequest(nsIRequest* aRequest,
> +                                        nsISupports* aContext)
>  {
>    nsCOMPtr<nsIHttpChannel> httpChannel = do_QueryInterface(aRequest);
> -  if (httpChannel) {
> +  if (httpChannel && LOG_ENABLED()) {

We could move do_QueryInterface inside LOG_ENABLED() 

if (LOG_ENABLED()) {
  nsCOMPtr<nsIHttpChannel> httpChannel = do_QueryInterface(aRequest);
  NS_ENSURE_TRUE(httpChannel, NS_OK)
  ...
}

::: toolkit/components/url-classifier/nsUrlClassifierDBService.cpp:2122
(Diff revision 2)
>  
>    nsAutoCString reportUriStr = NS_ConvertUTF16toUTF8(urlStr);
>    reportUriStr.Append("&$req=");
>    reportUriStr.Append(reportBody);
> +
> +  if (LOG_ENABLED()) {

I think we don't need the LOG_ENABLED() here since there is no extra cost when log is not enabled
Attachment #8933102 - Flags: review?(dlee)

(In reply to Dimi Lee[:dimi][:dlee] from comment #4)
> Comment on attachment 8933102 [details]
> Bug 1421803 - Send ThreatHit requests and telemetry at the right time.
> 
> https://reviewboard.mozilla.org/r/204076/#review209642

> Not sure if this is a concern, moving SendThreatHitReport here means we are
> doing it in child side instead of parent side.

Agree with Dimi. It would be ok to put SendThreatHitReport in child, but I think it would be better to be able to run it in both child and parent (reduce channel ipc cost from child to parent).

> I am not familiar with the design here, please correct me if anything wrong.
> 
> Right now we will call SetMatchedInfo twice for the same child channel (none
> for parent), one from [1], another via IPC call
> parentChannel->SetClassifierMatchedInfo[2]. So that's why we call
> SendThreathitReport fail in parent.
> 
> Another approach could be move the |classifiedChannel->SetMatchedInfo|
> to the beginning of this function and remove the 
> parentChannel->SetClassifierMatchedInfo.
> Then we will have both SetMatchInfo for child channel[3] and parent
> channel[4].
> In this case, then don't have to move the SendThreatHitReport inside
> SetBlockedContent.
The parent channel is not derived from nsIClassifiedChannel, so, in that way we may want to add more codes in HttpParentChannel to support that interface.
> 
> But maybe I miss the point why we added
> |parentChannel->SetClassifierMatchedInfo| in the first place.
As I remember, all we need from the matchedInfo is that we could query the information from child UI code (so, just ignore parent).
Alternative approach is, we could change SendThreatHitReport(nsIChannel *aChannel) to SendThreatHitReport(nsACString provider, nsACString table, nsACString fullhash) from several lines above. Don't need to query classifiedChannel, and it should be safe. Sorry, that was my original patch, and my last change to use classifiedChannel did not check the content-parent stuff. Although we have a test, it appears the test_threat_report is running on child, do we need to complement that mochitest to test in parent(just my idea)? 
https://searchfox.org/mozilla-central/rev/be78e6ea9b10b1f5b2b3b013f01d86e1062abb2b/netwerk/base/nsChannelClassifier.cpp#1127
Comment on attachment 8933102 [details]
Bug 1421803 - Send ThreatHit requests and telemetry at the right time.

https://reviewboard.mozilla.org/r/204076/#review209642

Thanks for your review Dimi!

Don't forget that you are more than welcome to give me an r- when you think I should make changes before landing ;)

> Not sure if this is a concern, moving SendThreatHitReport here means we are doing it in child side instead of parent side.
> 
> I am not familiar with the design here, please correct me if anything wrong.
> 
> Right now we will call SetMatchedInfo twice for the same child channel (none for parent), one from [1], another via IPC call parentChannel->SetClassifierMatchedInfo[2]. So that's why we call SendThreathitReport fail in parent.
> 
> Another approach could be move the |classifiedChannel->SetMatchedInfo|
> to the beginning of this function and remove the  parentChannel->SetClassifierMatchedInfo.
> Then we will have both SetMatchInfo for child channel[3] and parent channel[4].
> In this case, then don't have to move the SendThreatHitReport inside SetBlockedContent.
> 
> But maybe I miss the point why we added |parentChannel->SetClassifierMatchedInfo| in the first place.
> 
> 
> [1] https://searchfox.org/mozilla-central/source/netwerk/base/nsChannelClassifier.cpp#828
> [2] https://searchfox.org/mozilla-central/source/netwerk/base/nsChannelClassifier.cpp#819
> [3] https://searchfox.org/mozilla-central/source/netwerk/protocol/http/HttpChannelChild.cpp#1197
> [4] https://searchfox.org/mozilla-central/source/netwerk/base/nsChannelClassifier.cpp#1157

I'll try the approach that Thomas suggested in comment 5 (expanding the parameters of `SendThreatHitReport()`).

> We could move do_QueryInterface inside LOG_ENABLED() 
> 
> if (LOG_ENABLED()) {
>   nsCOMPtr<nsIHttpChannel> httpChannel = do_QueryInterface(aRequest);
>   NS_ENSURE_TRUE(httpChannel, NS_OK)
>   ...
> }

Good point. In fact that whole function doesn't need to do anything if logging is disabled. I'll put an early return in there.

> I think we don't need the LOG_ENABLED() here since there is no extra cost when log is not enabled

Good catch.
(In reply to François Marier [:francois] from comment #7)
> https://reviewboard.mozilla.org/r/204076/diff/2-3/

Is that what you had in mind Thomas?
Flags: needinfo?(tnguyen)
Yes, that's it :)
Flags: needinfo?(tnguyen)
Comment on attachment 8933102 [details]
Bug 1421803 - Send ThreatHit requests and telemetry at the right time.

https://reviewboard.mozilla.org/r/204076/#review210402

Looks good, Thanks!
Attachment #8933102 - Flags: review?(dlee) → review+
Pushed by fmarier@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/611182749ede
Send ThreatHit requests and telemetry at the right time. r=dimi
https://hg.mozilla.org/mozilla-central/rev/611182749ede
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla59
You need to log in before you can comment on or make changes to this bug.