1457362 - Intermittent browser/components/payments/test/browser/browser_address_edit.js | Test timed out -

Status: REOPENED

(Firefox :: WebPayments UI, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: nerli [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=175876267&repo=autoland

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

[task 2018-04-27T01:58:48.997Z] 01:58:48     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/payments/test/browser/browser_address_edit.js | Test timed out - 
[task 2018-04-27T01:58:48.998Z] 01:58:48     INFO - GECKO(6655) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2018-04-27T01:58:48.999Z] 01:58:48     INFO - GECKO(6655) | MEMORY STAT | vsize 2173MB | residentFast 266MB | heapAllocated 83MB
[task 2018-04-27T01:58:49.000Z] 01:58:49     INFO - TEST-OK | toolkit/components/payments/test/browser/browser_address_edit.js | took 45059ms
[task 2018-04-27T01:58:49.001Z] 01:58:49     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-04-27T01:58:49.002Z] 01:58:49     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/payments/test/browser/browser_address_edit.js | Found a tab after previous test timed out: https://example.com/browser/toolkit/components/payments/test/browser/blank_page.html - 
[task 2018-04-27T01:58:49.003Z] 01:58:49     INFO - checking window state
[task 2018-04-27T01:58:49.004Z] 01:58:49     INFO - TEST-START | toolkit/components/payments/test/browser/browser_card_edit.js
[task 2018-04-27T01:58:49.700Z] 01:58:49     INFO - GECKO(6655) | JavaScript error: chrome://payments/content/paymentDialogWrapper.js, line 293: NS_ERROR_NOT_INITIALIZED:
[task 2018-04-27T01:58:50.920Z] 01:58:50     INFO - GECKO(6655) | JavaScript error: chrome://payments/content/paymentDialogWrapper.js, line 293: NS_ERROR_NOT_INITIALIZED:
[task 2018-04-27T01:58:50.922Z] 01:58:50     INFO - GECKO(6655) | JavaScript error: chrome://payments/content/paymentDialogWrapper.js, line 293: NS_ERROR_NOT_INITIALIZED:
[task 2018-04-27T01:58:55.483Z] 01:58:55     INFO - GECKO(6655) | MEMORY STAT | vsize 2176MB | residentFast 282MB | heapAllocated 96MB

Comment 1

[Matthew N. [:MattN]]

Bug 1446203 which added this test was backed out.

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 8

Platform breakdown:
* linux64: 4
* windows7-32: 3
* linux32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1457362&startday=2018-04-23&endday=2018-04-29&tree=trunk

Comment 3

[Andreea Pavel [:apavel]]

Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=186576018&repo=autoland&lineNumber=2571

