1370585 - Intermittent toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html | ping should reach page in blacklist when tracking protection is off - got true, expected false

Status: RESOLVED FIXED

(Toolkit :: Safe Browsing, defect, P2)

Description

[Treeherder Bug Filer]

Filed by: rvandermeulen [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=104896195&repo=mozilla-inbound

https://queue.taskcluster.net/v1/task/YYnl53viTFCiZTZpZN6qkw/runs/0/artifacts/public/logs/live_backing.log

Comment 1

[Intermittent Failures Robot]

39 failures in 147 pushes (0.265 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* autoland: 20
* mozilla-inbound: 18
* mozilla-central: 1

Platform breakdown:
* android-4-3-armv7-api15: 38
* linux32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1370585&startday=2017-06-16&endday=2017-06-16&tree=all

Comment 2

[Joel Maher ( :jmaher ) (UTC -8) (PTO back normal Nov 17)]

primarily on android debug, this started June 14th and has had a high rate since then.

I have started some retriggers here:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-searchStr=mochitest-48&tochange=f65461f10e0a07b2ef94c51df003eda1612f6285&fromchange=6d2026f8b291d0aa09168d41e361dc6fafcfc410&selectedJob=106951381

Not sure if this will help find a root cause or not.


In the earlier log on the 14th:
https://queue.taskcluster.net/v1/task/NhDIeL-mTECn6aI3NrIldA/runs/0/artifacts/public/logs/live_backing.log

I see this text:
[task 2017-06-14T14:23:44.380842Z] 14:23:44     INFO -  151 INFO TEST-START | toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html
[task 2017-06-14T14:23:55.326101Z] 14:23:55     INFO -  Buffered messages logged at 14:23:40
[task 2017-06-14T14:23:55.326248Z] 14:23:55     INFO -  152 INFO TEST-PASS | toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html | A valid string reason is expected
[task 2017-06-14T14:23:55.326362Z] 14:23:55     INFO -  153 INFO TEST-PASS | toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html | Reason cannot be empty
[task 2017-06-14T14:23:55.326414Z] 14:23:55     INFO -  Buffered messages logged at 14:23:46
[task 2017-06-14T14:23:55.326530Z] 14:23:55     INFO -  154 INFO TEST-FAIL | toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html | The author of the test has indicated that flaky timeouts are expected.  Reason: Delay to make sure ping is made prior than XHR
[task 2017-06-14T14:23:55.326615Z] 14:23:55     INFO -  155 INFO TEST-PASS | toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html | ping should reach page not in blacklist
[task 2017-06-14T14:23:55.326665Z] 14:23:55     INFO -  Buffered messages logged at 14:23:47
[task 2017-06-14T14:23:55.326776Z] 14:23:55     INFO -  156 INFO TEST-FAIL | toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html | The author of the test has indicated that flaky timeouts are expected.  Reason: Delay to make sure ping is made prior than XHR
[task 2017-06-14T14:23:55.326825Z] 14:23:55     INFO -  Buffered messages finished
[task 2017-06-14T14:23:55.326925Z] 14:23:55     INFO -  157 INFO TEST-UNEXPECTED-FAIL | toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html | ping should reach page in blacklist when tracking protection is off - got true, expected false
[task 2017-06-14T14:23:55.326991Z] 14:23:55     INFO -      SimpleTest.is@SimpleTest/SimpleTest.js:312:5
[task 2017-06-14T14:23:55.327286Z] 14:23:55     INFO -      isPingedWithRetry/xhr.onload@toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html:96:9
[task 2017-06-14T14:23:55.327641Z] 14:23:55     INFO -  158 INFO TEST-FAIL | toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html | The author of the test has indicated that flaky timeouts are expected.  Reason: Delay to make sure ping is made prior than XHR
[task 2017-06-14T14:23:55.328170Z] 14:23:55     INFO -  159 INFO TEST-PASS | toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html | ping should not reach page in blacklist when tracking protection is on
[task 2017-06-14T14:23:55.328637Z] 14:23:55     INFO -  160 INFO TEST-OK | toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html | took 14772ms


With this higher failure rate I would like to see us get some type of resolution on this in the next week (fixed, reduced, disabled)

:francois, I see you are the triage owner for this component, can you find someone from the safe browsing team to look at this?

Comment 3

[Intermittent Failures Robot]

75 failures in 814 pushes (0.092 failures/push) were associated with this bug in the last 7 days. 

This is the #23 most frequent failure this week. 

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **  

Repository breakdown:
* mozilla-inbound: 41
* autoland: 33
* mozilla-central: 1

Platform breakdown:
* android-4-3-armv7-api15: 72
* linux32: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1370585&startday=2017-06-12&endday=2017-06-18&tree=all

Comment 4

[Henry Chang [:hchang]]

(In reply to Joel Maher ( :jmaher) from comment #2)
> primarily on android debug, this started June 14th and has had a high rate
> since then.
> 
> I have started some retriggers here:
> https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-
> searchStr=mochitest-
> 48&tochange=f65461f10e0a07b2ef94c51df003eda1612f6285&fromchange=6d2026f8b291d
> 0aa09168d41e361dc6fafcfc410&selectedJob=106951381
> 
> Not sure if this will help find a root cause or not.
> 
> 
> In the earlier log on the 14th:
> https://queue.taskcluster.net/v1/task/NhDIeL-mTECn6aI3NrIldA/runs/0/
> artifacts/public/logs/live_backing.log
> 
> I see this text:
> [task 2017-06-14T14:23:44.380842Z] 14:23:44     INFO -  151 INFO TEST-START
> | toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html
> [task 2017-06-14T14:23:55.326101Z] 14:23:55     INFO -  Buffered messages
> logged at 14:23:40
> [task 2017-06-14T14:23:55.326248Z] 14:23:55     INFO -  152 INFO TEST-PASS |
> toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html |
> A valid string reason is expected
> [task 2017-06-14T14:23:55.326362Z] 14:23:55     INFO -  153 INFO TEST-PASS |
> toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html |
> Reason cannot be empty
> [task 2017-06-14T14:23:55.326414Z] 14:23:55     INFO -  Buffered messages
> logged at 14:23:46
> [task 2017-06-14T14:23:55.326530Z] 14:23:55     INFO -  154 INFO TEST-FAIL |
> toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html |
> The author of the test has indicated that flaky timeouts are expected. 
> Reason: Delay to make sure ping is made prior than XHR
> [task 2017-06-14T14:23:55.326615Z] 14:23:55     INFO -  155 INFO TEST-PASS |
> toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html |
> ping should reach page not in blacklist
> [task 2017-06-14T14:23:55.326665Z] 14:23:55     INFO -  Buffered messages
> logged at 14:23:47
> [task 2017-06-14T14:23:55.326776Z] 14:23:55     INFO -  156 INFO TEST-FAIL |
> toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html |
> The author of the test has indicated that flaky timeouts are expected. 
> Reason: Delay to make sure ping is made prior than XHR
> [task 2017-06-14T14:23:55.326825Z] 14:23:55     INFO -  Buffered messages
> finished
> [task 2017-06-14T14:23:55.326925Z] 14:23:55     INFO -  157 INFO
> TEST-UNEXPECTED-FAIL |
> toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html |
> ping should reach page in blacklist when tracking protection is off - got
> true, expected false
> [task 2017-06-14T14:23:55.326991Z] 14:23:55     INFO -     
> SimpleTest.is@SimpleTest/SimpleTest.js:312:5
> [task 2017-06-14T14:23:55.327286Z] 14:23:55     INFO -     
> isPingedWithRetry/xhr.onload@toolkit/components/url-classifier/tests/
> mochitest/test_classify_ping.html:96:9
> [task 2017-06-14T14:23:55.327641Z] 14:23:55     INFO -  158 INFO TEST-FAIL |
> toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html |
> The author of the test has indicated that flaky timeouts are expected. 
> Reason: Delay to make sure ping is made prior than XHR
> [task 2017-06-14T14:23:55.328170Z] 14:23:55     INFO -  159 INFO TEST-PASS |
> toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html |
> ping should not reach page in blacklist when tracking protection is on
> [task 2017-06-14T14:23:55.328637Z] 14:23:55     INFO -  160 INFO TEST-OK |
> toolkit/components/url-classifier/tests/mochitest/test_classify_ping.html |
> took 14772ms
> 
> 
> With this higher failure rate I would like to see us get some type of
> resolution on this in the next week (fixed, reduced, disabled)
> 
> :francois, I see you are the triage owner for this component, can you find
> someone from the safe browsing team to look at this?

I had a look last week but haven't had an idea. Will spend more time looking
at this given that the failure rate is going higher and higher :(

Comment 5

[Henry Chang [:hchang]]

Attachment: Bug 1370585 - Periodically check the flag (at most 30 seconds) rather than checking only once.

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

Comment 6

[Henry Chang [:hchang]]

I don't know what change was made on 6/14 but the failed test
is a little timing sensitive: we trigger a "ping" for an anchor tag, 
wait a while then use XHR to check if the server state has been changed by 
the "ping" request. In theory the requests should be handled in the 
way "first-sent-first-come-first-served" so the waiting time shouldn't
matter. However, not all the operations (ping, XHR, blacklist check)
are synchronous so the waiting time might still be a thing. So, I changed
the one-time check to a periodic poll and it looks good in [1].

Francois, could you help review the patch given that the above argument?
I dup'ed 10 test cases and re-trigger a million times in [1] so it should be 
a good evidence to support what I've argued. 

Thanks.

[1] https://treeherder.mozilla.org/#/jobs?repo=try&revision=541473a1b112587bc20472b877e59b1f6c8b8651&selectedJob=108131977

Comment 7

[François Marier [:francois]]

Comment on attachment 8879087 [details]
Bug 1370585 - Periodically check the flag (at most 30 seconds) rather than checking only once.

https://reviewboard.mozilla.org/r/150424/#review155228

Comment 8

[François Marier [:francois]]

(In reply to Henry Chang [:hchang] from comment #6)
> Francois, could you help review the patch given that the above argument?
> I dup'ed 10 test cases and re-trigger a million times in [1] so it should be 
> a good evidence to support what I've argued. 

Sounds good to me. Let's merge and see how it goes. It should make this test more reliable.

Comment 9

[Intermittent Failures Robot]

30 failures in 151 pushes (0.199 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* autoland: 25
* mozilla-inbound: 5

Platform breakdown:
* android-4-3-armv7-api15: 30

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1370585&startday=2017-06-19&endday=2017-06-19&tree=all

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/d06f14a3eb8a
Periodically check the flag (at most 30 seconds) rather than checking only once. r=francois

Comment 11

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/d06f14a3eb8a

Comment 12

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/92582020c573

Comment 13

[Intermittent Failures Robot]

39 failures in 892 pushes (0.044 failures/push) were associated with this bug in the last 7 days.   

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. ** 

Repository breakdown:
* autoland: 27
* mozilla-inbound: 11
* try: 1

Platform breakdown:
* android-4-3-armv7-api15: 39

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1370585&startday=2017-06-19&endday=2017-06-25&tree=all

Comment 14

[Henry Chang [:hchang]]

The last failure was 7 days ago (6/20) so I am confident it has been actually fixed.