1784102 - Intermittent TVw ::: Test verification FAIL | TinderboxPrint: Per-test run of .../contain-intrinsic-size-031.html<br/>: FAILURE

Status: RESOLVED DUPLICATE of bug 1734020

(Core :: Layout, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: mlaza [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=386927552&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/UqR1FOdKQjGn3xOfi0RPHg/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://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/UqR1FOdKQjGn3xOfi0RPHg/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2022-08-10T15:43:01.258Z] 15:43:01     INFO - ::: Running tests in a loop 10 times with flags chaos_mode_flags=0xfb : PASS
[task 2022-08-10T15:43:01.259Z] 15:43:01     INFO - ::: Running tests in a loop with restarts 5 times with flags chaos_mode_flags=0xfb : FAIL
[task 2022-08-10T15:43:01.259Z] 15:43:01     INFO - :::
[task 2022-08-10T15:43:01.259Z] 15:43:01    ERROR - ::: Test verification FAIL
[task 2022-08-10T15:43:01.260Z] 15:43:01     INFO - :::
[task 2022-08-10T15:43:01.581Z] 15:43:01    ERROR - Return code: 1
[task 2022-08-10T15:43:01.581Z] 15:43:01    ERROR - # TBPL FAILURE #
[task 2022-08-10T15:43:01.582Z] 15:43:01  WARNING - setting return code to 2
[task 2022-08-10T15:43:01.582Z] 15:43:01    ERROR - TinderboxPrint: Per-test run of .../contain-intrinsic-size-031.html<br/>: FAILURE
[task 2022-08-10T15:43:01.582Z] 15:43:01     INFO - Running post-action listener: _package_coverage_data
[task 2022-08-10T15:43:01.582Z] 15:43:01     INFO - Running post-action listener: _resource_record_post_action
[task 2022-08-10T15:43:01.582Z] 15:43:01     INFO - Running post-action listener: process_java_coverage_data
[task 2022-08-10T15:43:01.582Z] 15:43:01     INFO - Running post-action listener: stop_device
[task 2022-08-10T15:43:01.582Z] 15:43:01     INFO - [mozharness: 2022-08-10 15:43:01.582450Z] Finished run-tests step (success)
[task 2022-08-10T15:43:01.582Z] 15:43:01     INFO - Running post-run listener: _resource_record_post_run
[task 2022-08-10T15:43:01.680Z] 15:43:01     INFO - Total resource usage - Wall time: 500s; CPU: 4%; Read bytes: 107655168; Write bytes: 839340032; Read time: 1323; Write time: 3074
[task 2022-08-10T15:43:01.680Z] 15:43:01     INFO - TinderboxPrint: CPU usage<br/>4.1%
[task 2022-08-10T15:43:01.680Z] 15:43:01     INFO - TinderboxPrint: I/O read bytes / time<br/>107,655,168 / 1,323
[task 2022-08-10T15:43:01.680Z] 15:43:01     INFO - TinderboxPrint: I/O write bytes / time<br/>839,340,032 / 3,074
[task 2022-08-10T15:43:01.680Z] 15:43:01     INFO - TinderboxPrint: CPU idle<br/>5,723.5 (95.5%)
[task 2022-08-10T15:43:01.680Z] 15:43:01     INFO - TinderboxPrint: CPU system<br/>102.8 (1.7%)
[task 2022-08-10T15:43:01.680Z] 15:43:01     INFO - TinderboxPrint: CPU user<br/>169.6 (2.8%)
[task 2022-08-10T15:43:01.680Z] 15:43:01     INFO - TinderboxPrint: Swap in / out<br/>349,958,144 / 0
[task 2022-08-10T15:43:01.681Z] 15:43:01     INFO - pull - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2022-08-10T15:43:01.681Z] 15:43:01     INFO - start-emulator - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2022-08-10T15:43:01.681Z] 15:43:01     INFO - verify-device - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2022-08-10T15:43:01.682Z] 15:43:01     INFO - install - Wall time: 20s; CPU: 14%; Read bytes: 244286976; Write bytes: 241438720; Read time: 15939; Write time: 465
[task 2022-08-10T15:43:01.688Z] 15:43:01     INFO - run-tests - Wall time: 481s; CPU: 4%; Read bytes: 102612992; Write bytes: 583655424; Read time: 1237; Write time: 2570
[task 2022-08-10T15:43:01.804Z] 15:43:01  WARNING - returning nonzero exit status 2
[taskcluster 2022-08-10T15:43:02.079Z]    Exit Code: 2
[taskcluster 2022-08-10T15:43:02.079Z]    User Time: 3m4.996338s
[taskcluster 2022-08-10T15:43:02.079Z]  Kernel Time: 53.461138s
[taskcluster 2022-08-10T15:43:02.079Z]    Wall Time: 9m36.730509s
[taskcluster 2022-08-10T15:43:02.079Z]       Result: FAILED
[taskcluster 2022-08-10T15:43:02.079Z] === Task Finished ===
[taskcluster 2022-08-10T15:43:02.079Z] Task Duration: 9m36.733873s

Comment 1

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

:Oriol, since you are the author of the regressor, bug 1783953, could you take a look?
For more information, please visit auto_nag documentation.

Comment 2

[Oriol Brufau [:Oriol]]

It seems that there is some bug that, when I create or modify one of this tests, then TVw fails on Mac. But once the change lands, then it doesn't fail. Or something like that. It doesn't seem a big deal. I'm going to mark it as a dupe of bug 1780838.

Comment 3

[Daniel Holbert [:dholbert]]

Looks like the failure here was just that the test was considered slow, under chaos mode. This is bug 1734020.

(In reply to Oriol Brufau [:Oriol] from comment #2)

It seems that there is some bug that, when I create or modify one of this tests, then TVw fails on Mac. But once the change lands, then it doesn't fail. Or something like that.

Yeah, this is specific to chaos-mode, which only runs during "test-verify" tasks (TVw), which only get scheduled when a test is modified and otherwise never get scheduled. The idea is: when a test gets added/modified, let's aggressively hammer it and see if we can preemptively flush out intermittent issues up-front, rather than discovering them slowly over time. We don't need that aggressive-hammering on every cycle, though; it's just to "vet" the test when it's added or changed.

In this case, we're just being too strict in our test timeout threshold for one of the phases of this task, as discussed in bug 1734020.