Open Bug 1942712 Opened 26 days ago Updated 19 days ago

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

Categories

(WebExtensions :: General, defect, P5)

defect

Tracking

(Not tracked)

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure, intermittent-testcase)

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


[task 2025-01-20T21:53:51.007Z] 21:53:51     INFO -  TEST-PASS | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_secfetch.js | took 12017ms
[task 2025-01-20T21:53:51.076Z] 21:53:51     INFO -  Cleaning up profile for /builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/extensions/test/xpcshell/test_ext_secfetch.js folder: /data/local/tmp/test_root/xpc/p/287e4541-a131-4a6a-a439-429358c9bd8f
[task 2025-01-20T21:53:51.268Z] 21:53:51     INFO -  TEST-START | xpcshell.toml:toolkit/mozapps/extensions/test/xpcshell/test_upgrade.js
[task 2025-01-20T21:53:51.268Z] 21:53:51     INFO -  TEST-SKIP | xpcshell.toml:toolkit/mozapps/extensions/test/xpcshell/test_upgrade.js | took 0ms
[task 2025-01-20T21:53:51.268Z] 21:53:51     INFO -  Retrying tests that failed when run in parallel.
[task 2025-01-20T21:53:51.725Z] 21:53:51     INFO -  TEST-START | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js
[task 2025-01-20T21:53:51.770Z] 21:53:51     INFO -  adb launch_application: am startservice -W -n 'org.mozilla.geckoview.test_runner/org.mozilla.geckoview.test_runner.XpcshellTestRunnerService$i0' -a android.intent.action.MAIN --es env0 XPCOM_DEBUG_BREAK=stack-and-abort --es env1 MOZ_CRASHREPORTER=1 --es env2 MOZ_CRASHREPORTER_NO_REPORT=1 --es env3 MOZ_DISABLE_NONLOCAL_CONNECTIONS=1 --es env4 MOZ_DEVELOPER_REPO_DIR=/builds/worker/checkouts/gecko --es env5 MOZ_DEVELOPER_OBJ_DIR=/builds/worker/workspace/obj-build --es env6 MOZ_DISABLE_CONTENT_SANDBOX=1 --es env7 MOZ_FETCHES_DIR=/builds/worker/fetches --es env8 MOZ_DISABLE_SOCKET_PROCESS=1 --es env9 LD_LIBRARY_PATH=/data/local/tmp/test_root/xpcb --es env10 MOZ_LINKER_CACHE=/data/local/tmp/test_root/xpcb --es env11 GRE_HOME=/data/local/tmp/test_root/xpcb --es env12 XPCSHELL_TEST_PROFILE_DIR=/data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f --es env13 HOME=/data/local/tmp/test_root/xpc/p --es env14 XPCSHELL_TEST_TEMP_DIR=/data/local/tmp/test_root/xpc/tmp/78e30a5d-9aae-43ee-b43e-5048c71db470 --es env15 MOZ_ANDROID_DATA_DIR=/data/local/tmp/test_root/xpcb --es env16 MOZ_IN_AUTOMATION=1 --es env17 MOZ_ANDROID_CPU_ABI=x86_64 --es env18 MOZHTTP2_PORT=34671 --es env19 MOZNODE_EXEC_PORT=35709 --es env20 MOZHTTP3_PORT=37324 --es env21 MOZHTTP3_PORT_FAILED=37220 --es env22 MOZHTTP3_PORT_ECH=48780 --es env23 MOZHTTP3_PORT_PROXY=59584 --es env24 MOZHTTP3_PORT_NO_RESPONSE=41546 --es env25 MOZHTTP3_ECH=AE3+DQBJBwAgACBbBx5sgdOu+o+G7oeTwuNnmuuQ6Q+QE4v2eiZNeChHPgAQAAEAAQABAAMAAgABAAIAA0AOcHVibGljLmV4YW1wbGUAAA== --es env26 MOZ_HTTP3_SERVER_PATH=/builds/worker/fetches/hostutils/http3server --es env27 MOZ_HTTP3_CERT_DB_PATH=/builds/worker/workspace/build/tests/xpcshell/http3server/http3serverDB --es env28 TMPDIR=/data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f --es env29 XPCSHELL_MINIDUMP_DIR=/data/local/tmp/test_root/xpc/minidumps/5bd8a6b3-15e4-4103-ac82-d2d69475c97f --es arg0 -g --es arg1 /data/local/tmp/test_root/xpcb --es arg2 --greomni --es arg3 /data/local/tmp/test_root/xpcb/geckoview-test_runner.apk --es arg4 -m --es arg5 -e --es arg6 'const _HEAD_JS_PATH = "/data/local/tmp/test_root/xpc/head.js";' --es arg7 -e --es arg8 'const _MOZINFO_JS_PATH = "/data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/mozinfo.json";' --es arg9 -e --es arg10 'const _PREFS_FILE = "/data/local/tmp/test_root/xpc/tmp/78e30a5d-9aae-43ee-b43e-5048c71db470/user.js";' --es arg11 -e --es arg12 'const _TESTING_MODULES_DIR = "/data/local/tmp/test_root/xpc/m";' --es arg13 -f --es arg14 /data/local/tmp/test_root/xpc/head.js --es arg15 -e --es arg16 'const _HEAD_FILES = ["/data/local/tmp/test_root/xpc/toolkit/components/extensions/test/xpcshell/head.js", "/data/local/tmp/test_root/xpc/toolkit/components/extensions/test/xpcshell/head_telemetry.js", "/data/local/tmp/test_root/xpc/toolkit/components/extensions/test/xpcshell/head_sync.js", "/data/local/tmp/test_root/xpc/toolkit/components/extensions/test/xpcshell/head_storage.js"];' --es arg17 -e --es arg18 'const _JSDEBUGGER_PORT = 0;' --es arg19 -e --es arg20 'const _TEST_CWD = "/data/local/tmp/test_root/xpc/toolkit/components/extensions/test/xpcshell";' --es arg21 -e --es arg22 'const _TEST_FILE = ["test_ext_userScripts_mv3_worlds.js"];' --es arg23 -e --es arg24 'const _TEST_NAME = "xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js";' --es arg25 -e --es arg26 '_execute_test(); quit(0);' --es out_file /data/local/tmp/test_root/xpc/logs/xpcshell-498f36cf-b45e-4e2c-9448-769d88c55a30.log
[task 2025-01-20T21:53:51.985Z] 21:53:51     INFO -  remotexpcshelltests.py | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | 31404 | Launched Test App
[task 2025-01-20T21:54:03.670Z] 21:54:03     INFO -  remotexpcshelltests.py | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | 31404 | Application ran for: 0:00:11.944967
[task 2025-01-20T21:54:03.735Z] 21:54:03  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | xpcshell return code: 0
[task 2025-01-20T21:54:03.735Z] 21:54:03     INFO -  TEST-INFO took 12010ms
[task 2025-01-20T21:54:03.735Z] 21:54:03     INFO -  >>>>>>>
[task 2025-01-20T21:54:03.735Z] 21:54:03     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2025-01-20T21:54:03.735Z] 21:54:03     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2025-01-20T21:54:03.736Z] 21:54:03     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2025-01-20T21:54:03.736Z] 21:54:03     INFO -  running event loop
[task 2025-01-20T21:54:03.736Z] 21:54:03     INFO -  xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | Starting setup check_remote
[task 2025-01-20T21:54:03.736Z] 21:54:03     INFO -  (xpcshell/head.js) | test check_remote pending (2)
[task 2025-01-20T21:54:03.736Z] 21:54:03     INFO -  TEST-PASS | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | check_remote - [check_remote : 1] useRemoteWebExtensions matches - false == false
[task 2025-01-20T21:54:03.736Z] 21:54:03     INFO -  TEST-PASS | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | check_remote - [check_remote : 1] testing from extension process - true == true
[task 2025-01-20T21:54:03.736Z] 21:54:03     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2025-01-20T21:54:03.736Z] 21:54:03     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2025-01-20T21:54:03.736Z] 21:54:03     INFO -  (xpcshell/head.js) | test check_remote finished (2)
[task 2025-01-20T21:54:03.737Z] 21:54:03     INFO -  xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | Starting setup
[task 2025-01-20T21:54:03.737Z] 21:54:03     INFO -  (xpcshell/head.js) | test pending (2)
[task 2025-01-20T21:54:03.737Z] 21:54:03     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2025-01-20T21:54:03.737Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032226	addons.manager	DEBUG	Application has been upgraded"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032227	addons.manager	DEBUG	Starting provider: XPIProvider"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032227	addons.xpi	DEBUG	startup"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032228	addons.xpi	INFO	SystemAddonLocation directory is missing"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032236	addons.xpi	INFO	Removing all system add-on upgrades."
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032237	addons.xpi	DEBUG	checkForChanges"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032237	addons.xpi	DEBUG	Loaded add-on state: ${}"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032238	addons.xpi	DEBUG	scanForChanges changed: false, state: {}"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032239	addons.xpi	DEBUG	Empty XPI database, setting schema version preference to 37"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032239	addons.xpi	DEBUG	No changes found"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032244	addons.manager	DEBUG	Registering shutdown blocker for XPIProvider"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032245	addons.manager	DEBUG	Provider finished startup: XPIProvider"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032246	addons.manager	DEBUG	Completed startup sequence"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  (xpcshell/head.js) | test run_next_test 2 pending (2)
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  (xpcshell/head.js) | test finished (2)
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | Starting default_USER_SCRIPT_world_behavior
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  (xpcshell/head.js) | test default_USER_SCRIPT_world_behavior pending (2)
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  (xpcshell/head.js) | test run_next_test 2 finished (2)
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "Could not download addons-mlbf.bin" {file: "resource://services-settings/Attachments.sys.mjs" line: 17}]
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  DownloadError@resource://services-settings/Attachments.sys.mjs:17:5
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  #fetchAttachment@resource://services-settings/Attachments.sys.mjs:456:11
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  async*download@resource://services-settings/Attachments.sys.mjs:171:33
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  download@resource://services-settings/RemoteSettingsClient.sys.mjs:233:26
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  _getMLBFData@resource://gre/modules/Blocklist.sys.mjs:931:40
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  _fetchMLBF@resource://gre/modules/Blocklist.sys.mjs:951:12
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  _updateMLBF/updatePromise<@resource://gre/modules/Blocklist.sys.mjs:1041:49
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  async*_updateMLBF@resource://gre/modules/Blocklist.sys.mjs:1052:7
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  getEntry@resource://gre/modules/Blocklist.sys.mjs:1196:18
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  getAddonBlocklistEntry@resource://gre/modules/Blocklist.sys.mjs:1550:36
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  findBlocklistEntry@resource://gre/modules/addons/XPIDatabase.sys.mjs:687:27
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  updateBlocklistState@resource://gre/modules/addons/XPIDatabase.sys.mjs:699:28
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  loadManifest@resource://gre/modules/addons/XPIInstall.sys.mjs:743:17
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  async*loadManifest@resource://gre/modules/addons/XPIInstall.sys.mjs:1584:28
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  init@resource://gre/modules/addons/XPIInstall.sys.mjs:2240:18
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  createLocalInstall@resource://gre/modules/addons/XPIInstall.sys.mjs:3290:20
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  getInstallForFile@resource://gre/modules/addons/XPIInstall.sys.mjs:4589:25
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  XPIProvider[meth]@resource://gre/modules/addons/XPIProvider.sys.mjs:3338:39
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  promiseCallProvider@resource://gre/modules/AddonManager.sys.mjs:251:31
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  getInstallForFile/<@resource://gre/modules/AddonManager.sys.mjs:1816:29
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  getInstallForFile@resource://gre/modules/AddonManager.sys.mjs:1830:7
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  getInstallForFile@resource://gre/modules/AddonManager.sys.mjs:4273:33
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  _install@resource://testing-common/ExtensionXPCShellUtils.sys.mjs:555:32
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  async*startup@resource://testing-common/ExtensionXPCShellUtils.sys.mjs:593:17
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  default_USER_SCRIPT_world_behavior@test_ext_userScripts_mv3_worlds.js:81:19
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  async*_run_next_test/<@/data/local/tmp/test_root/xpc/head.js:1759:22
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  _run_next_test@/data/local/tmp/test_root/xpc/head.js:1759:38
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  run@/data/local/tmp/test_root/xpc/head.js:808:9
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  _do_main@/data/local/tmp/test_root/xpc/head.js:245:6
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  _execute_test@/data/local/tmp/test_root/xpc/head.js:596:5
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  @-e:1:1
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032591	addons.repository	DEBUG	cacheAddons: enabled false IDs ["@default_USER_SCRIPT_world_behavior"]"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032591	addons.xpi-utils	DEBUG	Starting async load of XPI database /data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/extensions.json"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032603	addons.xpi-utils	DEBUG	Rebuilding XPI database with no extensions"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032606	addons.xpi	DEBUG	Starting install of @default_USER_SCRIPT_world_behavior from file:///data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/temp/generated-extension.xpi"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032615	addons.xpi	DEBUG	Addon @default_USER_SCRIPT_world_behavior will be installed as a packed xpi"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032619	addons.xpi-utils	DEBUG	Make addon app-profile:@default_USER_SCRIPT_world_behavior visible"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032620	addons.xpi	DEBUG	XPIStates adding add-on @default_USER_SCRIPT_world_behavior in {"addons":{},"staged":{},"path":"/data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/extensions"}: /data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/extensions/@default_USER_SCRIPT_world_behavior.xpi"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032621	addons.xpi	DEBUG	Updating XPIState for {"id":"@default_USER_SCRIPT_world_behavior","syncGUID":"{d0a77f3e-f296-4c57-b1ca-498137e83a6d}","version":"1.0","type":"extension","loader":null,"updateURL":null,"installOrigins":null,"manifestVersion":3,"optionsURL":null,"optionsType":null,"optionsBrowserStyle":true,"aboutURL":null,"defaultLocale":{"name":"Generated extension","creator":null,"developers":null,"translators":null,"contributors":null},"visible":true,"active":true,"userDisabled":false,"appDisabled":false,"embedderDisabled":false,"installDate":1737410032604,"updateDate":1737410032604,"applyBackgroundUpdates":1,"path":"/data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/extensions/@default_USER_SCRIPT_world_behavior.xpi","skinnable":false,"sourceURI":"file:///data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/temp/generated-extension.xpi","releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"strictCompatibility":true,"locales":[],"targetApplications":[{"id":"toolkit@mozilla.org","minVersion":null,"maxVersion":null}],"targetPlatforms":[],"signedState":4,"signedTypes":[2],"signedDate":null,"seen":true,"dependencies":[],"incognito":"spanning","userPermissions":{"permissions":[],"origins":[]},"optionalPermissions":{"permissions":["userScripts"],"origins":["*://example.com/*"]},"requestedPermissions":{"permissions":[],"origins":["*://example.com/*"]},"icons":{},"iconURL":null,"blocklistAttentionDismissed":false,"blocklistState":0,"blocklistURL":null,"startupData":null,"hidden":false,"installTelemetryInfo":null,"recommendationState":null,"rootURI":"jar:file:///data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/extensions/@default_USER_SCRIPT_world_behavior.xpi!/","location":"app-profile"}"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032622	addons.xpi	DEBUG	Install of file:///data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/temp/generated-extension.xpi completed."
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032623	addons.xpi	DEBUG	Loading bootstrap scope from jar:file:///data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/extensions/@default_USER_SCRIPT_world_behavior.xpi!/"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032624	addons.xpi	DEBUG	Calling bootstrap method install on @default_USER_SCRIPT_world_behavior version 1.0"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032624	addons.xpi	DEBUG	Calling bootstrap method startup on @default_USER_SCRIPT_world_behavior version 1.0"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "Extension attached"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410032933	addons.xpi	DEBUG	removeTemporaryFile: file:///data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/temp/generated-extension.xpi does not own temp file"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410038363	addons.xpi-utils	DEBUG	XPI Database saved, setting schema version preference to 37"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "Content-Security-Policy: The page’s settings blocked a JavaScript eval (script-src) from being executed because it violates the following directive: “script-src 'self' 'wasm-unsafe-eval'” (Missing 'unsafe-eval')" {file: "moz-extension://f0950e08-1b1e-41e8-81ec-e2abd823d702/world_checker.js" line: 14}]"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  TEST-PASS | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | default_USER_SCRIPT_world_behavior - [default_USER_SCRIPT_world_behavior : 85] browser (extension APIs) should be undefined - true == true
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  TEST-PASS | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | default_USER_SCRIPT_world_behavior - [default_USER_SCRIPT_world_behavior : 86] eval() should be blocked by default in the USER_SCRIPT world - "call to eval() blocked by CSP" == "call to eval() blocked by CSP"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410038699	addons.xpi	DEBUG	Calling bootstrap method shutdown on @default_USER_SCRIPT_world_behavior version 1.0"
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  (xpcshell/head.js) | test run_next_test 3 pending (2)
[task 2025-01-20T21:54:03.743Z] 21:54:03     INFO -  (xpcshell/head.js) | test default_USER_SCRIPT_world_behavior finished (2)
[task 2025-01-20T21:54:03.744Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410038754	addons.xpi	DEBUG	Calling bootstrap method uninstall on @default_USER_SCRIPT_world_behavior version 1.0"
[task 2025-01-20T21:54:03.744Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410038756	addons.xpi	DEBUG	Disabling XPIState for @default_USER_SCRIPT_world_behavior"
[task 2025-01-20T21:54:03.744Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410038760	addons.xpi	DEBUG	uninstallAddon: flushing jar cache /data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/extensions/@default_USER_SCRIPT_world_behavior.xpi for addon @default_USER_SCRIPT_world_behavior"
[task 2025-01-20T21:54:03.744Z] 21:54:03     INFO -  xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | Starting multiple_scripts_share_same_default_world
[task 2025-01-20T21:54:03.744Z] 21:54:03     INFO -  (xpcshell/head.js) | test multiple_scripts_share_same_default_world pending (2)
[task 2025-01-20T21:54:03.744Z] 21:54:03     INFO -  (xpcshell/head.js) | test run_next_test 3 finished (2)
[task 2025-01-20T21:54:03.744Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410038862	addons.repository	DEBUG	cacheAddons: enabled false IDs ["@multiple_scripts_share_same_default_world"]"
[task 2025-01-20T21:54:03.744Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410038864	addons.xpi	DEBUG	Starting install of @multiple_scripts_share_same_default_world from file:///data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/temp/generated-extension.xpi"
[task 2025-01-20T21:54:03.745Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410038873	addons.xpi	DEBUG	Addon @multiple_scripts_share_same_default_world will be installed as a packed xpi"
[task 2025-01-20T21:54:03.745Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410038877	addons.xpi-utils	DEBUG	Make addon app-profile:@multiple_scripts_share_same_default_world visible"
[task 2025-01-20T21:54:03.745Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410038877	addons.xpi	DEBUG	XPIStates adding add-on @multiple_scripts_share_same_default_world in {"addons":{},"staged":{},"path":"/data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/extensions"}: /data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/extensions/@multiple_scripts_share_same_default_world.xpi"
[task 2025-01-20T21:54:03.746Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410038878	addons.xpi	DEBUG	Updating XPIState for {"id":"@multiple_scripts_share_same_default_world","syncGUID":"{c8a83d11-7cc6-44b2-bb0d-e56daf029e71}","version":"1.0","type":"extension","loader":null,"updateURL":null,"installOrigins":null,"manifestVersion":3,"optionsURL":null,"optionsType":null,"optionsBrowserStyle":true,"aboutURL":null,"defaultLocale":{"name":"Generated extension","creator":null,"developers":null,"translators":null,"contributors":null},"visible":true,"active":true,"userDisabled":false,"appDisabled":false,"embedderDisabled":false,"installDate":1737410038863,"updateDate":1737410038863,"applyBackgroundUpdates":1,"path":"/data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/extensions/@multiple_scripts_share_same_default_world.xpi","skinnable":false,"sourceURI":"file:///data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/temp/generated-extension.xpi","releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"strictCompatibility":true,"locales":[],"targetApplications":[{"id":"toolkit@mozilla.org","minVersion":null,"maxVersion":null}],"targetPlatforms":[],"signedState":4,"signedTypes":[2],"signedDate":null,"seen":true,"dependencies":[],"incognito":"spanning","userPermissions":{"permissions":[],"origins":[]},"optionalPermissions":{"permissions":["userScripts"],"origins":["*://example.com/*"]},"requestedPermissions":{"permissions":[],"origins":["*://example.com/*"]},"icons":{},"iconURL":null,"blocklistAttentionDismissed":false,"blocklistState":0,"blocklistURL":null,"startupData":null,"hidden":false,"installTelemetryInfo":null,"recommendationState":null,"rootURI":"jar:file:///data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/extensions/@multiple_scripts_share_same_default_world.xpi!/","location":"app-profile"}"
[task 2025-01-20T21:54:03.746Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410038879	addons.xpi	DEBUG	Install of file:///data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/temp/generated-extension.xpi completed."
[task 2025-01-20T21:54:03.747Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410038880	addons.xpi	DEBUG	Loading bootstrap scope from jar:file:///data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/extensions/@multiple_scripts_share_same_default_world.xpi!/"
[task 2025-01-20T21:54:03.747Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410038880	addons.xpi	DEBUG	Calling bootstrap method install on @multiple_scripts_share_same_default_world version 1.0"
[task 2025-01-20T21:54:03.747Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410038880	addons.xpi	DEBUG	Calling bootstrap method startup on @multiple_scripts_share_same_default_world version 1.0"
[task 2025-01-20T21:54:03.747Z] 21:54:03     INFO -  "Extension attached"
[task 2025-01-20T21:54:03.747Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410039032	addons.xpi	DEBUG	removeTemporaryFile: file:///data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/temp/generated-extension.xpi does not own temp file"
[task 2025-01-20T21:54:03.748Z] 21:54:03     INFO -  TEST-PASS | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | multiple_scripts_share_same_default_world - [multiple_scripts_share_same_default_world : 158] Web page cannot see vars from USER_SCRIPT world - "undefined" == "undefined"
[task 2025-01-20T21:54:03.748Z] 21:54:03     INFO -  TEST-PASS | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | multiple_scripts_share_same_default_world - [multiple_scripts_share_same_default_world : 159] All user scripts should share the same scope - "12345_6789" == "12345_6789"
[task 2025-01-20T21:54:03.748Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410039439	addons.xpi	DEBUG	Calling bootstrap method shutdown on @multiple_scripts_share_same_default_world version 1.0"
[task 2025-01-20T21:54:03.748Z] 21:54:03     INFO -  (xpcshell/head.js) | test run_next_test 4 pending (2)
[task 2025-01-20T21:54:03.748Z] 21:54:03     INFO -  (xpcshell/head.js) | test multiple_scripts_share_same_default_world finished (2)
[task 2025-01-20T21:54:03.748Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410039492	addons.xpi	DEBUG	Calling bootstrap method uninstall on @multiple_scripts_share_same_default_world version 1.0"
[task 2025-01-20T21:54:03.748Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410039493	addons.xpi	DEBUG	Disabling XPIState for @multiple_scripts_share_same_default_world"
[task 2025-01-20T21:54:03.749Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410039493	addons.xpi	DEBUG	uninstallAddon: flushing jar cache /data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/extensions/@multiple_scripts_share_same_default_world.xpi for addon @multiple_scripts_share_same_default_world"
[task 2025-01-20T21:54:03.749Z] 21:54:03     INFO -  xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | Starting test_worldId_validation
[task 2025-01-20T21:54:03.749Z] 21:54:03     INFO -  (xpcshell/head.js) | test test_worldId_validation pending (2)
[task 2025-01-20T21:54:03.749Z] 21:54:03     INFO -  (xpcshell/head.js) | test run_next_test 4 finished (2)
[task 2025-01-20T21:54:03.749Z] 21:54:03     INFO -  "Extension attached"
[task 2025-01-20T21:54:03.749Z] 21:54:03     INFO -  TEST-PASS | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | test_worldId_validation - [test_worldId_validation : 157] Promise rejected, expecting rejection to match '"Invalid worldId: _"', got 'Error: Invalid worldId: _': worldId starting with underscore are reserved - true == true
[task 2025-01-20T21:54:03.750Z] 21:54:03     INFO -  "worldId containing underscore after start is OK"
[task 2025-01-20T21:54:03.750Z] 21:54:03     INFO -  TEST-PASS | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | test_worldId_validation - [test_worldId_validation : 157] Promise rejected, expecting rejection to match '/^Invalid worldId: x{257}$/', got 'Error: Invalid worldId: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx': Too long worldId is rejected - true == true
[task 2025-01-20T21:54:03.750Z] 21:54:03     INFO -  "worldId length of 256 characters is OK"
[task 2025-01-20T21:54:03.750Z] 21:54:03     INFO -  "worldId length of 256 double-byte characters is OK"
[task 2025-01-20T21:54:03.751Z] 21:54:03     INFO -  TEST-PASS | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | test_worldId_validation - [test_worldId_validation : 157] Promise rejected, expecting rejection to match '/^Invalid worldId: \\u{1f00d}{256}$/u', got 'Error: Invalid worldId: 🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍🀍': worldId length of 256 multi-code unit characters is rejected. - true == true
[task 2025-01-20T21:54:03.751Z] 21:54:03     INFO -  TEST-PASS | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | test_worldId_validation - [test_worldId_validation : 157] Function threw, expecting error to match '/worldId: Expected string instead of 123/', got 'Error: Type error for parameter scripts (Error processing 0.worldId: Expected string instead of 123) for userScripts.register.': Non-string worldId is rejected. - true == true
[task 2025-01-20T21:54:03.752Z] 21:54:03     INFO -  TEST-PASS | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | test_worldId_validation - [test_worldId_validation : 157] Promise rejected, expecting rejection to match '"worldId cannot be used with MAIN world."', got 'Error: worldId cannot be used with MAIN world.': Should not support worldId with MAIN world - true == true
[task 2025-01-20T21:54:03.752Z] 21:54:03     INFO -  TEST-PASS | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | test_worldId_validation - [test_worldId_validation : 157] Promise rejected, expecting rejection to match '"worldId cannot be used with MAIN world."', got 'Error: worldId cannot be used with MAIN world.': Should not support worldId with MAIN world - true == true
[task 2025-01-20T21:54:03.752Z] 21:54:03     INFO -  TEST-PASS | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | test_worldId_validation - [test_worldId_validation : 157] Promise rejected, expecting rejection to match '"worldId cannot be used with MAIN world."', got 'Error: worldId cannot be used with MAIN world.': Should not update worldId to non-default world for world MAIN - true == true
[task 2025-01-20T21:54:03.752Z] 21:54:03     INFO -  "Updating worldId + world=USER_SCRIPT at once is OK"
[task 2025-01-20T21:54:03.753Z] 21:54:03     INFO -  TEST-PASS | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | test_worldId_validation - [test_worldId_validation : 157] Promise rejected, expecting rejection to match '"worldId cannot be used with MAIN world."', got 'Error: worldId cannot be used with MAIN world.': Should not change world to MAIN when worldId is non-default worldId - true == true
[task 2025-01-20T21:54:03.753Z] 21:54:03     INFO -  "Update can set world=MAIN and clear worldId at once"
[task 2025-01-20T21:54:03.753Z] 21:54:03     INFO -  (xpcshell/head.js) | test run_next_test 5 pending (2)
[task 2025-01-20T21:54:03.753Z] 21:54:03     INFO -  (xpcshell/head.js) | test test_worldId_validation finished (2)
[task 2025-01-20T21:54:03.753Z] 21:54:03     INFO -  xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | Starting test_default_and_many_non_default_worldIds
[task 2025-01-20T21:54:03.753Z] 21:54:03     INFO -  (xpcshell/head.js) | test test_default_and_many_non_default_worldIds pending (2)
[task 2025-01-20T21:54:03.753Z] 21:54:03     INFO -  (xpcshell/head.js) | test run_next_test 5 finished (2)
[task 2025-01-20T21:54:03.754Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410039923	addons.repository	DEBUG	cacheAddons: enabled false IDs ["@test_default_and_many_non_default_worldIds"]"
[task 2025-01-20T21:54:03.754Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410039926	addons.xpi	DEBUG	Starting install of @test_default_and_many_non_default_worldIds from file:///data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/temp/generated-extension.xpi"
[task 2025-01-20T21:54:03.754Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410039933	addons.xpi	DEBUG	Addon @test_default_and_many_non_default_worldIds will be installed as a packed xpi"
[task 2025-01-20T21:54:03.754Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410039938	addons.xpi-utils	DEBUG	Make addon app-profile:@test_default_and_many_non_default_worldIds visible"
[task 2025-01-20T21:54:03.754Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410039938	addons.xpi	DEBUG	XPIStates adding add-on @test_default_and_many_non_default_worldIds in {"addons":{},"staged":{},"path":"/data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/extensions"}: /data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/extensions/@test_default_and_many_non_default_worldIds.xpi"
[task 2025-01-20T21:54:03.756Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410039938	addons.xpi	DEBUG	Updating XPIState for {"id":"@test_default_and_many_non_default_worldIds","syncGUID":"{4ac8958f-0c5a-4987-9f20-31a3b8558411}","version":"1.0","type":"extension","loader":null,"updateURL":null,"installOrigins":null,"manifestVersion":3,"optionsURL":null,"optionsType":null,"optionsBrowserStyle":true,"aboutURL":null,"defaultLocale":{"name":"Generated extension","creator":null,"developers":null,"translators":null,"contributors":null},"visible":true,"active":true,"userDisabled":false,"appDisabled":false,"embedderDisabled":false,"installDate":1737410039924,"updateDate":1737410039924,"applyBackgroundUpdates":1,"path":"/data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/extensions/@test_default_and_many_non_default_worldIds.xpi","skinnable":false,"sourceURI":"file:///data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/temp/generated-extension.xpi","releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"strictCompatibility":true,"locales":[],"targetApplications":[{"id":"toolkit@mozilla.org","minVersion":null,"maxVersion":null}],"targetPlatforms":[],"signedState":4,"signedTypes":[2],"signedDate":null,"seen":true,"dependencies":[],"incognito":"spanning","userPermissions":{"permissions":[],"origins":[]},"optionalPermissions":{"permissions":["userScripts"],"origins":["*://example.com/*"]},"requestedPermissions":{"permissions":[],"origins":["*://example.com/*"]},"icons":{},"iconURL":null,"blocklistAttentionDismissed":false,"blocklistState":0,"blocklistURL":null,"startupData":null,"hidden":false,"installTelemetryInfo":null,"recommendationState":null,"rootURI":"jar:file:///data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/extensions/@test_default_and_many_non_default_worldIds.xpi!/","location":"app-profile"}"
[task 2025-01-20T21:54:03.756Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410039939	addons.xpi	DEBUG	Install of file:///data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/temp/generated-extension.xpi completed."
[task 2025-01-20T21:54:03.756Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410039940	addons.xpi	DEBUG	Loading bootstrap scope from jar:file:///data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/extensions/@test_default_and_many_non_default_worldIds.xpi!/"
[task 2025-01-20T21:54:03.756Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410039941	addons.xpi	DEBUG	Calling bootstrap method install on @test_default_and_many_non_default_worldIds version 1.0"
[task 2025-01-20T21:54:03.756Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410039941	addons.xpi	DEBUG	Calling bootstrap method startup on @test_default_and_many_non_default_worldIds version 1.0"
[task 2025-01-20T21:54:03.756Z] 21:54:03     INFO -  "Extension attached"
[task 2025-01-20T21:54:03.756Z] 21:54:03     INFO -  "CONSOLE_MESSAGE: (info) 1737410040192	addons.xpi	DEBUG	removeTemporaryFile: file:///data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f/temp/generated-extension.xpi does not own temp file"
[task 2025-01-20T21:54:03.757Z] 21:54:03     INFO -  "Actual result (unsorted): -3,-2,-1,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45"
[task 2025-01-20T21:54:03.757Z] 21:54:03  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | test_default_and_many_non_default_worldIds - [test_default_and_many_non_default_worldIds : 359] Every script should execute in the world specified by worldId - [-3,-2,-1,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45] deepEqual [-3,-2,-1,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50]
[task 2025-01-20T21:54:03.757Z] 21:54:03     INFO -  test_ext_userScripts_mv3_worlds.js:test_default_and_many_non_default_worldIds:359
[task 2025-01-20T21:54:03.757Z] 21:54:03     INFO -  exiting test
[task 2025-01-20T21:54:03.757Z] 21:54:03     INFO -  Unexpected exception NS_ERROR_ABORT:
[task 2025-01-20T21:54:03.757Z] 21:54:03     INFO -  _abort_failed_test@/data/local/tmp/test_root/xpc/head.js:869:20
[task 2025-01-20T21:54:03.757Z] 21:54:03     INFO -  do_report_result@/data/local/tmp/test_root/xpc/head.js:981:5
[task 2025-01-20T21:54:03.757Z] 21:54:03     INFO -  Assert<@/data/local/tmp/test_root/xpc/head.js:70:21
[task 2025-01-20T21:54:03.758Z] 21:54:03     INFO -  Assert.prototype.report@resource://testing-common/Assert.sys.mjs:251:10
[task 2025-01-20T21:54:03.758Z] 21:54:03     INFO -  deepEqual@resource://testing-common/Assert.sys.mjs:331:8
[task 2025-01-20T21:54:03.758Z] 21:54:03     INFO -  test_default_and_many_non_default_worldIds@test_ext_userScripts_mv3_worlds.js:359:10
[task 2025-01-20T21:54:03.758Z] 21:54:03     INFO -  async*_run_next_test/<@/data/local/tmp/test_root/xpc/head.js:1759:22
[task 2025-01-20T21:54:03.758Z] 21:54:03     INFO -  _run_next_test@/data/local/tmp/test_root/xpc/head.js:1759:38
[task 2025-01-20T21:54:03.758Z] 21:54:03     INFO -  run@/data/local/tmp/test_root/xpc/head.js:808:9
[task 2025-01-20T21:54:03.758Z] 21:54:03     INFO -  _do_main@/data/local/tmp/test_root/xpc/head.js:245:6
[task 2025-01-20T21:54:03.758Z] 21:54:03     INFO -  _execute_test@/data/local/tmp/test_root/xpc/head.js:596:5
[task 2025-01-20T21:54:03.758Z] 21:54:03     INFO -  @-e:1:1
[task 2025-01-20T21:54:03.758Z] 21:54:03     INFO -  exiting test
[task 2025-01-20T21:54:03.758Z] 21:54:03  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js | test_default_and_many_non_default_worldIds - [test_default_and_many_non_default_worldIds : 67] Extension left running at test shutdown - "running" == "unloaded"
[task 2025-01-20T21:54:03.758Z] 21:54:03     INFO -  resource://testing-common/ExtensionXPCShellUtils.sys.mjs:ExtensionWrapper/<:67
[task 2025-01-20T21:54:03.759Z] 21:54:03     INFO -  /data/local/tmp/test_root/xpc/head.js:_execute_test/<:660
[task 2025-01-20T21:54:03.759Z] 21:54:03     INFO -  /data/local/tmp/test_root/xpc/head.js:_execute_test:669
[task 2025-01-20T21:54:03.759Z] 21:54:03     INFO -  -e:null:1
[task 2025-01-20T21:54:03.759Z] 21:54:03     INFO -  exiting test
[task 2025-01-20T21:54:03.759Z] 21:54:03     INFO -  NS_ERROR_ABORT:
[task 2025-01-20T21:54:03.759Z] 21:54:03     INFO -  _abort_failed_test@/data/local/tmp/test_root/xpc/head.js:869:20
[task 2025-01-20T21:54:03.759Z] 21:54:03     INFO -  do_report_result@/data/local/tmp/test_root/xpc/head.js:981:5
[task 2025-01-20T21:54:03.759Z] 21:54:03     INFO -  Assert<@/data/local/tmp/test_root/xpc/head.js:70:21
[task 2025-01-20T21:54:03.759Z] 21:54:03     INFO -  Assert.prototype.report@resource://testing-common/Assert.sys.mjs:251:10
[task 2025-01-20T21:54:03.759Z] 21:54:03     INFO -  equal@resource://testing-common/Assert.sys.mjs:293:8
[task 2025-01-20T21:54:03.759Z] 21:54:03     INFO -  ExtensionWrapper/<@resource://testing-common/ExtensionXPCShellUtils.sys.mjs:67:24
[task 2025-01-20T21:54:03.759Z] 21:54:03     INFO -  _execute_test/<@/data/local/tmp/test_root/xpc/head.js:660:28
[task 2025-01-20T21:54:03.759Z] 21:54:03     INFO -  _execute_test@/data/local/tmp/test_root/xpc/head.js:669:5
[task 2025-01-20T21:54:03.759Z] 21:54:03     INFO -  @-e:1:1
[task 2025-01-20T21:54:03.759Z] 21:54:03     INFO -  "Force a GC"
[task 2025-01-20T21:54:03.760Z] 21:54:03     INFO -  Error: Found unexpected files in temporary directory: generated-extension.xpi at resource://testing-common/AddonTestUtils.sys.mjs:363
[task 2025-01-20T21:54:03.760Z] 21:54:03     INFO -  init/<@resource://testing-common/AddonTestUtils.sys.mjs:363:15
[task 2025-01-20T21:54:03.760Z] 21:54:03     INFO -  _execute_test/<@/data/local/tmp/test_root/xpc/head.js:660:28
[task 2025-01-20T21:54:03.760Z] 21:54:03     INFO -  async*_execute_test@/data/local/tmp/test_root/xpc/head.js:669:5
[task 2025-01-20T21:54:03.760Z] 21:54:03     INFO -  @-e:1:1
[task 2025-01-20T21:54:03.760Z] 21:54:03     INFO -  <<<<<<<
[task 2025-01-20T21:54:03.816Z] 21:54:03     INFO -  Cleaning up profile for /builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/extensions/test/xpcshell/test_ext_userScripts_mv3_worlds.js folder: /data/local/tmp/test_root/xpc/p/5bd8a6b3-15e4-4103-ac82-d2d69475c97f
[task 2025-01-20T21:54:04.010Z] 21:54:04     INFO -  INFO | Result summary:
[task 2025-01-20T21:54:04.010Z] 21:54:04     INFO -  INFO | Passed: 469
[task 2025-01-20T21:54:04.010Z] 21:54:04  WARNING -  INFO | Failed: 1
[task 2025-01-20T21:54:04.010Z] 21:54:04  WARNING -  One or more unittests failed.
[task 2025-01-20T21:54:04.010Z] 21:54:04     INFO -  INFO | Todo: 0
[task 2025-01-20T21:54:04.010Z] 21:54:04     INFO -  INFO | Retried: 1
[task 2025-01-20T21:54:04.010Z] 21:54:04     INFO -  SUITE-END | took 1117s
[task 2025-01-20T21:54:04.010Z] 21:54:04     INFO -  Node moz-http2 server shutting down ...
[task 2025-01-20T21:54:04.017Z] 21:54:04     INFO -  cleared MOZHTTP2_PORT connection for port tcp:34671
[task 2025-01-20T21:54:04.023Z] 21:54:04     INFO -  cleared MOZNODE_EXEC_PORT connection for port tcp:35709
[task 2025-01-20T21:54:04.023Z] 21:54:04     INFO -  http3Server server shutting down ...
[task 2025-01-20T21:54:04.151Z] 21:54:04     INFO - Return code: 1
[task 2025-01-20T21:54:04.152Z] 21:54:04     INFO - TinderboxPrint: xpcshell<br/>469/<em class="testfail">1</em>/0
[task 2025-01-20T21:54:04.152Z] 21:54:04     INFO - ##### xpcshell log ends
[task 2025-01-20T21:54:04.152Z] 21:54:04  WARNING - setting return code to 1
[task 2025-01-20T21:54:04.152Z] 21:54:04     INFO - The xpcshell suite: xpcshell ran with return status: WARNING
[task 2025-01-20T21:54:04.152Z] 21:54:04     INFO - Running post-action listener: _package_coverage_data
[task 2025-01-20T21:54:04.152Z] 21:54:04     INFO - Running post-action listener: _resource_record_post_action
[task 2025-01-20T21:54:04.152Z] 21:54:04     INFO - Running post-action listener: process_java_coverage_data
[task 2025-01-20T21:54:04.152Z] 21:54:04     INFO - Running post-action listener: stop_device
[task 2025-01-20T21:54:04.445Z] 21:54:04     INFO - Killing logcat pid 1354.
[task 2025-01-20T21:54:04.445Z] 21:54:04     INFO - Killing every process called qemu-system-x86_64
[task 2025-01-20T21:54:04.451Z] 21:54:04     INFO - [mozharness: 2025-01-20 21:54:04.451049Z] Finished run-tests step (success)
[task 2025-01-20T21:54:04.451Z] 21:54:04     INFO - Running post-run listener: _resource_record_post_run
[task 2025-01-20T21:54:04.971Z] 21:54:04     INFO - Total resource usage - Wall time: 1171s; CPU: 47%; Read bytes: 0; Write bytes: 1652158464; Read time: 0; Write time: 1208232
[task 2025-01-20T21:54:04.972Z] 21:54:04     INFO - TinderboxPrint: CPU usage<br/>46.7%
[task 2025-01-20T21:54:04.972Z] 21:54:04     INFO - TinderboxPrint: I/O read bytes / time<br/>0 / 0
[task 2025-01-20T21:54:04.972Z] 21:54:04     INFO - TinderboxPrint: I/O write bytes / time<br/>1,652,158,464 / 1,208,232
[task 2025-01-20T21:54:04.972Z] 21:54:04     INFO - TinderboxPrint: CPU guest<br/>2,850.8 (23.5%)
[task 2025-01-20T21:54:04.972Z] 21:54:04     INFO - TinderboxPrint: CPU idle<br/>4,925.3 (40.6%)
[task 2025-01-20T21:54:04.972Z] 21:54:04     INFO - TinderboxPrint: CPU system<br/>1,267.6 (10.4%)
[task 2025-01-20T21:54:04.972Z] 21:54:04     INFO - TinderboxPrint: CPU user<br/>3,063.0 (25.2%)
[task 2025-01-20T21:54:04.972Z] 21:54:04     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2025-01-20T21:54:04.973Z] 21:54:04     INFO - start-emulator - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2025-01-20T21:54:04.977Z] 21:54:04     INFO - verify-device - Wall time: 31s; CPU: 27%; Read bytes: 0; Write bytes: 6647808; Read time: 0; Write time: 4348
[task 2025-01-20T21:54:04.980Z] 21:54:04     INFO - install - Wall time: 10s; CPU: 35%; Read bytes: 0; Write bytes: 215093248; Read time: 0; Write time: 183784
[task 2025-01-20T21:54:05.073Z] 21:54:05     INFO - run-tests - Wall time: 1129s; CPU: 47%; Read bytes: 0; Write bytes: 1430401024; Read time: 0; Write time: 1020068
[task 2025-01-20T21:54:07.649Z] 21:54:07  WARNING - returning nonzero exit status 1
[task 2025-01-20T21:54:07.881Z] cleanup
[task 2025-01-20T21:54:07.881Z] + cleanup
[task 2025-01-20T21:54:07.881Z] + local rv=1
[task 2025-01-20T21:54:07.881Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2025-01-20T21:54:07.881Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2025-01-20T21:54:07.882Z] + false
[task 2025-01-20T21:54:07.882Z] + '[' ']'
[task 2025-01-20T21:54:07.882Z] + true
[task 2025-01-20T21:54:07.882Z] + cleanup_xvfb
[task 2025-01-20T21:54:07.883Z] ++ pidof Xvfb
[task 2025-01-20T21:54:07.886Z] + local xvfb_pid=55
[task 2025-01-20T21:54:07.886Z] + local vnc=false
[task 2025-01-20T21:54:07.886Z] + local interactive=false
[task 2025-01-20T21:54:07.886Z] + '[' -n 55 ']'
[task 2025-01-20T21:54:07.886Z] + [[ false == false ]]
[task 2025-01-20T21:54:07.886Z] + [[ false == false ]]
[task 2025-01-20T21:54:07.886Z] + kill 55
[task 2025-01-20T21:54:07.886Z] + exit 1
[taskcluster 2025-01-20 21:54:08.679Z] === Task Finished ===
[taskcluster 2025-01-20 21:54:12.324Z] Unsuccessful task run with exit code: 1 completed in 1477.235 seconds
You need to log in before you can comment on or make changes to this bug.