Closed Bug 1951522 Opened 1 year ago Closed 2 months ago

Intermittent toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_perf.js | single tracking bug

Categories

(WebExtensions :: General, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, intermittent-testcase)

Filed by: abutkovits [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=497346095&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/flBPv4FBSyydHm3HJRBdaA/runs/0/artifacts/public/logs/live_backing.log


[task 2025-03-03T20:06:43.439Z] 20:06:43     INFO -  TEST-START | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_perf.js
[task 2025-03-03T20:09:26.918Z] 20:09:26  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_perf.js | xpcshell return code: 0
[task 2025-03-03T20:09:26.918Z] 20:09:26     INFO -  TEST-INFO took 163478ms
[task 2025-03-03T20:09:26.918Z] 20:09:26     INFO -  >>>>>>>
[task 2025-03-03T20:09:26.918Z] 20:09:26     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2025-03-03T20:09:26.918Z] 20:09:26     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2025-03-03T20:09:26.919Z] 20:09:26     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2025-03-03T20:09:26.919Z] 20:09:26     INFO -  running event loop
[task 2025-03-03T20:09:26.919Z] 20:09:26     INFO -  toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_perf.js | Starting setup check_remote
[task 2025-03-03T20:09:26.919Z] 20:09:26     INFO -  (xpcshell/head.js) | test check_remote pending (2)
[task 2025-03-03T20:09:26.920Z] 20:09:26     INFO -  TEST-PASS | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_perf.js | check_remote - [check_remote : 1] useRemoteWebExtensions matches - false == false
[task 2025-03-03T20:09:26.920Z] 20:09:26     INFO -  TEST-PASS | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_perf.js | check_remote - [check_remote : 1] testing from extension process - true == true
[task 2025-03-03T20:09:26.920Z] 20:09:26     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2025-03-03T20:09:26.920Z] 20:09:26     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2025-03-03T20:09:26.920Z] 20:09:26     INFO -  (xpcshell/head.js) | test check_remote finished (2)
[task 2025-03-03T20:09:26.921Z] 20:09:26     INFO -  toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_perf.js | Starting setup setup
[task 2025-03-03T20:09:26.921Z] 20:09:26     INFO -  (xpcshell/head.js) | test setup pending (2)
[task 2025-03-03T20:09:26.921Z] 20:09:26     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2025-03-03T20:09:26.921Z] 20:09:26     INFO -  (xpcshell/head.js) | test run_next_test 2 pending (2)
[task 2025-03-03T20:09:26.921Z] 20:09:26     INFO -  (xpcshell/head.js) | test setup finished (2)
[task 2025-03-03T20:09:26.921Z] 20:09:26     INFO -  toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_perf.js | Starting setup
[task 2025-03-03T20:09:26.922Z] 20:09:26     INFO -  (xpcshell/head.js) | test setup pending (2)
[task 2025-03-03T20:09:26.922Z] 20:09:26     INFO -  (xpcshell/head.js) | test run_next_test 2 finished (2)
[task 2025-03-03T20:09:26.922Z] 20:09:26     INFO -  (xpcshell/head.js) | test run_next_test 3 pending (2)
[task 2025-03-03T20:09:26.922Z] 20:09:26     INFO -  (xpcshell/head.js) | test setup finished (2)
[task 2025-03-03T20:09:26.922Z] 20:09:26     INFO -  toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_perf.js | Starting test_round_trip_perf
[task 2025-03-03T20:09:26.922Z] 20:09:26     INFO -  (xpcshell/head.js) | test test_round_trip_perf pending (2)
[task 2025-03-03T20:09:26.922Z] 20:09:26     INFO -  "Extension attached"
[task 2025-03-03T20:09:26.923Z] 20:09:26     INFO -  (xpcshell/head.js) | test run_next_test 3 finished (2)
[task 2025-03-03T20:09:26.923Z] 20:09:26  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_perf.js | test_round_trip_perf - [test_round_trip_perf : 126] Expected round trip time (32.29ms) to be less than 30ms - 32.29 <= 30
[task 2025-03-03T20:09:26.923Z] 20:09:26     INFO -  /opt/worker/tasks/task_174103142889060/build/tests/xpcshell/tests/toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_perf.js:test_round_trip_perf:126
[task 2025-03-03T20:09:26.923Z] 20:09:26     INFO -  exiting test
[task 2025-03-03T20:09:26.923Z] 20:09:26     INFO -  Unexpected exception NS_ERROR_ABORT:
[task 2025-03-03T20:09:26.924Z] 20:09:26     INFO -  _abort_failed_test@/opt/worker/tasks/task_174103142889060/build/tests/xpcshell/head.js:869:20
[task 2025-03-03T20:09:26.924Z] 20:09:26     INFO -  do_report_result@/opt/worker/tasks/task_174103142889060/build/tests/xpcshell/head.js:981:5
[task 2025-03-03T20:09:26.924Z] 20:09:26     INFO -  Assert<@/opt/worker/tasks/task_174103142889060/build/tests/xpcshell/head.js:70:21
[task 2025-03-03T20:09:26.924Z] 20:09:26     INFO -  Assert.prototype.report@resource://testing-common/Assert.sys.mjs:251:10
[task 2025-03-03T20:09:26.925Z] 20:09:26     INFO -  compareNumbers@resource://testing-common/Assert.sys.mjs:568:10
[task 2025-03-03T20:09:26.925Z] 20:09:26     INFO -  lessOrEqual@resource://testing-common/Assert.sys.mjs:652:18
[task 2025-03-03T20:09:26.925Z] 20:09:26     INFO -  test_round_trip_perf@/opt/worker/tasks/task_174103142889060/build/tests/xpcshell/tests/toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_perf.js:126:10
[task 2025-03-03T20:09:26.925Z] 20:09:26     INFO -  async*_run_next_test/<@/opt/worker/tasks/task_174103142889060/build/tests/xpcshell/head.js:1759:22
[task 2025-03-03T20:09:26.926Z] 20:09:26     INFO -  _run_next_test@/opt/worker/tasks/task_174103142889060/build/tests/xpcshell/head.js:1759:38
[task 2025-03-03T20:09:26.926Z] 20:09:26     INFO -  run@/opt/worker/tasks/task_174103142889060/build/tests/xpcshell/head.js:808:9
[task 2025-03-03T20:09:26.926Z] 20:09:26     INFO -  _do_main@/opt/worker/tasks/task_174103142889060/build/tests/xpcshell/head.js:245:6
[task 2025-03-03T20:09:26.927Z] 20:09:26     INFO -  _execute_test@/opt/worker/tasks/task_174103142889060/build/tests/xpcshell/head.js:596:5
[task 2025-03-03T20:09:26.927Z] 20:09:26     INFO -  @-e:1:1
[task 2025-03-03T20:09:26.927Z] 20:09:26     INFO -  exiting test
[task 2025-03-03T20:09:26.927Z] 20:09:26     INFO -  <<<<<<<
[task 2025-03-03T20:09:26.932Z] 20:09:26     INFO -  TEST-START | xpcshell-remote.toml:toolkit/components/extensions/test/xpcshell/test_ext_background_early_shutdown.js

I was looking at this test as part of auditing for non-deterministic uses of Date.now() following bug 1991910, and found this test, specifically https://searchfox.org/firefox-main/rev/21d3e8ab8b61715ddd39ac04c62a846fa79deddd/toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_perf.js#81-132

Unfortunately, it is not easy to come up with a deterministic way for the test to pass. It tests the interaction between:

  • Extension process
  • Firefox parent process
  • Subprocess worker (from Subprocess.sys.mjs)
  • External application, a Python script in this case.

and tries to confirm whether it all finished in a reasonable amount of time. If the system was particularly busy, the time thresholds may not apply. Note that the original report here mentions a threshold of 30ms (60ms on debug), but the test is currently accepting 90ms following the changes in bug 1945470 (7 months ago). Sadly, the intermittent failures history does not keep that much history, so I cannot tell what the impact was of increasing the threshold to 90ms. In any case, this test is inherently prone to time-sensitive test failures, so ideally we'd fix it.

See Also: → 1991910
See Also: → 1729546
Duplicate of this bug: 1729540
Status: NEW → RESOLVED
Closed: 2 months ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.