Closed Bug 1524614 Opened 6 years ago Closed 6 years ago

Intermittent raptor-main TEST-UNEXPECTED-FAIL: no raptor test results were found for raptor-speedometer-geckoview

Categories

(Testing :: Raptor, defect, P5)

Version 3
defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell unknown])

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

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

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

16:08:48 INFO - Killing logcat pid 428.
16:08:48 CRITICAL - PERFHERDER_DATA was seen 0 times, expected 1.
16:08:48 INFO - copying raptor results to upload dir:
16:08:48 INFO - /builds/worker/workspace/build/blobber_upload_dir/perfherder-data.json
16:08:48 INFO - copying raptor results from /builds/worker/workspace/build/raptor.json to /builds/worker/workspace/build/blobber_upload_dir/perfherder-data.json
16:08:48 CRITICAL - Error copying results /builds/worker/workspace/build/raptor.json to upload dir /builds/worker/workspace/build/blobber_upload_dir/perfherder-data.json
16:08:48 INFO - [Errno 2] No such file or directory: u'/builds/worker/workspace/build/raptor.json'
16:08:48 INFO - Running post-action listener: _package_coverage_data
16:08:48 INFO - Running post-action listener: _resource_record_post_action
16:08:48 INFO - Running post-action listener: process_java_coverage_data
16:08:48 INFO - Running post-action listener: stop_device
16:08:48 INFO - Killing logcat pid 428.
16:08:48 INFO - [mozharness: 2019-02-01 16:08:48.205970Z] Finished run-tests step (success)
16:08:48 INFO - Running post-run listener: _resource_record_post_run
16:08:48 INFO - Total resource usage - Wall time: 954s; CPU: 8.0%; Read bytes: 1704842240; Write bytes: 18264489984; Read time: 596884; Write time: 10715664
16:08:48 INFO - TinderboxPrint: CPU usage<br/>8.0%
16:08:48 INFO - TinderboxPrint: I/O read bytes / time<br/>1,704,842,240 / 596,884
16:08:48 INFO - TinderboxPrint: I/O write bytes / time<br/>18,264,489,984 / 10,715,664
16:08:48 INFO - TinderboxPrint: CPU idle<br/>3,072.4 (80.8%)
16:08:48 INFO - TinderboxPrint: CPU iowait<br/>421.4 (11.1%)
16:08:48 INFO - TinderboxPrint: CPU system<br/>132.3 (3.5%)
16:08:48 INFO - TinderboxPrint: CPU user<br/>157.6 (4.1%)
16:08:48 INFO - TinderboxPrint: Swap in / out<br/>0 / 0
16:08:48 INFO - install - Wall time: 10s; CPU: 7.0%; Read bytes: 21282816; Write bytes: 101228544; Read time: 72; Write time: 61836
16:08:48 INFO - run-tests - Wall time: 944s; CPU: 8.0%; Read bytes: 1680155648; Write bytes: 18162950144; Read time: 596664; Write time: 10653532
16:08:48 WARNING - returning nonzero exit status 1
cleanup
+ cleanup
+ local rv=1
+ [[ -s /builds/worker/.xsession-errors ]]
+ false
+ exit 1

There have been 43 failures within the last 7 days, all of them on Android 7.0 MotoG5 opt and Android 8.0 Pixel2 opt
Recent log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=227785961&repo=autoland&lineNumber=1052

