1527493 - Intermittent raptor-main TEST-UNEXPECTED-FAIL: test 'raptor-tp6-paypal-chrome' timed out loading test page: https://www.paypal.com/myaccount/summary/

Status: RESOLVED WORKSFORME

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

#[markdown(off)]
Filed by: apavel [at] mozilla.com

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

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

08:19:44 INFO - raptor-main starting raptor test: raptor-tp6-tumblr-chrome
08:19:44 INFO - raptor-main test settings: {'python3_win_manifest': 'python3{x64}.manifest', 'alert_threshold': '2.0', 'playback_pageset_manifest': 'mitmproxy-recordings-raptor-tumblr.manifest', 'gecko_profile_entries': '2000000', 'lower_is_better': 'true', 'alert_on': ['fcp', 'loadtime'], 'here': '/home/cltbld/tasks/task_1549556176/build/tests/raptor/raptor/tests', 'measure': 'fcp, loadtime', 'path': '/home/cltbld/tasks/task_1549556176/build/tests/raptor/raptor/tests/raptor-tp6-tumblr-chrome', 'gecko_profile_interval': '1', 'unit': 'ms', 'ancestor-manifest': '/home/cltbld/tasks/task_1549556176/build/tests/raptor/raptor/raptor.ini', 'playback_binary_manifest': 'mitmproxy-rel-bin-{platform}.manifest', 'name': 'raptor-tp6-tumblr-chrome', 'playback_recordings': 'tumblr.mp', 'page_cycles': '25', 'apps': 'chrome', 'test_url': 'https://www.tumblr.com/dashboard', 'manifest': '/home/cltbld/tasks/task_1549556176/build/tests/raptor/raptor/tests/raptor-tp6-10.ini', 'page_timeout': '60000', 'playback': 'mitmproxy', 'expected': 'pass', 'type': 'pageload', 'relpath': 'tests/raptor-tp6-tumblr-chrome'}
08:19:44 INFO - raptor-main raptor config: {'playback_binary_zip': None, 'app': 'chrome', 'symbols_path': 'https://queue.taskcluster.net/v1/task/B70FuPk8RUa72M6xpnMOLA/artifacts/public/build/target.crashreporter-symbols.zip', 'power_test': False, 'run_local': False, 'gecko_profile_interval': None, 'binary': '/home/cltbld/tasks/task_1549556176/mozharness/mozharness/mozilla/testing/chrome/chrome-linux/chrome', 'local_profile_dir': '/tmp/tmpIguWIz.mozrunner/Default', 'platform': 'linux', 'gecko_profile': False, 'python3_win_manifest': 'python3{x64}.manifest', 'gecko_profile_entries': None, 'playback_pageset_manifest': 'mitmproxy-recordings-raptor-paypal.manifest', 'playback_pageset_zip': None, 'playback_tool': 'mitmproxy', 'host': '127.0.0.1', 'subtest_alert_on': ['fcp', 'loadtime'], 'playback_binary_manifest': 'mitmproxy-rel-bin-{platform}.manifest', 'obj_path': None, 'playback_recordings': 'paypal.mp', 'is_release_build': False, 'processor': 'x86_64'}
08:19:44 INFO - raptor-gen-test-config writing test settings into background js, so webext can get it
08:19:44 INFO - raptor-gen-test-config finished writing test config to /home/cltbld/tasks/task_1549556176/build/tests/raptor/webext/raptor/auto_gen_test_config.js
08:19:44 INFO - raptor-main installing webext /home/cltbld/tasks/task_1549556176/build/tests/raptor/webext/raptor
08:19:44 INFO - raptor-main test uses playback tool: mitmproxy
08:19:44 INFO - raptor-mitmproxy raptor_dir used for mitmproxy downloads and exe files: /home/cltbld/tasks/task_1549556176/testing/raptor
08:19:44 INFO - raptor-mitmproxy downloading mitmproxy binary
08:19:44 INFO - raptor-utils INFO - untarring "mitmproxy-2.0.2-linux.tar.gz"
08:19:44 INFO - raptor-mitmproxy downloading mitmproxy pageset
08:19:44 INFO - raptor-utils INFO - File mitmproxy-tp6-tumblr.zip not present in local cache folder /builds/tooltool_cache
08:19:44 INFO - raptor-utils INFO - Attempting to fetch from 'https://tooltool.mozilla-releng.net/'...
08:19:46 INFO - raptor-utils INFO - File mitmproxy-tp6-tumblr.zip fetched from https://tooltool.mozilla-releng.net/ as /home/cltbld/tasks/task_1549556176/testing/raptor/tmpjj7clm
08:19:46 INFO - raptor-utils INFO - File integrity verified, renaming tmpjj7clm to mitmproxy-tp6-tumblr.zip
08:19:46 INFO - raptor-utils INFO - Updating local cache /builds/tooltool_cache...
08:19:46 INFO - raptor-utils INFO - Local cache /builds/tooltool_cache updated with mitmproxy-tp6-tumblr.zip
08:19:46 INFO - raptor-utils INFO - unzipping "mitmproxy-tp6-tumblr.zip"
08:19:46 INFO - raptor-mitmproxy mitmdump path: /home/cltbld/tasks/task_1549556176/testing/raptor/mitmdump
08:19:46 INFO - raptor-mitmproxy recording path: /home/cltbld/tasks/task_1549556176/testing/raptor
08:19:46 INFO - raptor-mitmproxy recordings list: ['tumblr.mp']
08:19:46 INFO - raptor-mitmproxy browser path: /home/cltbld/tasks/task_1549556176/mozharness/mozharness/mozilla/testing/chrome/chrome-linux/chrome
08:19:46 INFO - raptor-mitmproxy Starting mitmproxy playback using env path: /home/cltbld/tasks/task_1549556176/mozharness/mozharness/mozilla/testing/chrome/chrome-linux;/home/cltbld/tasks/task_1549556176/build/venv/bin:/bin:/sbin:/usr/bin:/usr/sbin:/usr/local/bin
08:19:46 INFO - raptor-mitmproxy Starting mitmproxy playback using command: /home/cltbld/tasks/task_1549556176/testing/raptor/mitmdump -k -q -s /home/cltbld/tasks/task_1549556176/build/tests/raptor/raptor/playback/alternate-server-replay.py /home/cltbld/tasks/task_1549556176/testing/raptor/tumblr.mp
08:19:56 INFO - raptor-mitmproxy Mitmproxy playback successfully started as pid 3889
08:19:56 INFO - raptor-main starting chrome
08:19:56 INFO - Application command: /home/cltbld/tasks/task_1549556176/mozharness/mozharness/mozilla/testing/chrome/chrome-linux/chrome --user-data-dir=/tmp/tmpIguWIz.mozrunner --profile-directory=Default --no-first-run --proxy-server=127.0.0.1:8080 --proxy-bypass-list=localhost;127.0.0.1 --ignore-certificate-errors --no-default-browser-check --load-extension=/home/cltbld/tasks/task_1549556176/build/tests/raptor/webext/raptor
08:19:56 INFO - 127.0.0.1 - - [07/Feb/2019 08:19:56] "POST / HTTP/1.1" 200 -
08:19:56 INFO - raptor-control-server received webext_status: raptor runner.js is loaded!
08:19:56 INFO - 127.0.0.1 - - [07/Feb/2019 08:19:56] "GET /raptor-tp6-tumblr-chrome.json HTTP/1.1" 200 -
08:19:56 INFO - raptor-control-server reading test settings from raptor-tp6-tumblr-chrome.json
08:19:56 INFO - raptor-control-server sent test settings to web ext runner

