1637716 - Intermittent browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js | xpcshell return code: 0

Status: RESOLVED FIXED

(Firefox :: Enterprise Policies, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-05-13T17:45:24.841Z] 17:45:24 INFO - TEST-START | browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js
[task 2020-05-13T17:45:25.684Z] 17:45:25 WARNING - TEST-UNEXPECTED-FAIL | browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js | xpcshell return code: 0
[task 2020-05-13T17:45:25.684Z] 17:45:25 INFO - TEST-INFO took 840ms
[task 2020-05-13T17:45:25.684Z] 17:45:25 INFO - >>>>>>>
[task 2020-05-13T17:45:25.684Z] 17:45:25 INFO - PID 1578 | *** You are running in chaos test mode. See ChaosMode.h. ***
[task 2020-05-13T17:45:25.684Z] 17:45:25 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2020-05-13T17:45:25.684Z] 17:45:25 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2020-05-13T17:45:25.684Z] 17:45:25 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2020-05-13T17:45:25.684Z] 17:45:25 INFO - running event loop
[task 2020-05-13T17:45:25.684Z] 17:45:25 INFO - browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js | Starting test_local_addon_update
[task 2020-05-13T17:45:25.684Z] 17:45:25 INFO - (xpcshell/head.js) | test test_local_addon_update pending (2)
[task 2020-05-13T17:45:25.684Z] 17:45:25 INFO - (xpcshell/head.js) | test test_local_addon_update pending (2)
[task 2020-05-13T17:45:25.684Z] 17:45:25 INFO - "CONSOLE_MESSAGE: (info) 1589391924991 addons.manager DEBUG Application has been upgraded"
[task 2020-05-13T17:45:25.684Z] 17:45:25 INFO - "CONSOLE_MESSAGE: (info) 1589391924991 addons.manager DEBUG Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider", "XPIInternal"]"
[task 2020-05-13T17:45:25.684Z] 17:45:25 INFO - "CONSOLE_MESSAGE: (info) 1589391924994 addons.manager DEBUG Loaded provider scope for resource://gre/modules/addons/GMPProvider.jsm"
[task 2020-05-13T17:45:25.685Z] 17:45:25 INFO - "CONSOLE_MESSAGE: (info) 1589391924995 addons.manager DEBUG Loaded provider scope for resource://gre/modules/addons/PluginProvider.jsm"
[task 2020-05-13T17:45:25.685Z] 17:45:25 INFO - "CONSOLE_MESSAGE: (info) 1589391924995 addons.manager DEBUG Starting provider: XPIProvider"
[task 2020-05-13T17:45:25.685Z] 17:45:25 INFO - "CONSOLE_MESSAGE: (info) 1589391924995 addons.xpi DEBUG startup"
[task 2020-05-13T17:45:25.685Z] 17:45:25 INFO - "CONSOLE_MESSAGE: (info) 1589391924996 addons.xpi INFO SystemAddonLocation directory is missing"
[task 2020-05-13T17:45:25.685Z] 17:45:25 INFO - "CONSOLE_MESSAGE: (info) 1589391925003 addons.xpi INFO Removing all system add-on upgrades."
[task 2020-05-13T17:45:25.685Z] 17:45:25 INFO - "CONSOLE_MESSAGE: (info) 1589391925003 addons.xpi DEBUG checkForChanges"
[task 2020-05-13T17:45:25.685Z] 17:45:25 INFO - "CONSOLE_MESSAGE: (info) 1589391925003 addons.xpi DEBUG Loaded add-on state: ${}"
[task 2020-05-13T17:45:25.685Z] 17:45:25 INFO - "CONSOLE_MESSAGE: (info) 1589391925004 addons.xpi DEBUG scanForChanges changed: false, state: {}"
[task 2020-05-13T17:45:25.685Z] 17:45:25 INFO - "CONSOLE_MESSAGE: (info) 1589391925004 addons.xpi DEBUG Empty XPI database, setting schema version preference to 32"
[task 2020-05-13T17:45:25.685Z] 17:45:25 INFO - "CONSOLE_MESSAGE: (info) 1589391925004 addons.xpi DEBUG No changes found"
[task 2020-05-13T17:45:25.685Z] 17:45:25 INFO - "CONSOLE_MESSAGE: (info) 1589391925009 addons.xpi-utils DEBUG Synchronously loading the add-ons database"
[task 2020-05-13T17:45:25.685Z] 17:45:25 INFO - "CONSOLE_MESSAGE: (info) 1589391925010 addons.xpi-utils DEBUG Starting async load of XPI database /tmp/xpc-profile-G7_2E_/extensions.json"
[task 2020-05-13T17:45:25.685Z] 17:45:25 INFO - (xpcshell/head.js) | test run_next_test 0 finished (2)

Comment 1

[Mike Kaply [:mkaply]]

So I've spent some time looking into these and it looks like the AddonManager doesn't really like it when you install an addon over the same addon.

It leaves Temp files around and other things.

I'm at a loss how to work around this. All the problems stem from doing an install of a XPI for an addon with the same ID.

I see things like this:

 0:13.40 INFO "CONSOLE_MESSAGE: (info) 1589404448838    addons.xpi      DEBUG   Install of http://example.com/data/policy_test2.xpi completed."
 0:13.40 INFO "CONSOLE_MESSAGE: (info) 1589404448839    addons.xpi      DEBUG   Loading bootstrap scope from jar:file:///c:/users/mkaply/appdata/local/temp/firefox/xpcshellprofile/extensions/[e-mail]!/"
 0:13.40 INFO "CONSOLE_MESSAGE: (info) 1589404448839    addons.xpi      DEBUG   Calling bootstrap method update on updatable2@test version 2.0"
 0:13.40 INFO (xpcshell/head.js) | test run_next_test 2 finished (1)
 0:13.40 INFO exiting test
 0:13.41 ERROR Error: Found unexpected files in temporary directory: tmp-pi5.xpi at resource://testing-common/AddonTestUtils.jsm:450
init/<@resource://testing-common/AddonTestUtils.jsm:450:15
_execute_test/<@d:\mozilla-unified\testing\xpcshell\head.js:635:28
async*_execute_test@d:\mozilla-unified\testing\xpcshell\head.js:644:5
@-e:1:1

 0:13.43 INFO "CONSOLE_MESSAGE: (info) 1589404448863    addons.xpi      DEBUG   Calling bootstrap method startup on updatable2@test version 2.0"
 0:13.43 INFO "CONSOLE_MESSAGE: (info) 1589404448869    addons.xpi      DEBUG   removeTemporaryFile: http://example.com/data/policy_test2.xpi removing temp file c:\\users\\mkaply\\appdata\\local\\temp\\firefox\\xpcshellprofile\\temp\\tmp-pi5.xpi"

which is funny because we're removing the temporary file, just not doing it until after ADdonTestUtils checks for it...

Comment 2

[Mike Kaply [:mkaply]]

I verified this works if I do it with just addon manager:

  let install = await AddonManager.getInstallForURL("http://example.com/data/policy_test1.xpi");
  let p = AddonTestUtils.promiseInstallEvent("onInstallEnded");
  install.install();
  await p;
  let addon = await AddonManager.getAddonByID(id);
  notEqual(addon, null, "Addon should not be null");

  install = await AddonManager.getInstallForURL("http://example.com/data/policy_test2.xpi");
  p = AddonTestUtils.promiseInstallEvent("onInstallEnded");
  install.install();
  await p;
  addon = await AddonManager.getAddonByID(id);
  notEqual(addon, null, "Addon should not be null");

And I was able to recreate the temp file problem if I finished the test without waiting for onInstallEnded.

Not sure why this is happening in our case.

Comment 3

[Mike Kaply [:mkaply]]

Attachment: test that uninstalls after double install

I did verify that if we try to uninstall an addon after doing a double install, it fails.

This appears to be a bug in the AOM.

If you only install once it fails. Errors are multiple but the main one is

FAIL browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js - xpcshell return code: 0
ERROR Error: Test cleanup: path c:\users\mkaply\appdata\local\temp\firefox\xpcshellprofile\extensions\trash exists when it should not at resource://testing-common/AddonTestUtils.jsm:420

Comment 4

[Mike Kaply [:mkaply]]

I opened bug 1638035 for the test failure. I think if that were fixed, it would fix this issue.

Comment 5

[Intermittent Failures Robot]

2 failures in 5488 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform breakdown:

• linux1804-64: 1
• linux1804-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1637716&startday=2020-05-11&endday=2020-05-17&tree=all

Comment 6

[Razvan Maries]

Tier 1 failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=303090901&repo=autoland&lineNumber=2460

Comment 7

[Intermittent Failures Robot]

2 failures in 4727 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform breakdown:

• linux1804-64-shippable: 1
• linux1804-64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1637716&startday=2020-05-18&endday=2020-05-24&tree=all

Comment 8

[Shane Caraveo (:mixedpuppy)]

The test in bug 1638035 had some minor issues, which once fixed also fixed the failure. Policies.jsm does not wait on the install promise to resolve, and that is likely the base issue. In real life it boils down to a test issue. You may instead want to wait on extension startup in the test (assuming you don't want to change policies.jsm) to do something like:

  let extension = ExtensionTestUtils.expectExtension(ADDON_ID);
  await Promise.all([
    extension.awaitStartup(),
    setupPolicyEngineWithJson({
      policies: {
        ExtensionSettings: {
          "updatable@test": {
            installation_mode: "force_installed",
            install_url: Services.io.newFileURI(tmpDir).spec + "/" + TEST_NAME,
          },
        },
      },
    }),
  ]);

Comment 9

[Mike Kaply [:mkaply]]

Attachment: Bug 1637716 - Shutdown AddonManager at end of test. r?mixedpuppy

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/004a7596ab7c
Shutdown AddonManager at end of test. r=mixedpuppy

Comment 11

[Bogdan Tara[:bogdan_tara | bogdant]]

Backed out changeset 004a7596ab7c (bug 1637716) for test_addon_update.js failures

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&fromchange=5a7f6e78b0bb6f78a63eb5f745bcd090d425a8e4&searchStr=xpc&tochange=9aec2eafbb016a78a0a1f7e5c331fb668220a1b4&selectedTaskRun=Kxx-m-7lSia4nqXsJjLPAw-0

Backout link: https://hg.mozilla.org/integration/autoland/rev/9aec2eafbb016a78a0a1f7e5c331fb668220a1b4

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=303821083&repo=autoland&lineNumber=2959

[task 2020-05-26T19:42:41.684Z] 19:42:41     INFO -  TEST-START | browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js
[task 2020-05-26T19:42:44.521Z] 19:42:44  WARNING -  TEST-UNEXPECTED-FAIL | browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js | xpcshell return code: 0
[task 2020-05-26T19:42:44.521Z] 19:42:44     INFO -  TEST-INFO took 2832ms
[task 2020-05-26T19:42:44.522Z] 19:42:44     INFO -  >>>>>>>
[task 2020-05-26T19:42:44.523Z] 19:42:44     INFO -  PID 22098 | [22098, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp, line 2924
[task 2020-05-26T19:42:44.525Z] 19:42:44     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2020-05-26T19:42:44.526Z] 19:42:44     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2020-05-26T19:42:44.527Z] 19:42:44     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2020-05-26T19:42:44.528Z] 19:42:44     INFO -  running event loop
[task 2020-05-26T19:42:44.529Z] 19:42:44     INFO -  PID 22098 | [22098, Main Thread] WARNING: Couldn't get the user appdata directory, crash dumps will go in an unusual location: file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp, line 2984
[task 2020-05-26T19:42:44.530Z] 19:42:44     INFO -  browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js | Starting test_local_addon_update
[task 2020-05-26T19:42:44.531Z] 19:42:44     INFO -  (xpcshell/head.js) | test test_local_addon_update pending (2)
[task 2020-05-26T19:42:44.532Z] 19:42:44     INFO -  PID 22098 | [22116, MainThread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp, line 202
[task 2020-05-26T19:42:44.532Z] 19:42:44     INFO -  PID 22098 | [22116, MainThread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp, line 202
[task 2020-05-26T19:42:44.533Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162079	addons.manager	DEBUG	Application has been upgraded"
[task 2020-05-26T19:42:44.536Z] 19:42:44     INFO -  PID 22098 | [Socket 22116, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, kKnownEsrVersion) failed with result 0x80004002 (NS_NOINTERFACE): file /builds/worker/checkouts/gecko/toolkit/components/resistfingerprinting/nsRFPService.cpp, line 673
[task 2020-05-26T19:42:44.537Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162079	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider", "XPIInternal"]"
[task 2020-05-26T19:42:44.540Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162088	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/GMPProvider.jsm"
[task 2020-05-26T19:42:44.543Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162092	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/PluginProvider.jsm"
[task 2020-05-26T19:42:44.546Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162092	addons.manager	DEBUG	Starting provider: XPIProvider"
[task 2020-05-26T19:42:44.549Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162093	addons.xpi	DEBUG	startup"
[task 2020-05-26T19:42:44.551Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162093	addons.xpi	DEBUG	List of built-in add-ons is missing or invalid.: [Exception... "Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsIXPCComponents_Utils.readUTF8URI]"  nsresult: "0xc1f30001 (NS_ERROR_NOT_INITIALIZED)"  location: "JS frame :: resource://gre/modules/addons/XPIProvider.jsm :: startup :: line 2433"  data: no] Stack trace: startup()@resource://gre/modules/addons/XPIProvider.jsm:2433
[task 2020-05-26T19:42:44.553Z] 19:42:44     INFO -  callProvider()@resource://gre/modules/AddonManager.jsm:212
[task 2020-05-26T19:42:44.553Z] 19:42:44     INFO -  _startProvider()@resource://gre/modules/AddonManager.jsm:583
[task 2020-05-26T19:42:44.554Z] 19:42:44     INFO -  startup()@resource://gre/modules/AddonManager.jsm:807
[task 2020-05-26T19:42:44.554Z] 19:42:44     INFO -  startup()@resource://gre/modules/AddonManager.jsm:3462
[task 2020-05-26T19:42:44.554Z] 19:42:44     INFO -  observe()@resource://gre/modules/addonManager.js:87
[task 2020-05-26T19:42:44.555Z] 19:42:44     INFO -  promiseStartupManager()@resource://testing-common/AddonTestUtils.jsm:977
[task 2020-05-26T19:42:44.555Z] 19:42:44     INFO -  test_local_addon_update()@/builds/worker/workspace/build/tests/xpcshell/tests/browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js:25
[task 2020-05-26T19:42:44.556Z] 19:42:44     INFO -  _run_next_test/<()@/builds/worker/workspace/build/tests/xpcshell/head.js:1618
[task 2020-05-26T19:42:44.556Z] 19:42:44     INFO -  _run_next_test()@/builds/worker/workspace/build/tests/xpcshell/head.js:1618
[task 2020-05-26T19:42:44.556Z] 19:42:44     INFO -  run()@/builds/worker/workspace/build/tests/xpcshell/head.js:777
[task 2020-05-26T19:42:44.557Z] 19:42:44     INFO -  _do_main()@/builds/worker/workspace/build/tests/xpcshell/head.js:248
[task 2020-05-26T19:42:44.557Z] 19:42:44     INFO -  _execute_test()@/builds/worker/workspace/build/tests/xpcshell/head.js:577
[task 2020-05-26T19:42:44.557Z] 19:42:44     INFO -  -e:1"
[task 2020-05-26T19:42:44.558Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162098	addons.xpi	INFO	SystemAddonLocation directory is missing"
[task 2020-05-26T19:42:44.559Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162118	addons.xpi	INFO	Removing all system add-on upgrades."
[task 2020-05-26T19:42:44.560Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162119	addons.xpi	DEBUG	checkForChanges"
[task 2020-05-26T19:42:44.561Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162119	addons.xpi	DEBUG	Loaded add-on state: ${}"
[task 2020-05-26T19:42:44.563Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162121	addons.xpi	DEBUG	scanForChanges changed: false, state: {}"
[task 2020-05-26T19:42:44.564Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162122	addons.xpi	DEBUG	Empty XPI database, setting schema version preference to 32"
[task 2020-05-26T19:42:44.565Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162122	addons.xpi	DEBUG	No changes found"
[task 2020-05-26T19:42:44.567Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162137	addons.xpi-utils	DEBUG	Synchronously loading the add-ons database"
[task 2020-05-26T19:42:44.568Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162137	addons.xpi-utils	DEBUG	Starting async load of XPI database /tmp/xpc-profile-5wDyOV/extensions.json"
[task 2020-05-26T19:42:44.569Z] 19:42:44     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2020-05-26T19:42:44.569Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162212	addons.xpi-utils	DEBUG	Rebuilding XPI database with no extensions"
[task 2020-05-26T19:42:44.570Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162216	addons.manager	DEBUG	Registering shutdown blocker for XPIProvider"
[task 2020-05-26T19:42:44.572Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162217	addons.manager	DEBUG	Provider finished startup: XPIProvider"
[task 2020-05-26T19:42:44.573Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162217	addons.manager	DEBUG	Starting provider: PluginProvider"
[task 2020-05-26T19:42:44.574Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162217	addons.manager	DEBUG	Registering shutdown blocker for PluginProvider"
[task 2020-05-26T19:42:44.575Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162218	addons.manager	DEBUG	Provider finished startup: PluginProvider"
[task 2020-05-26T19:42:44.575Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522162218	addons.manager	DEBUG	Completed startup sequence"
[task 2020-05-26T19:42:44.577Z] 19:42:44     INFO -  TEST-PASS | browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js | test_local_addon_update - [test_local_addon_update : 50] Sanity check the temporary file doesn't exist. - true == true
[task 2020-05-26T19:42:44.577Z] 19:42:44     INFO -  PID 22098 | LoadPlugin() /tmp/xpc-plugins-PEXSix/libnptest.so returned 7ffbbf3f32b0
[task 2020-05-26T19:42:44.577Z] 19:42:44     INFO -  PID 22098 | LoadPlugin() /tmp/xpc-plugins-PEXSix/libnpthirdtest.so returned 7ffbbf3f3310
[task 2020-05-26T19:42:44.578Z] 19:42:44     INFO -  PID 22098 | LoadPlugin() /tmp/xpc-plugins-PEXSix/libnpsecondtest.so returned 7ffbbf3f3bb0
[task 2020-05-26T19:42:44.578Z] 19:42:44     INFO -  PID 22098 | LoadPlugin() /tmp/xpc-plugins-PEXSix/libnpswftest.so returned 7ffbbf3f3ac0
[task 2020-05-26T19:42:44.578Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163492	addons.repository	DEBUG	cacheAddons: enabled false IDs ["updatable1@test"]"
[task 2020-05-26T19:42:44.580Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163505	addons.xpi	DEBUG	Starting install of updatable1@test from file:///tmp/xpc-profile-5wDyOV/temp//updatable.xpi"
[task 2020-05-26T19:42:44.580Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163517	addons.xpi	DEBUG	Addon updatable1@test will be installed as a packed xpi"
[task 2020-05-26T19:42:44.581Z] 19:42:44     INFO -  TEST-PASS | browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js | test_local_addon_update - [test_local_addon_update : 53] Addon should not be null - {} != null
[task 2020-05-26T19:42:44.581Z] 19:42:44     INFO -  TEST-PASS | browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js | test_local_addon_update - [test_local_addon_update : 54] Addon 1.0 installed - "1.0" == "1.0"
[task 2020-05-26T19:42:44.581Z] 19:42:44     INFO -  TEST-PASS | browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js | test_local_addon_update - [test_local_addon_update : 50] Sanity check the temporary file doesn't exist. - true == true
[task 2020-05-26T19:42:44.582Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163521	addons.xpi-utils	DEBUG	Make addon app-profile:updatable1@test visible"
[task 2020-05-26T19:42:44.582Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163522	addons.xpi	DEBUG	XPIStates adding add-on updatable1@test in {"addons":{},"staged":{},"path":"/tmp/xpc-profile-5wDyOV/extensions"}: /tmp/xpc-profile-5wDyOV/extensions/[e-mail]"
[task 2020-05-26T19:42:44.583Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163524	addons.xpi	DEBUG	Updating XPIState for {"id":"updatable1@test","syncGUID":"{7566204b-93ac-4ef3-b989-7142dcb2eb4b}","version":"1.0","type":"extension","loader":null,"updateURL":null,"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":1590522163502,"updateDate":1590522163502,"applyBackgroundUpdates":1,"path":"/tmp/xpc-profile-5wDyOV/extensions/[e-mail]","skinnable":false,"sourceURI":"file:///tmp/xpc-profile-5wDyOV/temp//updatable.xpi","releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"strictCompatibility":true,"locales":[],"targetApplications":[{"id":"[e-mail]","minVersion":null,"maxVersion":null}],"targetPlatforms":[],"signedState":4,"signedDate":null,"seen":true,"dependencies":[],"incognito":"spanning","userPermissions":{"permissions":[],"origins":[]},"optionalPermissions":{"permissions":[],"origins":[]},"icons":{},"iconURL":null,"blocklistState":0,"blocklistURL":null,"startupData":null,"hidden":false,"installTelemetryInfo":{"source":"enterprise-policy"},"recommendationState":null,"rootURI":"jar:file:///tmp/xpc-profile-5wDyOV/extensions/[e-mail]!/","location":"app-profile"}"
[task 2020-05-26T19:42:44.584Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163525	addons.xpi	DEBUG	Install of file:///tmp/xpc-profile-5wDyOV/temp//updatable.xpi completed."
[task 2020-05-26T19:42:44.584Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163527	addons.xpi	DEBUG	Loading bootstrap scope from jar:file:///tmp/xpc-profile-5wDyOV/extensions/[e-mail]!/"
[task 2020-05-26T19:42:44.586Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163527	addons.xpi	DEBUG	Calling bootstrap method install on updatable1@test version 1.0"
[task 2020-05-26T19:42:44.587Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163528	addons.xpi	DEBUG	Calling bootstrap method startup on updatable1@test version 1.0"

task 2020-05-26T19:42:44.589Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163558	addons.xpi	DEBUG	removeTemporaryFile: file:///tmp/xpc-profile-5wDyOV/temp//updatable.xpi does not own temp file"
[task 2020-05-26T19:42:44.589Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163565	addons.xpi-utils	DEBUG	XPI Database saved, setting schema version preference to 32"
[task 2020-05-26T19:42:44.592Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163586	addons.repository	DEBUG	cacheAddons: enabled false IDs ["updatable1@test"]"
[task 2020-05-26T19:42:44.592Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163597	addons.xpi	DEBUG	Starting install of updatable1@test from file:///tmp/xpc-profile-5wDyOV/temp//updatable.xpi"
[task 2020-05-26T19:42:44.593Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163606	addons.xpi	DEBUG	Addon updatable1@test will be installed as a packed xpi"
[task 2020-05-26T19:42:44.593Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163609	addons.xpi	DEBUG	Calling bootstrap method shutdown on updatable1@test version 1.0"
[task 2020-05-26T19:42:44.595Z] 19:42:44     INFO -  TEST-PASS | browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js | test_local_addon_update - [test_local_addon_update : 82] Addon 2.0 installed - "2.0" == "2.0"
[task 2020-05-26T19:42:44.596Z] 19:42:44     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2020-05-26T19:42:44.596Z] 19:42:44     INFO -  (xpcshell/head.js) | test test_local_addon_update finished (2)
[task 2020-05-26T19:42:44.596Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163615	addons.xpi-utils	DEBUG	Make addon app-profile:updatable1@test visible"
[task 2020-05-26T19:42:44.598Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163615	addons.xpi	DEBUG	Updating XPIState for {"id":"updatable1@test","syncGUID":"{7566204b-93ac-4ef3-b989-7142dcb2eb4b}","version":"2.0","type":"extension","loader":null,"updateURL":null,"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":1590522163000,"updateDate":1590522163596,"applyBackgroundUpdates":1,"path":"/tmp/xpc-profile-5wDyOV/extensions/[e-mail]","skinnable":false,"sourceURI":"file:///tmp/xpc-profile-5wDyOV/temp//updatable.xpi","releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"strictCompatibility":true,"locales":[],"targetApplications":[{"id":"[e-mail]","minVersion":null,"maxVersion":null}],"targetPlatforms":[],"signedState":4,"signedDate":null,"seen":true,"dependencies":[],"incognito":"spanning","userPermissions":{"permissions":[],"origins":[]},"optionalPermissions":{"permissions":[],"origins":[]},"icons":{},"iconURL":null,"blocklistState":0,"blocklistURL":null,"startupData":null,"hidden":false,"installTelemetryInfo":{"source":"enterprise-policy"},"recommendationState":null,"rootURI":"jar:file:///tmp/xpc-profile-5wDyOV/extensions/[e-mail]!/","location":"app-profile"}"
[task 2020-05-26T19:42:44.598Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163616	addons.xpi	DEBUG	Updating XPIState for {"id":"updatable1@test","syncGUID":"{7566204b-93ac-4ef3-b989-7142dcb2eb4b}","version":"2.0","type":"extension","loader":null,"updateURL":null,"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":1590522163000,"updateDate":1590522163596,"applyBackgroundUpdates":1,"path":"/tmp/xpc-profile-5wDyOV/extensions/[e-mail]","skinnable":false,"sourceURI":"file:///tmp/xpc-profile-5wDyOV/temp//updatable.xpi","releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"strictCompatibility":true,"locales":[],"targetApplications":[{"id":"[e-mail]","minVersion":null,"maxVersion":null}],"targetPlatforms":[],"signedState":4,"signedDate":null,"seen":true,"dependencies":[],"incognito":"spanning","userPermissions":{"permissions":[],"origins":[]},"optionalPermissions":{"permissions":[],"origins":[]},"icons":{},"iconURL":null,"blocklistState":0,"blocklistURL":null,"startupData":null,"hidden":false,"installTelemetryInfo":{"source":"enterprise-policy"},"recommendationState":null,"rootURI":"jar:file:///tmp/xpc-profile-5wDyOV/extensions/[e-mail]!/","location":"app-profile"}"
[task 2020-05-26T19:42:44.600Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163616	addons.xpi	DEBUG	Install of file:///tmp/xpc-profile-5wDyOV/temp//updatable.xpi completed."
[task 2020-05-26T19:42:44.601Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163618	addons.xpi	DEBUG	Loading bootstrap scope from jar:file:///tmp/xpc-profile-5wDyOV/extensions/[e-mail]!/"
[task 2020-05-26T19:42:44.601Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163618	addons.xpi	DEBUG	Calling bootstrap method update on updatable1@test version 2.0"
[task 2020-05-26T19:42:44.602Z] 19:42:44     INFO -  browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js | Starting test_newurl_addon_update
[task 2020-05-26T19:42:44.602Z] 19:42:44     INFO -  (xpcshell/head.js) | test test_newurl_addon_update pending (2)
[task 2020-05-26T19:42:44.602Z] 19:42:44     INFO -  TEST-PASS | browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js | test_newurl_addon_update - [test_newurl_addon_update : 50] Sanity check the temporary file doesn't exist. - true == true
[task 2020-05-26T19:42:44.602Z] 19:42:44     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2020-05-26T19:42:44.602Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163675	addons.xpi	DEBUG	Calling bootstrap method startup on updatable1@test version 2.0"
[task 2020-05-26T19:42:44.602Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163689	addons.xpi	DEBUG	removeTemporaryFile: file:///tmp/xpc-profile-5wDyOV/temp//updatable.xpi does not own temp file"
[task 2020-05-26T19:42:44.603Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163713	addons.xpi	DEBUG	Download started for http://example.com/data/policy_test1.xpi to file /tmp/xpc-profile-5wDyOV/temp/tmp-ibc.xpi"
[task 2020-05-26T19:42:44.605Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163714	addons.xpi	DEBUG	Download of http://example.com/data/policy_test1.xpi completed."
[task 2020-05-26T19:42:44.607Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163734	addons.repository	DEBUG	cacheAddons: enabled false IDs ["updatable2@test"]"
[task 2020-05-26T19:42:44.609Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163742	addons.xpi	DEBUG	Starting install of updatable2@test from http://example.com/data/policy_test1.xpi"
[task 2020-05-26T19:42:44.609Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163758	addons.xpi	DEBUG	Addon updatable2@test will be installed as a packed xpi"
[task 2020-05-26T19:42:44.611Z] 19:42:44     INFO -  TEST-PASS | browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js | test_newurl_addon_update - [test_newurl_addon_update : 128] Addon should not be null - {} != null
[task 2020-05-26T19:42:44.612Z] 19:42:44     INFO -  TEST-PASS | browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js | test_newurl_addon_update - [test_newurl_addon_update : 129] Addon 1.0 installed - "1.0" == "1.0"
[task 2020-05-26T19:42:44.612Z] 19:42:44     INFO -  TEST-PASS | browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js | test_newurl_addon_update - [test_newurl_addon_update : 50] Sanity check the temporary file doesn't exist. - true == true
[task 2020-05-26T19:42:44.612Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163762	addons.xpi-utils	DEBUG	Make addon app-profile:updatable2@test visible"
[task 2020-05-26T19:42:44.614Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163762	addons.xpi	DEBUG	XPIStates adding add-on updatable2@test in {"addons":{"updatable1@test":{"dependencies":[],"enabled":true,"lastModifiedTime":1590522163000,"loader":null,"path":"[e-mail]","rootURI":"jar:file:///tmp/xpc-profile-5wDyOV/extensions/[e-mail]!/","runInSafeMode":false,"signedState":4,"signedDate":null,"telemetryKey":"updatable1%40test:2.0","version":"2.0"}},"staged":{},"path":"/tmp/xpc-profile-5wDyOV/extensions"}: /tmp/xpc-profile-5wDyOV/extensions/[e-mail]"
[task 2020-05-26T19:42:44.615Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163764	addons.xpi	DEBUG	Updating XPIState for {"id":"updatable2@test","syncGUID":"{dccf64be-7964-4c02-8e4b-cf853e1de03d}","version":"1.0","type":"extension","loader":null,"updateURL":null,"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":1590522163735,"updateDate":1590522163735,"applyBackgroundUpdates":1,"path":"/tmp/xpc-profile-5wDyOV/extensions/[e-mail]","skinnable":false,"sourceURI":"http://example.com/data/policy_test1.xpi","releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"strictCompatibility":true,"locales":[],"targetApplications":[{"id":"[e-mail]","minVersion":null,"maxVersion":null}],"targetPlatforms":[],"signedState":4,"signedDate":null,"seen":true,"dependencies":[],"incognito":"spanning","userPermissions":{"permissions":[],"origins":[]},"optionalPermissions":{"permissions":[],"origins":[]},"icons":{},"iconURL":null,"blocklistState":0,"blocklistURL":null,"startupData":null,"hidden":false,"installTelemetryInfo":{"source":"enterprise-policy"},"recommendationState":null,"rootURI":"jar:file:///tmp/xpc-profile-5wDyOV/extensions/[e-mail]!/","location":"app-profile"}"
[task 2020-05-26T19:42:44.618Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163764	addons.xpi	DEBUG	Install of http://example.com/data/policy_test1.xpi completed."
[task 2020-05-26T19:42:44.619Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163765	addons.xpi	DEBUG	Loading bootstrap scope from jar:file:///tmp/xpc-profile-5wDyOV/extensions/[e-mail]!/"
[task 2020-05-26T19:42:44.620Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163765	addons.xpi	DEBUG	Calling bootstrap method install on updatable2@test version 1.0"
[task 2020-05-26T19:42:44.621Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163766	addons.xpi	DEBUG	Calling bootstrap method startup on updatable2@test version 1.0"
[task 2020-05-26T19:42:44.622Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163785	addons.xpi	DEBUG	removeTemporaryFile: http://example.com/data/policy_test1.xpi removing temp file /tmp/xpc-profile-5wDyOV/temp/tmp-ibc.xpi"
[task 2020-05-26T19:42:44.623Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163806	addons.xpi	DEBUG	Download started for http://example.com/data/policy_test2.xpi to file /tmp/xpc-profile-5wDyOV/temp/tmp-2km.xpi"
[task 2020-05-26T19:42:44.624Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163807	addons.xpi	DEBUG	Download of http://example.com/data/policy_test2.xpi completed."
[task 2020-05-26T19:42:44.626Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163822	addons.repository	DEBUG	cacheAddons: enabled false IDs ["updatable2@test"]"
[task 2020-05-26T19:42:44.627Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163829	addons.xpi	DEBUG	Starting install of updatable2@test from http://example.com/data/policy_test2.xpi"
[task 2020-05-26T19:42:44.628Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163836	addons.xpi	DEBUG	Addon updatable2@test will be installed as a packed xpi"
[task 2020-05-26T19:42:44.629Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163840	addons.xpi	DEBUG	Calling bootstrap method shutdown on updatable2@test version 1.0"
[task 2020-05-26T19:42:44.630Z] 19:42:44     INFO -  TEST-PASS | browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js | test_newurl_addon_update - [test_newurl_addon_update : 146] Addon 2.0 installed - "2.0" == "2.0"
[task 2020-05-26T19:42:44.631Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163845	addons.xpi-utils	DEBUG	Make addon app-profile:updatable2@test visible"
[task 2020-05-26T19:42:44.632Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163846	addons.xpi	DEBUG	Updating XPIState for {"id":"updatable2@test","syncGUID":"{dccf64be-7964-4c02-8e4b-cf853e1de03d}","version":"2.0","type":"extension","loader":null,"updateURL":null,"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":1590522163000,"updateDate":1590522163822,"applyBackgroundUpdates":1,"path":"/tmp/xpc-profile-5wDyOV/extensions/[e-mail]","skinnable":false,"sourceURI":"http://example.com/data/policy_test2.xpi","releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"strictCompatibility":true,"locales":[],"targetApplications":[{"id":"[e-mail]","minVersion":null,"maxVersion":null}],"targetPlatforms":[],"signedState":4,"signedDate":null,"seen":true,"dependencies":[],"incognito":"spanning","userPermissions":{"permissions":[],"origins":[]},"optionalPermissions":{"permissions":[],"origins":[]},"icons":{},"iconURL":null,"blocklistState":0,"blocklistURL":null,"startupData":null,"hidden":false,"installTelemetryInfo":{"source":"enterprise-policy"},"recommendationState":null,"rootURI":"jar:file:///tmp/xpc-profile-5wDyOV/extensions/[e-mail]!/","location":"app-profile"}"
[task 2020-05-26T19:42:44.634Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163846	addons.xpi	DEBUG	Updating XPIState for {"id":"updatable2@test","syncGUID":"{dccf64be-7964-4c02-8e4b-cf853e1de03d}","version":"2.0","type":"extension","loader":null,"updateURL":null,"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":1590522163000,"updateDate":1590522163822,"applyBackgroundUpdates":1,"path":"/tmp/xpc-profile-5wDyOV/extensions/[e-mail]","skinnable":false,"sourceURI":"http://example.com/data/policy_test2.xpi","releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"strictCompatibility":true,"locales":[],"targetApplications":[{"id":"[e-mail]","minVersion":null,"maxVersion":null}],"targetPlatforms":[],"signedState":4,"signedDate":null,"seen":true,"dependencies":[],"incognito":"spanning","userPermissions":{"permissions":[],"origins":[]},"optionalPermissions":{"permissions":[],"origins":[]},"icons":{},"iconURL":null,"blocklistState":0,"blocklistURL":null,"startupData":null,"hidden":false,"installTelemetryInfo":{"source":"enterprise-policy"},"recommendationState":null,"rootURI":"jar:file:///tmp/xpc-profile-5wDyOV/extensions/[e-mail]!/","location":"app-profile"}"
[task 2020-05-26T19:42:44.635Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163846	addons.xpi	DEBUG	Install of http://example.com/data/policy_test2.xpi completed."
[task 2020-05-26T19:42:44.636Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163847	addons.xpi	DEBUG	Loading bootstrap scope from jar:file:///tmp/xpc-profile-5wDyOV/extensions/[e-mail]!/"
[task 2020-05-26T19:42:44.637Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163848	addons.xpi	DEBUG	Calling bootstrap method update on updatable2@test version 2.0"
[task 2020-05-26T19:42:44.638Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163854	addons.xpi	DEBUG	Calling bootstrap method shutdown on updatable1@test version 2.0"
[task 2020-05-26T19:42:44.639Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163856	addons.manager	DEBUG	before shutdown"
[task 2020-05-26T19:42:44.640Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163857	addons.manager	DEBUG	shutdown"
[task 2020-05-26T19:42:44.641Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163857	addons.manager	DEBUG	Calling shutdown blocker for XPIProvider"
[task 2020-05-26T19:42:44.642Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163857	addons.xpi	DEBUG	shutdown"
[task 2020-05-26T19:42:44.643Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163857	addons.xpi-utils	DEBUG	shutdown"
[task 2020-05-26T19:42:44.644Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163857	addons.manager	DEBUG	Calling shutdown blocker for PluginProvider"
[task 2020-05-26T19:42:44.645Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163871	addons.xpi	DEBUG	Calling bootstrap method startup on updatable2@test version 2.0"
[task 2020-05-26T19:42:44.646Z] 19:42:44     INFO -  (xpcshell/head.js) | test run_next_test 2 pending (2)
[task 2020-05-26T19:42:44.646Z] 19:42:44     INFO -  (xpcshell/head.js) | test test_newurl_addon_update finished (2)
[task 2020-05-26T19:42:44.647Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163877	addons.manager	DEBUG	Async provider shutdown done"
[task 2020-05-26T19:42:44.648Z] 19:42:44     INFO -  (xpcshell/head.js) | test run_next_test 2 finished (1)
[task 2020-05-26T19:42:44.648Z] 19:42:44     INFO -  exiting test
[task 2020-05-26T19:42:44.649Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163887	addons.xpi	DEBUG	removeTemporaryFile: http://example.com/data/policy_test2.xpi removing temp file /tmp/xpc-profile-5wDyOV/temp/tmp-2km.xpi"
[task 2020-05-26T19:42:44.650Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (info) 1590522163887	addons.xpi	WARN	Failed to remove temporary file /tmp/xpc-profile-5wDyOV/temp/tmp-2km.xpi for addon http://example.com/data/policy_test2.xpi: TypeError: flushJarCache is not a function(resource://gre/modules/addons/XPIInstall.jsm:1468:20) JS Stack trace: [e-mail]:1468:20
[task 2020-05-26T19:42:44.651Z] 19:42:44     INFO -  [e-mail]:1840:12
[task 2020-05-26T19:42:44.652Z] 19:42:44     INFO -  async*[e-mail]:1353:14
[task 2020-05-26T19:42:44.652Z] 19:42:44     INFO -  [e-mail]:2147:22
[task 2020-05-26T19:42:44.653Z] 19:42:44     INFO -  [e-mail]:1668:10
[task 2020-05-26T19:42:44.654Z] 19:42:44     INFO -  [e-mail]:1350:14
[task 2020-05-26T19:42:44.654Z] 19:42:44     INFO -  [e-mail]:2147:22
[task 2020-05-26T19:42:44.655Z] 19:42:44     INFO -  checkPrompt/<@XPIInstall.jsm:1639:12
[task 2020-05-26T19:42:44.655Z] 19:42:44     INFO -  async*[e-mail]:1640:7
[task 2020-05-26T19:42:44.656Z] 19:42:44     INFO -  [e-mail]:1347:14
[task 2020-05-26T19:42:44.656Z] 19:42:44     INFO -  [e-mail]:2147:22
[task 2020-05-26T19:42:44.657Z] 19:42:44     INFO -  [e-mail]:2524:12
[task 2020-05-26T19:42:44.657Z] 19:42:44     INFO -  async*onStopRequest/<@XPIInstall.jsm:2433:20
[task 2020-05-26T19:42:44.658Z] 19:42:44     INFO -  [e-mail]:248:6
[task 2020-05-26T19:42:44.658Z] 19:42:44     INFO -  [e-mail]:577:5
[task 2020-05-26T19:42:44.659Z] 19:42:44     INFO -  @-e:1:1"
[task 2020-05-26T19:42:44.659Z] 19:42:44     INFO -  PID 22098 | JavaScript error: resource://gre/modules/addons/XPIInstall.jsm, line 3034: TypeError: getFile is not a function
[task 2020-05-26T19:42:44.660Z] 19:42:44     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "TypeError: getFile is not a function" {file: "resource://gre/modules/addons/XPIInstall.jsm" line: 3034}]"
[task 2020-05-26T19:42:44.660Z] 19:42:44  WARNING -  TEST-UNEXPECTED-FAIL | browser/components/enterprisepolicies/tests/xpcshell/test_addon_update.js | test_newurl_addon_update - [test_newurl_addon_update : 265] A promise chain failed to handle a rejection: getFile is not a function - stack: getStagingDir@resource://gre/modules/addons/XPIInstall.jsm:3034:12
[task 2020-05-26T19:42:44.661Z] 19:42:44     INFO -  cleanStagingDir@resource://gre/modules/addons/XPIInstall.jsm:3075:20
[task 2020-05-26T19:42:44.661Z] 19:42:44     INFO -  releaseStagingDir@resource://gre/modules/addons/XPIInstall.jsm:3060:12
[task 2020-05-26T19:42:44.662Z] 19:42:44     INFO -  startInstall@resource://gre/modules/addons/XPIInstall.jsm:1841:31
[task 2020-05-26T19:42:44.662Z] 19:42:44     INFO -  async*install@resource://gre/modules/addons/XPIInstall.jsm:1353:14
[task 2020-05-26T19:42:44.663Z] 19:42:44     INFO -  install@resource://gre/modules/addons/XPIInstall.jsm:2147:22
[task 2020-05-26T19:42:44.663Z] 19:42:44     INFO -  checkForBlockers@resource://gre/modules/addons/XPIInstall.jsm:1668:10
[task 2020-05-26T19:42:44.664Z] 19:42:44     INFO -  install@resource://gre/modules/addons/XPIInstall.jsm:1350:14
[task 2020-05-26T19:42:44.664Z] 19:42:44     INFO -  install@resource://gre/modules/addons/XPIInstall.jsm:2147:22
[task 2020-05-26T19:42:44.665Z] 19:42:44     INFO -  checkPrompt/<@resource://gre/modules/addons/XPIInstall.jsm:1639:12
[task 2020-05-26T19:42:44.665Z] 19:42:44     INFO -  async*checkPrompt@resource://gre/modules/addons/XPIInstall.jsm:1640:7
[task 2020-05-26T19:42:44.666Z] 19:42:44     INFO -  install@resource://gre/modules/addons/XPIInstall.jsm:1347:14
[task 2020-05-26T19:42:44.666Z] 19:42:44     INFO -  install@resource://gre/modules/addons/XPIInstall.jsm:2147:22
[task 2020-05-26T19:42:44.667Z] 19:42:44     INFO -  downloadCompleted@resource://gre/modules/addons/XPIInstall.jsm:2524:12
[task 2020-05-26T19:42:44.667Z] 19:42:44     INFO -  async*onStopRequest/<@resource://gre/modules/addons/XPIInstall.jsm:2433:20
[task 2020-05-26T19:42:44.668Z] 19:42:44     INFO -  _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:248:6
[task 2020-05-26T19:42:44.668Z] 19:42:44     INFO -  _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:577:5
[task 2020-05-26T19:42:44.669Z] 19:42:44     INFO -  @-e:1:1
[task 2020-05-26T19:42:44.669Z] 19:42:44     INFO -  Rejection date: Tue May 26 2020 19:42:43 GMT+0000 (Coordinated Universal Time) - false == true
[task 2020-05-26T19:42:44.670Z] 19:42:44     INFO -  resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:265
[task 2020-05-26T19:42:44.671Z] 19:42:44     INFO -  /builds/worker/workspace/build/tests/xpcshell/head.js:_execute_test:578
[task 2020-05-26T19:42:44.671Z] 19:42:44     INFO -  -e:null:1
[task 2020-05-26T19:42:44.672Z] 19:42:44     INFO -  exiting test
[task 2020-05-26T19:42:44.673Z] 19:42:44     INFO -  Error: Found unexpected files in temporary directory: tmp-2km.xpi at resource://testing-common/AddonTestUtils.jsm:450
[task 2020-05-26T19:42:44.674Z] 19:42:44     INFO -  init/<@resource://testing-common/AddonTestUtils.jsm:450:15
[task 2020-05-26T19:42:44.674Z] 19:42:44     INFO -  _execute_test/<@/builds/worker/workspace/build/tests/xpcshell/head.js:641:28
[task 2020-05-26T19:42:44.675Z] 19:42:44     INFO -  async*_execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:650:5
[task 2020-05-26T19:42:44.676Z] 19:42:44     INFO -  @-e:1:1
[task 2020-05-26T19:42:44.677Z] 19:42:44     INFO -  PID 22098 | [22098, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-05-26T19:42:44.677Z] 19:42:44     INFO -  PID 22098 | [22098, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp, line 202
[task 2020-05-26T19:42:44.678Z] 19:42:44     INFO -  PID 22098 | [22098, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp, line 202
[task 2020-05-26T19:42:44.679Z] 19:42:44     INFO -  <<<<<<<

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/1e8ef1bb4ce8
Shutdown AddonManager at end of test. r=mixedpuppy

Comment 13

[Razvan Maries]

https://hg.mozilla.org/mozilla-central/rev/1e8ef1bb4ce8

Comment 14

[Intermittent Failures Robot]

2 failures in 5458 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform breakdown:

• linux1804-64: 1
• linux1804-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1637716&startday=2020-05-25&endday=2020-05-31&tree=all