Closed Bug 1518446 Opened 6 years ago Closed 6 years ago

Intermittent raptor-main TEST-UNEXPECTED-FAIL: test 'raptor-tp6-yahoo-news-firefox' timed out loading test page: https://www.yahoo.com/lifestyle/police-respond-noise-complaint-end-playing-video-games-respectful-tenants-002329963.html

Categories

(Testing :: Raptor, defect, P5)

Version 3
defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

Filed by: dluca [at] mozilla.com

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

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

Return code: 0
08:26:18 INFO - raptor-mitmproxy mitmdump path: C:\Users\task_1546927423\testing\raptor\py3venv\Scripts\mitmdump
08:26:18 INFO - raptor-mitmproxy recording path: C:\Users\task_1546927423\testing\raptor
08:26:18 INFO - raptor-mitmproxy recordings list: ['yahoo-news.mp']
08:26:18 INFO - raptor-mitmproxy browser path: C:\Users\task_1546927423\build\application\firefox\firefox.exe
08:26:18 INFO - raptor-mitmproxy Starting mitmproxy playback using env path: C:\Users\task_1546927423\build\application\firefox;C:\Users\task_1546927423\build\venv\Scripts;C:\Program Files\Mercurial;C:\mozilla-build\bin;C:\mozilla-build\kdiff3;C:\mozilla-build\moztools-x64\bin;C:\mozilla-build\mozmake;C:\mozilla-build\msys\bin;C:\mozilla-build\msys\local\bin;C:\mozilla-build\nsis-3.01;C:\mozilla-build\python;C:\mozilla-build\python\Scripts;C:\mozilla-build\python3;C:\windows\system32;C:\windows;C:\windows\System32\Wbem;C:\windows\System32\WindowsPowerShell\v1.0;C:\Program Files\Mellanox\MLNX_VPI\IB\Tools;C:\Program Files\Mellanox\MLNX_CIMProvider\lib\mft;C:\windows\system32\config\systemprofile\AppData\Local\Microsoft\WindowsApps;C:\Program Files (x86)\Windows Kits\8.1\Windows Performance Toolkit;C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit;C:\Users\task_1546927423\AppData\Local\Microsoft\WindowsApps
08:26:18 INFO - raptor-mitmproxy Starting mitmproxy playback using command: C:\Users\task_1546927423\testing\raptor\py3venv\Scripts\mitmdump -k -q -s ""C:\\Users\\task_1546927423\\build\\tests\\raptor\\raptor\\playback\\alternate-server-replay.py C:\\Users\\task_1546927423\\testing\\raptor\\yahoo-news.mp""
08:26:28 INFO - raptor-mitmproxy Mitmproxy playback successfully started as pid 2616
08:26:28 INFO - raptor-mitmproxy Installing mitmproxy CA certficate into Firefox
08:26:28 INFO - raptor-mitmproxy folder already exists: C:\Users\task_1546927423\build\application\firefox\distribution
08:26:28 INFO - raptor-mitmproxy writing: C:\Users\task_1546927423\build\application\firefox\distribution\policies.json
08:26:28 INFO - raptor-mitmproxy reading: C:\Users\task_1546927423\build\application\firefox\distribution\policies.json
08:26:28 INFO - raptor-mitmproxy Firefox policies file contents:
08:26:28 INFO - raptor-mitmproxy {
08:26:28 INFO - "policies": {
08:26:28 INFO - "Certificates": {
08:26:28 INFO - "Install": ["C:\Users\task_1546927423\.mitmproxy\mitmproxy-ca-cert.cer"]
08:26:28 INFO - },
08:26:28 INFO - "Proxy": {
08:26:28 INFO - "Mode": "manual",
08:26:28 INFO - "HTTPProxy": "127.0.0.1:8080",
08:26:28 INFO - "SSLProxy": "127.0.0.1:8080",
08:26:28 INFO - "Passthrough": "localhost, 127.0.0.1, 127.0.0.1",
08:26:28 INFO - "Locked": true
08:26:28 INFO - }
08:26:28 INFO - }
08:26:28 INFO - }
08:26:28 INFO - raptor-mitmproxy Verified mitmproxy CA certificate is installed in Firefox
08:26:28 INFO - raptor-main starting firefox
08:26:28 INFO - Application command: C:\Users\task_1546927423\build\application\firefox\firefox.exe --wait-for-browser -profile c:\users\task_1546927423\appdata\local\temp\tmpl26ymh.mozrunner
08:26:29 INFO - raptor-control-server received webext_status: raptor runner.js is loaded!
08:26:29 INFO - raptor-control-server reading test settings from raptor-tp6-yahoo-news-firefox.json
08:26:29 INFO - raptor-control-server sent test settings to web ext runner
08:26:29 INFO - raptor-control-server received webext_status: * pausing 30 seconds to let browser settle... *
08:26:59 INFO - raptor-control-server received webext_status: running 25 pagecycles of https://www.yahoo.com/lifestyle/police-respond-noise-complaint-end-playing-video-games-respectful-tenants-002329963.html
08:26:59 INFO - raptor-control-server received webext_status: opened new empty tab 1
08:27:00 INFO - raptor-control-server received webext_status: begin pagecycle 1
08:27:01 INFO - raptor-control-server received webext_status: update tab 1
08:27:01 INFO - raptor-control-server received webext_status: test tab updated 1
08:27:30 INFO - raptor-control-server received webext_raptor-page-timeout: [u'raptor-tp6-yahoo-news-firefox', u'https://www.yahoo.com/lifestyle/police-respond-noise-complaint-end-playing-video-games-respectful-tenants-002329963.html']
08:27:30 INFO - raptor-control-server received webext_status: __raptor_shutdownBrowser
08:27:30 INFO - raptor-control-server shutting down browser (pid: 7848)
08:27:30 INFO - raptor-control-server received webext_status: Removed tab 1
08:27:30 INFO - PID 7848 | [Parent 576, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 332
08:27:47 INFO - raptor-mitmproxy Stopping mitmproxy playback, klling process 2616
08:27:57 INFO - raptor-mitmproxy Successfully killed the mitmproxy playback process
08:27:57 INFO - raptor-mitmproxy Turning off the browser proxy
08:27:57 INFO - raptor-mitmproxy writing: C:\Users\task_1546927423\build\application\firefox\distribution\policies.json
08:27:57 INFO - raptor-main removing webext C:\Users\task_1546927423\build\tests\raptor\webext\raptor
08:27:57 INFO - results-handler summarizing raptor test results
08:27:57 INFO - raptor-output ignoring the first dcf value due to initial pageload noise
08:27:57 INFO - raptor-output ignoring the first fnbpaint value due to initial pageload noise
08:27:57 INFO - raptor-output ignoring the first ttfi value due to initial pageload noise
08:27:57 INFO - raptor-output ignoring the first loadtime value due to initial pageload noise
08:27:57 INFO - raptor-output PERFHERDER_DATA: {"framework": {"name": "raptor"}, "suites": [{"extraOptions": [], "name": "raptor-tp6-reddit-firefox", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 1138.0, "subtests": [{"name": "raptor-tp6-reddit-firefox-dcf", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 824.5, "replicates": [1208, 978, 959, 995, 793, 924, 784, 829, 820, 801, 805, 836, 800, 801, 787, 865, 801, 809, 779, 846, 803, 834, 869, 837, 839], "unit": "ms"}, {"name": "raptor-tp6-reddit-firefox-fnbpaint", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 311.5, "replicates": [471, 292, 294, 298, 300, 384, 300, 316, 308, 364, 306, 367, 299, 299, 303, 373, 307, 319, 324, 370, 309, 339, 325, 318, 314], "unit": "ms"}, {"name": "raptor-tp6-reddit-firefox-ttfi", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 2746.0, "replicates": [3390, 3274, 3187, 2996, 2515, 2717, 2425, 2909, 2451, 3404, 2883, 2809, 3092, 2467, 2340, 2752, 2449, 2395, 2553, 2924, 2494, 2622, 3255, 2997, 2740], "unit": "ms"}, {"name": "raptor-tp6-reddit-firefox-loadtime", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 2374.0, "replicates": [3120, 2639, 2618, 2636, 2241, 2585, 2291, 2327, 2320, 3207, 2333, 2676, 2360, 2335, 2195, 2388, 2316, 2249, 2307, 2696, 2359, 2477, 2494, 2457, 2595], "unit": "ms"}], "type": "pageload", "unit": "ms"}]}
08:27:57 INFO - raptor-output results can also be found locally at: C:\Users\task_1546927423\build\raptor.json
08:27:57 INFO - raptor-control-server shutting down control server
08:27:57 INFO - raptor-main finished
08:27:57 INFO - raptor-main TEST-UNEXPECTED-FAIL: test 'raptor-tp6-yahoo-news-firefox' timed out loading test page: https://www.yahoo.com/lifestyle/police-respond-noise-complaint-end-playing-video-games-respectful-tenants-002329963.html
08:27:57 INFO - T / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:23:46] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:23:56] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:23:57] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:23:58] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:23:58] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:24:09] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:24:10] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:24:11] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:24:11] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:24:21] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:24:22] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:24:23] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:24:23] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:24:34] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:24:35] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:24:36] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:24:36] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:24:46] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:24:47] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:24:48] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:24:48] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:24:59] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:25:00] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:25:01] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:25:01] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:25:11] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:25:12] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:25:13] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:25:13] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:25:24] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:25:25] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:25:26] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:25:26] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:25:36] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:25:37] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:25:38] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:25:38] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:25:49] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:25:49] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:25:49] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:25:49] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:26:29] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:26:29] "GET /raptor-tp6-yahoo-news-firefox.json HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:26:29] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:26:59] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:26:59] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:27:00] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:27:01] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:27:01] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:27:30] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:27:30] "POST / HTTP/1.1" 200 -
08:27:57 INFO - 127.0.0.1 - - [08/Jan/2019 08:27:30] "POST / HTTP/1.1" 200 -
WARNING | IO Completion Port failed to signal process shutdown
Parent process 6084 exited with children alive:
PIDS: 4156, 7632, 6168
Attempting to kill them, but no guarantee of success
08:31:02 ERROR - Return code: 1
08:31:02 WARNING - setting return code to 1
08:31:02 INFO - Validating PERFHERDER_DATA against C:\Users\task_1546927423\mozharness\external_tools\performance-artifact-schema.json
08:31:02 INFO - copying raptor results to upload dir:
08:31:02 INFO - C:\Users\task_1546927423\build\blobber_upload_dir\perfherder-data.json
08:31:02 INFO - copying raptor results from C:\Users\task_1546927423\build\raptor.json to C:\Users\task_1546927423\build\blobber_upload_dir\perfherder-data.json
08:31:02 INFO - Running post-action listener: _package_coverage_data
08:31:02 INFO - Running post-action listener: _resource_record_post_action
08:31:02 INFO - Running post-action listener: process_java_coverage_data
08:31:02 INFO - Running post-action listener: stop_device
08:31:02 INFO - [mozharness: 2019-01-08 08:31:02.985000Z] Finished run-tests step (success)
08:31:02 INFO - Running post-run listener: _resource_record_post_run
08:31:03 INFO - Total resource usage - Wall time: 703s; CPU: 6.0%; Read bytes: 247287296; Write bytes: 671991296; Read time: 3; Write time: 16
08:31:03 INFO - TinderboxPrint: CPU usage<br/>6.4%
08:31:03 INFO - TinderboxPrint: I/O read bytes / time<br/>247,287,296 / 3
08:31:03 INFO - TinderboxPrint: I/O write bytes / time<br/>671,991,296 / 16
08:31:03 INFO - TinderboxPrint: CPU idle<br/>5,265.9 (93.6%)
08:31:03 INFO - TinderboxPrint: CPU system<br/>72.2 (1.3%)
08:31:03 INFO - TinderboxPrint: CPU user<br/>286.7 (5.1%)
08:31:03 INFO - install - Wall time: 2s; CPU: 15.0%; Read bytes: 294400; Write bytes: 1356288; Read time: 0; Write time: 0
08:31:03 INFO - run-tests - Wall time: 702s; CPU: 6.0%; Read bytes: 244691968; Write bytes: 650749440; Read time: 3; Write time: 16
08:31:03 WARNING - returning nonzero exit status 1
[taskcluster 2019-01-08T08:31:03.194Z] Exit Code: 1
[taskcluster 2019-01-08T08:31:03.194Z] User Time: 0s
[taskcluster 2019-01-08T08:31:03.194Z] Kernel Time: 0s
[taskcluster 2019-01-08T08:31:03.194Z] Wall Time: 13m0.3634775s
[taskcluster 2019-01-08T08:31:03.194Z] Result: FAILED
[taskcluster 2019-01-08T08:31:03.194Z] === Task Finished ===
[taskcluster 2019-01-08T08:31:03.194Z] Task Duration: 13m0.3644995s
[taskcluster 2019-01-08T08:31:03.515Z] Uploading artifact public/logs/localconfig.json from file logs\localconfig.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2020-01-08T07:08:34.332Z
[taskcluster 2019-01-08T08:31:04.217Z] Uploading artifact public/logs/raptor_critical.log from file logs\raptor_critical.log with content encoding "gzip", mime type "text/plain" and expiry 2020-01-08T07:08:34.332Z
[taskcluster 2019-01-08T08:31:04.642Z] Uploading artifact public/logs/raptor_error.log from file logs\raptor_error.log with content encoding "gzip", mime type "text/plain" and expiry 2020-01-08T07:08:34.332Z
[taskcluster 2019-01-08T08:31:05.042Z] Uploading artifact public/logs/raptor_fatal.log from file logs\raptor_fatal.log with content encoding "gzip", mime type "text/plain" and expiry 2020-01-08T07:08:34.332Z
[taskcluster 2019-01-08T08:31:05.420Z] Uploading artifact public/logs/raptor_info.log from file logs\raptor_info.log with content encoding "gzip", mime type "text/plain" and expiry 2020-01-08T07:08:34.332Z
[taskcluster 2019-01-08T08:31:05.935Z] Uploading artifact public/logs/raptor_raw.log from file logs\raptor_raw.log with content encoding "gzip", mime type "text/plain" and expiry 2020-01-08T07:08:34.332Z
[taskcluster 2019-01-08T08:31:06.308Z] Uploading artifact public/logs/raptor_warning.log from file logs\raptor_warning.log with content encoding "gzip", mime type "text/plain" and expiry 2020-01-08T07:08:34.332Z
[taskcluster 2019-01-08T08:31:06.684Z] Uploading artifact public/test_info/perfherder-data.json from file build\blobber_upload_dir\perfherder-data.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2020-01-08T07:08:34.332Z
[taskcluster 2019-01-08T08:31:07.068Z] Uploading artifact public/test_info/resource-usage.json from file build\blobber_upload_dir\resource-usage.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2020-01-08T07:08:34.332Z
[taskcluster 2019-01-08T08:31:07.785Z] Uploading redirect artifact public/logs/live.log to URL https://queue.taskcluster.net/v1/task/Pc4Yz2lhTfiRhfE8b1S6FA/runs/0/artifacts/public/logs/live_backing.log with mime type "text/plain; charset=utf-8" and expiry 2020-01-08T07:08:34.332Z
[taskcluster:error] exit status 1