00:08:46 INFO - 127.0.0.1 - - [12/Feb/2019 00:08:46] "POST / HTTP/1.1" 200 -
00:08:46 INFO - raptor-control-server received webext_status: raptor runner.js is loaded!
00:08:46 INFO - 127.0.0.1 - - [12/Feb/2019 00:08:46] "GET /raptor-speedometer-geckoview.json HTTP/1.1" 200 -
00:08:46 INFO - raptor-control-server reading test settings from raptor-speedometer-geckoview.json
00:08:46 INFO - raptor-control-server sent test settings to web ext runner
00:08:46 INFO - 127.0.0.1 - - [12/Feb/2019 00:08:46] "POST / HTTP/1.1" 200 -
00:08:46 INFO - raptor-control-server received webext_status: * pausing 30 seconds to let browser settle... *
00:09:16 INFO - 127.0.0.1 - - [12/Feb/2019 00:09:16] "POST / HTTP/1.1" 200 -
00:09:16 INFO - raptor-control-server received webext_status: running 1 pagecycles of http://127.0.0.1:41865/Speedometer/index.html?raptor
00:09:17 INFO - 127.0.0.1 - - [12/Feb/2019 00:09:17] "POST / HTTP/1.1" 200 -
00:09:17 INFO - raptor-control-server received webext_status: begin pagecycle 1
00:09:18 INFO - 127.0.0.1 - - [12/Feb/2019 00:09:18] "POST / HTTP/1.1" 200 -
00:09:18 INFO - raptor-control-server received webext_status: update tab 0
00:09:18 INFO - 127.0.0.1 - - [12/Feb/2019 00:09:18] "POST / HTTP/1.1" 200 -
00:09:18 INFO - raptor-control-server received webext_status: test tab updated 0
00:24:10 INFO - raptor-main application timed out after 930 seconds
00:24:11 INFO - adb shell_output: adb -s ZY322LDKCW wait-for-device shell am force-stop org.mozilla.geckoview_example; echo adb_returncode=$?, timeout: None, root: False, timedout: None, exitcode: 0, output:
00:24:12 INFO - adb command_output: adb -s ZY322LDKCW wait-for-device pull /sdcard/raptor/profile/minidumps /tmp/tmplXrFp3/minidumps, timeout: None, timedout: None, exitcode: 0, output: pull: building file list...
00:24:12 INFO - /sdcard/raptor/profile/minidumps/: 0 files pulled.
00:24:12 INFO - raptor-main removing webext /builds/worker/workspace/build/tests/raptor/webext/raptor
00:24:12 INFO - results-handler summarizing raptor test results
00:24:12 INFO - raptor-output error: no raptor test results found for raptor-speedometer-geckoview
00:24:12 INFO - raptor-output error: no summarized raptor results found for raptor-speedometer-geckoview
00:24:12 INFO - raptor-control-server shutting down control server
00:24:12 INFO - raptor-main removing reverse socket connections
00:24:12 INFO - adb command_output: adb -s ZY322LDKCW wait-for-device reverse --remove-all, timeout: None, timedout: None, exitcode: 0, output:
00:24:12 INFO - raptor-main finished
00:24:12 INFO - raptor-main TEST-UNEXPECTED-FAIL: no raptor test results were found for raptor-speedometer-geckoview
00:24:12 ERROR - Return code: 1
00:24:12 WARNING - setting return code to 1
00:24:12 INFO - Killing logcat pid 429.
00:24:12 CRITICAL - PERFHERDER_DATA was seen 0 times, expected 1.
00:24:12 INFO - copying raptor results to upload dir:
00:24:12 INFO - /builds/worker/workspace/build/blobber_upload_dir/perfherder-data.json
00:24:12 INFO - copying raptor results from /builds/worker/workspace/build/raptor.json to /builds/worker/workspace/build/blobber_upload_dir/perfherder-data.json
00:24:12 CRITICAL - Error copying results /builds/worker/workspace/build/raptor.json to upload dir /builds/worker/workspace/build/blobber_upload_dir/perfherder-data.json
00:24:12 INFO - [Errno 2] No such file or directory: u'/builds/worker/workspace/build/raptor.json'

Whiteboard: [stockwell needswork]

There are 21 total failures in the last 7 days and 94 in the last 30 days, all on Android 7.0 MotoG5 opt and Android 8.0 Pixel2 opt

Failure rate here seems to have decreased starting with the 18th of February.

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