[task 2018-07-05T11:10:53.841Z]     INFO - TEST-START | browser/components/payments/test/browser/browser_address_edit.js
[task 2018-07-05T11:12:23.977Z]     INFO - TEST-INFO | started process screentopng
[task 2018-07-05T11:12:24.696Z]     INFO - TEST-INFO | screentopng: exit 0
[task 2018-07-05T11:12:24.697Z]     INFO - Buffered messages logged at 11:10:53
[task 2018-07-05T11:12:24.697Z]     INFO - Entering test bound setup_head
[task 2018-07-05T11:12:24.698Z]     INFO - Leaving test bound setup_head
[task 2018-07-05T11:12:24.699Z]     INFO - Entering test bound test_add_link
[task 2018-07-05T11:12:24.699Z]     INFO - Buffered messages logged at 11:10:54
[task 2018-07-05T11:12:24.699Z]     INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 170}]
[task 2018-07-05T11:12:24.699Z]     INFO - Buffered messages finished
[task 2018-07-05T11:12:24.699Z]     INFO - TEST-UNEXPECTED-FAIL | browser/components/payments/test/browser/browser_address_edit.js | Test timed out - 
[task 2018-07-05T11:12:24.700Z]     INFO - GECKO(2054) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2018-07-05T11:12:24.703Z]     INFO - GECKO(2054) | MEMORY STAT heapAllocated not supported in this build configuration.
[task 2018-07-05T11:12:24.704Z]     INFO - GECKO(2054) | MEMORY STAT | vsize 20973905MB | residentFast 959MB
[task 2018-07-05T11:12:24.707Z]     INFO - TEST-OK | browser/components/payments/test/browser/browser_address_edit.js | took 90194ms
[task 2018-07-05T11:12:24.708Z]     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-07-05T11:12:24.711Z]     INFO - TEST-UNEXPECTED-FAIL | browser/components/payments/test/browser/browser_address_edit.js | Found a tab after previous test timed out: about:blank - 
[task 2018-07-05T11:12:24.712Z]     INFO - checking window state
[task 2018-07-05T11:12:24.773Z]     INFO - TEST-START | browser/components/payments/test/browser/browser_card_edit.js
[task 2018-07-05T11:12:24.790Z]     INFO - TEST-SKIP | browser/components/payments/test/browser/browser_card_edit.js | bound test_add_link 
[task 2018-07-05T11:12:24.790Z]  WARNING - Skipping test bound test_add_link
[task 2018-07-05T11:13:54.794Z]     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-07-05T11:13:54.796Z]     INFO - Buffered messages logged at 11:12:24
[task 2018-07-05T11:13:54.798Z]     INFO - Entering test bound setup_head
[task 2018-07-05T11:13:54.799Z]     INFO - Leaving test bound setup_head
[task 2018-07-05T11:13:54.802Z]     INFO - Entering test bound test_private_add_link
[task 2018-07-05T11:13:54.805Z]     INFO - Buffered messages logged at 11:12:26
[task 2018-07-05T11:13:54.806Z]     INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 170}]
[task 2018-07-05T11:13:54.811Z]     INFO - Buffered messages logged at 11:12:27
[task 2018-07-05T11:13:54.812Z]     INFO - waitForMessageFromWidget: paymentDialogReady
[task 2018-07-05T11:13:54.813Z]     INFO - Buffered messages finished
[task 2018-07-05T11:13:54.814Z]     INFO - TEST-UNEXPECTED-FAIL | browser/components/payments/test/browser/browser_card_edit.js | Test timed out - 
[task 2018-07-05T11:13:54.835Z]     INFO - GECKO(2054) | MEMORY STAT | vsize 20973952MB | residentFast 1009MB
[task 2018-07-05T11:13:54.836Z]     INFO - TEST-OK | browser/components/payments/test/browser/browser_card_edit.js | took 90069ms
[task 2018-07-05T11:13:54.982Z]     INFO - checking window state
[task 2018-07-05T11:13:54.990Z]     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-07-05T11:13:54.991Z]     INFO - TEST-UNEXPECTED-FAIL | browser/components/payments/test/browser/browser_card_edit.js | Found a browser window after previous test timed out - 
[task 2018-07-05T11:13:54.991Z]     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-07-05T11:13:54.991Z]     INFO - TEST-UNEXPECTED-FAIL | browser/components/payments/test/browser/browser_card_edit.js | Found a  after previous test timed out - 
[task 2018-07-05T11:13:54.992Z]     INFO - GECKO(2054) | must wait for focus
[task 2018-07-05T11:13:55.101Z]     INFO - TEST-START | browser/components/payments/test/browser/browser_change_shipping.js
[task 2018-07-05T11:14:01.000Z]     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-07-05T11:14:01.000Z]     INFO - Buffered messages logged at 11:13:55
[task 2018-07-05T11:14:01.000Z]     INFO - Entering test bound setup_head
[task 2018-07-05T11:14:01.000Z]     INFO - Leaving test bound setup_head
[task 2018-07-05T11:14:01.000Z]     INFO - Entering test bound test_change_shipping
[task 2018-07-05T11:14:01.000Z]     INFO - waitForMessageFromWidget: paymentDialogReady
[task 2018-07-05T11:14:01.001Z]     INFO - Buffered messages finished
[task 2018-07-05T11:14:01.001Z]     INFO - TEST-UNEXPECTED-FAIL | browser/components/payments/test/browser/browser_change_shipping.js | Uncaught exception - payment dialog should be the most recent - timed out after 50 tries.
[task 2018-07-05T11:14:01.001Z]     INFO - Leaving test bound test_change_shipping
[task 2018-07-05T11:14:01.003Z]     INFO - Entering test bound test_default_shippingOptions_noneSelected
[task 2018-07-05T11:14:01.568Z]     INFO - make sure no shipping options are selected
[task 2018-07-05T11:14:01.570Z]     INFO - waitForMessageFromWidget: paymentDialogReady
[task 2018-07-05T11:14:06.763Z]     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-07-05T11:14:06.765Z]     INFO - TEST-UNEXPECTED-FAIL | browser/components/payments/test/browser/browser_change_shipping.js | Uncaught exception - payment dialog should be the most recent - timed out after 50 tries.
[task 2018-07-05T11:14:06.769Z]     INFO - Leaving test bound test_default_shippingOptions_noneSelected
[task 2018-07-05T11:14:06.770Z]     INFO - Entering test bound test_default_shippingOptions_allSelected
[task 2018-07-05T11:14:07.321Z]     INFO - make sure no shipping options are selected
[task 2018-07-05T11:14:07.321Z]     INFO - waitForMessageFromWidget: paymentDialogReady
[task 2018-07-05T11:15:50.705Z]     INFO - Console message: [JavaScript Error: "getScreenshot(https://example.com/browser/browser/components/payments/test/browser/blank_page.html) failed: TypeError: NetworkError when attempting to fetch resource." {file: "resource://activity-stream/lib/Screenshots.jsm" line: 47}]
[task 2018-07-05T11:15:50.706Z]     INFO - getScreenshotForURL@resource://activity-stream/lib/Screenshots.jsm:47:7
[task 2018-07-05T11:15:50.707Z]     INFO - async*maybeCacheScreenshot@resource://activity-stream/lib/Screenshots.jsm:101:32
[task 2018-07-05T11:15:50.707Z]     INFO - async*_fetchScreenshot@resource://activity-stream/lib/TopSitesFeed.jsm:231:11
[task 2018-07-05T11:15:50.708Z]     INFO - async*_fetchIcon@resource://activity-stream/lib/TopSitesFeed.jsm:219:11
[task 2018-07-05T11:15:50.708Z]     INFO - async*getLinksWithDefaults@resource://activity-stream/lib/TopSitesFeed.jsm:158:11
[task 2018-07-05T11:15:50.709Z]     INFO - async*refresh@resource://activity-stream/lib/TopSitesFeed.jsm:180:25
[task 2018-07-05T11:15:50.709Z]     INFO - async*onAction@resource://activity-stream/lib/TopSitesFeed.jsm:400:9
[task 2018-07-05T11:15:50.710Z]     INFO - _middleware/</<@resource://activity-stream/lib/Store.jsm:51:11
[task 2018-07-05T11:15:50.711Z]     INFO - Store/this[method]@resource://activity-stream/lib/Store.jsm:29:55
[task 2018-07-05T11:15:50.711Z]     INFO - init/this.intervalId<@resource://activity-stream/lib/SystemTickFeed.jsm:18:41
[task 2018-07-05T11:15:50.712Z]     INFO - notify@resource://gre/modules/Timer.jsm:44:7
[task 2018-07-05T11:15:50.712Z]     INFO - showPayment@jar:file:///builds/worker/workspace/build/application/firefox/browser/omni.ja!/components/paymentUIService.js:49:5
[task 2018-07-05T11:15:50.713Z]     INFO - 
[task 2018-07-05T11:22:00.707Z]     INFO - Buffered messages finished
[task 2018-07-05T11:22:00.709Z]    ERROR - TEST-UNEXPECTED-TIMEOUT | browser/components/payments/test/browser/browser_change_shipping.js | application timed out after 370 seconds with no output
[task 2018-07-05T11:22:00.710Z]    ERROR - Force-terminating active process(es).
[task 2018-07-05T11:22:00.712Z]     INFO - Determining child pids from psutil...
[task 2018-07-05T11:22:00.714Z]     INFO - [2119, 2166, 2196, 2208]
[task 2018-07-05T11:22:00.716Z]     INFO - ==> process 2054 launched child process 2072
[task 2018-07-05T11:22:00.718Z]     INFO - ==> process 2054 launched child process 2119
[task 2018-07-05T11:22:00.719Z]     INFO - ==> process 2054 launched child process 2166
[task 2018-07-05T11:22:00.722Z]     INFO - ==> process 2054 launched child process 2196
[task 2018-07-05T11:22:00.723Z]     INFO - ==> process 2054 launched child process 2208
[task 2018-07-05T11:22:00.725Z]     INFO - Found child pids: set([2208, 2072, 2196, 2166, 2119])
[task 2018-07-05T11:22:00.726Z]     INFO - Failed to get child procs
[task 2018-07-05T11:22:00.728Z]     INFO - Killing process: 2208

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1457362&startday=2018-07-02&endday=2018-07-08&tree=trunk

