1683253 - Intermittent TEST-UNEXPECTED-TIMEOUT | toolkit/components/extensions/test/xpcshell/test_ext_webRequest_cancelWithReason.js | Test timed out

Status: REOPENED

(WebExtensions :: General, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: btara [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=324901855&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Z2eBbzcZRYeZx6jvXgZr7w/runs/0/artifacts/public/logs/live_backing.log

---

[task 2020-12-18T05:22:16.583Z] 05:22:16     INFO -  TEST-START | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_ext_webRequest_cancelWithReason.js
[task 2020-12-18T05:27:16.586Z] 05:27:16  WARNING -  TEST-UNEXPECTED-TIMEOUT | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_ext_webRequest_cancelWithReason.js | Test timed out
[task 2020-12-18T05:27:16.586Z] 05:27:16     INFO -  TEST-INFO took 300002ms
[task 2020-12-18T05:27:16.671Z] 05:27:16     INFO -  xpcshell return code: 143
[task 2020-12-18T05:27:16.704Z] 05:27:16  WARNING -  TEST-UNEXPECTED-FAIL | Received SIGINT (control-C), so stopped run. (Use --keep-going to keep running tests after killing one with SIGINT)
[task 2020-12-18T05:27:16.705Z] 05:27:16     INFO -  INFO | Result summary:
[task 2020-12-18T05:27:16.705Z] 05:27:16     INFO -  INFO | Passed: 394
[task 2020-12-18T05:27:16.705Z] 05:27:16  WARNING -  INFO | Failed: 1
[task 2020-12-18T05:27:16.705Z] 05:27:16  WARNING -  One or more unittests failed.
[task 2020-12-18T05:27:16.705Z] 05:27:16     INFO -  INFO | Todo: 4
[task 2020-12-18T05:27:16.705Z] 05:27:16     INFO -  INFO | Retried: 0
[task 2020-12-18T05:27:16.705Z] 05:27:16     INFO -  SUITE-END | took 942s
[task 2020-12-18T05:27:16.706Z] 05:27:16     INFO -  Node moz-http2 server shutting down ...
[task 2020-12-18T05:27:16.789Z] 05:27:16    ERROR - Return code: 1
[task 2020-12-18T05:27:16.789Z] 05:27:16     INFO - TinderboxPrint: xpcshell<br/>394/<em class="testfail">1</em>/4
[task 2020-12-18T05:27:16.790Z] 05:27:16     INFO - ##### xpcshell log ends
[task 2020-12-18T05:27:16.790Z] 05:27:16  WARNING - # TBPL WARNING #
[task 2020-12-18T05:27:16.790Z] 05:27:16  WARNING - setting return code to 1```

Comment 1

[Intermittent Failures Robot]

8 failures in 3421 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 7
• try: 1

Platform breakdown:

• android-em-7-0-x86_64-shippable: 8

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1683253&startday=2020-12-14&endday=2020-12-20&tree=all

Comment 2

[Intermittent Failures Robot]

4 failures in 1450 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 2
• mozilla-central: 2

Platform breakdown:

• android-em-7-0-x86_64-shippable: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1683253&startday=2020-12-21&endday=2020-12-27&tree=all

Comment 3

[Intermittent Failures Robot]

2 failures in 2956 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1
• try: 1

Platform breakdown:

• android-em-7-0-x86_64-shippable: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1683253&startday=2021-01-04&endday=2021-01-10&tree=all

Comment 4

[Intermittent Failures Robot]

4 failures in 3810 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1
• mozilla-central: 1
• autoland: 2

Platform breakdown:

• android-em-7-0-x86_64-shippable: 2
• android-em-7-0-x86_64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1683253&startday=2021-01-11&endday=2021-01-17&tree=all

Comment 5

[Intermittent Failures Robot]

18 failures in 587 pushes (0.031 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 18

Platform breakdown:

• android-em-7-0-x86_64: 18

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1683253&startday=2021-01-19&endday=2021-01-19&tree=all

Comment 6

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Fails frequently on Android, please investigate (first failures on 2020-12-18 UTC morning then almost gone, now back to frequent).

Comment 7

[Intermittent Failures Robot]

23 failures in 649 pushes (0.035 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 23

Platform breakdown:

• android-em-7-0-x86_64: 23

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1683253&startday=2021-01-20&endday=2021-01-20&tree=all

Comment 8

[Intermittent Failures Robot]

32 failures in 720 pushes (0.044 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 32

Platform and build breakdown:

• android-em-7-0-x86_64: 32
  • opt: 32

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1683253&startday=2021-01-21&endday=2021-01-21&tree=all

Comment 9

[Intermittent Failures Robot]

18 failures in 665 pushes (0.027 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 18

Platform and build breakdown:

• android-em-7-0-x86_64: 18
  • opt: 18

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1683253&startday=2021-01-22&endday=2021-01-22&tree=all

Comment 10

[Noemi Erli[:noemi_erli]]

We had 104 occurrences of this failure in the past week: https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2021-01-16&endday=2021-01-23&tree=all&bug=1683253, all of them on android-em-7-0-x86_64 opt.
Most recent one: https://treeherder.mozilla.org/logviewer?job_id=327556072&repo=autoland&lineNumber=2338

[task 2021-01-23T03:45:21.340Z] 03:45:21 INFO - TEST-START | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_ext_webRequest_cancelWithReason.js
[task 2021-01-23T03:50:21.341Z] 03:50:21 WARNING - TEST-UNEXPECTED-TIMEOUT | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_ext_webRequest_cancelWithReason.js | Test timed out
[task 2021-01-23T03:50:21.342Z] 03:50:21 INFO - TEST-INFO took 300001ms
[task 2021-01-23T03:50:21.413Z] 03:50:21 INFO - xpcshell return code: 143
[task 2021-01-23T03:50:21.442Z] 03:50:21 WARNING - TEST-UNEXPECTED-FAIL | Received SIGINT (control-C), so stopped run. (Use --keep-going to keep running tests after killing one with SIGINT)
[task 2021-01-23T03:50:21.442Z] 03:50:21 INFO - INFO | Result summary:
[task 2021-01-23T03:50:21.442Z] 03:50:21 INFO - INFO | Passed: 265
[task 2021-01-23T03:50:21.442Z] 03:50:21 WARNING - INFO | Failed: 1
[task 2021-01-23T03:50:21.442Z] 03:50:21 WARNING - One or more unittests failed.
[task 2021-01-23T03:50:21.442Z] 03:50:21 INFO - INFO | Todo: 0
[task 2021-01-23T03:50:21.442Z] 03:50:21 INFO - INFO | Retried: 0
[task 2021-01-23T03:50:21.442Z] 03:50:21 INFO - SUITE-END | took 844s
[task 2021-01-23T03:50:21.443Z] 03:50:21 INFO - Node moz-http2 server shutting down ...
[task 2021-01-23T03:50:21.567Z] 03:50:21 ERROR - Return code: 1
[task 2021-01-23T03:50:21.567Z] 03:50:21 INFO - TinderboxPrint: xpcshell<br/>265/<em class="testfail">1</em>/0
[task 2021-01-23T03:50:21.567Z] 03:50:21 INFO - ##### xpcshell log ends
[task 2021-01-23T03:50:21.567Z] 03:50:21 WARNING - # TBPL WARNING #
[task 2021-01-23T03:50:21.567Z] 03:50:21 WARNING - setting return code to 1
[task 2021-01-23T03:50:21.567Z] 03:50:21 WARNING - The xpcshell suite: xpcshell ran with return status: WARNING
[task 2021-01-23T03:50:21.567Z] 03:50:21 INFO - Running post-action listener: _package_coverage_data
[task 2021-01-23T03:50:21.568Z] 03:50:21 INFO - Running post-action listener: _resource_record_post_action
[task 2021-01-23T03:50:21.568Z] 03:50:21 INFO - Running post-action listener: process_java_coverage_data
[task 2021-01-23T03:50:21.568Z] 03:50:21 INFO - Running post-action listener: stop_device
[task 2021-01-23T03:50:21.948Z] 03:50:21 INFO - Killing logcat pid 1756.
[task 2021-01-23T03:50:21.948Z] 03:50:21 INFO - Killing every process called qemu-system-x86_64
[task 2021-01-23T03:50:21.958Z] 03:50:21 INFO - [mozharness: 2021-01-23 03:50:21.957658Z] Finished run-tests step (success)
[task 2021-01-23T03:50:21.958Z] 03:50:21 INFO - Running post-run listener: _resource_record_post_run
[task 2021-01-23T03:50:22.381Z] 03:50:22 INFO - Total resource usage - Wall time: 881s; CPU: 53.0%; Read bytes: 226567680; Write bytes: 2231271424; Read time: 55747; Write time: 209250
[task 2021-01-23T03:50:22.382Z] 03:50:22 INFO - TinderboxPrint: CPU usage<br/>53.5%
[task 2021-01-23T03:50:22.382Z] 03:50:22 INFO - TinderboxPrint: I/O read bytes / time<br/>226,567,680 / 55,747
[task 2021-01-23T03:50:22.382Z] 03:50:22 INFO - TinderboxPrint: I/O write bytes / time<br/>2,231,271,424 / 209,250
[task 2021-01-23T03:50:22.382Z] 03:50:22 INFO - TinderboxPrint: CPU guest<br/>16,494.9 (16.5%)
[task 2021-01-23T03:50:22.382Z] 03:50:22 INFO - TinderboxPrint: CPU idle<br/>38,636.8 (38.8%)
[task 2021-01-23T03:50:22.382Z] 03:50:22 INFO - TinderboxPrint: CPU system<br/>7,149.8 (7.2%)
[task 2021-01-23T03:50:22.382Z] 03:50:22 INFO - TinderboxPrint: CPU user<br/>36,487.5 (36.6%)
[task 2021-01-23T03:50:22.382Z] 03:50:22 INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2021-01-23T03:50:22.383Z] 03:50:22 INFO - start-emulator - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-01-23T03:50:22.388Z] 03:50:22 INFO - verify-device - Wall time: 27s; CPU: 51.0%; Read bytes: 0; Write bytes: 24784896; Read time: 0; Write time: 2095
[task 2021-01-23T03:50:22.388Z] 03:50:22 INFO - install - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-01-23T03:50:22.523Z] 03:50:22 INFO - run-tests - Wall time: 855s; CPU: 54.0%; Read bytes: 226567680; Write bytes: 2206486528; Read time: 55747; Write time: 207155
[task 2021-01-23T03:50:25.140Z] 03:50:25 WARNING - returning nonzero exit status 1
[task 2021-01-23T03:50:25.202Z] cleanup
[task 2021-01-23T03:50:25.202Z] + cleanup
[task 2021-01-23T03:50:25.202Z] + local rv=1
[task 2021-01-23T03:50:25.202Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2021-01-23T03:50:25.202Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2021-01-23T03:50:25.204Z] + '[' ']'
[task 2021-01-23T03:50:25.204Z] + true
[task 2021-01-23T03:50:25.204Z] + cleanup_xvfb
[task 2021-01-23T03:50:25.205Z] ++ pidof Xvfb
[task 2021-01-23T03:50:25.210Z] + local xvfb_pid=50
[task 2021-01-23T03:50:25.210Z] + local vnc=false
[task 2021-01-23T03:50:25.210Z] + local interactive=false
[task 2021-01-23T03:50:25.210Z] + '[' -n 50 ']'
[task 2021-01-23T03:50:25.210Z] + [[ false == false ]]
[task 2021-01-23T03:50:25.210Z] + [[ false == false ]]
[task 2021-01-23T03:50:25.210Z] + kill 50
[task 2021-01-23T03:50:25.210Z] + screen -XS xvfb quit
[task 2021-01-23T03:50:25.225Z] + exit 1
[taskcluster 2021-01-23 03:50:26.774Z] === Task Finished ===
[taskcluster 2021-01-23 03:50:28.873Z] Unsuccessful task run with exit code: 1 completed in 1056.667 seconds

Comment 11

[Narcis Beleuzu [:NarcisB]]

:tcampbell , I did some backfills and it seems that the fail started with the landing of Bug 1667804.
Can you please take a look?

Backfill: https://treeherder.mozilla.org/jobs?repo=autoland&selectedTaskRun=CYPyi9RLSVGWeMWAMXpCgA.0&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel&classifiedState=classified&searchStr=android%2C7.0%2Cx86-64%2Copt%2Cxpcshell%2Ctests%2Ctest-android-em-7.0-x86_64%2Fopt-geckoview-xpcshell-e10s%2Cx1&tochange=ae6b6624d3a78948e21b6eee1075d6df31491084&fromchange=97c55f8706aaf50d738885cdc8b9fdb81fed90c4

Comment 12

[Intermittent Failures Robot]

105 failures in 3488 pushes (0.03 failures/push) were associated with this bug in the last 7 days.

This is the #5 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:

• autoland: 105

Platform and build breakdown:

• android-em-7-0-x86_64: 105
  • opt: 105

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1683253&startday=2021-01-18&endday=2021-01-24&tree=all

Comment 13

[Ted Campbell [:tcampbell]]

Looking at 'similar jobs' view, I see that successes are ~19min, while failures have a 20min limit. At the very least we need to bump the timeout. I'm still trying to understand the specific test case and why it is often the victim of the whole task.

EDIT: This is incorrect. The specific test is timing out. Normally is ~1sec, but in failures it is 5min which fails the job.

Comment 14

[Ted Campbell [:tcampbell]]

Bug 1667804 definitely caused this to get quite intermittent. I do see occasional failures beforehand though. We are still doing a few experiments on try to narrow down since toggling prefs isn't having the impact that I was expecting on xpc-shell.

The primary impact of Bug 1667804 will be GC operations appearing at different times and general timing changes. This makes me suspect there is some sort of pre-exisiting race condition in test.

Comment 15

[Ted Campbell [:tcampbell]]

With further investigation, I find that without stencil-mvp, but simple disabling the off-thread parsing (which is a performance heuristic and slightly dynamic already), I can trigger failures. To me, this indicates that the test or the code it is testing is brittle and slight changes in gc-timing are breaking it. Disabling off-thread JS parsing removes some extra garbage collector traffic.

The issue is likely not recent, but changes if browser timings have made it appear more often.

Comment 16

[Intermittent Failures Robot]

11 failures in 3891 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 11

Platform and build breakdown:

• android-em-7-0-x86_64: 11
  • opt: 11

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1683253&startday=2021-01-25&endday=2021-01-31&tree=all

Comment 17

[Intermittent Failures Robot]

33 failures in 756 pushes (0.044 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 31
• mozilla-central: 2

Platform and build breakdown:

• android-em-7-0-x86_64: 31
  • opt: 23
  • debug: 8
• android-em-7-0-x86_64-shippable: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1683253&startday=2021-02-11&endday=2021-02-11&tree=all

Comment 18

[Alexandru Michis [:malexandru]]

There have been 77 total failures in the last 7 days:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2021-02-06&endday=2021-02-13&tree=trunk&bug=1683253
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=329861391&repo=autoland&lineNumber=3004

Affected platforms are:

• linux1804-64-shippable
• android-em-7-0-x86_64-shippable
• android-em-7-0-x86_64 opt & debug

Comment 19

[Intermittent Failures Robot]

45 failures in 834 pushes (0.054 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 39
• mozilla-central: 4
• try: 2

Platform and build breakdown:

• android-em-7-0-x86_64: 38
  • opt: 23
  • debug: 15
• android-em-7-0-x86_64-shippable: 6
  • opt: 6
• linux1804-64-shippable: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1683253&startday=2021-02-12&endday=2021-02-12&tree=all

Comment 20

[Intermittent Failures Robot]

28 failures in 186 pushes (0.151 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 27
• mozilla-central: 1

Platform and build breakdown:

• android-em-7-0-x86_64: 27
  • debug: 12
  • opt: 15
• android-em-7-0-x86_64-shippable: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1683253&startday=2021-02-13&endday=2021-02-13&tree=all

Comment 21

[Natalia Csoregi [:nataliaCs]]

Attachment: Bug 1683253 - Disabled test_ext_webRequest_cancelWithReason.js on Android 7.0 x86-64. r?#intermittent-reviewers

Comment 22

[Natalia Csoregi [:nataliaCs]]

Update:

There has been a total of 107 failures within the last 7 days on Android 7.0 x86-64 Shippable opt and Android 7.0 x86-64 opt/debug.

Created a disabling patch until further updates.

Try push: https://treeherder.mozilla.org/jobs?repo=try&group_state=expanded&revision=e54bc611dd4bde92f7d34bbfd75de070aea522b7

Comment 23

[Intermittent Failures Robot]

111 failures in 4322 pushes (0.026 failures/push) were associated with this bug in the last 7 days.

This is the #5 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:

• autoland: 101
• mozilla-central: 8
• try: 2

Platform and build breakdown:

• android-em-7-0-x86_64: 101
  • opt: 64
  • debug: 37
• android-em-7-0-x86_64-shippable: 10
  • opt: 10

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1683253&startday=2021-02-08&endday=2021-02-14&tree=all

Comment 24

[Intermittent Failures Robot]

25 failures in 501 pushes (0.05 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 23
• mozilla-central: 2

Platform and build breakdown:

• android-em-7-0-x86_64: 23
  • opt: 17
  • debug: 6
• android-em-7-0-x86_64-shippable: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1683253&startday=2021-02-15&endday=2021-02-15&tree=all

Comment 25

[Intermittent Failures Robot]

42 failures in 709 pushes (0.059 failures/push) were associated with this bug yesterday.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• mozilla-central: 2
• autoland: 39
• try: 1

Platform and build breakdown:

• android-em-7-0-x86_64-shippable: 1
  • opt: 1
• android-em-7-0-x86_64: 41
  • opt: 23
  • debug: 18

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1683253&startday=2021-02-16&endday=2021-02-16&tree=all

Comment 26

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/35ad405ddd13
Disabled test_ext_webRequest_cancelWithReason.js on Android 7.0 x86-64. r=intermittent-reviewers,mixedpuppy,jmaher

Comment 27

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/35ad405ddd13

Comment 28

[Intermittent Failures Robot]

74 failures in 3737 pushes (0.02 failures/push) were associated with this bug in the last 7 days.

This is the #7 most frequent failure this week.

** 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: 68
• mozilla-central: 4
• try: 2

Platform and build breakdown:

• android-em-7-0-x86_64: 70
  • opt: 44
  • debug: 26
• android-em-7-0-x86_64-shippable: 4
  • opt: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1683253&startday=2021-02-15&endday=2021-02-21&tree=all