1421803 - ThreatHit requests are sent too early

Assignee

Description

•

5 years ago

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 hidden (mozreview-request)

The ThreatHit requests were never being sent because SetMatchedInfo() was
called on the channel _after_ calling SendThreatHitReport().

Additionally, the telemetry was sent in OnStartRequest() and so errors
returned in OnStopRequest() would not be caught.

This patch also includes some improvements to the logging of these
requests which can be toggled using:

    MOZ_LOG="UrlClassifierDbService:5,nsChannelClassifier:5"

Review commit: https://reviewboard.mozilla.org/r/204076/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/204076/

François Marier [:francois]

Assignee

Comment 2

•

5 years ago

mozreview-review

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 hidden (mozreview-request)

Comment on attachment 8933102 [details]
Bug 1421803 - Send ThreatHit requests and telemetry at the right time.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/204076/diff/1-2/

Dimi Lee [:dimi][:dlee]

Comment 4

•

5 years ago

mozreview-review

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)

Thomas Nguyen (:tnguyen)

Comment 5

•

5 years ago


(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

François Marier [:francois]

Assignee

Comment 6

•

5 years ago

mozreview-review-reply

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.

Comment hidden (mozreview-request)

Comment on attachment 8933102 [details]
Bug 1421803 - Send ThreatHit requests and telemetry at the right time.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/204076/diff/2-3/

François Marier [:francois]

Assignee

Comment 8

•

5 years ago

(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)

Thomas Nguyen (:tnguyen)

Comment 9

•

5 years ago

Yes, that's it :)

Flags: needinfo?(tnguyen)

François Marier [:francois]

Assignee

Comment 10

•

5 years ago

Try looks good: https://treeherder.mozilla.org/#/jobs?repo=try&revision=2008b9dfb8550252eee453c91f39595f9ea4affc

Dimi Lee [:dimi][:dlee]

Comment 11

•

5 years ago

mozreview-review

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+

Pulsebot

Comment 12

•

5 years ago

Pushed by fmarier@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/611182749ede
Send ThreatHit requests and telemetry at the right time. r=dimi

Bogdan Tara[:bogdan_tara | bogdant]

Comment 13

•

5 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/611182749ede

Status: ASSIGNED → RESOLVED

Closed: 5 years ago

status-firefox59: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → mozilla59

Bugzilla

ThreatHit requests are sent too early

Categories

(Toolkit :: Safe Browsing, defect, P1)

Tracking

()

People

(Reporter: francois, Assigned: francois)

References

Details

(Whiteboard: pwphish-threathit)

Crash Data

Security

(public)

User Story

Attachments

(1 file)

Description

Comment 1

Comment 2

Comment 3

Comment 4

Comment 5

Comment 6

Comment 7

Comment 8

Comment 9

Comment 10

Comment 11

Comment 12

Comment 13