1442790 - test-verify may fail: "No checks run."

Status: RESOLVED FIXED

(Testing :: General, defect, P5)

Description

[Geoff Brown [:gbrown]]

In the case addressed by bug 1423771, where a modified file is in a reftest manifest, but the file is not a test file, and the reftest harness avoids the "No tests to run" error, structured logging may still complain "No checks run."

https://treeherder.mozilla.org/logviewer.html#?job_id=165592716&repo=try&lineNumber=5464

Comment 1

[Andreea Pavel [:apavel]]

Geoff, hi. OS X tier2 failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=165878348&repo=mozilla-inbound&lineNumber=18702

Comment 3

[Intermittent Failures Robot]

24 failures in 110 pushes (0.218 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-central: 19
* mozilla-inbound: 5

Platform breakdown:
* windows7-32: 10
* windows10-64: 8
* linux64: 4
* osx-10-10: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1442790&startday=2018-05-02&endday=2018-05-02&tree=trunk

Comment 5

[Intermittent Failures Robot]

24 failures in 551 pushes (0.044 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 18
* mozilla-inbound: 6

Platform breakdown:
* windows7-32: 9
* windows10-64: 9
* linux64: 4
* osx-10-10: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1442790&startday=2018-04-30&endday=2018-05-06&tree=trunk

Comment 6

[Intermittent Failures Robot]

33 failures in 127 pushes (0.26 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 15
* autoland: 15
* mozilla-central: 3

Platform breakdown:
* linux64: 12
* android-4-3-armv7-api16: 10
* windows7-32: 4
* osx-10-10: 4
* windows10-64: 3

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

Comment 7

[Joel Maher ( :jmaher ) (UTC -8)]

here is a good view of TV failures:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=59a49b12b26846302393edfbd20b5e72ef6b1d85&filter-searchStr=tv

the android ones are annotated here, but the jobs are failing because tests are taking too long to run.  Should we have fewer tests/chunk on android?  It seems like we are not confusing the state of previous failures anymore.

Comment 8

[Joel Maher ( :jmaher ) (UTC -8)]

I also noticed in that run the TVw jobs, specifically win10 opt, we fail properly on /css/vendor-imports/mozilla/mozilla-central-reftests/shapes1/shape-outside-polygon-032.html, but TV summary shows:
11:32:56     INFO - ### /css/vendor-imports/mozilla/mozilla-central-reftests/shapes1/shape-outside-polygon-032.html ###
11:32:56     INFO - | Subtest | Results | Messages |
11:32:56     INFO - |---------|---------|----------|
11:32:56     INFO - |         | FAIL    |          |
11:32:56     INFO - 
11:32:56     INFO - ::: Running tests in a loop 10 times : PASS
11:32:56     INFO - ::: Running tests in a loop with restarts 5 times : PASS
11:32:56     INFO - ::: Running tests in a loop 10 times with flags chaos_mode_flags=3 : PASS
11:32:56     INFO - ::: Running tests in a loop with restarts 5 times with flags chaos_mode_flags=3 : PASS
11:32:56     INFO - :::
11:32:56     INFO - ::: Test verification PASS
11:32:56     INFO - :::
11:32:56     INFO - Return code: 0
11:32:56  WARNING - # TBPL WARNING #
11:32:56  WARNING - setting return code to 1
11:32:56  WARNING - TinderboxPrint: Per-test run of ...\shape-outside-polygon-032.html<br/>: WARNING


but the next test (last test) yields what looks to be success, yet a tbpl warning:
11:34:08     INFO - ### /css/css-syntax/unicode-range-selector.html ###
11:34:08     INFO - |                                 Subtest                                  | Results | Messages |
11:34:08     INFO - |--------------------------------------------------------------------------|---------|----------|
11:34:08     INFO - |                                                                          | OK      |          |
11:34:08     INFO - | `Unicode range is not a token, and doesn't cause confusion in selectors` | PASS    |          |
11:34:08     INFO - 
11:34:08     INFO - ::: Running tests in a loop 10 times : PASS
11:34:08     INFO - ::: Running tests in a loop with restarts 5 times : PASS
11:34:08     INFO - ::: Running tests in a loop 10 times with flags chaos_mode_flags=3 : PASS
11:34:08     INFO - ::: Running tests in a loop with restarts 5 times with flags chaos_mode_flags=3 : PASS
11:34:08     INFO - :::
11:34:08     INFO - ::: Test verification PASS
11:34:08     INFO - :::
11:34:08     INFO - Return code: 0
11:34:08  WARNING - # TBPL WARNING #
11:34:08  WARNING - TinderboxPrint: Per-test run of ...\unicode-range-selector.html<br/>: WARNING

it seems like there is more we can do here, I just need more data or other opinions:)

Comment 9

[Intermittent Failures Robot]

18 failures in 82 pushes (0.22 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 6
* mozilla-central: 6
* autoland: 6

Platform breakdown:
* android-4-3-armv7-api16: 18

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1442790&startday=2018-05-11&endday=2018-05-11&tree=trunk

Comment 10

[Intermittent Failures Robot]

62 failures in 660 pushes (0.094 failures/push) were associated with this bug in the last 7 days. 

This is the #21 most frequent failure this week.  

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

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

Repository breakdown:
* mozilla-inbound: 26
* autoland: 25
* mozilla-central: 11

Platform breakdown:
* android-4-3-armv7-api16: 33
* linux64: 12
* windows7-32: 9
* windows10-64: 4
* osx-10-10: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1442790&startday=2018-05-07&endday=2018-05-13&tree=trunk

Comment 11

[Geoff Brown [:gbrown]]

I'm seeing some things I don't expect - will try to look into this today.

Comment 12

[Geoff Brown [:gbrown]]

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

Running command: ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/mochitest/runtestsremote.py', ... '--verify-max-time=900', '--verify', u'dom/animation/test/chrome/test_running_on_compositor.html'
...
[task 2018-05-11T07:29:07.073Z] 07:29:07     INFO -  1 INFO TEST-START | dom/animation/test/chrome/test_running_on_compositor.html
...
[task 2018-05-11T07:48:05.001Z] 07:48:05     INFO -  SUITE-END | took 365s
[task 2018-05-11T07:48:05.001Z] 07:48:05     INFO -  ::: Test verification is taking too long: Giving up!
[task 2018-05-11T07:48:05.001Z] 07:48:05     INFO -  ::: So far, all checks passed, but not all checks were run.
[task 2018-05-11T07:48:05.001Z] 07:48:05     INFO -  SUITE-START | Running 1 tests
[task 2018-05-11T07:48:05.002Z] 07:48:05     INFO -  :::
[task 2018-05-11T07:48:05.002Z] 07:48:05     INFO -  ::: Test verification summary for:
[task 2018-05-11T07:48:05.003Z] 07:48:05     INFO -  :::
[task 2018-05-11T07:48:05.003Z] 07:48:05     INFO -  ::: dom/animation/test/chrome/test_running_on_compositor.html
[task 2018-05-11T07:48:05.003Z] 07:48:05     INFO -  :::
[task 2018-05-11T07:48:05.003Z] 07:48:05     INFO -  ::: 1. Run each test 10 times in one browser. : Pass
[task 2018-05-11T07:48:05.003Z] 07:48:05     INFO -  ::: 2. Run each test 5 times in a new browser each time. : Pass
[task 2018-05-11T07:48:05.004Z] 07:48:05     INFO -  ::: 3. Run each test 10 times in one browser, in chaos mode. : Pass
[task 2018-05-11T07:48:05.004Z] 07:48:05     INFO -  ::: 4. Run each test 5 times in a new browser each time, in chaos mode. : not run / incomplete
[task 2018-05-11T07:48:05.004Z] 07:48:05     INFO -  :::
[task 2018-05-11T07:48:05.005Z] 07:48:05     INFO -  ::: Test verification PASSED
...
[task 2018-05-11T07:48:06.103Z] 07:48:06     INFO -  SUITE-END | took 1s
[task 2018-05-11T07:48:06.105Z] 07:48:06     INFO - Return code: 0
[task 2018-05-11T07:48:06.106Z] 07:48:06     INFO - TinderboxPrint: mochitest-chrome<br/>6439/0/0
[task 2018-05-11T07:48:06.106Z] 07:48:06     INFO - ##### mochitest-chrome log ends
[task 2018-05-11T07:48:06.106Z] 07:48:06     INFO - # TBPL SUCCESS #
[task 2018-05-11T07:48:06.107Z] 07:48:06     INFO - TinderboxPrint: Per-test run of .../test_running_on_compositor.html<br/>: SUCCESS

Good: A long-running test exceeded the 15 minute max time. Verification passed.


Next test:

[task 2018-05-11T08:06:24.774Z] 08:06:24     INFO -  :::
[task 2018-05-11T08:06:24.774Z] 08:06:24     INFO -  ::: Test verification summary for:
[task 2018-05-11T08:06:24.774Z] 08:06:24     INFO -  :::
[task 2018-05-11T08:06:24.775Z] 08:06:24     INFO -  ::: dom/animation/test/chrome/test_animation_properties.html
[task 2018-05-11T08:06:24.775Z] 08:06:24     INFO -  :::
[task 2018-05-11T08:06:24.775Z] 08:06:24     INFO -  ::: 1. Run each test 10 times in one browser. : Pass
[task 2018-05-11T08:06:24.776Z] 08:06:24     INFO -  ::: 2. Run each test 5 times in a new browser each time. : Pass
[task 2018-05-11T08:06:24.776Z] 08:06:24     INFO -  ::: 3. Run each test 10 times in one browser, in chaos mode. : Pass
[task 2018-05-11T08:06:24.776Z] 08:06:24     INFO -  ::: 4. Run each test 5 times in a new browser each time, in chaos mode. : Pass
[task 2018-05-11T08:06:24.777Z] 08:06:24     INFO -  :::
[task 2018-05-11T08:06:24.777Z] 08:06:24     INFO -  ::: Test verification PASSED
[task 2018-05-11T08:06:24.777Z] 08:06:24     INFO -  :::
...
[task 2018-05-11T08:06:26.100Z] 08:06:26     INFO -  SUITE-END | took 1s
[task 2018-05-11T08:06:26.111Z] 08:06:26     INFO - Return code: 0
[task 2018-05-11T08:06:26.112Z] 08:06:26     INFO - TinderboxPrint: mochitest-chrome<br/>5964/0/0
[task 2018-05-11T08:06:26.112Z] 08:06:26     INFO - ##### mochitest-chrome log ends
[task 2018-05-11T08:06:26.112Z] 08:06:26     INFO - # TBPL FAILURE #
[task 2018-05-11T08:06:26.112Z] 08:06:26  WARNING - setting return code to 2
[task 2018-05-11T08:06:26.113Z] 08:06:26     INFO - TinderboxPrint: Per-test run of .../test_animation_properties.html<br/>: FAILURE

I don't understand the TBPL_FAILURE -- I don't see a reason for it.


Next test:

[task 2018-05-11T08:25:31.271Z] 08:25:31     INFO -  :::
[task 2018-05-11T08:25:31.271Z] 08:25:31     INFO -  ::: Test verification summary for:
[task 2018-05-11T08:25:31.272Z] 08:25:31     INFO -  :::
[task 2018-05-11T08:25:31.272Z] 08:25:31     INFO -  ::: dom/animation/test/chrome/test_animation_observers_sync.html
[task 2018-05-11T08:25:31.272Z] 08:25:31     INFO -  :::
[task 2018-05-11T08:25:31.272Z] 08:25:31     INFO -  ::: 1. Run each test 10 times in one browser. : Pass
[task 2018-05-11T08:25:31.273Z] 08:25:31     INFO -  ::: 2. Run each test 5 times in a new browser each time. : Pass
[task 2018-05-11T08:25:31.273Z] 08:25:31     INFO -  ::: 3. Run each test 10 times in one browser, in chaos mode. : Pass
[task 2018-05-11T08:25:31.274Z] 08:25:31     INFO -  ::: 4. Run each test 5 times in a new browser each time, in chaos mode. : Pass
[task 2018-05-11T08:25:31.274Z] 08:25:31     INFO -  :::
[task 2018-05-11T08:25:31.274Z] 08:25:31     INFO -  ::: Test verification PASSED
[task 2018-05-11T08:25:31.274Z] 08:25:31     INFO -  :::
...
[task 2018-05-11T08:25:32.604Z] 08:25:32     INFO -  SUITE-END | took 1s
[task 2018-05-11T08:25:32.615Z] 08:25:32     INFO - Return code: 0
[task 2018-05-11T08:25:32.615Z] 08:25:32     INFO - TinderboxPrint: mochitest-chrome<br/>15194/0/0
[task 2018-05-11T08:25:32.615Z] 08:25:32     INFO - ##### mochitest-chrome log ends
[task 2018-05-11T08:25:32.615Z] 08:25:32     INFO - # TBPL FAILURE #
[task 2018-05-11T08:25:32.616Z] 08:25:32     INFO - TinderboxPrint: Per-test run of .../test_animation_observers_sync.html<br/>: FAILURE

Ditto.


Trying to reproduce and debug....

Comment 13

[Geoff Brown [:gbrown]]

Also meant to note: "No checks run" is not in this log. It seems like most of the recent failures are mis-stars.

Comment 14

[Geoff Brown [:gbrown]]

I think comment 12 and the spike of failures between May 8 and May 12 were addressed by bug 1460666. Android TV with the same tests as comment 12 no longer fails:

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

Comment 15

[Geoff Brown [:gbrown]]

(In reply to Joel Maher ( :jmaher ) (UTC-4) from comment #7)
> here is a good view of TV failures:
> https://treeherder.mozilla.org/#/jobs?repo=mozilla-
> inbound&revision=59a49b12b26846302393edfbd20b5e72ef6b1d85&filter-searchStr=tv
> 
> the android ones are annotated here, but the jobs are failing because tests
> are taking too long to run.  Should we have fewer tests/chunk on android? 
> It seems like we are not confusing the state of previous failures anymore.

I do not think jobs are or were failing because tests are taking too long to run. When you see

[task 2018-05-11T07:48:05.001Z] 07:48:05     INFO -  ::: Test verification is taking too long: Giving up!
[task 2018-05-11T07:48:05.001Z] 07:48:05     INFO -  ::: So far, all checks passed, but not all checks were run.
[task 2018-05-11T07:48:05.001Z] 07:48:05     INFO -  SUITE-START | Running 1 tests
[task 2018-05-11T07:48:05.002Z] 07:48:05     INFO -  :::
[task 2018-05-11T07:48:05.002Z] 07:48:05     INFO -  ::: Test verification summary for:
[task 2018-05-11T07:48:05.003Z] 07:48:05     INFO -  :::
[task 2018-05-11T07:48:05.003Z] 07:48:05     INFO -  ::: dom/animation/test/chrome/test_running_on_compositor.html
[task 2018-05-11T07:48:05.003Z] 07:48:05     INFO -  :::
[task 2018-05-11T07:48:05.003Z] 07:48:05     INFO -  ::: 1. Run each test 10 times in one browser. : Pass
[task 2018-05-11T07:48:05.003Z] 07:48:05     INFO -  ::: 2. Run each test 5 times in a new browser each time. : Pass
[task 2018-05-11T07:48:05.004Z] 07:48:05     INFO -  ::: 3. Run each test 10 times in one browser, in chaos mode. : Pass
[task 2018-05-11T07:48:05.004Z] 07:48:05     INFO -  ::: 4. Run each test 5 times in a new browser each time, in chaos mode. : not run / incomplete

The harness per-test max-verify-time has been exceeded and the harness explicitly passes, and I expect to see

[task 2018-05-11T07:48:05.005Z] 07:48:05     INFO -  ::: Test verification PASSED

Comment 16

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-central: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1442790&startday=2018-05-14&endday=2018-05-20&tree=trunk

Comment 17

[Joel Maher ( :jmaher ) (UTC -8)]

ok, let me fix the no checks are run failures, and assume that all is well :)

Comment 18

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: ignore failures of "no tests run" in per-test mode

a try push:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=c0f5f4abdbdda0a5c1fb31ca9b767058d6ee6d9e

and what we saw before (look at windows):
https://treeherder.mozilla.org/#/jobs?repo=try&revision=fa2bbaad71d7615303d1abcf9bf1d104241c8f87

Comment 19

[Andrew Halberstadt [:ahal]]

Comment on attachment 8980592 [details] [diff] [review]
ignore failures of "no tests run" in per-test mode

Review of attachment 8980592 [details] [diff] [review]:
-----------------------------------------------------------------

I can't say I understand how this fixes the problem, but the code looks good, so nominal r+ from me.

::: testing/mozharness/mozharness/mozilla/structuredlog.py
@@ +127,5 @@
> +        RunSummary = namedtuple("RunSummary",
> +                                ("unexpected_statuses",
> +                                    "expected_statuses",
> +                                    "log_level_counts",
> +                                    "action_counts"))

nit: indentation is off here.

Comment 20

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/baf00899e3d1
fix test-verify to not fail on: 'No checks run.'. r=ahal

Comment 21

[Andrei Ciure[:aciure]]

https://hg.mozilla.org/mozilla-central/rev/baf00899e3d1