Comment 5

[Intermittent Failures Robot]

53 failures in 558 pushes (0.095 failures/push) were associated with this bug yesterday.

Repository breakdown:
* autoland: 39
* mozilla-central: 2
* mozilla-inbound: 12

Platform breakdown:
* windows7-32: 1
* osx-10-10: 52

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1457362&startday=2018-10-17&endday=2018-10-17&tree=all

Comment 6

[Bogdan Tara[:bogdan_tara | bogdant]]

In the last 7 days there have been 108 failures on OS X debug.

Comment 7

[Cosmin Sabou [:CosminS]]

Hi! After looking at the failure rate between 15-18 october I decided to do some digging to see what caused the spike in failure rate. https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2018-10-15&endday=2018-10-18&tree=trunk&page=1&page_size=20&bug=1457362

Did some retriggers and ended up to this push: http://tinyurl.com/ycw3jbvf

The push before this has 22 jobs all green: http://tinyurl.com/y87dsde8

Range of r/b: http://tinyurl.com/y745zb68

Tim, could you take a look over this? Thanks.

Comment 8

[Intermittent Failures Robot]

52 failures in 494 pushes (0.105 failures/push) were associated with this bug yesterday.

Repository breakdown:
* try: 1
* autoland: 37
* mozilla-inbound: 14

