Closed Bug 1585652 Opened 5 years ago Closed 5 years ago

Intermittent Android Reftests Crashtest Many TEST-UNEXPECTED-PASS/FAIL | */crashtests/*.xhtml | assertion count X is less / more than expected Y assertions

Categories

(Core :: Layout, defect, P5)

Product:
Core
Component:
Layout
Type:
defect

Tracking

()

Status:
RESOLVED DUPLICATE of bug 1521640

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure, regression)

Filed by: btara [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=269396645&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/dXEimKSHRcukYB6228zwgA/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/dXEimKSHRcukYB6228zwgA/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2019-10-02T10:42:17.744Z] 10:42:17 INFO - REFTEST TEST-START | http://10.0.2.2:8854/tests/dom/media/test/crashtests/1257700.html
[task 2019-10-02T10:42:17.744Z] 10:42:17 INFO - REFTEST TEST-LOAD | http://10.0.2.2:8854/tests/dom/media/test/crashtests/1257700.html | 627 / 3833 (16%)
[task 2019-10-02T10:47:15.016Z] 10:47:15 INFO - REFTEST TEST-UNEXPECTED-FAIL | http://10.0.2.2:8854/tests/dom/media/test/crashtests/1257700.html | load failed: timed out after 300000 ms waiting for 'load' event for http://10.0.2.2:8854/tests/dom/media/test/crashtests/1257700.html
[task 2019-10-02T10:47:15.016Z] 10:47:15 INFO - REFTEST INFO | Saved log: START http://10.0.2.2:8854/tests/dom/media/test/crashtests/1257700.html
[task 2019-10-02T10:47:15.016Z] 10:47:15 INFO - REFTEST TEST-END | http://10.0.2.2:8854/tests/dom/media/test/crashtests/1257700.html
...
[task 2019-10-02T10:50:59.177Z] 10:50:59 INFO - REFTEST TEST-START | http://10.0.2.2:8854/tests/layout/base/crashtests/453894-1.xhtml
[task 2019-10-02T10:50:59.177Z] 10:50:59 INFO - REFTEST TEST-LOAD | http://10.0.2.2:8854/tests/layout/base/crashtests/453894-1.xhtml | 1672 / 3833 (43%)
[task 2019-10-02T10:50:59.178Z] 10:50:59 INFO - REFTEST TEST-PASS | http://10.0.2.2:8854/tests/layout/base/crashtests/453894-1.xhtml | (LOAD ONLY)
[task 2019-10-02T10:50:59.178Z] 10:50:59 INFO - REFTEST TEST-END | http://10.0.2.2:8854/tests/layout/base/crashtests/453894-1.xhtml
[task 2019-10-02T10:50:59.178Z] 10:50:59 INFO - REFTEST TEST-UNEXPECTED-PASS | http://10.0.2.2:8854/tests/layout/base/crashtests/453894-1.xhtml | assertion count 1 is less than expected 2 assertions
[task 2019-10-02T10:50:59.178Z] 10:50:59 INFO - REFTEST TEST-START | chrome://reftest/content/crashtests/layout/base/crashtests/454751-1.xul
[task 2019-10-02T10:50:59.178Z] 10:50:59 INFO - REFTEST TEST-LOAD | chrome://reftest/content/crashtests/layout/base/crashtests/454751-1.xul | 1673 / 3833 (43%)
[task 2019-10-02T10:50:59.179Z] 10:50:59 INFO - REFTEST TEST-PASS | chrome://reftest/content/crashtests/layout/base/crashtests/454751-1.xul | (LOAD ONLY)
[task 2019-10-02T10:50:59.179Z] 10:50:59 INFO - REFTEST TEST-END | chrome://reftest/content/crashtests/layout/base/crashtests/454751-1.xul
...
[task 2019-10-02T10:51:09.851Z] 10:51:09 INFO - REFTEST TEST-START | http://10.0.2.2:8854/tests/layout/base/crashtests/690247-1.html
[task 2019-10-02T10:51:09.851Z] 10:51:09 INFO - REFTEST TEST-LOAD | http://10.0.2.2:8854/tests/layout/base/crashtests/690247-1.html | 1800 / 3833 (46%)
[task 2019-10-02T10:51:09.851Z] 10:51:09 INFO - REFTEST TEST-PASS | http://10.0.2.2:8854/tests/layout/base/crashtests/690247-1.html | (LOAD ONLY)
[task 2019-10-02T10:51:09.852Z] 10:51:09 INFO - REFTEST TEST-END | http://10.0.2.2:8854/tests/layout/base/crashtests/690247-1.html
[task 2019-10-02T10:51:09.852Z] 10:51:09 INFO - REFTEST TEST-UNEXPECTED-FAIL | http://10.0.2.2:8854/tests/layout/base/crashtests/690247-1.html | assertion count 1 is more than expected 0 assertions
[task 2019-10-02T10:51:09.852Z] 10:51:09 INFO - REFTEST TEST-START | http://10.0.2.2:8854/tests/layout/base/crashtests/690619-1.html
[task 2019-10-02T10:51:09.852Z] 10:51:09 INFO - REFTEST TEST-LOAD | http://10.0.2.2:8854/tests/layout/base/crashtests/690619-1.html | 1801 / 3833 (46%)
[task 2019-10-02T10:51:09.853Z] 10:51:09 INFO - REFTEST TEST-PASS | http://10.0.2.2:8854/tests/layout/base/crashtests/690619-1.html | (LOAD ONLY)
[task 2019-10-02T10:51:09.853Z] 10:51:09 INFO - REFTEST TEST-END | http://10.0.2.2:8854/tests/layout/base/crashtests/690619-1.html
...
[task 2019-10-02T10:52:03.211Z] 10:52:03 INFO - REFTEST TEST-START | http://10.0.2.2:8854/tests/layout/generic/crashtests/323386-1.html
[task 2019-10-02T10:52:03.211Z] 10:52:03 INFO - REFTEST TEST-LOAD | http://10.0.2.2:8854/tests/layout/generic/crashtests/323386-1.html | 2098 / 3833 (54%)
[task 2019-10-02T10:52:03.212Z] 10:52:03 INFO - REFTEST TEST-PASS | http://10.0.2.2:8854/tests/layout/generic/crashtests/323386-1.html | (LOAD ONLY)
[task 2019-10-02T10:52:03.212Z] 10:52:03 INFO - REFTEST TEST-END | http://10.0.2.2:8854/tests/layout/generic/crashtests/323386-1.html
[task 2019-10-02T10:52:03.212Z] 10:52:03 INFO - REFTEST TEST-UNEXPECTED-PASS | http://10.0.2.2:8854/tests/layout/generic/crashtests/323386-1.html | assertion count 0 is less than expected 1 assertions
[task 2019-10-02T10:52:03.212Z] 10:52:03 INFO - REFTEST TEST-START | http://10.0.2.2:8854/tests/layout/generic/crashtests/323389-1.html
[task 2019-10-02T10:52:03.212Z] 10:52:03 INFO - REFTEST TEST-LOAD | http://10.0.2.2:8854/tests/layout/generic/crashtests/323389-1.html | 2099 / 3833 (54%)
[task 2019-10-02T10:52:03.213Z] 10:52:03 INFO - REFTEST TEST-PASS | http://10.0.2.2:8854/tests/layout/generic/crashtests/323389-1.html | (LOAD ONLY)
[task 2019-10-02T10:52:03.213Z] 10:52:03 INFO - REFTEST TEST-END | http://10.0.2.2:8854/tests/layout/generic/crashtests/323389-1.html
...

Android debug crashtests have many unexpected results for some runs: https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel%2Crunnable&fromchange=8003680668ad9d8858d06ced667683f15e80b824&tochange=4e984f54259d60d6bdb6dab40c2ffd6d263e2737&searchStr=android%2Ccrashtest&selectedJob=269400761

Most of them are in layout/ and about an unexpected assertion count. The first one (1257700.html) is likely unrelated.

Daniel, do you have insights what started this? It's not always the same assertion. From https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=269385254&repo=autoland&lineNumber=8556

10-02 09:54:29.390 2813 2828 I Gecko : REFTEST TEST-LOAD | http://10.0.2.2:8854/tests/layout/base/crashtests/453894-1.xhtml | 1672 / 3833 (43%)
10-02 09:54:29.427 2883 2898 I Gecko : [Child 2883, Main Thread] ###!!! ASSERTION: didn't subtract all that we added: '(space == 0 || space == nscoord_MAX) && ((l2t == FLEX_PCT_LARGE) ? (-0.001f < basis.f && basis.f < 0.001f) : (basis.c == 0 || basis.c == nscoord_MAX))', file /builds/worker/workspace/build/src/layout/tables/BasicTableLayoutStrategy.cpp, line 990

10-02 09:54:44.016 2813 2828 I Gecko : REFTEST TEST-LOAD | http://10.0.2.2:8854/tests/layout/base/crashtests/690247-1.html | 1800 / 3833 (46%)
10-02 09:54:44.067 2883 2898 I Gecko : [Child 2883, Main Thread] ###!!! ASSERTION: Bounds computation mismatch: 'mContainerBounds.IsEqualInterior(mAccumulatedChildBounds)', file /builds/worker/workspace/build/src/layout/painting/FrameLayerBuilder.cpp, line 5964

Component: Reftest → Layout
Flags: needinfo?(dholbert)
Product: Testing → Core
Summary: Intermittent Android Reftests Crashtest Many TEST-UNEXPECTED-PASS | */crashtests/*.xhtml | assertion count X is less / more than expected Y assertions → Intermittent Android Reftests Crashtest Many TEST-UNEXPECTED-PASS/FAIL | */crashtests/*.xhtml | assertion count X is less / more than expected Y assertions
Version: Version 3 → unspecified

Given that it's a mix of too-many / too-few, my first guess would be that we're just mis-attributing which assertions go with which tests, perhaps due to logcat lines appearing out-of-order or something.

To investigate this, someone would want to compare the logcat output from a "good" vs. a "bad" crashtest run, and look at which assertions are spammed / not-spammed for a section of affected tests, and see if they're all the same but in a different order.

Flags: needinfo?(dholbert)

Actually.... maybe there are no "good" recent runs??

Consider for example this purportedly green run, here:
https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel%2Crunnable&searchStr=android%2C7.0%2Ccrashtest%2Cdebug&revision=46c2aeec240856f8f86678dc32ed9717ea2f41fd

It's green and has "Result: success", BUT if you click through to the log, it shows the same issue (unexpected passes/fails from unexpected assertion counts), though it does still show "Result: success" at the top left corner:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=269367370&repo=autoland&lineNumber=8550

So there are two different problems here:
(1) something is wrong with "success" assessments on this platform
(2) we have unexpected assertion counts (possibly from mis-grouping assertions with tests)
...and issue #2 has simply been masked by issue #1 prior to the orange reports here.

Flags: needinfo?(aryx.bugmail)

Perusing mozilla-central TreeHerder to go back in time more quickly, it looks like this goes back weeks (at least).

E.g. here's a run from Sept 16 which has the same problems (unexpected assertion counts, and mis-classified as success/green):
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=266981715&repo=mozilla-central&lineNumber=8571

I think the recent oranges are simply due to the unrelated test timeout ("1257700.html | load failed: timed out after 300000 ms waiting for 'load' event for http://10.0.2.2:8854/tests/dom/media/test/crashtests/1257700.html").

The log-parser thinks it should show all of the TEST-UNEXPECTED-FAIL/PASS lines for the unexpected assertion counts as well, but in fact those are not what caused the log to get assessed as orange.

So maybe there's a known issue with assertion count mismatches on android (e.g. due to mis-grouping as is my current working theory), and so we intentionally ignore them, but the log parser isn't smart enough to know that we're ignoring them, so it still highlights them when the testrun is classified as a failure for other test-failure reasons? (e.g. timeouts/crashes)

(In reply to Daniel Holbert [:dholbert] from comment #5)

So maybe there's a known issue with assertion count mismatches on android (e.g. due to mis-grouping as is my current working theory), and so we intentionally ignore them

This does seem to be a known issue -- it was filed previously as bug 1521640, 8 months ago (so this bug here is perhaps a dupe of that bug).

At that point, it looks like this wasn't as bad -- the log has expired, but based on gbrown's note there, it seems like there was only one crashtest with an unexpected assertion-count in that log (and it's not clear whether it reproduced 100% of the time then as it does now).

Bug 1575666 tracks the 1257700.html issue. Let's set this one as duplicate of

Status: NEW → RESOLVED
Closed: 5 years ago
Flags: needinfo?(aryx.bugmail)
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.