20:11:59 INFO - raptor-main starting geckoview
20:12:00 INFO - adb shell_output: adb -s ZY322MQ9B5 wait-for-device shell am force-stop org.mozilla.geckoview_example; echo adb_returncode=$?, timeout: None, root: False, timedout: None, exitcode: 0, output:
20:12:00 INFO - adb Granting important runtime permissions to org.mozilla.geckoview_example
20:12:01 INFO - adb shell_output: adb -s ZY322MQ9B5 wait-for-device shell pm grant org.mozilla.geckoview_example android.permission.WRITE_EXTERNAL_STORAGE; echo adb_returncode=$?, timeout: None, root: False, timedout: None, exitcode: 0, output:
20:12:02 INFO - adb shell_output: adb -s ZY322MQ9B5 wait-for-device shell pm grant org.mozilla.geckoview_example android.permission.READ_EXTERNAL_STORAGE; echo adb_returncode=$?, timeout: None, root: False, timedout: None, exitcode: 0, output:
20:12:03 INFO - adb shell_output: adb -s ZY322MQ9B5 wait-for-device shell pm grant org.mozilla.geckoview_example android.permission.ACCESS_COARSE_LOCATION; echo adb_returncode=$?, timeout: None, root: False, timedout: None, exitcode: 0, output:
20:12:04 INFO - adb shell_output: adb -s ZY322MQ9B5 wait-for-device shell pm grant org.mozilla.geckoview_example android.permission.ACCESS_FINE_LOCATION; echo adb_returncode=$?, timeout: None, root: False, timedout: None, exitcode: 0, output:
20:12:05 INFO - adb shell_output: adb -s ZY322MQ9B5 wait-for-device shell pm grant org.mozilla.geckoview_example android.permission.CAMERA; echo adb_returncode=$?, timeout: None, root: False, timedout: None, exitcode: 0, output:
20:12:06 INFO - adb shell_output: adb -s ZY322MQ9B5 wait-for-device shell pm grant org.mozilla.geckoview_example android.permission.RECORD_AUDIO; echo adb_returncode=$?, timeout: None, root: False, timedout: None, exitcode: 0, output:
20:12:06 INFO - adb launch_application: am start -W -n org.mozilla.geckoview_example/org.mozilla.geckoview_example.GeckoViewActivity -a android.intent.action.Main --ez use_multiprocess True --es args "-profile /sdcard/raptor/profile --es env0 LOG_VERBOSE=1 --es env1 R_LOG_LEVEL=6" -d about:blank
20:12:07 INFO - adb shell_output: adb -s ZY322MQ9B5 wait-for-device shell am start -W -n org.mozilla.geckoview_example/org.mozilla.geckoview_example.GeckoViewActivity -a android.intent.action.Main --ez use_multiprocess True --es args "-profile /sdcard/raptor/profile --es env0 LOG_VERBOSE=1 --es env1 R_LOG_LEVEL=6" -d about:blank; echo adb_returncode=$?, timeout: None, root: False, timedout: None, exitcode: 0, output: Starting: Intent { act=android.intent.action.Main dat=about:blank cmp=org.mozilla.geckoview_example/.GeckoViewActivity (has extras) }
20:12:07 INFO - Status: ok
20:12:07 INFO - Activity: org.mozilla.geckoview_example/.GeckoViewActivity
20:12:07 INFO - ThisTime: 468
20:12:07 INFO - TotalTime: 468
20:12:07 INFO - WaitTime: 483
20:12:07 INFO - Complete
20:12:10 INFO - 127.0.0.1 - - [22/Feb/2019 20:12:10] "POST / HTTP/1.1" 200 -
20:12:10 INFO - raptor-control-server received webext_status: raptor runner.js is loaded!
20:12:10 INFO - 127.0.0.1 - - [22/Feb/2019 20:12:10] "GET /raptor-speedometer-geckoview.json HTTP/1.1" 200 -
20:12:10 INFO - raptor-control-server reading test settings from raptor-speedometer-geckoview.json
20:12:10 INFO - raptor-control-server sent test settings to web ext runner
20:12:11 INFO - 127.0.0.1 - - [22/Feb/2019 20:12:11] "POST / HTTP/1.1" 200 -
20:12:11 INFO - raptor-control-server received webext_status: * pausing 30 seconds to let browser settle... *
20:12:41 INFO - 127.0.0.1 - - [22/Feb/2019 20:12:41] "POST / HTTP/1.1" 200 -
20:12:41 INFO - raptor-control-server received webext_status: running 1 pagecycles of http://127.0.0.1:51033/Speedometer/index.html?raptor
20:12:42 INFO - 127.0.0.1 - - [22/Feb/2019 20:12:42] "POST / HTTP/1.1" 200 -
20:12:42 INFO - raptor-control-server received webext_status: begin pagecycle 1
20:12:43 INFO - 127.0.0.1 - - [22/Feb/2019 20:12:43] "POST / HTTP/1.1" 200 -
20:12:43 INFO - raptor-control-server received webext_status: update tab 0
20:12:43 INFO - 127.0.0.1 - - [22/Feb/2019 20:12:43] "POST / HTTP/1.1" 200 -
20:12:43 INFO - raptor-control-server received webext_status: test tab updated 0
20:27:37 INFO - raptor-main application timed out after 933 seconds
20:27:38 INFO - adb shell_output: adb -s ZY322MQ9B5 wait-for-device shell am force-stop org.mozilla.geckoview_example; echo adb_returncode=$?, timeout: None, root: False, timedout: None, exitcode: 0, output:
20:27:39 INFO - adb command_output: adb -s ZY322MQ9B5 wait-for-device pull /sdcard/raptor/profile/minidumps /tmp/tmptmp4ro/minidumps, timeout: None, timedout: None, exitcode: 0, output: pull: building file list...
20:27:39 INFO - /sdcard/raptor/profile/minidumps/: 0 files pulled.
20:27:39 INFO - raptor-main removing webext /builds/worker/workspace/build/tests/raptor/webext/raptor
20:27:39 INFO - results-handler summarizing raptor test results
20:27:39 INFO - raptor-output error: no raptor test results found for raptor-speedometer-geckoview
20:27:39 INFO - raptor-output error: no summarized raptor results found for raptor-speedometer-geckoview
20:27:39 INFO - raptor-control-server shutting down control server
20:27:39 INFO - raptor-main removing reverse socket connections
20:27:39 INFO - adb command_output: adb -s ZY322MQ9B5 wait-for-device reverse --remove-all, timeout: None, timedout: None, exitcode: 0, output:
20:27:39 INFO - raptor-main finished
20:27:39 INFO - raptor-main TEST-UNEXPECTED-FAIL: no raptor test results were found for raptor-speedometer-geckoview
20:27:39 ERROR - Return code: 1
20:27:39 WARNING - setting return code to 1
20:27:39 INFO - Killing logcat pid 431.
20:27:39 CRITICAL - PERFHERDER_DATA was seen 0 times, expected 1.