Platform breakdown:
* windows2012-64: 2
* windows2012-32: 1
* osx-10-10: 49

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1457362&startday=2018-10-18&endday=2018-10-18&tree=all

Comment 10

[Tim Guan-tin Chien [:timdream] (please needinfo)]

I looked at the test failure a bit and they stop at "waiting for focus". It is unclear to me at the first glance that why the failure rate could change with my patch. Will keep looking.

Comment 11

[Intermittent Failures Robot]

188 failures in 2759 pushes (0.068 failures/push) were associated with this bug in the last 7 days.

This is the #7 most frequent failure this week.

** 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-inbound: 26
* autoland: 156
* mozilla-central: 2
* try: 4

Platform breakdown:
* osx-10-10: 184
* windows7-32: 1
* windows2012-32: 1
* windows2012-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1457362&startday=2018-10-15&endday=2018-10-21&tree=all

Comment 12

[Matthew N. [:MattN]]

I don't think this should be disabled since it seems like the problem is gone now.

Comment 13

[Cristina Coroiu [:ccoroiu]]

There are no new failures since 18th October.

Comment 14

[Eliza Balazs [:ebalazs_]]

Clearing the [stockwell disable-recommended] tag. See Comment 12 and Comment 13.

Comment 15

[Intermittent Failures Robot]

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

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

Repository breakdown:
* autoland: 4
* mozilla-inbound: 3

Platform breakdown:
* osx-10-10: 7

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1457362&startday=2018-10-22&endday=2018-10-28&tree=all

Comment 16

[Matthew N. [:MattN]]

Again, clearing [stockwell disable-recommended] because the problem is gone…

Eliza, can you fix the algorithm for adding [stockwell disable-recommended] as it clearly shouldn't be added with only 7 failures in 7 days?

Comment 17

[Eliza Balazs [:ebalazs_]]

MattN: Hi, this tag is added when there are 150 failures in the last 21 days.

Looking at this range https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2018-10-09&endday=2018-10-30&tree=all&page=1&page_size=20&bug=1457362 there are 196 failures, that is why the tag was added again.

I think we need to wait ~ 7 days for this to be changed, because the 19th of October was the day when the failure rate decreased.

jmaher: Do you think that we can change something in the algorithm for adding the [stockwell disable-recommended]? Thanks!

Comment 18

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

good idea, filed bug 1503188

Comment 19

[Intermittent Failures Robot]

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

** 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-inbound: 2
* autoland: 4

Platform breakdown:
* osx-10-10: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1457362&startday=2018-10-29&endday=2018-11-04&tree=all

Comment 20

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-inbound: 1
* autoland: 8

Platform breakdown:
* osx-10-10: 9

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1457362&startday=2018-11-05&endday=2018-11-11&tree=all

Comment 21

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-central: 2
* autoland: 5
* mozilla-inbound: 3

Platform breakdown:
* osx-10-10: 9
* macosx64-nightly: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1457362&startday=2018-11-12&endday=2018-11-18&tree=all

Comment 22

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-inbound: 1
* autoland: 3
* mozilla-central: 1

Platform breakdown:
* osx-10-10: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1457362&startday=2018-11-19&endday=2018-11-25&tree=all

Comment 23

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 4
* try: 1

Platform breakdown:
* osx-10-10: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1457362&startday=2018-11-26&endday=2018-12-02&tree=all

Comment 24

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 2

Platform breakdown:
* osx-10-10: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1457362&startday=2018-12-03&endday=2018-12-09&tree=all

Comment 25

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 2
* mozilla-central: 1

Platform breakdown:
* osx-10-10: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1457362&startday=2018-12-10&endday=2018-12-16&tree=all

Comment 26

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-inbound: 1
* autoland: 2

Platform breakdown:
* osx-10-10: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1457362&startday=2018-12-17&endday=2018-12-23&tree=all