Closed Bug 1711120 Opened 3 years ago Closed 3 years ago

Intermittent toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js | xpcshell return code: 0

Categories

(WebExtensions :: General, defect, P5)

defect

Tracking

(firefox95 fixed)

RESOLVED FIXED
95 Branch
Tracking Status
firefox95 --- fixed

People

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

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell unknown])

Attachments

(1 file)

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


[task 2021-05-13T18:16:34.650Z] 18:16:34     INFO -  TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js
[task 2021-05-13T18:16:36.573Z] 18:16:36  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js | xpcshell return code: 0
[task 2021-05-13T18:16:36.574Z] 18:16:36     INFO -  TEST-INFO took 1927ms
[task 2021-05-13T18:16:36.574Z] 18:16:36     INFO -  >>>>>>>
[task 2021-05-13T18:16:36.574Z] 18:16:36     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2021-05-13T18:16:36.575Z] 18:16:36     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2021-05-13T18:16:36.575Z] 18:16:36     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2021-05-13T18:16:36.576Z] 18:16:36     INFO -  running event loop
[task 2021-05-13T18:16:36.576Z] 18:16:36     INFO -  xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js | Starting check_remote
[task 2021-05-13T18:16:36.576Z] 18:16:36     INFO -  (xpcshell/head.js) | test check_remote pending (2)
[task 2021-05-13T18:16:36.577Z] 18:16:36     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js | check_remote - [check_remote : 1] useRemoteWebExtensions matches - true == true
[task 2021-05-13T18:16:36.577Z] 18:16:36     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js | check_remote - [check_remote : 1] testing from extension process - false == false
[task 2021-05-13T18:16:36.578Z] 18:16:36     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2021-05-13T18:16:36.578Z] 18:16:36     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2021-05-13T18:16:36.578Z] 18:16:36     INFO -  (xpcshell/head.js) | test check_remote finished (2)
[task 2021-05-13T18:16:36.579Z] 18:16:36     INFO -  xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js | Starting```

Update:

There have been 35 failures within the last 7 days:

  • 7 failures on Windows 7 WebRender Shippable opt
  • 28 failures on windows7-32-qr opt

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=349840829&repo=autoland&lineNumber=5570

[task 2021-08-28T19:32:27.883Z] 19:32:27     INFO -  TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js
[task 2021-08-28T19:32:30.738Z] 19:32:30  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js | xpcshell return code: 0
[task 2021-08-28T19:32:30.740Z] 19:32:30     INFO -  TEST-INFO took 2853ms
[task 2021-08-28T19:32:30.740Z] 19:32:30     INFO -  >>>>>>>
[task 2021-08-28T19:32:30.740Z] 19:32:30     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2021-08-28T19:32:30.740Z] 19:32:30     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2021-08-28T19:32:30.742Z] 19:32:30     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2021-08-28T19:32:30.742Z] 19:32:30     INFO -  running event loop
[task 2021-08-28T19:32:30.742Z] 19:32:30     INFO -  xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js | Starting check_remote
[task 2021-08-28T19:32:30.742Z] 19:32:30     INFO -  (xpcshell/head.js) | test check_remote pending (2)
[task 2021-08-28T19:32:30.743Z] 19:32:30     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js | check_remote - [check_remote : 1] useRemoteWebExtensions matches - true == true

Shane, could you help us assign this to someone?
Thank you.

Flags: needinfo?(mixedpuppy)
Whiteboard: [stockwell needswork:owner]

Update:
There have been 33 failures within the last 7 days:
• 1 failures on Windows 10 x86 WebRender debug
• 1 failures on Windows 10 x64 CCov WebRender opt
• 23 failures on windows7-32-qr opt
• 8 failures on Windows 7 WebRender Shippable opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=350615236&repo=autoland&lineNumber=5534

[task 2021-09-05T23:56:41.889Z] 23:56:41     INFO -  TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js
[task 2021-09-05T23:56:43.837Z] 23:56:43  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js | xpcshell return code: 0
[task 2021-09-05T23:56:43.837Z] 23:56:43     INFO -  TEST-INFO took 1948ms
[task 2021-09-05T23:56:43.837Z] 23:56:43     INFO -  >>>>>>>
[task 2021-09-05T23:56:43.838Z] 23:56:43     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2021-09-05T23:56:43.838Z] 23:56:43     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2021-09-05T23:56:43.838Z] 23:56:43     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2021-09-05T23:56:43.839Z] 23:56:43     INFO -  running event loop
[task 2021-09-05T23:56:43.839Z] 23:56:43     INFO -  xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js | Starting check_remote
[task 2021-09-05T23:56:43.839Z] 23:56:43     INFO -  (xpcshell/head.js) | test check_remote pending (2)
[task 2021-09-05T23:56:43.840Z] 23:56:43     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js | check_remote - [check_remote : 1] useRemoteWebExtensions matches - true == true
[task 2021-09-05T23:56:43.840Z] 23:56:43     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js | check_remote - [check_remote : 1] testing from extension process - false == false
[task 2021-09-05T23:56:43.841Z] 23:56:43     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2021-09-05T23:56:43.841Z] 23:56:43     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2021-09-05T23:56:43.841Z] 23:56:43     INFO -  (xpcshell/head.js) | test check_remote finished (2)
[task 2021-09-05T23:56:43.842Z] 23:56:43     INFO -  xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js | Starting
[task 2021-09-05T23:56:43.842Z] 23:56:43     INFO -  (xpcshell/head.js) | test pending (2)
[task 2021-09-05T23:56:43.842Z] 23:56:43     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2021-09-05T23:56:43.843Z] 23:56:43     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js |  - fr locale is avialable - true == true
[task 2021-09-05T23:56:43.843Z] 23:56:43     INFO -  "Extension attached"
[task 2021-09-05T23:56:43.844Z] 23:56:43     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js |  - Expected extension version - "1.0" == "1.0"
[task 2021-09-05T23:56:43.844Z] 23:56:43     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js |  - Got expected manifest name - "en-US 1.0" == "en-US 1.0"
[task 2021-09-05T23:56:43.844Z] 23:56:43     INFO -  "Restart and re-check"
[task 2021-09-05T23:56:43.844Z] 23:56:43     INFO -  "Extension attached"
[task 2021-09-05T23:56:43.845Z] 23:56:43     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js |  - Expected extension version - "1.0" == "1.0"
[task 2021-09-05T23:56:43.845Z] 23:56:43     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js |  - Got expected manifest name - "en-US 1.0" == "en-US 1.0"
[task 2021-09-05T23:56:43.846Z] 23:56:43     INFO -  "Change locale to 'fr' and restart"
[task 2021-09-05T23:56:43.846Z] 23:56:43     INFO -  "Extension attached"
[task 2021-09-05T23:56:43.846Z] 23:56:43     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js |  - Expected extension version - "1.0" == "1.0"
[task 2021-09-05T23:56:43.847Z] 23:56:43     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js |  - Got expected manifest name - "fr 1.0" == "fr 1.0"
[task 2021-09-05T23:56:43.847Z] 23:56:43     INFO -  "Update to version 1.1"
[task 2021-09-05T23:56:43.847Z] 23:56:43     INFO -  PID 17072 | Missing chrome or resource URL: chrome://global/locale/intl.properties
[task 2021-09-05T23:56:43.848Z] 23:56:43     INFO -  "Extension attached"
[task 2021-09-05T23:56:43.848Z] 23:56:43     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js |  - Expected extension version - "1.1" == "1.1"
[task 2021-09-05T23:56:43.849Z] 23:56:43     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js |  - Got expected manifest name - "fr 1.1" == "fr 1.1"
[task 2021-09-05T23:56:43.849Z] 23:56:43     INFO -  "Change locale to 'en-US' and restart"
[task 2021-09-05T23:56:43.849Z] 23:56:43     INFO -  "Extension attached"
[task 2021-09-05T23:56:43.850Z] 23:56:43     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js |  - Expected extension version - "1.1" == "1.1"
[task 2021-09-05T23:56:43.850Z] 23:56:43     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js |  - Got expected manifest name - "en-US 1.1" == "en-US 1.1"
[task 2021-09-05T23:56:43.850Z] 23:56:43     INFO -  "uninstall locale 'fr'"
[task 2021-09-05T23:56:43.851Z] 23:56:43     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js |  - fr locale is removed - true == true
[task 2021-09-05T23:56:43.852Z] 23:56:43     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "1630886203758	addons.xpi	ERROR	Failed to remove file C:\\Users\\task_1630884891\\AppData\\Local\\Temp\\xpc-profile-f42fhwdp\\extensions\\trash\\@test-langpack.xpi: [Exception... "Component returned failure code: 0x80520015 (NS_ERROR_FILE_ACCESS_DENIED) [nsIFile.remove]"  nsresult: "0x80520015 (NS_ERROR_FILE_ACCESS_DENIED)"  location: "JS frame :: resource://gre/modules/addons/XPIInstall.jsm :: recursiveRemove :: line 1018"  data: no] Stack trace: recursiveRemove()@resource://gre/modules/addons/XPIInstall.jsm:1018
[task 2021-09-05T23:56:43.852Z] 23:56:43     INFO -  recursiveRemove()@resource://gre/modules/addons/XPIInstall.jsm:1032
[task 2021-09-05T23:56:43.853Z] 23:56:43     INFO -  uninstallAddon()@resource://gre/modules/addons/XPIInstall.jsm:3345
[task 2021-09-05T23:56:43.853Z] 23:56:43     INFO -  uninstall()@resource://gre/modules/addons/XPIInstall.jsm:4666
[task 2021-09-05T23:56:43.853Z] 23:56:43     INFO -  uninstallAddon()@resource://gre/modules/addons/XPIInstall.jsm:4693
[task 2021-09-05T23:56:43.854Z] 23:56:43     INFO -  _do_main()@Z:\\task_1630884891\\build\\tests\\xpcshell\\head.js:240
[task 2021-09-05T23:56:43.854Z] 23:56:43     INFO -  _execute_test()@Z:\\task_1630884891\\build\\tests\\xpcshell\\head.js:597
[task 2021-09-05T23:56:43.854Z] 23:56:43     INFO -  -e:1" {file: "resource://gre/modules/Log.jsm" line: 723}]
[task 2021-09-05T23:56:43.855Z] 23:56:43     INFO -  append@resource://gre/modules/Log.jsm:723:12
[task 2021-09-05T23:56:43.855Z] 23:56:43     INFO -  log@resource://gre/modules/Log.jsm:379:16
[task 2021-09-05T23:56:43.855Z] 23:56:43     INFO -  error@resource://gre/modules/Log.jsm:387:10
[task 2021-09-05T23:56:43.855Z] 23:56:43     INFO -  recursiveRemove@resource://gre/modules/addons/XPIInstall.jsm:1022:14
[task 2021-09-05T23:56:43.856Z] 23:56:43     INFO -  recursiveRemove@resource://gre/modules/addons/XPIInstall.jsm:1032:11
[task 2021-09-05T23:56:43.856Z] 23:56:43     INFO -  uninstallAddon@resource://gre/modules/addons/XPIInstall.jsm:3345:26
[task 2021-09-05T23:56:43.856Z] 23:56:43     INFO -  uninstall@resource://gre/modules/addons/XPIInstall.jsm:4666:37
[task 2021-09-05T23:56:43.857Z] 23:56:43     INFO -  uninstallAddon@resource://gre/modules/addons/XPIInstall.jsm:4693:9
[task 2021-09-05T23:56:43.857Z] 23:56:43     INFO -  _do_main@Z:\\task_1630884891\\build\\tests\\xpcshell\\head.js:240:6
[task 2021-09-05T23:56:43.857Z] 23:56:43     INFO -  _execute_test@Z:\\task_1630884891\\build\\tests\\xpcshell\\head.js:597:5
[task 2021-09-05T23:56:43.858Z] 23:56:43     INFO -  @-e:1:1
[task 2021-09-05T23:56:43.858Z] 23:56:43     INFO -  "
[task 2021-09-05T23:56:43.859Z] 23:56:43     INFO -  "CONSOLE_MESSAGE: (info) 1630886203759	addons.xpi	WARN	Failed to remove trash directory when uninstalling @test-langpack: [Exception... "Component returned failure code: 0x80520015 (NS_ERROR_FILE_ACCESS_DENIED) [nsIFile.remove]"  nsresult: "0x80520015 (NS_ERROR_FILE_ACCESS_DENIED)"  location: "JS frame :: resource://gre/modules/addons/XPIInstall.jsm :: recursiveRemove :: line 1018"  data: no] Stack trace: recursiveRemove()@resource://gre/modules/addons/XPIInstall.jsm:1018
[task 2021-09-05T23:56:43.859Z] 23:56:43     INFO -  recursiveRemove()@resource://gre/modules/addons/XPIInstall.jsm:1032
[task 2021-09-05T23:56:43.859Z] 23:56:43     INFO -  uninstallAddon()@resource://gre/modules/addons/XPIInstall.jsm:3345
[task 2021-09-05T23:56:43.860Z] 23:56:43     INFO -  uninstall()@resource://gre/modules/addons/XPIInstall.jsm:4666
[task 2021-09-05T23:56:43.860Z] 23:56:43     INFO -  uninstallAddon()@resource://gre/modules/addons/XPIInstall.jsm:4693
[task 2021-09-05T23:56:43.860Z] 23:56:43     INFO -  _do_main()@Z:\\task_1630884891\\build\\tests\\xpcshell\\head.js:240
[task 2021-09-05T23:56:43.861Z] 23:56:43     INFO -  _execute_test()@Z:\\task_1630884891\\build\\tests\\xpcshell\\head.js:597
[task 2021-09-05T23:56:43.861Z] 23:56:43     INFO -  -e:1"
[task 2021-09-05T23:56:43.861Z] 23:56:43     INFO -  (xpcshell/head.js) | test run_next_test 2 pending (2)
[task 2021-09-05T23:56:43.862Z] 23:56:43     INFO -  (xpcshell/head.js) | test finished (2)
<...>
[task 2021-09-05T23:56:43.882Z] 23:56:43     INFO -  exiting test
[task 2021-09-05T23:56:43.882Z] 23:56:43     INFO -  Error: Test cleanup: path C:\\Users\\task_1630884891\\AppData\\Local\\Temp\\xpc-profile-f42fhwdp\\extensions\\trash exists when it should not at resource://testing-common/AddonTestUtils.jsm:387
[task 2021-09-05T23:56:43.883Z] 23:56:43     INFO -  pathShouldntExist@resource://testing-common/AddonTestUtils.jsm:387:15
[task 2021-09-05T23:56:43.883Z] 23:56:43     INFO -  init/<@resource://testing-common/AddonTestUtils.jsm:441:24
[task 2021-09-05T23:56:43.883Z] 23:56:43     INFO -  _execute_test/<@Z:\task_1630884891\build\tests\xpcshell\head.js:661:28
[task 2021-09-05T23:56:43.884Z] 23:56:43     INFO -  _execute_test@Z:\task_1630884891\build\tests\xpcshell\head.js:673:16
[task 2021-09-05T23:56:43.884Z] 23:56:43     INFO -  @-e:1:1
[task 2021-09-05T23:56:43.884Z] 23:56:43     INFO -  <<<<<<<
[task 2021-09-05T23:56:43.903Z] 23:56:43     INFO -  TEST-START | xpcshell.ini:toolkit/components/search/tests/xpcshell/test_settings_obsolete.js
Assignee: nobody → lgreco
Status: NEW → ASSIGNED

I was able to reproduce this issue on windows (using a debug artifact build and mach xpcshell-test --verify) and so I took a look into it.

The attached patch fixed the intermittent failure for me locally, the reason for the failure seems to be the usual windows-only problem when we try to remove from disk xpi files that may still be technical in use by Gecko itself, and the attached patch just change the call to await addon.uninstall() into a await addon.disable() which is equivalent for actual purpose of the test case.

The langpack xpi is installed through one of the AddonTestUtils methods, and AddonTestUtils will take care of uninstalling that xpi file from its cleanupTempXPIs method, which will also force a GC if removing the xpi file did fail after we flushed the jar cache.

Flags: needinfo?(mixedpuppy)
Pushed by scaraveo@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/62e601166715
Fix test_ext_startup_cache intermittent failures on windows builds. r=mixedpuppy
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → 95 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: