1399769 - Intermittent Return code: 254

Status: RESOLVED FIXED

(Testing :: Mochitest, defect, P5)

Description

[Treeherder Bug Filer]

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

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

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

[task 2017-09-14T06:41:33.686530Z] 06:41:33     INFO -  1048 INFO TEST-START | dom/xml/test/test_bug445330.html
[task 2017-09-14T06:41:33.831627Z] 06:41:33     INFO -  GECKO(3827) | MEMORY STAT | vsize 1744MB | residentFast 89MB | heapAllocated 21MB
[task 2017-09-14T06:41:33.856018Z] 06:41:33     INFO -  1049 INFO TEST-OK | dom/xml/test/test_bug445330.html | took 177ms
[task 2017-09-14T06:41:33.920955Z] 06:41:33     INFO -  1050 INFO TEST-START | dom/xml/test/test_bug691215.html
[task 2017-09-14T06:41:35.700976Z] 06:41:35     INFO -  GECKO(3827) | MEMORY STAT | vsize 1793MB | residentFast 107MB | heapAllocated 31MB
[task 2017-09-14T06:41:35.871454Z] 06:41:35     INFO -  1051 INFO TEST-OK | dom/xml/test/test_bug691215.html | took 1942ms
[task 2017-09-14T06:41:35.919765Z] 06:41:35     INFO -  1052 INFO TEST-START | dom/xml/test/test_viewport.xhtml
[task 2017-09-14T06:41:36.057031Z] 06:41:36     INFO -  GECKO(3827) | MEMORY STAT | vsize 1796MB | residentFast 109MB | heapAllocated 32MB
[task 2017-09-14T06:41:36.078004Z] 06:41:36     INFO -  1053 INFO TEST-OK | dom/xml/test/test_viewport.xhtml | took 157ms
[task 2017-09-14T06:41:36.160238Z] 06:41:36     INFO -  1054 INFO TEST-START | Shutdown
[task 2017-09-14T06:41:36.166024Z] 06:41:36     INFO -  1055 INFO Passed:  21
[task 2017-09-14T06:41:36.171522Z] 06:41:36     INFO -  1056 INFO Failed:  0
[task 2017-09-14T06:41:36.171798Z] 06:41:36     INFO -  1057 INFO Todo:    0
[task 2017-09-14T06:41:36.172039Z] 06:41:36     INFO -  1058 INFO Mode:    e10s
[task 2017-09-14T06:41:36.175968Z] 06:41:36     INFO -  1059 INFO Slowest: 1943ms - /tests/dom/xml/test/test_bug691215.html
[task 2017-09-14T06:41:36.179458Z] 06:41:36     INFO -  1060 INFO SimpleTest FINISHED
[task 2017-09-14T06:41:36.182746Z] 06:41:36     INFO -  1061 INFO TEST-INFO | Ran 1 Loops
[task 2017-09-14T06:41:36.184894Z] 06:41:36     INFO -  1062 INFO SimpleTest FINISHED
[task 2017-09-14T06:41:36.929156Z] 06:41:36     INFO -  GECKO(3827) | *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: telemetry_modules_ping
[task 2017-09-14T06:41:37.834468Z] 06:41:37     INFO -  TEST-INFO | Main app process: exit 0
[task 2017-09-14T06:41:37.836416Z] 06:41:37     INFO -  runtests.py | Application ran for: 0:00:15.969530
[task 2017-09-14T06:41:37.837615Z] 06:41:37     INFO -  zombiecheck | Reading PID log: /tmp/tmpdrqoS2pidlog
[task 2017-09-14T06:41:37.840692Z] 06:41:37     INFO -  ==> process 3827 launched child process 3848
[task 2017-09-14T06:41:37.842469Z] 06:41:37     INFO -  ==> process 3827 launched child process 3878
[task 2017-09-14T06:41:37.845338Z] 06:41:37     INFO -  zombiecheck | Checking for orphan process with PID: 3848
[task 2017-09-14T06:41:37.847039Z] 06:41:37     INFO -  zombiecheck | Checking for orphan process with PID: 3878
[task 2017-09-14T06:41:37.848760Z] 06:41:37     INFO -  Stopping web server
[task 2017-09-14T06:41:37.863073Z] 06:41:37     INFO -  Stopping web socket server
[task 2017-09-14T06:41:37.864903Z] 06:41:37     INFO -  Stopping ssltunnel
[task 2017-09-14T06:41:37.885554Z] 06:41:37     INFO -  leakcheck | refcount logging is off, so leaks can't be detected!
[task 2017-09-14T06:41:37.886778Z] 06:41:37     INFO -  runtests.py | Running tests: end.
[task 2017-09-14T06:41:37.936485Z] 06:41:37     INFO -  Buffered messages finished
[task 2017-09-14T06:41:37.936786Z] 06:41:37     INFO -  0 INFO TEST-START | Shutdown
[task 2017-09-14T06:41:37.938895Z] 06:41:37     INFO -  1 INFO Passed:  10615
[task 2017-09-14T06:41:37.939985Z] 06:41:37  WARNING -  2 INFO Failed:  1
[task 2017-09-14T06:41:37.940311Z] 06:41:37  WARNING -  One or more unittests failed.
[task 2017-09-14T06:41:37.942977Z] 06:41:37     INFO -  3 INFO Todo:    71
[task 2017-09-14T06:41:37.943390Z] 06:41:37     INFO -  4 INFO Mode:    e10s
[task 2017-09-14T06:41:37.943629Z] 06:41:37     INFO -  5 INFO SimpleTest FINISHED
[task 2017-09-14T06:41:37.943872Z] 06:41:37     INFO -  Buffered messages finished
[task 2017-09-14T06:41:37.944101Z] 06:41:37     INFO -  SUITE-END | took 959s
[task 2017-09-14T06:41:38.016929Z] 06:41:38    ERROR - Return code: 254

