Closed Bug 1828279 Opened 2 years ago Closed 2 years ago

Intermittent TVg TinderboxPrint: Per-test run of .../layout/reftests/svg/about:blank<br/>: FAILURE

Categories

(Testing :: General, defect, P5)

Product:
Testing
Component:
General
Type:
defect

Tracking

(firefox-esr102 unaffected, firefox112 unaffected, firefox113 unaffected, firefox114 wontfix, firefox115 fixed)

Status:
RESOLVED FIXED
Milestone:
115 Branch
Tracking Flags:
Tracking Status
firefox-esr102 --- unaffected
firefox112 --- unaffected
firefox113 --- unaffected
firefox114 --- wontfix
firefox115 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: jmaher)

References

(Regression)

Details

(Keywords: intermittent-failure, regression, test-verify-fail)

Attachments

(1 file)

Bug 1828279 - do not run test-verify on about:* pages. r=gbrown!
48 bytes, text/x-phabricator-request
Details | Review

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

[task 2023-04-15T15:10:09.993Z] 15:10:09     INFO -           State: Error getting state: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange" at addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-04-15T15:10:09.994Z] 15:10:09     INFO - addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-04-15T15:10:09.995Z] 15:10:09     INFO - addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-04-15T15:10:09.996Z] 15:10:09     INFO - setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-04-15T15:10:10.000Z] 15:10:09     INFO - @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-04-15T15:10:10.000Z] 15:10:10     INFO - @resource://gre/modules/osfile.jsm:12:30
[task 2023-04-15T15:10:10.000Z] 15:10:10     INFO - @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-04-15T15:10:10.001Z] 15:10:10     INFO - _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:859:17
[task 2023-04-15T15:10:10.001Z] 15:10:10     INFO - setup@resource://gre/modules/TelemetrySend.sys.mjs:799:18
[task 2023-04-15T15:10:10.002Z] 15:10:10     INFO - setup@resource://gre/modules/TelemetrySend.sys.mjs:237:30
[task 2023-04-15T15:10:10.002Z] 15:10:10     INFO - setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-04-15T15:10:10.002Z] 15:10:10     INFO - observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-04-15T15:10:10.003Z] 15:10:10     INFO - WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-04-15T15:10:10.003Z] 15:10:10     INFO - WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-04-15T15:10:10.004Z] 15:10:10     INFO - addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-04-15T15:10:10.004Z] 15:10:10     INFO - addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-04-15T15:10:10.004Z] 15:10:10     INFO - setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-04-15T15:10:10.004Z] 15:10:10     INFO - @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-04-15T15:10:10.005Z] 15:10:10     INFO - @resource://gre/modules/osfile.jsm:12:30
[task 2023-04-15T15:10:10.005Z] 15:10:10     INFO - @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-04-15T15:10:10.007Z] 15:10:10     INFO - _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:859:17
[task 2023-04-15T15:10:10.007Z] 15:10:10     INFO - setup@resource://gre/modules/TelemetrySend.sys.mjs:799:18
[task 2023-04-15T15:10:10.008Z] 15:10:10     INFO - setup@resource://gre/modules/TelemetrySend.sys.mjs:237:30
[task 2023-04-15T15:10:10.008Z] 15:10:10     INFO - setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-04-15T15:10:10.009Z] 15:10:10     INFO - observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-04-15T15:10:10.009Z] 15:10:10     INFO - JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-04-15T15:10:10.010Z] 15:10:10     INFO - JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-04-15T15:10:10.011Z] 15:10:10     INFO - JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-04-15T15:10:10.012Z] 15:10:10     INFO - JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-04-15T15:10:10.012Z] 15:10:10     INFO - JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-04-15T15:10:10.013Z] 15:10:10     INFO - JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-04-15T15:10:10.201Z] 15:10:10     INFO - REFTEST INFO | Process mode: e10s
[task 2023-04-15T15:10:10.203Z] 15:10:10     INFO - REFTEST SUITE-START | Running 0 tests
[task 2023-04-15T15:10:10.205Z] 15:10:10     INFO - REFTEST INFO | Result summary:
[task 2023-04-15T15:10:10.206Z] 15:10:10     INFO - REFTEST INFO | Successful: 0 (0 pass, 0 load only)
[task 2023-04-15T15:10:10.206Z] 15:10:10     INFO - REFTEST INFO | Unexpected: 0 (0 unexpected fail, 0 unexpected pass, 0 unexpected asserts, 0 failed load, 0 exception)
[task 2023-04-15T15:10:10.207Z] 15:10:10     INFO - REFTEST INFO | Known problems: 0 (0 known fail, 0 known asserts, 0 random, 0 skipped, 0 slow)
[task 2023-04-15T15:10:10.208Z] 15:10:10     INFO - REFTEST SUITE-END | Shutdown
[task 2023-04-15T15:10:10.209Z] 15:10:10     INFO - REFTEST INFO | :::
[task 2023-04-15T15:10:10.210Z] 15:10:10     INFO - REFTEST INFO | ::: Test verification summary for:
[task 2023-04-15T15:10:10.210Z] 15:10:10     INFO - REFTEST INFO | :::
[task 2023-04-15T15:10:10.211Z] 15:10:10     INFO - REFTEST INFO | ::: /builds/worker/workspace/build/tests/reftest/tests/layout/reftests/svg/about:blank
[task 2023-04-15T15:10:10.212Z] 15:10:10     INFO - REFTEST INFO | :::
[task 2023-04-15T15:10:10.213Z] 15:10:10     INFO - REFTEST INFO | ::: 1. Run each test 10 times in one browser. : Pass
[task 2023-04-15T15:10:10.214Z] 15:10:10     INFO - REFTEST INFO | ::: 2. Run each test 5 times in a new browser each time. : Pass
[task 2023-04-15T15:10:10.215Z] 15:10:10     INFO - REFTEST INFO | ::: 3. Run each test 10 times in one browser, in chaos mode. : Pass
[task 2023-04-15T15:10:10.216Z] 15:10:10     INFO - REFTEST INFO | ::: 4. Run each test 5 times in a new browser each time, in chaos mode. : Pass
[task 2023-04-15T15:10:10.217Z] 15:10:10     INFO - REFTEST INFO | :::
[task 2023-04-15T15:10:10.218Z] 15:10:10     INFO - REFTEST INFO | ::: Test verification PASSED
[task 2023-04-15T15:10:10.219Z] 15:10:10     INFO - REFTEST INFO | :::
[task 2023-04-15T15:10:10.241Z] 15:10:10     INFO - Return code: 0
[task 2023-04-15T15:10:10.241Z] 15:10:10    ERROR - No checks run.
[task 2023-04-15T15:10:10.242Z] 15:10:10     INFO - TinderboxPrint: reftest-reftest<br/><em class="testfail">T-FAIL</em>
[task 2023-04-15T15:10:10.242Z] 15:10:10  WARNING - setting return code to 2
[task 2023-04-15T15:10:10.242Z] 15:10:10    ERROR - TinderboxPrint: Per-test run of .../layout/reftests/svg/about:blank<br/>: FAILURE
[task 2023-04-15T15:10:10.243Z] 15:10:10     INFO - Per-test suites: {}
[task 2023-04-15T15:10:10.243Z] 15:10:10     INFO - Running post-action listener: _package_coverage_data
[task 2023-04-15T15:10:10.243Z] 15:10:10     INFO - Running post-action listener: _resource_record_post_action
[task 2023-04-15T15:10:10.244Z] 15:10:10     INFO - Running post-action listener: process_java_coverage_data
[task 2023-04-15T15:10:10.244Z] 15:10:10     INFO - [mozharness: 2023-04-15 15:10:10.244513Z] Finished run-tests step (success)
[task 2023-04-15T15:10:10.245Z] 15:10:10     INFO - [mozharness: 2023-04-15 15:10:10.244762Z] Running uninstall step.
[task 2023-04-15T15:10:10.245Z] 15:10:10     INFO - Running pre-action listener: _resource_record_pre_action
[task 2023-04-15T15:10:10.245Z] 15:10:10     INFO - Running main action method: uninstall
[task 2023-04-15T15:10:10.246Z] 15:10:10     INFO - Skipping uninstall for non-MSIX test
[task 2023-04-15T15:10:10.246Z] 15:10:10     INFO - Running post-action listener: _resource_record_post_action
[task 2023-04-15T15:10:10.246Z] 15:10:10     INFO - [mozharness: 2023-04-15 15:10:10.246115Z] Finished uninstall step (success)
[task 2023-04-15T15:10:10.246Z] 15:10:10     INFO - Running post-run listener: _resource_record_post_run
[task 2023-04-15T15:10:10.331Z] 15:10:10     INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2023-04-15T15:10:10.335Z] 15:10:10     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"name": ".overall", "extraOptions": ["e10s", "taskcluster-projects/887720501152/machineTypes/n2-standard-2"], "subtests": [{"name": "cpu_percent", "value": 47.70639097744362}, {"name": "io_write_bytes", "value": 1218441216}, {"name": "io.read_bytes", "value": 376832}, {"name": "io_write_time", "value": 174240}, {"name": "io_read_time", "value": 16}]}, {"name": ".start-pulseaudio", "subtests": [{"name": "time", "value": 0.03525853157043457}, {"name": "cpu_percent", "value": 0}]}, {"name": ".install", "subtests": [{"name": "time", "value": 11.387584209442139}, {"name": "cpu_percent", "value": 50.894999999999996}]}, {"name": ".stage-files", "subtests": [{"name": "time", "value": 0.0028815269470214844}, {"name": "cpu_percent", "value": 0}]}, {"name": ".run-tests", "subtests": [{"name": "time", "value": 122.00319027900696}, {"name": "cpu_percent", "value": 47.328099173553724}]}, {"name": ".uninstall", "subtests": [{"name": "time", "value": 0.0007231235504150391}, {"name": "cpu_percent", "value": 0}]}]}
[task 2023-04-15T15:10:10.336Z] 15:10:10     INFO - Total resource usage - Wall time: 133s; CPU: Can't collect data; Read bytes: 376832; Write bytes: 1218441216; Read time: 16; Write time: 174240
[task 2023-04-15T15:10:10.336Z] 15:10:10     INFO - TinderboxPrint: I/O read bytes / time<br/>376,832 / 16
[task 2023-04-15T15:10:10.337Z] 15:10:10     INFO - TinderboxPrint: I/O write bytes / time<br/>1,218,441,216 / 174,240
[task 2023-04-15T15:10:10.337Z] 15:10:10     INFO - TinderboxPrint: CPU idle<br/>137.9 (52.1%)
[task 2023-04-15T15:10:10.338Z] 15:10:10     INFO - TinderboxPrint: CPU nice<br/>37.5 (14.1%)
[task 2023-04-15T15:10:10.338Z] 15:10:10     INFO - TinderboxPrint: CPU system<br/>20.6 (7.8%)
[task 2023-04-15T15:10:10.339Z] 15:10:10     INFO - TinderboxPrint: CPU user<br/>67.1 (25.4%)
[task 2023-04-15T15:10:10.339Z] 15:10:10     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2023-04-15T15:10:10.340Z] 15:10:10     INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-04-15T15:10:10.341Z] 15:10:10     INFO - install - Wall time: 11s; CPU: 51%; Read bytes: 0; Write bytes: 6021120; Read time: 0; Write time: 16
[task 2023-04-15T15:10:10.341Z] 15:10:10     INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-04-15T15:10:10.341Z] 15:10:10     INFO - run-tests - Wall time: 122s; CPU: 47%; Read bytes: 212992; Write bytes: 1210937344; Read time: 0; Write time: 173528
[task 2023-04-15T15:10:10.342Z] 15:10:10     INFO - uninstall - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-04-15T15:10:10.355Z] 15:10:10  WARNING - returning nonzero exit status 2
Keywords: regression
Regressed by: 1827960

Set release status flags based on info from the regressing bug 1827960

:emilio, since you are the author of the regressor, bug 1827960, could you take a look?

For more information, please visit auto_nag documentation.

status-firefox112: --- → unaffected
status-firefox113: --- → unaffected
status-firefox114: --- → affected
status-firefox-esr102: --- → unaffected
Flags: needinfo?(emilio)

I think this is a verify bug. It shouldn't be using ../.../about:blank, just about:blank

Flags: needinfo?(emilio) → needinfo?(jmaher)
Assignee: nobody → jmaher
Status: NEW → ASSIGNED

patch up here: https://phabricator.services.mozilla.com/D177205

Flags: needinfo?(jmaher)

fwiw, I remember testing about:blank cases with TV long ago; I suppose a few things have changed since then!

Pushed by jmaher@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/44770d5c9e91 do not run test-verify on about:* pages. r=gbrown

https://hg.mozilla.org/mozilla-central/rev/44770d5c9e91

Status: ASSIGNED → RESOLVED
Closed: 2 years ago
status-firefox115: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 115 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: