1373346 - Intermittent dom/push/test/test_data.html | Test timed out

Status: NEW

(Core :: DOM: Push Subscriptions, defect, P3)

Description

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

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

08:51:28     INFO -  4464 INFO SpawnTask.js | Entering test compareJSONSubscription
08:51:28     INFO -  4465 INFO TEST-PASS | dom/push/test/test_data.html | Wrong endpoint
08:51:28     INFO -  4466 INFO TEST-PASS | dom/push/test/test_data.html | Mismatched Base64-encoded key: p256dh
08:51:28     INFO -  4467 INFO TEST-PASS | dom/push/test/test_data.html | Mismatched Base64-encoded key: auth
08:51:28     INFO -  4468 INFO SpawnTask.js | Leaving test compareJSONSubscription
08:51:28     INFO -  4469 INFO SpawnTask.js | Entering test comparePublicKey
08:51:28     INFO -  4470 INFO TEST-PASS | dom/push/test/test_data.html | Key share should be 65 octets
08:51:28     INFO -  4471 INFO TEST-PASS | dom/push/test/test_data.html | Mismatched key share
08:51:28     INFO -  4472 INFO TEST-PASS | dom/push/test/test_data.html | 16 - Auth secret should be 16 octets
08:51:28     INFO -  4473 INFO TEST-PASS | dom/push/test/test_data.html | Mismatched auth secret
08:51:28     INFO -  4474 INFO SpawnTask.js | Leaving test comparePublicKey
08:51:28     INFO -  4475 INFO SpawnTask.js | Entering test sendPushMessageFromPage
08:51:28     INFO -  Buffered messages finished
08:51:28    ERROR -  4476 INFO TEST-UNEXPECTED-FAIL | dom/push/test/test_data.html | Test timed out.
08:51:28     INFO -      reportError@SimpleTest/TestRunner.js:121:7
08:51:28     INFO -      TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      TestRunner.runTests@SimpleTest/TestRunner.js:380:5
08:51:28     INFO -      RunSet.runtests@SimpleTest/setup.js:194:3
08:51:28     INFO -      RunSet.runall@SimpleTest/setup.js:173:5
08:51:28     INFO -      hookupTests@SimpleTest/setup.js:266:5
08:51:28     INFO -  parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5
08:51:28     INFO -  getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11
08:51:28     INFO -  EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3
08:51:28     INFO -      hookup@SimpleTest/setup.js:246:5
08:51:28     INFO -  EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=c%3A%5Cusers%5Cgenericworker%5Cappdata%5Clocal%5Ctemp&cleanupCrashes=true:11:1
08:51:29     INFO -  Not taking screenshot here: see the one that was previously logged
08:51:29    ERROR -  4477 INFO TEST-UNEXPECTED-FAIL | dom/push/test/test_data.html | This test left a service worker registered without cleaning it up

Comment 2

[Intermittent Failures Robot]