Comment 1

[Geoff Brown [:gbrown]]

Mostly Linux, all mochitest.

Follows a mochitest run in which one or more tests failed. Regression from bug 1394910? Probably harmless, but annoying.

Comment 2

[Geoff Brown [:gbrown]]

Confirmed: mozharness' run_command() prints the return code from the harness as an error if it is unexpected (non-0 for mochitests).

Modify run_command() to not report this error? No - it's probably important for some situations.

Allow -2/254 explicitly for mochitests? Seems like a messy complication.

Perhaps backout 1394910 such that failed tests do not modify the script return code, and use a different mechanism for verify to detect failed tests.

Comment 3

[Geoff Brown [:gbrown]]

Attachment: normally return 0 from runtests.py, even when tests fail

Passing mochitest jobs are still green, and a test failure results in orange. 

https://treeherder.mozilla.org/#/jobs?repo=try&revision=f158b67919c7a6e8eafe6de940dbdefd5cc97a8c

Note that when a test fails, the return code is 0 once again.

https://public-artifacts.taskcluster.net/LvyjvGZ-TZykSlaAzeIgwA/0/public/logs/live_backing.log

[task 2017-09-14T15:37:19.403287Z] 15:37:19     INFO -  Browser Chrome Test Summary
[task 2017-09-14T15:37:19.405276Z] 15:37:19     INFO -  	Passed: 12598
[task 2017-09-14T15:37:19.407060Z] 15:37:19  WARNING -  	Failed: 2
[task 2017-09-14T15:37:19.408798Z] 15:37:19  WARNING -  One or more unittests failed.
[task 2017-09-14T15:37:19.411493Z] 15:37:19     INFO -  	Todo: 1
[task 2017-09-14T15:37:19.413177Z] 15:37:19     INFO -  	Mode: e10s
[task 2017-09-14T15:37:19.414886Z] 15:37:19     INFO -  *** End BrowserChrome Test Results ***
[task 2017-09-14T15:37:19.421660Z] 15:37:19     INFO -  Buffered messages finished
[task 2017-09-14T15:37:19.423324Z] 15:37:19     INFO -  SUITE-END | took 1440s
[task 2017-09-14T15:37:19.481541Z] 15:37:19     INFO - Return code: 0


Test verification still fails fast, as desired:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=787d914f1f4c30f7bfcdcc68ae2147d4e1a28598&filter-tier=1&filter-tier=2&filter-tier=3

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/267e6c477d86
Do not modify runtests.py return code for failed tests; r=jmaher

Comment 5

[Intermittent Failures Robot]

107 failures in 191 pushes (0.56 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 57
* mozilla-inbound: 50

Platform breakdown:
* linux32: 52
* linux64: 33
* osx-10-10: 13
* linux64-stylo-disabled: 5
* linux32-stylo-disabled: 4

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1399769&startday=2017-09-14&endday=2017-09-14&tree=all

Comment 6

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/267e6c477d86

Comment 7

[Intermittent Failures Robot]

18 failures in 149 pushes (0.121 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 18

Platform breakdown:
* linux32-stylo-disabled: 12
* linux64-stylo-disabled: 3
* linux64: 2
* linux32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1399769&startday=2017-09-15&endday=2017-09-15&tree=all

Comment 8

[Intermittent Failures Robot]

124 failures in 1032 pushes (0.12 failures/push) were associated with this bug in the last 7 days. 

This is the #18 most frequent failure this week. 

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **   

Repository breakdown:
* autoland: 76
* mozilla-inbound: 48

Platform breakdown:
* linux32: 54
* linux64: 34
* linux32-stylo-disabled: 19
* osx-10-10: 10
* linux64-stylo-disabled: 7

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1399769&startday=2017-09-11&endday=2017-09-17&tree=all