08:22:01 INFO - raptor-output results can also be found locally at: /home/cltbld/tasks/task_1549556176/build/raptor.json
08:22:01 INFO - raptor-control-server shutting down control server
08:22:02 INFO - raptor-main finished
08:22:02 INFO - raptor-main TEST-UNEXPECTED-FAIL: test 'raptor-tp6-paypal-chrome' timed out loading test page: https://www.paypal.com/myaccount/summary/
08:22:02 ERROR - Return code: 1
08:22:02 WARNING - setting return code to 1
08:22:02 INFO - Validating PERFHERDER_DATA against /home/cltbld/tasks/task_1549556176/mozharness/external_tools/performance-artifact-schema.json
08:22:02 INFO - copying raptor results to upload dir:
08:22:02 INFO - /home/cltbld/tasks/task_1549556176/build/blobber_upload_dir/perfherder-data.json
08:22:02 INFO - copying raptor results from /home/cltbld/tasks/task_1549556176/build/raptor.json to /home/cltbld/tasks/task_1549556176/build/blobber_upload_dir/perfherder-data.json

This is from bug 1518776,from that push because the new test starts directly before the failure report: 05:53:06 INFO - Replaying from files: ['/home/cltbld/tasks/task_1549547112/testing/raptor/tumblr.mp']

