1548651 - Intermittent raptor-main TEST-UNEXPECTED-FAIL: test 'raptor-tp6-youtube-firefox-cold' timed out loading test page: https://www.youtube.com pending metrics: fcp, fnb paint, dcf, load time

Status: RESOLVED INCOMPLETE

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: ncsoregi [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=244228029&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/Tg9gxbXXQluDgiuJ6VCgPQ/runs/0/artifacts/public/logs/live_backing.log

---

17:37:02 INFO - raptor-output screen captures can be found locally at: C:\Users\task_1556814580\build\screenshots.html
17:37:02 INFO - raptor-output PERFHERDER_DATA: {"framework": {"name": "raptor"}, "suites": [{"extraOptions": [], "name": "raptor-tp6-youtube-firefox-cold", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 652.99, "subtests": [{"name": "dcf", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 749, "replicates": [1432, 792, 821, 853, 720, 722, 719, 758, 764, 750, 719, 727, 729, 726, 736, 749, 753, 774, 740, 741, 739, 749, 758], "unit": "ms"}, {"name": "fcp", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 567, "shouldAlert": true, "replicates": [941, 604, 616, 636, 538, 548, 784, 587, 556, 568, 549, 532, 790, 780, 571, 566, 565, 565, 550, 567, 567, 549, 583], "unit": "ms"}, {"name": "fnbpaint", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 335, "replicates": [347, 318, 350, 335, 317, 315, 343, 374, 322, 350, 328, 315, 339, 346, 335, 332, 331, 331, 332, 361, 353, 335, 344], "unit": "ms"}, {"name": "loadtime", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 1277, "shouldAlert": true, "replicates": [1799, 1032, 1384, 1164, 1277, 1004, 1255, 1408, 1197, 1342, 1022, 1029, 1326, 1371, 1504, 1190, 1204, 1241, 1296, 1178, 1333, 1316, 1385], "unit": "ms"}], "type": "pageload", "unit": "ms"}]}
17:37:02 INFO - raptor-output results can also be found locally at: C:\Users\task_1556814580\build\raptor.json
17:37:02 INFO - raptor-control-server shutting down control server
17:37:03 INFO - raptor-main finished
17:37:03 INFO - raptor-main TEST-UNEXPECTED-FAIL: test 'raptor-tp6-youtube-firefox-cold' timed out loading test page: https://www.youtube.com pending metrics: fcp, fnb paint, dcf, load time
17:37:03 ERROR - Return code: 1
17:37:03 WARNING - setting return code to 1

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 4
• mozilla-central: 2

Platform breakdown:

• windows10-64-shippable: 2
• osx-10-10-shippable: 1
• windows7-32-shippable: 1
• linux64-shippable: 1
• windows10-64-ux: 1

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

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1

Platform breakdown:

• macosx1010-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1548651&startday=2019-05-27&endday=2019-06-02&tree=all

Comment 4

[Andreea Pavel [:apavel]]

Reopening based on https://bugzilla.mozilla.org/show_bug.cgi?id=1539184#c55

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=244746368&repo=mozilla-central&lineNumber=1642

20:13:51 INFO - raptor-main starting firefox
20:13:51 INFO - Application command: C:\Users\task_1557083914\build\application\firefox\firefox.exe --wait-for-browser -profile c:\users\task_1557083914\appdata\local\temp\tmpxabaqp.mozrunner
20:13:57 INFO - raptor-control-server received webext_status: raptor runner.js is loaded!
20:13:57 INFO - raptor-control-server reading test settings from raptor-tp6-youtube-firefox-cold.json

0:14:50 INFO - raptor-output combining results from browser cycle 2 for raptor-tp6-youtube-firefox-cold
20:14:50 INFO - raptor-output adding replicates for dcf
20:14:50 INFO - raptor-output adding replicates for fcp
20:14:50 INFO - raptor-output adding replicates for fnbpaint
20:14:50 INFO - raptor-output adding replicates for loadtime
20:14:50 INFO - raptor-output screen captures can be found locally at: C:\Users\task_1557083914\build\screenshots.html
20:14:50 INFO - raptor-output PERFHERDER_DATA: {"framework": {"name": "raptor"}, "suites": [{"extraOptions": [], "name": "raptor-tp6-youtube-firefox-cold", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 1047.97, "subtests": [{"name": "dcf", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 1459.5, "replicates": [4054, 1408, 1329, 1408, 1315, 2306, 1349, 1533, 1440, 4089, 1510, 5510, 1203, 1331, 1312, 1463, 1506, 1456, 1387, 1616, 1618, 1484, 1905, 1451], "unit": "ms"}, {"name": "fcp", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 981.0, "shouldAlert": true, "replicates": [1503, 961, 900, 944, 921, 1741, 915, 1025, 993, 1607, 983, 4672, 852, 964, 888, 993, 1013, 982, 945, 1160, 1112, 967, 820, 980], "unit": "ms"}, {"name": "fnbpaint", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 464.5, "replicates": [958, 393, 384, 393, 420, 776, 464, 442, 443, 590, 466, 2294, 407, 548, 438, 459, 480, 465, 462, 475, 493, 469, 404, 465], "unit": "ms"}, {"name": "loadtime", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 1812.5, "shouldAlert": true, "replicates": [5706, 1747, 1575, 6817, 1552, 2701, 1630, 1798, 1791, 4026, 1758, 5964, 2074, 1717, 1708, 1780, 1794, 1827, 1745, 2021, 1899, 2858, 2679, 3038], "unit": "ms"}], "type": "pageload", "unit": "ms"}]}
20:14:50 INFO - raptor-output results can also be found locally at: C:\Users\task_1557083914\build\raptor.json
20:14:50 INFO - raptor-control-server shutting down control server
20:14:50 INFO - raptor-main finished
20:14:50 INFO - raptor-main TEST-UNEXPECTED-FAIL: test 'raptor-tp6-youtube-firefox-cold' timed out loading test page: https://www.youtube.com pending metrics: fcp, fnb paint, dcf, load time
20:14:51 ERROR - Traceback (most recent call last):
20:14:51 INFO - File "C:\Users\task_1557083914\build\venv\lib\site-packages\mozprocess\processhandler.py", line 550, in _custom_wait
20:14:51 INFO - item = self._process_events.get(timeout=timeout)
20:14:51 INFO - File "c:\mozilla-build\python\Lib\Queue.py", line 176, in get
20:14:51 INFO - raise Empty
20:14:51 INFO - Empty
20:14:51 INFO - Exception in thread Thread-32:
20:14:51 ERROR - Traceback (most recent call last):
20:14:51 INFO - File "c:\mozilla-build\python\Lib\threading.py", line 801, in __bootstrap_inner
20:14:51 INFO - self.run()
20:14:51 INFO - File "c:\mozilla-build\python\Lib\threading.py", line 754, in run
20:14:51 INFO - self.__target(*self.__args, **self.__kwargs)
20:14:51 INFO - File "C:\Users\task_1557083914\build\tests\raptor\raptor\control_server.py", line 334, in wait_for_quit
20:14:51 INFO - self.browser_proc.wait(timeout)
20:14:51 INFO - File "C:\Users\task_1557083914\build\venv\lib\site-packages\mozprocess\processhandler.py", line 917, in wait
20:14:51 INFO - self.returncode = self.proc.wait()
20:14:51 INFO - File "C:\Users\task_1557083914\build\venv\lib\site-packages\mozprocess\processhandler.py", line 229, in wait
20:14:51 INFO - self.returncode = self._custom_wait(timeout=timeout)
20:14:51 INFO - File "C:\Users\task_1557083914\build\venv\lib\site-packages\mozprocess\processhandler.py", line 556, in _custom_wait
20:14:51 INFO - raise OSError("IO Completion Port failed to signal process shutdown")
20:14:51 INFO - OSError: IO Completion Port failed to signal process shutdown
20:14:51 ERROR - Return code: 1

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-inbound: 1

Platform breakdown:

• windows7-32-shippable: 1

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

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1

Platform breakdown:

• windows10-64-shippable-qr: 1

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

Comment 7

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 8

[Andreea Pavel [:apavel]]

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

[task 2019-09-25T23:36:22.520Z] 23:36:22 INFO - raptor-main Info: starting firefox
[task 2019-09-25T23:36:22.521Z] 23:36:22 INFO - Application command: C:\Users\task_1569452365\build\application\firefox\firefox.exe --wait-for-browser -profile c:\users\task_1569452365\appdata\local\temp\tmpys2yt3.mozrunner
[task 2019-09-25T23:36:23.310Z] 23:36:23 INFO - PID 6508 | console.log: "[raptor-runnerjs] Attaching event listener successful!"
[task 2019-09-25T23:36:23.332Z] 23:36:23 INFO - PID 6508 | console.log: "[raptor-runnerjs] starting raptorRunner"
[task 2019-09-25T23:36:23.332Z] 23:36:23 INFO - PID 6508 | console.log: "[raptor-runnerjs] test name is: raptor-tp6-youtube-firefox-cold"
[task 2019-09-25T23:36:23.332Z] 23:36:23 INFO - PID 6508 | console.log: "[raptor-runnerjs] test settings url is: http://127.0.0.1:49772/json/raptor-tp6-youtube-firefox-cold.json"
[task 2019-09-25T23:36:23.332Z] 23:36:23 INFO - PID 6508 | console.log: "[raptor-runnerjs] raptor runner.js is loaded!"
[task 2019-09-25T23:36:23.332Z] 23:36:23 INFO - PID 6508 | console.log: "[raptor-runnerjs] posting to control server"
[task 2019-09-25T23:36:23.332Z] 23:36:23 INFO - PID 6508 | console.log: "[raptor-runnerjs] raptor runner.js is loaded!"
[task 2019-09-25T23:36:23.363Z] 23:36:23 INFO - PID 6508 | console.log: "[raptor-runnerjs] testing on Firefox 71.0a1 20190925215653"
[task 2019-09-25T23:36:23.363Z] 23:36:23 INFO - PID 6508 | console.log: "[raptor-runnerjs] getting test settings from control server"
[task 2019-09-25T23:36:23.368Z] 23:36:23 INFO - raptor-control-server Info: received webext_status: raptor runner.js is loaded!
[task 2019-09-25T23:36:23.368Z] 23:36:23 INFO - raptor-control-server Info: reading test settings from json/raptor-tp6-youtube-firefox-cold.json
[task 2019-09-25T23:36:23.368Z] 23:36:23 INFO - raptor-control-server Info: sent test settings to webext runner
[task 2019-09-25T23:36:23.387Z] 23:36:23 INFO - PID 6508 | console.log: "[raptor-runnerjs] post success"
[task 2019-09-25T23:36:23.387Z] 23:36:23 INFO - PID 6508 | console.log: "[raptor-runnerjs] {"raptor-options": {"expected_browser_cycles": 25, "subtest_unit": "ms", "alert_threshold": 2.0, "type": "pageload", "page_cycles": 1, "subtest_lower_is_better": true, "alert_on": ["fcp", "loadtime"], "test_url": "https://www.youtube.com\", "page_timeout": 60000, "host": "127.0.0.1", "measure": {"fcp": true, "dcf": true, "fnbpaint": true, "loadtime": true}, "cold": true, "lower_is_better": true, "unit": "ms"}}"
[task 2019-09-25T23:36:23.387Z] 23:36:23 INFO - PID 6508 | console.log: "[raptor-runnerjs] https://www.youtube.com"
[task 2019-09-25T23:36:23.387Z] 23:36:23 INFO - PID 6508 | console.log: "[raptor-runnerjs] using page timeout: 60000ms"
[task 2019-09-25T23:36:23.426Z] 23:36:23 INFO - PID 6508 | console.log: "[raptor-runnerjs] wrote settings to ext local storage"
[task 2019-09-25T23:36:23.426Z] 23:36:23 INFO - PID 6508 | console.log: "[raptor-runnerjs] pageload test start"
[task 2019-09-25T23:36:23.426Z] 23:36:23 INFO - PID 6508 | console.log: "[raptor-runnerjs] * pausing 30 seconds to let browser settle... *"
[task 2019-09-25T23:36:23.426Z] 23:36:23 INFO - PID 6508 | console.log: "[raptor-runnerjs] posting to control server"
[task 2019-09-25T23:36:23.426Z] 23:36:23 INFO - PID 6508 | console.log: "[raptor-runnerjs] * pausing 30 seconds to let browser settle... *"
[task 2019-09-25T23:36:23.428Z] 23:36:23 INFO - raptor-control-server Info: received webext_status: * pausing 30 seconds to let browser settle... *

[task 2019-09-25T23:36:58.589Z] 23:36:58 INFO - perftest-output Info: combining results from browser cycle 2 for raptor-tp6-youtube-firefox-cold
[task 2019-09-25T23:36:58.589Z] 23:36:58 INFO - perftest-output Info: adding replicates for dcf
[task 2019-09-25T23:36:58.589Z] 23:36:58 INFO - perftest-output Info: adding replicates for fcp
[task 2019-09-25T23:36:58.589Z] 23:36:58 INFO - perftest-output Info: adding replicates for fnbpaint
[task 2019-09-25T23:36:58.589Z] 23:36:58 INFO - perftest-output Info: adding replicates for loadtime
[task 2019-09-25T23:36:58.589Z] 23:36:58 INFO - perftest-output Info: screen captures can be found locally at: C:\Users\task_1569452365\build\screenshots.html
[task 2019-09-25T23:36:58.589Z] 23:36:58 INFO - perftest-output Info: PERFHERDER_DATA: {"framework": {"name": "raptor"}, "suites": [{"extraOptions": [], "name": "raptor-tp6-youtube-firefox-cold", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 658.93, "subtests": [{"name": "dcf", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 945.0, "replicates": [1533, 1070, 1077, 1091, 912, 925, 952, 936, 957, 912, 1041, 957, 900, 966, 942, 941, 927, 905, 908, 978, 1030, 948, 912, 932], "unit": "ms"}, {"name": "fcp", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 732.0, "shouldAlert": true, "replicates": [471, 873, 873, 889, 722, 722, 741, 741, 739, 722, 723, 741, 722, 739, 723, 739, 725, 724, 723, 793, 739, 721, 722, 742], "unit": "ms"}, {"name": "fnbpaint", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 252.5, "replicates": [266, 250, 252, 249, 252, 251, 280, 269, 268, 250, 255, 268, 254, 252, 255, 250, 253, 251, 252, 255, 251, 250, 254, 269], "unit": "ms"}, {"name": "loadtime", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 1078.0, "shouldAlert": true, "replicates": [1597, 1235, 1251, 1263, 1059, 1061, 1109, 1084, 1073, 1076, 1050, 1068, 1071, 1081, 1080, 1083, 1037, 1080, 1061, 1147, 1071, 1057, 1056, 1080], "unit": "ms"}], "type": "pageload", "unit": "ms"}]}
[task 2019-09-25T23:36:58.589Z] 23:36:58 INFO - perftest-output Info: results can also be found locally at: C:\Users\task_1569452365\build\raptor.json
[task 2019-09-25T23:36:58.590Z] 23:36:58 INFO - perftest-results-handler Info: Validating PERFHERDER_DATA against C:\Users\task_1569452365\mozharness\external_tools\performance-artifact-schema.json
[task 2019-09-25T23:36:58.594Z] 23:36:58 INFO - raptor-control-server Info: shutting down control server
[task 2019-09-25T23:36:58.852Z] 23:36:58 INFO - raptor-main Info: finished
[task 2019-09-25T23:36:58.852Z] 23:36:58 ERROR - raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-tp6-youtube-firefox-cold' timed out loading test page: https://www.youtube.com pending metrics: fcp, fnb paint, dcf
[task 2019-09-25T23:36:58.974Z] 23:36:58 ERROR - Return code: 1

Comment 9

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-64-qr: 1

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

Comment 10

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-64-ref-hw-2017: 1

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

Comment 11

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 12

[Daniel Varga [:dvarga]]

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=295926153&repo=try&lineNumber=14929

Comment 13

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform breakdown:

• linux64-shippable-qr: 1

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

Comment 14

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.