1497740 - Intermittent task runs set as failures without obvious reason

Status: RESOLVED INCOMPLETE

(Testing :: General, defect, P3)

Description

[Natalia Csoregi [:nataliaCs]]

Several logs without any failures parsed have appeared, and all of them have in common this line:
compiz (core) - Warn: Attempted to restack relative to 0x1200006 which is not a child of the root window or a window compiz owns

Example failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=204352813&repo=autoland&lineNumber=802

[task 2018-10-09T22:50:53.133Z] 22:50:53     INFO - Running command: ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool-cache'] in /builds/worker/workspace/build/.android
[task 2018-10-09T22:50:53.134Z] 22:50:53     INFO - Copy/paste: /usr/bin/python2.7 -u /builds/worker/workspace/mozharness/external_tools/tooltool.py --url http://relengapi/tooltool/ fetch -m /builds/worker/workspace/build/.android/releng.manifest -o -c /builds/worker/tooltool-cache
[task 2018-10-09T22:50:53.135Z] 22:50:53     INFO - Calling ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool-cache'] with output_timeout 600
[task 2018-10-09T22:50:53.450Z] 22:50:53     INFO -  INFO - File AVDs-armv7a-android-4.3.1_r1-build-2016-08-02.tar.gz retrieved from local cache /builds/worker/tooltool-cache
[task 2018-10-09T22:50:53.830Z] 22:50:53     INFO -  INFO - untarring "AVDs-armv7a-android-4.3.1_r1-build-2016-08-02.tar.gz"
[task 2018-10-09T22:50:53.938Z] compiz (core) - Warn: Attempted to restack relative to 0x1200006 which is not a child of the root window or a window compiz owns
[task 2018-10-09T22:50:59.354Z] 22:50:59     INFO - Return code: 0
[task 2018-10-09T22:50:59.390Z] 22:50:59     INFO - Running post-action listener: _resource_record_post_action
[task 2018-10-09T22:50:59.390Z] 22:50:59     INFO - [mozharness: 2018-10-09 22:50:59.390405Z] Finished setup-avds step (success)
[task 2018-10-09T22:50:59.391Z] 22:50:59     INFO - [mozharness: 2018-10-09 22:50:59.390675Z] Running start-emulator step.
[task 2018-10-09T22:50:59.391Z] 22:50:59     INFO - Running pre-action listener: _resource_record_pre_action
[task 2018-10-09T22:50:59.391Z] 22:50:59     INFO - Running main action method: start_emulator
[task 2018-10-09T22:50:59.391Z] 22:50:59     INFO - Writing to file /builds/worker/workspace/build/tooltool.tt
[task 2018-10-09T22:50:59.391Z] 22:50:59     INFO - Contents:
[task 2018-10-09T22:50:59.392Z] 22:50:59     INFO -  
[task 2018-10-09T22:50:59.394Z] 22:50:59     INFO -          [
[task 2018-10-09T22:50:59.394Z] 22:50:59     INFO -          {
[task 2018-10-09T22:50:59.394Z] 22:50:59     INFO -          "size": 38451805,
[task 2018-10-09T22:50:59.394Z] 22:50:59     INFO -          "digest": "ac3000aa6846dd1b09a420a1ba84727e393036f49da1419d6c9e5ec2490fc6105c74ca18b616c465dbe693992e2939afd88bc2042d961a9050a3cafd2a673ff4",
[task 2018-10-09T22:50:59.394Z] 22:50:59     INFO -          "algorithm": "sha512",
[task 2018-10-09T22:50:59.394Z] 22:50:59     INFO -          "filename": "android-sdk_r24.0.2a-linux.tar.gz",
[task 2018-10-09T22:50:59.394Z] 22:50:59     INFO -          "unpack": "True"
[task 2018-10-09T22:50:59.394Z] 22:50:59     INFO -          }
[task 2018-10-09T22:50:59.394Z] 22:50:59     INFO -          ] 
[task 2018-10-09T22:50:59.394Z] 22:50:59     INFO - retry: Calling run_command with args: (['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/tooltool.tt', '-o', '-c', '/builds/worker/tooltool-cache'],), kwargs: {'output_timeout': 600, 'error_list': [{'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x7f46524ab408>, 'level': 'warning'}, {'substr': 'Traceback (most recent call last)', 'level': 'error'}, {'substr': 'SyntaxError: ', 'level': 'error'}, {'substr': 'TypeError: ', 'level': 'error'}, {'substr': 'NameError: ', 'level': 'error'}, {'substr': 'ZeroDivisionError: ', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x7f46534f1c48>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x7f4652d63168>, 'level': 'critical'}, {'substr': 'ERROR - ', 'level': 'error'}], 'cwd': '/builds/worker/workspace/build', 'privileged': False}, attempt #1
[task 2018-10-09T22:50:59.395Z] 22:50:59     INFO - Running command: ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/tooltool.tt', '-o', '-c', '/builds/worker/tooltool-cache'] in /builds/worker/workspace/build
[task 2018-10-09T22:50:59.395Z] 22:50:59     INFO - Copy/paste: /usr/bin/python2.7 -u /builds/worker/workspace/mozharness/external_tools/tooltool.py --url http://relengapi/tooltool/ fetch -m /builds/worker/workspace/build/tooltool.tt -o -c /builds/worker/tooltool-cache
[task 2018-10-09T22:50:59.395Z] 22:50:59     INFO - Calling ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/tooltool.tt', '-o', '-c', '/builds/worker/tooltool-cache'] with output_timeout 600
[task 2018-10-09T22:50:59.485Z] 22:50:59     INFO -  INFO - File android-sdk_r24.0.2a-linux.tar.gz retrieved from local cache /builds/worker/tooltool-cache
[task 2018-10-09T22:50:59.602Z] 22:50:59     INFO -  INFO - untarring "android-sdk_r24.0.2a-linux.tar.gz"
[task 2018-10-09T22:51:00.163Z] 22:51:00     INFO - Return code: 0

@Aryx can you please double check if this is the real issue, as in the end, the test seems to be successful, and point me to the person that could help fix this? Thank you

Comment 1

[Intermittent Failures Robot]

18 failures in 537 pushes (0.034 failures/push) were associated with this bug yesterday.

Repository breakdown:
* autoland: 18

Platform breakdown:
* android-em-4-3-armv7-api16: 10
* linux64-qr: 1
* linux64: 3
* linux32: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1497740&startday=2018-10-09&endday=2018-10-09&tree=all

Comment 2

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

Didn't spot any failure in the log. There is a logcat excerpt in the shutdown - is there a hidden crash?

[task 2018-10-09T23:37:17.657Z] 23:37:17     INFO -  REFTEST SUITE-END | Shutdown
[task 2018-10-09T23:37:17.658Z] 23:37:17     INFO -  REFTEST INFO | Slowest test took 6205ms (http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=test262/language/statements/for-await-of/async-gen-dstr-let-obj-ptrn-prop-eval-err.js)
[task 2018-10-09T23:37:17.658Z] 23:37:17     INFO -  REFTEST INFO | Total canvas count = 0
[task 2018-10-09T23:37:17.658Z] 23:37:17     INFO -  REFTEST WARNING | Failed to find the test-plugin.
[task 2018-10-09T23:37:17.658Z] 23:37:17     INFO -  REFTEST WARNING | Failed to find the test-plugin.
[task 2018-10-09T23:37:17.658Z] 23:37:17     INFO -  REFTEST WARNING | Failed to get test plugin tags.
[task 2018-10-09T23:37:39.393Z] 23:37:39     INFO -  wait for org.mozilla.fennec_aurora complete; top activity=com.android.launcher
[task 2018-10-09T23:37:39.697Z] 23:37:39     INFO -  INFO | automation.py | Application ran for: 0:44:36.476569
[task 2018-10-09T23:37:39.698Z] 23:37:39     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmpE09jqgpidlog
[task 2018-10-09T23:37:40.211Z] 23:37:40     INFO -  /data/tombstones does not exist; tombstone check skipped
[task 2018-10-09T23:37:44.847Z] 23:37:44     INFO -  leakcheck | refcount logging is off, so leaks can't be detected!
[task 2018-10-09T23:37:45.177Z] 23:37:45     INFO -  10-09 16:36:25.337 I/Gecko   (  794):
[task 2018-10-09T23:37:45.178Z] 23:37:45     INFO -  10-09 16:36:25.337 I/Gecko   (  794): {"action":"log","time":1539128185343,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"Initializing canvas snapshot"}

Comment 3

[Geoff Brown [:gbrown]]

The logcat seems okay to me. I don't see a failure anywhere in the log, and there are signs of success everywhere:

https://treeherder.mozilla.org/logviewer.html#?job_id=204352813&repo=autoland&lineNumber=2600-2603

[task 2018-10-09T23:37:17.657Z] 23:37:17     INFO -  REFTEST INFO | Result summary:
[task 2018-10-09T23:37:17.657Z] 23:37:17     INFO -  REFTEST INFO | Successful: 306 (0 pass, 306 load only)
[task 2018-10-09T23:37:17.657Z] 23:37:17     INFO -  REFTEST INFO | Unexpected: 0 (0 unexpected fail, 0 unexpected pass, 0 unexpected asserts, 0 failed load, 0 exception)
[task 2018-10-09T23:37:17.657Z] 23:37:17     INFO -  REFTEST INFO | Known problems: 8 (0 known fail, 0 known asserts, 0 random, 8 skipped, 0 slow)


[task 2018-10-09T23:37:46.059Z] 23:37:46     INFO - [mozharness: 2018-10-09 23:37:46.059698Z] Finished run-tests step (success)


[task 2018-10-09T23:37:47.314Z] + exit 0
[taskcluster 2018-10-09 23:37:47.634Z] === Task Finished ===
[taskcluster 2018-10-09 23:37:54.695Z] Successful task run with exit code: 0 completed in 2846.09 seconds


Maybe we need some treeherder eyes on this?

Comment 4

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

Same issue like bug 1497753 comment 5?

Comment 5

[Cameron Dawson [:camd]]

The status that we get of "testfailed" is not determined by Treeherder.  We take the "result" field from the Pulse message we get from taskcluster-treeherder.  Presumably Taskcluster got an equivalent state from Mozharness to indicate this failure.  

Treeherder's log parsing will not change the "result" value we receive.  It's only an attempt to locate the lines that would be associated with a failure.  So something upstream has marked these as failed.

Comment 6

[Geoff Brown [:gbrown]]

(In reply to Cameron Dawson [:camd] from comment #5)

Thanks :camd.

> Presumably Taskcluster got an equivalent state from
> Mozharness to indicate this failure.  

In comment 3 and most of the failures reported here, the mozharness script is returning 0 (success).

Comment 7

[Geoff Brown [:gbrown]]

(In reply to Sebastian Hengst [:aryx] (needinfo on intermittent or backout) from comment #4)
> Same issue like bug 1497753 comment 5?

I think that might be it.

Comment 8

[Intermittent Failures Robot]

18 failures in 2740 pushes (0.007 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* autoland: 18

Platform breakdown:
* linux32: 4
* linux64: 3
* linux64-qr: 1
* android-em-4-3-armv7-api16: 10

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1497740&startday=2018-10-08&endday=2018-10-14&tree=all

Comment 9

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.