Closed Bug 1507529 Opened 7 years ago Closed 6 years ago

Intermittent raptor-main TEST-UNEXPECTED-FAIL: test 'raptor-tp6-slides-firefox' timed out loading test page: https://docs.google.com/presentation/d/1Ici0ceWwpFvmIb3EmKeWSq_vAQdmmdFcWqaiLqUkJng/edit?usp=sharing

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: csabou [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=211993113&repo=autoland https://queue.taskcluster.net/v1/task/fkf0x6GYSXSEsqdgxTvKRA/runs/0/artifacts/public/logs/live_backing.log 16:05:43 INFO - raptor-control-server received webext_status: Removed tab 3 16:05:43 INFO - PID 3692 | [Parent 2816, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346 16:05:43 INFO - PID 3692 | [Child 1692, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346 16:05:43 INFO - PID 3692 | [Child 1692, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346 16:05:59 INFO - raptor-mitmproxy Stopping mitmproxy playback, klling process 8280 16:06:09 INFO - raptor-mitmproxy Successfully killed the mitmproxy playback process 16:06:09 INFO - raptor-mitmproxy Turning off the browser proxy 16:06:09 INFO - raptor-main removing webext C:\Users\task_1542297027\build\tests\raptor\webext\raptor 16:06:09 INFO - results-handler summarizing raptor test results 16:06:09 INFO - raptor-output ignoring the first fnbpaint value due to initial pageload noise 16:06:09 INFO - raptor-output ignoring the first hero:hero1 value due to initial pageload noise 16:06:09 INFO - raptor-output ignoring the first fnbpaint value due to initial pageload noise 16:06:09 INFO - raptor-output ignoring the first hero:hero1 value due to initial pageload noise 16:06:09 INFO - raptor-output PERFHERDER_DATA: {"framework": {"name": "raptor"}, "suites": [{"extraOptions": [], "name": "raptor-tp6-docs-firefox", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 1958.17, "subtests": [{"name": "raptor-tp6-docs-firefox-fnbpaint", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 1255.0, "replicates": [1960, 1390, 1425, 1480, 1232, 1432, 1259, 1143, 2241, 1200, 1248, 1215, 1146, 1440, 1416, 1461, 1231, 1251, 1139, 1278, 1237, 1394, 1322, 1204, 1130], "unit": "ms"}, {"name": "raptor-tp6-docs-firefox-hero:hero1", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 3055.0, "replicates": [4814, 3175, 3222, 2992, 2821, 3049, 3744, 4118, 4032, 3322, 3027, 2973, 2926, 3061, 3239, 3227, 3497, 3154, 2975, 2927, 5650, 3048, 2777, 2984, 2914], "unit": "ms"}], "type": "pageload", "unit": "ms"}, {"extraOptions": [], "name": "raptor-tp6-sheets-firefox", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 753.0, "subtests": [{"name": "raptor-tp6-sheets-firefox-fnbpaint", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 289.5, "replicates": [830, 368, 371, 360, 290, 256, 289, 373, 255, 462, 364, 349, 245, 262, 257, 260, 261, 340, 250, 251, 432, 263, 273, 371, 370], "unit": "ms"}, {"name": "raptor-tp6-sheets-firefox-hero:hero1", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 1956.0, "replicates": [1728, 1908, 2143, 2154, 2272, 1946, 1831, 1870, 1894, 1921, 2597, 2787, 1966, 1994, 1927, 1029, 1892, 2041, 2011, 1945, 2183, 1053, 1780, 2114, 3255], "unit": "ms"}], "type": "pageload", "unit": "ms"}]} 16:06:09 INFO - raptor-output results can also be found locally at: C:\Users\task_1542297027\build\raptor.json 16:06:09 INFO - raptor-control-server shutting down control server 16:06:10 INFO - raptor-main finished 16:06:10 INFO - raptor-main TEST-UNEXPECTED-FAIL: test 'raptor-tp6-slides-firefox' timed out loading test page: https://docs.google.com/presentation/d/1Ici0ceWwpFvmIb3EmKeWSq_vAQdmmdFcWqaiLqUkJng/edit?usp=sharing 16:06:10 INFO - :20] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:03:21] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:03:22] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:03:22] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:03:24] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:03:25] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:03:26] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:03:26] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:03:28] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:03:29] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:03:30] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:03:30] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:03:34] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:03:34] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:03:34] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:03:34] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:04:12] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:04:12] "GET /raptor-tp6-slides-firefox.json HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:04:12] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:04:42] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:04:42] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:04:43] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:04:44] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:04:44] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:05:43] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:05:43] "POST / HTTP/1.1" 200 - 16:06:10 INFO - 127.0.0.1 - - [15/Nov/2018 16:05:43] "POST / HTTP/1.1" 200 - WARNING | IO Completion Port failed to signal process shutdown Parent process 3328 exited with children alive: PIDS: 7424, 5316, 1716, 8956 Attempting to kill them, but no guarantee of success 16:09:15 ERROR - Return code: 1
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE

This is still happening.

Recent failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=221061975&repo=mozilla-inbound&lineNumber=1146

03:28:05 INFO - 127.0.0.1 - - [10/Jan/2019 03:28:05] "POST / HTTP/1.1" 200 -
03:28:05 INFO - raptor-control-server received webext_status: Removed tab 3
03:28:21 INFO - raptor-mitmproxy Stopping mitmproxy playback, klling process 5725
03:28:21 INFO - Replaying from files: ['/home/cltbld/tasks/task_1547119188/testing/raptor/google-slides.mp']
03:28:31 INFO - raptor-mitmproxy Successfully killed the mitmproxy playback process
03:28:31 INFO - raptor-mitmproxy Turning off the browser proxy
03:28:31 INFO - raptor-mitmproxy writing: /home/cltbld/tasks/task_1547119188/build/application/firefox/distribution/policies.json
03:28:31 INFO - raptor-main removing webext /home/cltbld/tasks/task_1547119188/build/tests/raptor/webext/raptor
03:28:31 INFO - results-handler summarizing raptor test results
03:28:31 INFO - raptor-output ignoring the first dcf value due to initial pageload noise
03:28:31 INFO - raptor-output ignoring the first fnbpaint value due to initial pageload noise
03:28:31 INFO - raptor-output ignoring the first hero:hero1 value due to initial pageload noise
03:28:31 INFO - raptor-output ignoring the first dcf value due to initial pageload noise
03:28:31 INFO - raptor-output ignoring the first fnbpaint value due to initial pageload noise
03:28:31 INFO - raptor-output ignoring the first hero:hero1 value due to initial pageload noise
03:28:31 INFO - raptor-output PERFHERDER_DATA: {"framework": {"name": "raptor"}, "suites": [{"extraOptions": [], "name": "raptor-tp6-docs-firefox", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 1180.22, "subtests": [{"name": "raptor-tp6-docs-firefox-dcf", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 567.5, "replicates": [1186, 691, 739, 773, 496, 567, 524, 651, 568, 487, 665, 528, 671, 598, 544, 609, 521, 633, 508, 545, 539, 574, 510, 651, 553], "unit": "ms"}, {"name": "raptor-tp6-docs-firefox-fnbpaint", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 1137.0, "replicates": [1800, 1300, 1375, 1393, 1098, 1322, 1150, 1123, 1072, 979, 1145, 1129, 1156, 1193, 1044, 1091, 1027, 1159, 992, 1179, 1172, 1126, 994, 1204, 1046], "unit": "ms"}, {"name": "raptor-tp6-docs-firefox-hero:hero1", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 2546.5, "replicates": [3745, 2495, 2675, 2746, 2353, 2614, 2629, 3544, 2656, 2295, 2567, 2398, 2570, 2510, 2461, 2802, 2878, 2856, 2408, 2490, 2450, 2958, 2333, 2526, 2347], "unit": "ms"}], "type": "pageload", "unit": "ms"}, {"extraOptions": [], "name": "raptor-tp6-sheets-firefox", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 453.14, "subtests": [{"name": "raptor-tp6-sheets-firefox-dcf", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 218.0, "replicates": [788, 294, 295, 310, 237, 209, 205, 203, 212, 248, 216, 212, 218, 210, 206, 213, 237, 330, 368, 336, 218, 216, 257, 211, 250], "unit": "ms"}, {"name": "raptor-tp6-sheets-firefox-fnbpaint", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 245.5, "replicates": [802, 302, 304, 319, 262, 225, 222, 220, 219, 255, 246, 221, 236, 220, 224, 220, 296, 337, 426, 395, 245, 222, 288, 219, 257], "unit": "ms"}, {"name": "raptor-tp6-sheets-firefox-hero:hero1", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 1734.0, "replicates": [2588, 1744, 1226, 1566, 1533, 1733, 1709, 1698, 1810, 1918, 1441, 1714, 1868, 1812, 1735, 1447, 1907, 2814, 2970, 2740, 1560, 1478, 1757, 1460, 1764], "unit": "ms"}], "type": "pageload", "unit": "ms"}]}
03:28:31 INFO - raptor-output results can also be found locally at: /home/cltbld/tasks/task_1547119188/build/raptor.json
03:28:31 INFO - raptor-control-server shutting down control server
03:28:32 INFO - raptor-main finished
03:28:32 INFO - raptor-main TEST-UNEXPECTED-FAIL: test 'raptor-tp6-slides-firefox' timed out loading test page: https://docs.google.com/presentation/d/1Ici0ceWwpFvmIb3EmKeWSq_vAQdmmdFcWqaiLqUkJng/edit?usp=sharing
03:28:32 ERROR - Return code: 1
03:28:32 WARNING - setting return code to 1
03:28:32 INFO - Validating PERFHERDER_DATA against /home/cltbld/tasks/task_1547119188/mozharness/external_tools/performance-artifact-schema.json
03:28:32 INFO - copying raptor results to upload dir:
03:28:32 INFO - /home/cltbld/tasks/task_1547119188/build/blobber_upload_dir/perfherder-data.json
03:28:32 INFO - copying raptor results from /home/cltbld/tasks/task_1547119188/build/raptor.json to /home/cltbld/tasks/task_1547119188/build/blobber_upload_dir/perfherder-data.json
03:28:32 INFO - Running post-action listener: _package_coverage_data
03:28:32 INFO - Running post-action listener: _resource_record_post_action
03:28:32 INFO - Running post-action listener: process_java_coverage_data
03:28:32 INFO - Running post-action listener: stop_device
03:28:32 INFO - [mozharness: 2019-01-10 11:28:32.444902Z] Finished run-tests step (success)
03:28:32 INFO - Running post-run listener: _resource_record_post_run
03:28:32 INFO - Total resource usage - Wall time: 498s; CPU: 9.0%; Read bytes: 145530880; Write bytes: 1688051712; Read time: 1216; Write time: 59716
03:28:32 INFO - TinderboxPrint: CPU usage<br/>8.7%
03:28:32 INFO - TinderboxPrint: I/O read bytes / time<br/>145,530,880 / 1,216
03:28:32 INFO - TinderboxPrint: I/O write bytes / time<br/>1,688,051,712 / 59,716
03:28:32 INFO - TinderboxPrint: CPU idle<br/>3,613.1 (91.3%)
03:28:32 INFO - TinderboxPrint: CPU user<br/>289.5 (7.3%)
03:28:32 INFO - TinderboxPrint: Swap in / out<br/>0 / 0
03:28:32 INFO - install - Wall time: 14s; CPU: 13.0%; Read bytes: 95404032; Write bytes: 2146304; Read time: 560; Write time: 16
03:28:32 INFO - run-tests - Wall time: 484s; CPU: 9.0%; Read bytes: 47636480; Write bytes: 1685905408; Read time: 656; Write time: 59700
03:28:32 WARNING - returning nonzero exit status 1
[taskcluster 2019-01-10T11:28:32.613Z] Exit Code: 1
[taskcluster 2019-01-10T11:28:32.613Z] User Time: 5m19.028s
[taskcluster 2019-01-10T11:28:32.613Z] Kernel Time: 35.608s
[taskcluster 2019-01-10T11:28:32.613Z] Wall Time: 8m41.393784472s
[taskcluster 2019-01-10T11:28:32.613Z] Result: FAILED
[taskcluster 2019-01-10T11:28:32.613Z] === Task Finished ===

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 6 years ago6 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.