1431394 - Intermittent Automation Error: mozprocess timed out after 1000 seconds running ['Z:\\task_1516262307\\build\\venv\\Scripts\\python', '-u', 'Z:\\task_1516262307\\build\\tests\\mochitest\\runtests.py', '--appname=Z:\\task_1516262307\\build\\application\\

Status: RESOLVED FIXED

(Testing :: mozscreenshots, defect, P1)

Description

[Treeherder Bug Filer]

Filed by: archaeopteryx [at] coole-files.de

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

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

08:29:08     INFO -  72 INFO *** Start BrowserChrome Test Results ***
08:29:08     INFO -  73 INFO checking window state
08:29:08     INFO -  74 INFO TEST-START | browser/tools/mozscreenshots/primaryUI/browser_primaryUI.js
08:29:20     INFO -  GECKO(4620) | 1516264160461	addons.xpi	WARN	Attempting to activate an already active default theme
08:29:21     INFO -  GECKO(4620) | [DEBUG SHUTDOWN] Shutdown: decoder=010DFB60 state machine=0DB7D800
08:29:21     INFO -  GECKO(4620) | [DEBUG SHUTDOWN] Enter: state machine=08E65CC0 reader=010DE350
08:29:21     INFO -  GECKO(4620) | [DEBUG SHUTDOWN] Shutdown: reader=08EFD000 shutdown demuxer=08EEE230
08:29:21     INFO -  GECKO(4620) | [DEBUG SHUTDOWN] Shutdown: pool=0DBF2900 count=1
08:29:21     INFO -  GECKO(4620) | [DEBUG SHUTDOWN] operator (): pool=0DBF2900 shutdown=true count=0
08:29:21     INFO -  GECKO(4620) | [DEBUG SHUTDOWN] TearDownDecoders: reader=08EFD000 shut down audio task queue
08:29:21     INFO -  GECKO(4620) | [DEBUG SHUTDOWN] TearDownDecoders: reader=08EFD000 shut down video task queue
08:29:21     INFO -  GECKO(4620) | [DEBUG SHUTDOWN] FinishShutdown: state machine=0DB7D800
08:29:21     INFO -  GECKO(4620) | [DEBUG SHUTDOWN] Unregister: decoder=010DFB60, count=0
08:46:01     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['Z:\\task_1516262307\\build\\venv\\Scripts\\python', '-u', 'Z:\\task_1516262307\\build\\tests\\mochitest\\runtests.py', '--appname=Z:\\task_1516262307\\build\\application\\firefox\\firefox.exe', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=https://queue.taskcluster.net/v1/task/ROgw7ivmSuaKoBDi3cob5Q/artifacts/public/build/target.crashreporter-symbols.zip', '--certificate-path=tests/certs', '--quiet', '--log-raw=Z:\\task_1516262307\\build\\blobber_upload_dir\\browser-chrome-screenshots_raw.log', '--log-errorsummary=Z:\\task_1516262307\\build\\blobber_upload_dir\\browser-chrome-screenshots_errorsummary.log', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--flavor=browser', '--subsuite=screenshots']
[taskcluster 2018-01-18T09:12:04.830Z] Aborting task - max run time exceeded!

Comment 1

[Matthew N. [:MattN]]

This is basically a dupe of bug 1425394 but for Windows. Now that we know the approach works, we can probably make https://hg.mozilla.org/mozilla-central/rev/2ab411552083 apply to all OS and move it to where we increase other timeouts.

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 1

Platform breakdown:
* windows7-32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1431394&startday=2018-01-15&endday=2018-01-21&tree=all

Comment 3

[Matthew N. [:MattN]]

Steps to fix this:

1) Revert the changes from https://hg.mozilla.org/mozilla-central/rev/2ab411552083
2) Move the `SimpleTest.requestCompleteLog();` line to after https://dxr.mozilla.org/mozilla-central/rev/5faab9e619901b1513fd4ca137747231be550def/browser/tools/mozscreenshots/head.js#18 with a comment saying "Generate output so mozprocess knows we're still alive for the long session"
3) Run `./mach build faster` and `./mach test browser/tools/mozscreenshots/preferences` and make sure the screenshots are captured.

Comment 4

[Edan]

Attachment: bug.patch

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/466cff873e2a
requestCompleteLog so mozprocess knows we're still alive for the long session. r=MattN

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/e13d6cbf2383
Follow-up lint fix and comment re-order. r=bustage

Comment 7

[Dorel Luca [:dluca]]

https://hg.mozilla.org/mozilla-central/rev/466cff873e2a
https://hg.mozilla.org/mozilla-central/rev/e13d6cbf2383

Comment 8

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/1544a22ca313