Comment 1

[Florin Strugariu [:Bebe]]

Tested this today and can't reproduce locally.

That commit does not affect/change anything on the raptor-tp6-paypal test

rwood any suggestion?

Comment 2

[Andreea Pavel [:apavel]]

There are 30 total failures in the last 7 days on win, linux and osx.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=237043607&repo=mozilla-central&lineNumber=983

00:02:31 INFO - raptor-main starting chrome
00:02:31 INFO - Application command: /Users/cltbld/tasks/task_1553903883/fetches/chrome-mac/Chromium.app/Contents/MacOS/Chromium --user-data-dir=/var/folders/yw/bppt02gj4gjcqcqxc2dd5mvm00000x/T/tmpiHJp0J.mozrunner --profile-directory=Default --no-first-run --proxy-server=127.0.0.1:8080 --proxy-bypass-list=localhost;127.0.0.1 --ignore-certificate-errors --no-default-browser-check --use-mock-keychain --load-extension=/Users/cltbld/tasks/task_1553903883/build/tests/raptor/raptor/../webext/raptor
00:02:32 INFO - 127.0.0.1 - - [30/Mar/2019 00:02:32] "POST / HTTP/1.1" 200 -

00:04:48 INFO - mozproxy Successfully killed the mitmproxy playback process
00:04:48 INFO - raptor-main removing webext /Users/cltbld/tasks/task_1553903883/build/tests/raptor/raptor/../webext/raptor
00:04:48 INFO - results-handler summarizing raptor test results
00:04:48 INFO - raptor-output ignoring the first fcp value due to initial pageload noise
00:04:48 INFO - raptor-output turning on subtest alerting for measurement type: fcp
00:04:48 INFO - raptor-output ignoring the first loadtime value due to initial pageload noise
00:04:48 INFO - raptor-output turning on subtest alerting for measurement type: loadtime
00:04:48 INFO - raptor-output PERFHERDER_DATA: {"framework": {"name": "raptor"}, "suites": [{"extraOptions": [], "name": "raptor-tp6-tumblr-chrome", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 549.47, "subtests": [{"name": "fcp", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 220.5849999999998, "shouldAlert": true, "replicates": [1047.3700000000008, 272.42499999999836, 337.7049999999713, 224.42499999999654, 234.56499999997504, 208.4600000000023, 231.96500000000242, 224.254999999971, 162.32500000000982, 221.74000000001115, 287.70500000001675, 243.42999999998938, 368.4949999999958, 178.96500000000515, 254.6649999999886, 210.29999999996107, 154.8750000000041, 178.80000000002383, 133.76999999996997, 219.42999999998847, 134.16499999999587, 130.80999999999676, 191.56499999996868, 151.08500000002323, 290.8249999999839], "unit": "ms"}, {"name": "loadtime", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 1366.5, "shouldAlert": true, "replicates": [3689, 2105, 1433, 1394, 1331, 1304, 1468, 1307, 1721, 1586, 1531, 1576, 1346, 1237, 1398, 1380, 1180, 1306, 1330, 1353, 1344, 1407, 1266, 1212, 1630], "unit": "ms"}], "type": "pageload", "unit": "ms"}]}
00:04:48 INFO - raptor-output results can also be found locally at: /Users/cltbld/tasks/task_1553903883/build/raptor.json
00:04:48 INFO - raptor-control-server shutting down control server
00:04:48 INFO - raptor-main finished
00:04:48 INFO - raptor-main TEST-UNEXPECTED-FAIL: test 'raptor-tp6-paypal-chrome' timed out loading test page: https://www.paypal.com/myaccount/summary/ pending metrics: fcp, load time
00:04:48 ERROR - Return code: 1
00:04:48 WARNING - setting return code to 1

Robert can you take a look or assign someone?

Comment 3

[Intermittent Failures Robot]

19 failures in 660 pushes (0.029 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 19

Platform breakdown:

• osx-10-10-shippable: 4
• windows7-32-shippable: 7
• windows10-64-shippable: 6
• linux64-shippable: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1527493&startday=2019-03-29&endday=2019-03-29&tree=all

Comment 4

[Intermittent Failures Robot]

66 failures in 3910 pushes (0.017 failures/push) were associated with this bug in the last 7 days.

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

• mozilla-central: 66

Platform breakdown:

• osx-10-10-shippable: 10
• linux64-shippable: 4
• windows10-64-shippable: 26
• windows7-32-shippable: 26

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1527493&startday=2019-03-25&endday=2019-03-31&tree=all

Comment 5

[Robert Wood [:rwood]]

:bebe, can you add this to your queue please and have a look? Thanks!

Comment 6

[Florin Strugariu [:Bebe]]

Attachment: chrome fail.txt

Comment 7

[Florin Strugariu [:Bebe]]

Attachment: Chrome pass.txt

Comment 8

[Florin Strugariu [:Bebe]]

added chrome browser logging and took a look at the browser logs.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=65813d41f3de42733371795a0f4f23432d52b6a6&selectedJob=237565774

Looks like for some reason the page is not loaded and the timeout is triggered.

Please take a look at the attached console logs

Comment 9

[Robert Wood [:rwood]]

(In reply to Florin Strugariu [:Bebe] from comment #8)

added chrome browser logging and took a look at the browser logs.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=65813d41f3de42733371795a0f4f23432d52b6a6&selectedJob=237565774

Failed on the 13th page cycle (timeout). :bebe please take this bug and investigate and resolve it, thank you!

Comment 10

[Intermittent Failures Robot]

17 failures in 574 pushes (0.03 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 17

Platform breakdown:

• windows10-64-shippable: 6
• windows7-32-shippable: 6
• osx-10-10-shippable: 2
• linux64-shippable: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1527493&startday=2019-04-04&endday=2019-04-04&tree=all

Comment 11

[Florin Strugariu [:Bebe]]

Let's disable this tests and open a bug to investigate this issue

Comment 12

[Intermittent Failures Robot]

66 failures in 2843 pushes (0.023 failures/push) were associated with this bug in the last 7 days.

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

• mozilla-central: 66

Platform breakdown:

• osx-10-10-shippable: 11
• windows10-64-shippable: 24
• windows7-32-shippable: 25
• linux64-shippable: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1527493&startday=2019-04-01&endday=2019-04-07&tree=all

Comment 13

[Florin Strugariu [:Bebe]]

Disabled this and opened Bug 1542757

Let's investigate this in that bug

Comment 14

[Intermittent Failures Robot]

20 failures in 3025 pushes (0.007 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-central: 18
• try: 2

Platform breakdown:

• osx-10-10-shippable: 4
• windows7-32-shippable: 8
• windows10-64-shippable: 7
• linux64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1527493&startday=2019-04-08&endday=2019-04-14&tree=all

Comment 15

[Florin Strugariu [:Bebe]]

Checked and this run fine on try and central with no intermitents