Robert can you assign someone here?

Flags: needinfo?(rwood)
Whiteboard: [stockwell needswork] → [stockwell needswork:owner]
Whiteboard: [stockwell unknown] → [stockwell needswork:owner]

There are 33 failures on this bug over the last 7 days. These happen on android-hw-g5-7-0-arm7-api-16, android-hw-p2-8-0-android-aarch64

Here is the most recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=231505546&repo=mozilla-inbound&lineNumber=1060

22:48:58 INFO - raptor-control-server received webext_status: test tab updated 0
23:03:52 INFO - raptor-main application timed out after 933 seconds
23:03:53 INFO - adb shell_output: adb -s ZY322MQ9B5 wait-for-device shell am force-stop org.mozilla.geckoview_example; echo adb_returncode=$?, timeout: None, root: False, timedout: None, exitcode: 0, output:
23:03:54 INFO - adb command_output: adb -s ZY322MQ9B5 wait-for-device pull /sdcard/raptor/profile/minidumps /tmp/tmpI6ZW8L/minidumps, timeout: None, timedout: None, exitcode: 0, output: pull: building file list...
23:03:54 INFO - /sdcard/raptor/profile/minidumps/: 0 files pulled.
23:03:54 INFO - raptor-main removing webext /builds/worker/workspace/build/tests/raptor/webext/raptor
23:03:54 INFO - results-handler summarizing raptor test results
23:03:54 INFO - raptor-output error: no raptor test results found for raptor-speedometer-geckoview
23:03:54 INFO - raptor-output error: no summarized raptor results found for raptor-speedometer-geckoview
23:03:54 INFO - raptor-control-server shutting down control server
23:03:54 INFO - raptor-main removing reverse socket connections
23:03:54 INFO - adb command_output: adb -s ZY322MQ9B5 wait-for-device reverse --remove-all, timeout: None, timedout: None, exitcode: 0, output:
23:03:54 INFO - raptor-main finished
23:03:54 INFO - raptor-main TEST-UNEXPECTED-FAIL: no raptor test results were found for raptor-speedometer-geckoview
23:03:55 ERROR - Return code: 1
23:03:55 WARNING - setting return code to 1
23:03:55 INFO - Killing logcat pid 436.
23:03:55 CRITICAL - PERFHERDER_DATA was seen 0 times, expected 1.
23:03:55 INFO - copying raptor results to upload dir:
23:03:55 INFO - /builds/worker/workspace/build/blobber_upload_dir/perfherder-data.json
23:03:55 INFO - copying raptor results from /builds/worker/workspace/build/raptor.json to /builds/worker/workspace/build/blobber_upload_dir/perfherder-data.json
23:03:55 CRITICAL - Error copying results /builds/worker/workspace/build/raptor.json to upload dir /builds/worker/workspace/build/blobber_upload_dir/perfherder-data.json
23:03:55 INFO - [Errno 2] No such file or directory: u'/builds/worker/workspace/build/raptor.json'
23:03:55 INFO - Running post-action listener: _package_coverage_data
23:03:55 INFO - Running post-action listener: _resource_record_post_action
23:03:55 INFO - Running post-action listener: process_java_coverage_data
23:03:55 INFO - Running post-action listener: stop_device
23:03:55 INFO - Killing logcat pid 436.
23:03:55 INFO - [mozharness: 2019-03-02 23:03:55.147113Z] Finished run-tests step (success)
23:03:55 INFO - Running post-run listener: _resource_record_post_run
23:03:55 INFO - Total resource usage - Wall time: 960s; CPU: 7.0%; Read bytes: 305906688; Write bytes: 12603891712; Read time: 10332; Write time: 3625788
23:03:55 INFO - TinderboxPrint: CPU usage<br/>6.5%
23:03:55 INFO - TinderboxPrint: I/O read bytes / time<br/>305,906,688 / 10,332
23:03:55 INFO - TinderboxPrint: I/O write bytes / time<br/>12,603,891,712 / 3,625,788
23:03:55 INFO - TinderboxPrint: CPU idle<br/>3,396.5 (89.0%)
23:03:55 INFO - TinderboxPrint: CPU iowait<br/>170.3 (4.5%)
23:03:55 INFO - TinderboxPrint: CPU system<br/>67.3 (1.8%)
23:03:55 INFO - TinderboxPrint: CPU user<br/>177.4 (4.6%)
23:03:55 INFO - TinderboxPrint: Swap in / out<br/>0 / 0
23:03:55 INFO - install - Wall time: 11s; CPU: 7.0%; Read bytes: 20946944; Write bytes: 320733184; Read time: 160; Write time: 155900
23:03:55 INFO - run-tests - Wall time: 950s; CPU: 7.0%; Read bytes: 284959744; Write bytes: 12282626048; Read time: 10172; Write time: 3469396
23:03:55 WARNING - returning nonzero exit status 1
cleanup

Not sure what the issue is here but I'll spend a bit of time digging through production logcats to see if I can spot any clues.

Flags: needinfo?(rwood)

Not sure if this is related but I do notice several telemetry errors - telemetry is trying to ping, possibly this can be turned off somehow in a pref.

03-02 15:36:16.132 5653 5669 E GeckoConsole: [JavaScript Error: "1551569776131 Toolkit.Telemetry ERROR TelemetrySend::_doPing - error making request to https://127.0.0.1/telemetry-dummy//submit/telemetry/b6984eae-5c24-4ba6-bd1e-0373f34821e6/health/Fennec/67.0a1/default/20190302214639?v=4: eUnreachable" {file: "resource://gre/modules/Log.jsm" line: 679}]
03-02 15:36:16.132 5653 5669 E GeckoConsole: append@resource://gre/modules/Log.jsm:679:12
03-02 15:36:16.132 5653 5669 E GeckoConsole: log@resource://gre/modules/Log.jsm:360:16
03-02 15:36:16.132 5653 5669 E GeckoConsole: getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:484:18
03-02 15:36:16.132 5653 5669 E GeckoConsole: error@resource://gre/modules/Log.jsm:368:10
03-02 15:36:16.132 5653 5669 E GeckoConsole: errorhandler@resource://gre/modules/TelemetrySend.jsm:1165:17

Also seeing this error:

03-02 15:32:18.962 5673 5692 D GeckoViewProgress[C]: ProgressTracker updateProgress data={"prev":20.285930633544922,"uri":"http://127.0.0.1:33289/Speedometer/index.html?raptor","locationChange":true,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":false,"parsed":true,"totalReceived":4997,"totalExpected":4997} progress=35.28593063354492
03-02 15:32:18.963 5653 5653 I GeckoViewActivity: onProgressChange 35
03-02 15:32:18.969 5673 5692 I Web Content: raptor benchmark-relay content loaded
03-02 15:32:19.004 5673 5692 W Web Content: [JavaScript Warning: "The script from “http://127.0.0.1:33289/resources/runner.js” was loaded even though its MIME type (“application/json”) is not a valid JavaScript MIME type." {file: "http://127.0.0.1:33289/Speedometer/index.html?raptor" line: 0}]
03-02 15:32:19.005 5673 5692 W Web Content: [JavaScript Warning: "Loading failed for the <script> with source “http://127.0.0.1:33289/resources/runner.js”." {file: "http://127.0.0.1:33289/Speedometer/index.html?raptor" line: 1}]

However I see the same error message on successful / green raptor speedometer geckoview runs, so that message is not a factor. Also the logs confirm both the main raptor runner.js and benchmark-relay.js scripts were successfully injected into the Speedometer content.

Filed Bug 1533879 to follow-up re: telemetry

Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
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.