Closed Bug 1447980 Opened 7 years ago Closed 7 years ago

Intermittent TVw (tier 2) Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/web-platform/runtests.py', '--log-raw=-'

Categories

(Testing :: web-platform-tests, defect, P5)

Product:
Testing
Component:
web-platform-tests
Version:
Version 3
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED WORKSFORME

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

Filed by: apavel [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=169626395&repo=mozilla-inbound https://queue.taskcluster.net/v1/task/RLvOpcXNQSGq_8nXhhGvNQ/runs/0/artifacts/public/logs/live_backing.log [task 2018-03-22T10:23:24.594Z] 10:23:24 INFO - TEST-START | /webdriver/tests/actions/mouse_pause_dblclick.py [task 2018-03-22T10:23:24.595Z] 10:23:24 INFO - TEST-SKIP | /webdriver/tests/actions/mouse_pause_dblclick.py | took 0ms [task 2018-03-22T10:23:24.596Z] 10:23:24 INFO - SUITE-END | took 0s [task 2018-03-22T10:23:24.678Z] 10:23:24 INFO - ## All results ## [task 2018-03-22T10:23:24.678Z] 10:23:24 INFO - [task 2018-03-22T10:23:24.679Z] 10:23:24 INFO - ### /webdriver/tests/actions/mouse_pause_dblclick.py ### [task 2018-03-22T10:23:24.679Z] 10:23:24 INFO - | Subtest | Results | Messages | [task 2018-03-22T10:23:24.680Z] 10:23:24 INFO - |---------|---------|----------| [task 2018-03-22T10:23:24.680Z] 10:23:24 INFO - | | SKIP | | [task 2018-03-22T10:23:24.680Z] 10:23:24 INFO - [task 2018-03-22T10:23:24.681Z] 10:23:24 INFO - ::: Running tests in a loop 10 times : PASS [task 2018-03-22T10:23:24.681Z] 10:23:24 INFO - ::: Running tests in a loop with restarts 5 times : PASS [task 2018-03-22T10:23:24.682Z] 10:23:24 INFO - ::: Running tests in a loop 10 times with flags chaos_mode_flags=3 : PASS [task 2018-03-22T10:23:24.683Z] 10:23:24 INFO - ::: Running tests in a loop with restarts 5 times with flags chaos_mode_flags=3 : PASS [task 2018-03-22T10:23:24.683Z] 10:23:24 INFO - ::: [task 2018-03-22T10:23:24.684Z] 10:23:24 INFO - ::: Test verification PASS [task 2018-03-22T10:23:24.684Z] 10:23:24 INFO - ::: [task 2018-03-22T10:40:04.720Z] 10:40:04 INFO - Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/web-platform/runtests.py', '--log-raw=-', '--log-raw=/builds/worker/workspace/build/blobber_upload_dir/wpt_raw.log', '--log-wptreport=/builds/worker/workspace/build/blobber_upload_dir/wptreport.json', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/wpt_errorsummary.log', '--binary=/builds/worker/workspace/build/application/firefox/firefox', '--symbols-path=https://queue.taskcluster.net/v1/task/O8kerSM0RtSBQXcxkf-njA/artifacts/public/build/target.crashreporter-symbols.zip', '--stackwalk-binary=/usr/local/bin/linux64-minidump_stackwalk', '--stackfix-dir=/builds/worker/workspace/build/tests/bin', '--run-by-dir=3', '--no-pause-after-test', u'--test-type=wdspec', '--stylo-threads=4', '--webdriver-binary=/builds/worker/workspace/build/tests/bin/geckodriver', '--webdriver-arg=-vv', '--prefs-root=/builds/worker/workspace/build/tests/web-platform/prefs', '--processes=1', '--config=/builds/worker/workspace/build/tests/web-platform/wptrunner.ini', '--ca-cert-path=/builds/worker/workspace/build/tests/web-platform/certs/cacert.pem', '--host-key-path=/builds/worker/workspace/build/tests/web-platform/certs/web-platform.test.key', '--host-cert-path=/builds/worker/workspace/build/tests/web-platform/certs/web-platform.test.pem', '--certutil-binary=/builds/worker/workspace/build/tests/bin/certutil', '--verify-log-full', '--verify', u'tests/web-platform/tests/webdriver/tests/actions/mouse_pause_dblclick.py'] [task 2018-03-22T10:40:04.760Z] 10:40:04 ERROR - timed out after 1000 seconds of no output [task 2018-03-22T10:40:04.760Z] 10:40:04 ERROR - Return code: -15 [task 2018-03-22T10:40:04.760Z] 10:40:04 ERROR - # TBPL FAILURE # [task 2018-03-22T10:40:04.761Z] 10:40:04 WARNING - setting return code to 2 [task 2018-03-22T10:40:04.761Z] 10:40:04 ERROR - TinderboxPrint: Verification of .../actions/mouse_pause_dblclick.py<br/>: FAILURE [task 2018-03-22T10:40:04.761Z] 10:40:04 INFO - Running post-action listener: _package_coverage_data [task 2018-03-22T10:40:04.762Z] 10:40:04 INFO - Running post-action listener: _resource_record_post_action [task 2018-03-22T10:40:04.762Z] 10:40:04 INFO - [mozharness: 2018-03-22 10:40:04.762228Z] Finished run-tests step (success) [task 2018-03-22T10:40:04.762Z] 10:40:04 INFO - Running post-run listener: _resource_record_post_run [task 2018-03-22T10:40:04.892Z] 10:40:04 INFO - Total resource usage - Wall time: 1295s; CPU: 7.0%; Read bytes: 10878976; Write bytes: 1939140608; Read time: 440; Write time: 336256 [task 2018-03-22T10:40:04.892Z] 10:40:04 INFO - TinderboxPrint: CPU usage<br/>6.7% [task 2018-03-22T10:40:04.893Z] 10:40:04 INFO - TinderboxPrint: I/O read bytes / time<br/>10,878,976 / 440 [task 2018-03-22T10:40:04.894Z] 10:40:04 INFO - TinderboxPrint: I/O write bytes / time<br/>1,939,140,608 / 336,256 [task 2018-03-22T10:40:04.894Z] 10:40:04 INFO - TinderboxPrint: CPU idle<br/>4,771.4 (93.2%) [task 2018-03-22T10:40:04.894Z] 10:40:04 INFO - TinderboxPrint: CPU system<br/>66.3 (1.3%) [task 2018-03-22T10:40:04.895Z] 10:40:04 INFO - TinderboxPrint: CPU user<br/>267.5 (5.2%) [task 2018-03-22T10:40:04.895Z] 10:40:04 INFO - TinderboxPrint: Swap in / out<br/>0 / 0 [task 2018-03-22T10:40:04.896Z] 10:40:04 INFO - pull - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0 [task 2018-03-22T10:40:04.897Z] 10:40:04 INFO - install - Wall time: 23s; CPU: 25.0%; Read bytes: 0; Write bytes: 137945088; Read time: 0; Write time: 147508 [task 2018-03-22T10:40:04.912Z] 10:40:04 INFO - run-tests - Wall time: 1272s; CPU: 6.0%; Read bytes: 10878976; Write bytes: 1801195520; Read time: 440; Write time: 188748 [task 2018-03-22T10:40:05.301Z] 10:40:05 INFO - Running post-run listener: _upload_blobber_files [task 2018-03-22T10:40:05.301Z] 10:40:05 WARNING - Blob upload gear skipped. Missing cmdline options. [task 2018-03-22T10:40:05.301Z] 10:40:05 INFO - Running post-run listener: copy_logs_to_upload_dir [task 2018-03-22T10:40:05.302Z] 10:40:05 INFO - Copying logs to upload dir... [task 2018-03-22T10:40:05.302Z] 10:40:05 INFO - mkdir: /builds/worker/workspace/build/upload/logs [task 2018-03-22T10:40:05.314Z] 10:40:05 INFO - Copying logs to upload dir... [task 2018-03-22T10:40:05.328Z] 10:40:05 WARNING - returning nonzero exit status 2 [task 2018-03-22T10:40:05.777Z] cleanup [task 2018-03-22T10:40:05.777Z] + cleanup [task 2018-03-22T10:40:05.777Z] + local rv=2 [task 2018-03-22T10:40:05.777Z] + [[ -s /builds/worker/.xsession-errors ]] [task 2018-03-22T10:40:05.777Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log [task 2018-03-22T10:40:05.781Z] + true [task 2018-03-22T10:40:05.781Z] + cleanup_xvfb [task 2018-03-22T10:40:05.781Z] pidof Xvfb [task 2018-03-22T10:40:05.781Z] ++ pidof Xvfb [task 2018-03-22T10:40:05.787Z] + local xvfb_pid=25 [task 2018-03-22T10:40:05.787Z] + local vnc=false [task 2018-03-22T10:40:05.788Z] + local interactive=false [task 2018-03-22T10:40:05.788Z] + '[' -n 25 ']' [task 2018-03-22T10:40:05.788Z] + [[ false == false ]] [task 2018-03-22T10:40:05.793Z] + [[ false == false ]] [task 2018-03-22T10:40:05.793Z] + kill 25 [task 2018-03-22T10:40:05.793Z] + screen -XS xvfb quit [task 2018-03-22T10:40:05.794Z] XIO: fatal IO error 11 (Resource temporarily unavailable) on X server ":0" [task 2018-03-22T10:40:05.794Z] after 8456 requests (8456 known processed) with 0 events remaining. [task 2018-03-22T10:40:05.794Z] compizconfig - Info: Backend : ini [task 2018-03-22T10:40:05.794Z] compizconfig - Info: Integration : true [task 2018-03-22T10:40:05.795Z] compizconfig - Info: Profile : default [task 2018-03-22T10:40:05.968Z] No screen session found. [task 2018-03-22T10:40:05.968Z] + true [task 2018-03-22T10:40:05.968Z] + exit 2 [taskcluster 2018-03-22 10:40:06.951Z] === Task Finished === [taskcluster 2018-03-22 10:40:14.383Z] Unsuccessful task run with exit code: 2 completed in 1766.801 seconds
Summary: Intermittent Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/web-platform/runtests.py', '--log-raw=-' → Intermittent tier 2 Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/web-platform/runtests.py', '--log-raw=-'
So this is a failure from a job running all the tests as we usually only do in wdspec only for all wpt tests. The job is called `opt-test-verify-wpt-e10s`. Personally I was not aware that we run our webdriver tests in a different job too. James and Maja is that something we do for wpt sync? I have no idea why it hangs at this stage and what the script is trying to do anyway.
Flags: needinfo?(mjzffr)
Flags: needinfo?(james)
This is the test-verify job. It's not really related to the sync. It seems like the job is passing and then for some reason we hang. On that basis, I'm guessing it's something in the cleanup that isn't working, but it's not immediately obvious what. But if this is reproducable you should be able to figure it out by adding print statements up the callstack from write_summary in stability.py under wptrunner.
Flags: needinfo?(james)
So far it seems to have been a single commit only. We should keep an eye on it and do some investigation when it happens more often.
Flags: needinfo?(mjzffr)
Summary: Intermittent tier 2 Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/web-platform/runtests.py', '--log-raw=-' → Intermittent TVw (tier 2) Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/web-platform/runtests.py', '--log-raw=-'
(In reply to OrangeFactor Robot from comment #5) > 11 failures in 765 pushes (0.014 failures/push) were associated with this > bug in the last 7 days. > > Repository breakdown: > * try: 10 > * mozilla-central: 1 All those failures were wrongly starred, and as such are related to bug 1416929 but not that one. Sebastian, can you please check this with the SV sheriffs? Thanks.
Flags: needinfo?(aryx.bugmail)
Thank you, done.
Flags: needinfo?(aryx.bugmail)
(In reply to OrangeFactor Robot from comment #8) > 2 failures in 792 pushes (0.003 failures/push) were associated with this bug > in the last 7 days. Both failures are wrongly starred again. Given that this failure happened only once 25 days ago and since then only got false starrings I'm going to close it as WFM now.
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.