Assignee: nobody → fstrugariu
08:26:29     INFO -  raptor-control-server reading test settings from raptor-tp6-yahoo-news-firefox.json
08:26:29     INFO -  raptor-control-server sent test settings to web ext runner
08:26:29     INFO -  raptor-control-server received webext_status: * pausing 30 seconds to let browser settle... *
08:26:59     INFO -  raptor-control-server received webext_status: running 25 pagecycles of https://www.yahoo.com/lifestyle/police-respond-noise-complaint-end-playing-video-games-respectful-tenants-002329963.html
08:26:59     INFO -  raptor-control-server received webext_status: opened new empty tab 1
08:27:00     INFO -  raptor-control-server received webext_status: begin pagecycle 1
08:27:01     INFO -  raptor-control-server received webext_status: update tab 1
08:27:01     INFO -  raptor-control-server received webext_status: test tab updated 1
08:27:30     INFO -  raptor-control-server received webext_raptor-page-timeout: [u'raptor-tp6-yahoo-news-firefox', u'https://www.yahoo.com/lifestyle/police-respond-noise-complaint-end-playing-video-games-respectful-tenants-002329963.html']

Looks like it failed on the cold load

3 failures in 2383 pushes (0.001 failures/push) I have the feeling this is acceptable

:rwood what's the next step in this case?

Flags: needinfo?(rwood)

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

3 failures in 2383 pushes (0.001 failures/push) I have the feeling this is acceptable

:rwood what's the next step in this case?

Yes it's a really low intermittent rate so it's fine just leaving it open as a P5. Hopefully at some point we'll have time to revisit all these lower-priority intermittent failures but until then we'll just see how it goes, and increase the priority if the intermittent rate increases.

Flags: needinfo?(rwood)
Assignee: fstrugariu → nobody
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.