34 failures in 147 pushes (0.231 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* mozilla-inbound: 28
* autoland: 4
* try: 1
* mozilla-central: 1

Platform breakdown:
* windows7-32-vm: 21
* windows8-64: 13

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

Comment 3

[Intermittent Failures Robot]

25 failures in 50 pushes (0.5 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* autoland: 25

Platform breakdown:
* windows7-32-vm: 14
* windows8-64: 11

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

Comment 4

[Joel Maher ( :jmaher ) (UTC -8)]

64 failures since June 15th, all on opt/pgo, not debug and in e10s tests only.

I have done some retriggers:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-searchStr=mochitest-e10s-2%20win%20opt&tochange=cb10c0fd0c6a585a13f1796f17fa77aa0cc6202c&fromchange=dfee29c06556ebe2f4ac43cf0744be9e93390d1d&selectedJob=107235629

Possibly this will help narrow down the root cause.

here is a log:
https://queue.taskcluster.net/v1/task/RObwNtCqStylF0lrbFup0w/runs/0/artifacts/public/logs/live_backing.log

and the text related to the failure:
08:46:28     INFO -  4457 INFO TEST-START | dom/push/test/test_data.html
08:46:59     INFO -  GECKO(1980) | Unable to read VR Path Registry from C:\Users\GenericWorker\AppData\Local\openvr\openvrpaths.vrpath
08:46:59     INFO -  GECKO(1980) | [Parent 1980] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
08:51:28     INFO -  TEST-INFO | started process screenshot
08:51:28     INFO -  TEST-INFO | screenshot: exit 0
08:51:28     INFO -  Buffered messages logged at 08:46:29
08:51:28     INFO -  4458 INFO SpawnTask.js | Entering test start
08:51:28     INFO -  4459 INFO SpawnTask.js | Leaving test start
08:51:28     INFO -  4460 INFO SpawnTask.js | Entering test createControlledIFrame
08:51:28     INFO -  4461 INFO SpawnTask.js | Leaving test createControlledIFrame
08:51:28     INFO -  4462 INFO SpawnTask.js | Entering test subscribe
08:51:28     INFO -  4463 INFO SpawnTask.js | Leaving test subscribe
08:51:28     INFO -  4464 INFO SpawnTask.js | Entering test compareJSONSubscription
08:51:28     INFO -  4465 INFO TEST-PASS | dom/push/test/test_data.html | Wrong endpoint
08:51:28     INFO -  4466 INFO TEST-PASS | dom/push/test/test_data.html | Mismatched Base64-encoded key: p256dh
08:51:28     INFO -  4467 INFO TEST-PASS | dom/push/test/test_data.html | Mismatched Base64-encoded key: auth
08:51:28     INFO -  4468 INFO SpawnTask.js | Leaving test compareJSONSubscription
08:51:28     INFO -  4469 INFO SpawnTask.js | Entering test comparePublicKey
08:51:28     INFO -  4470 INFO TEST-PASS | dom/push/test/test_data.html | Key share should be 65 octets
08:51:28     INFO -  4471 INFO TEST-PASS | dom/push/test/test_data.html | Mismatched key share
08:51:28     INFO -  4472 INFO TEST-PASS | dom/push/test/test_data.html | 16 - Auth secret should be 16 octets
08:51:28     INFO -  4473 INFO TEST-PASS | dom/push/test/test_data.html | Mismatched auth secret
08:51:28     INFO -  4474 INFO SpawnTask.js | Leaving test comparePublicKey
08:51:28     INFO -  4475 INFO SpawnTask.js | Entering test sendPushMessageFromPage
08:51:28     INFO -  Buffered messages finished
08:51:28    ERROR -  4476 INFO TEST-UNEXPECTED-FAIL | dom/push/test/test_data.html | Test timed out.
08:51:28     INFO -      reportError@SimpleTest/TestRunner.js:121:7
08:51:28     INFO -      TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:28     INFO -      TestRunner.runTests@SimpleTest/TestRunner.js:380:5
08:51:28     INFO -      RunSet.runtests@SimpleTest/setup.js:194:3
08:51:28     INFO -      RunSet.runall@SimpleTest/setup.js:173:5
08:51:28     INFO -      hookupTests@SimpleTest/setup.js:266:5
08:51:28     INFO -  parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5
08:51:28     INFO -  getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11
08:51:28     INFO -  EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3
08:51:28     INFO -      hookup@SimpleTest/setup.js:246:5
08:51:28     INFO -  EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=c%3A%5Cusers%5Cgenericworker%5Cappdata%5Clocal%5Ctemp&cleanupCrashes=true:11:1
08:51:29     INFO -  Not taking screenshot here: see the one that was previously logged
08:51:29    ERROR -  4477 INFO TEST-UNEXPECTED-FAIL | dom/push/test/test_data.html | This test left a service worker registered without cleaning it up
08:51:29     INFO -      afterCleanup@SimpleTest/SimpleTest.js:1196:17
08:51:29     INFO -      executeCleanupFunction@SimpleTest/SimpleTest.js:1218:13
08:51:29     INFO -      promise callback*executeCleanupFunction@SimpleTest/SimpleTest.js:1230:13
08:51:29     INFO -      SimpleTest.finish@SimpleTest/SimpleTest.js:1237:5
08:51:29     INFO -      killTest@SimpleTest/TestRunner.js:130:7
08:51:29     INFO -      delayedKillTest@SimpleTest/TestRunner.js:157:47
08:51:29     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:157:7
08:51:29     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:29     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:29     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:29     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:29     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:29     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:29     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:29     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:29     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:29     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
08:51:29     INFO -      TestRunner.runTests@SimpleTest/TestRunner.js:380:5
08:51:29     INFO -      RunSet.runtests@SimpleTest/setup.js:194:3
08:51:29     INFO -      RunSet.runall@SimpleTest/setup.js:173:5
08:51:29     INFO -      hookupTests@SimpleTest/setup.js:266:5
08:51:29     INFO -  parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5
08:51:29     INFO -  getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11
08:51:29     INFO -  EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3
08:51:29     INFO -      hookup@SimpleTest/setup.js:246:5
08:51:29     INFO -  EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=c%3A%5Cusers%5Cgenericworker%5Cappdata%5Clocal%5Ctemp&cleanupCrashes=true:11:1
08:51:29     INFO -  GECKO(1980) | MEMORY STAT | vsize 401MB | vsizeMaxContiguous 571MB | residentFast 25MB | heapAllocated 12MB
08:51:29     INFO -  4478 INFO TEST-OK | dom/push/test/test_data.html | took 301143ms


:overholt- as the triage owner can you find someone from the push notifications team to look into this and get a resolution in the next week?

Comment 5

[Andrew Overholt [:overholt]]

I wouldn't be surprised if this were related to the recent changes with setTimeout but Kit will know best.

Comment 6

[Intermittent Failures Robot]

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

This is the #17 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: 39
* mozilla-inbound: 37
* try: 6
* mozilla-central: 4

Platform breakdown:
* windows7-32-vm: 55
* windows8-64: 31

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

Comment 7

[Lina Butler [:lina]]

I won't have cycles to look at this until after the work week, sorry. :-( This test will need some more logging, via `dom.push.loglevel = "all"` and `info()`, too. I can't tell if it's stuck waiting for the worker, failing to deliver the message through the mock push service, or something else. Keeping ni? until then.

Comment 8

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: temporarily disable on win opt

as the failure rate is 60+/day, this is close to perma failing, lets disable until there is time to look at a real fix.

Comment 9

[Geoff Brown [:gbrown]]

Comment on attachment 8879235 [details] [diff] [review]
temporarily disable on win opt

Review of attachment 8879235 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/push/test/mochitest.ini
@@ +18,5 @@
>  [test_unregister.html]
>  [test_multiple_register_different_scope.html]
>  [test_subscription_change.html]
>  [test_data.html]
> +skip-if = os=="win" && !debug # Bug 1373346

I'm not sure it is necessary, but we usually have spaces around the ==, so

skip-if = os == "win" && !debug

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/bde143a9c8b2
Intermittent dom/push/test/test_data.html - temporarily disable. r=gbrown

Comment 11

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-inbound: 82
* autoland: 52
* mozilla-central: 15
* try: 2

Platform breakdown:
* windows7-32-vm: 109
* windows8-64: 42

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

Comment 12

[Carsten Book [:Tomcat]]

joel, geoff, this is still perma failing

Comment 13

[Carsten Book [:Tomcat]]

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

Comment 14

[Joel Maher ( :jmaher ) (UTC -8)]

pushing to try:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=793a732ef2e7478a5d3bc23f88dd0398905301ba

on my second round, appears there is a lot broken here.

Comment 15

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: disable other tests that are perma fail

here are some try pushes:
https://treeherder.mozilla.org/#/jobs?repo=try&author=[e-mail]&fromchange=2c8538bc0960af169ca0eb2ebd45d3662f91bbd0&tochange=686017e0c1d7ca22b654686f899524eb2beec921

Comment 16

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/c4d6c50a1434
dom/push/test has many perma failing mochitests, disable for now. r=gbrown

Comment 17

[Intermittent Failures Robot]

114 failures in 173 pushes (0.659 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* autoland: 89
* mozilla-inbound: 12
* mozilla-central: 9
* try: 4

Platform breakdown:
* windows7-32-vm: 111
* windows8-64: 3

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

Comment 18

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

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

Comment 20

[Intermittent Failures Robot]

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

This is the #1 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: 152
* mozilla-inbound: 105
* mozilla-central: 28
* try: 19

Platform breakdown:
* windows7-32-vm: 260
* windows8-64: 44

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

Comment 21

[Geoff Brown [:gbrown]]

This started up again, now on Windows Debug.

Comment 22

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/4579ac092409
Skip some dom/push tests on Windows Debug too; r=me,test-only

Comment 23

[Intermittent Failures Robot]

16 failures in 131 pushes (0.122 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* autoland: 9
* mozilla-inbound: 4
* mozilla-central: 2
* try: 1

Platform breakdown:
* windows7-32-vm: 16

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

Comment 24

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/4579ac092409

Comment 25

[Intermittent Failures Robot]

48 failures in 718 pushes (0.067 failures/push) were associated with this bug in the last 7 days. 

This is the #27 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: 23
* mozilla-inbound: 10
* mozilla-central: 10
* try: 4
* pine: 1

Platform breakdown:
* windows7-32-vm: 46
* windows8-64: 2

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

Comment 26

[Lina Butler [:lina]]

(In reply to Lina Cambridge (she/her) [:lina] from comment #7)
> I won't have cycles to look at this until after the work week, sorry. :-(

"After the work week" turned into "after a year". :-/

Comment 27

[Jens Stutte [:jstutte]]

:perry, is this bug obsolete or did we just disable the failing tests?

Comment 28

[Perry Jiang [:perry] [no longer employee, use ni?]]

Looks like failing tests were disabled. I'm not sure if any thing has happened so that this could be re-enabled...

Comment 29

[Intermittent Failures Robot]

1 failures in 4004 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• macosx1014-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1373346&startday=2020-01-20&endday=2020-01-26&tree=all

Comment 30

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 5

Platform breakdown:

• linux1804-64: 3
• linux64-tsan: 1
• macosx1014-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1373346&startday=2020-03-16&endday=2020-03-22&tree=all

Comment 31

[Intermittent Failures Robot]

1 failures in 3626 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1373346&startday=2022-10-31&endday=2022-11-06&tree=all

Comment 32

[Intermittent Failures Robot]

1 failures in 3589 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-shippable-qr: 1
  • opt: 1

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