Closed Bug 1087110 Opened 10 years ago Closed 9 years ago

Intermittent browser_experiments.js | A promise chain failed to handle a rejection: - at resource://app/modules/experiments/Experiments.jsm:876 - Error: uninit() alrady called

Categories

(Firefox Health Report Graveyard :: Client: Desktop, defect)

x86_64
Linux
defect
Not set
normal

Tracking

(firefox36 wontfix, firefox37 wontfix, firefox38 fixed, firefox39 fixed, firefox-esr31 unaffected)

RESOLVED FIXED
Firefox 39
Tracking Status
firefox36 --- wontfix
firefox37 --- wontfix
firefox38 --- fixed
firefox39 --- fixed
firefox-esr31 --- unaffected

People

(Reporter: RyanVM, Assigned: Yoric)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

https://treeherder.mozilla.org/ui/logviewer.html#?job_id=337610&repo=mozilla-aurora

builder 	Ubuntu VM 12.04 x64 mozilla-aurora pgo test mochitest-browser-chrome-3
buildid 	20141021110545
builduid 	232506cdf3f4477085eabe791e0c81f1
results 	warnings (1)
revision 	7e151ae385b9
slave 		tst-linux64-spot-160
starttime 	Tue Oct 21 2014 17:43:57 GMT-0400 (Eastern Standard Time)

14:54:36 INFO - 1413928476560 Browser.Experiments.Experiments TRACE Experiments #0::_main iteration
14:54:36 INFO - 1413928476561 Browser.Experiments.Experiments TRACE Experiments #0::_evaluateExperiments
14:54:36 INFO - 1413928476564 Browser.Experiments.Experiments TRACE ExperimentEntry #5::isApplicable() - now=1413928476.564, randomValue=0.6159184771708407, data={"id":"experiment-2","xpiURL":"http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi","xpiHash":"IRRELEVANT","startTime":1413924876.34,"endTime":1413932076.34,"maxActiveSeconds":600,"appName":["Firefox"],"channel":["default"]}
14:54:36 INFO - 1413928476566 Browser.Experiments.Experiments TRACE ExperimentEntry #5::stop() - id=experiment-2, terminationKind=experiment-2
14:54:36 INFO - 1413928476567 Browser.Experiments.Experiments TRACE ExperimentEntry #5::reconcileAddonState()
14:54:36 INFO - 1413928476568 Browser.Experiments.Experiments INFO ExperimentEntry #5::reconcileAddonState() - Uninstalling add-on for inactive experiment: test-experiment1@experiments.mozilla.org
14:54:36 INFO - 1413928476572 addons.xpi WARN Add-on test-experiment1@experiments.mozilla.org is missing bootstrap method shutdown
14:54:36 INFO - 1413928476572 addons.xpi DEBUG Removing manifest for /tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi
14:54:36 INFO - 1413928476580 addons.xpi WARN Add-on test-experiment1@experiments.mozilla.org is missing bootstrap method uninstall
14:54:36 INFO - 1413928476582 addons.xpi DEBUG uninstallAddon: flushing jar cache /tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi for addon test-experiment1@experiments.mozilla.org
14:54:36 INFO - 1413928476583 DeferredSave.extensions.json DEBUG Save changes
14:54:36 INFO - 1413928476584 DeferredSave.extensions.json DEBUG Data changed while write in progress
14:54:36 INFO - 1413928476585 addons.xpi DEBUG Removing XPIState for app-profile:test-experiment1@experiments.mozilla.org
14:54:36 INFO - 1413928476588 Browser.Experiments.Experiments TRACE Experiments #0::onUninstalled() - addon id: test-experiment1@experiments.mozilla.org
14:54:36 INFO - 1413928476589 Browser.Experiments.Experiments TRACE Experiments #0::matches pending uninstall
14:54:36 INFO - 1413928476595 Browser.Experiments.Experiments WARN ExperimentEntry #5::stop() - unknown terminationKind experiment-2
14:54:36 INFO - 1413928476596 Browser.Experiments.Experiments TRACE ExperimentEntry #5::isApplicable() - now=1413928476.596, randomValue=0.6159184771708407, data={"id":"experiment-2","xpiURL":"http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi","xpiHash":"IRRELEVANT","startTime":1413924876.34,"endTime":1413932076.34,"maxActiveSeconds":600,"appName":["Firefox"],"channel":["default"]}
14:54:36 INFO - 1413928476598 Browser.Experiments.Experiments TRACE ExperimentEntry #4::isApplicable() - now=1413928476.598, randomValue=0.9051111768413012, data={"id":"experiment-1","xpiURL":"http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi","xpiHash":"IRRELEVANT","startTime":1413924875.533,"endTime":1413932075.533,"maxActiveSeconds":600,"appName":["Firefox"],"channel":["default"]}
14:54:36 INFO - 1413928476601 Browser.Experiments.Experiments TRACE PreviousExperimentProvider #3::updateExperimentList() - adding experiment-2
14:54:36 INFO - 1413928476612 Browser.Experiments.Experiments TRACE Experiments #0::_saveToCache
14:54:36 INFO - 1413928476785 DeferredSave.extensions.json DEBUG Write succeeded
14:54:36 INFO - 1413928476788 DeferredSave.extensions.json DEBUG Starting timer
14:54:36 INFO - 1413928476799 Browser.Experiments.Experiments DEBUG Experiments #0::_saveToCache saved to /tmp/tmpT2ehgm.mozrunner/experiments.json
14:54:36 INFO - 1413928476802 Browser.Experiments.Experiments TRACE Experiments #0::_main finished, scheduling next run
14:54:36 INFO - 1413928476804 Browser.Experiments.Experiments TRACE Experiments #0::_updateExperiments() - experiments: {"version":1,"experiments":[{"id":"experiment-3","xpiURL":"http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi","xpiHash":"IRRELEVANT","startTime":1413410076.803,"endTime":1414792476.803,"maxActiveSeconds":8640000,"appName":["Firefox"],"channel":["default"]}]}
14:54:36 INFO - 1413928476805 Browser.Experiments.Experiments TRACE ExperimentEntry #6::isManifestDataValid() - data: {"id":"experiment-3","xpiURL":"http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi","xpiHash":"IRRELEVANT","startTime":1413410076.803,"endTime":1414792476.803,"maxActiveSeconds":8640000,"appName":["Firefox"],"channel":["default"]}
14:54:36 INFO - 1413928476806 Browser.Experiments.Experiments TRACE Experiments #0::_run
14:54:36 INFO - 1413928476807 Browser.Experiments.Experiments TRACE Experiments #0::_main iteration
14:54:36 INFO - 1413928476808 Browser.Experiments.Experiments TRACE Experiments #0::_evaluateExperiments
14:54:36 INFO - 1413928476810 Browser.Experiments.Experiments TRACE ExperimentEntry #6::isApplicable() - now=1413496476.803, randomValue=0.06821292060147821, data={"id":"experiment-3","xpiURL":"http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi","xpiHash":"IRRELEVANT","startTime":1413410076.803,"endTime":1414792476.803,"maxActiveSeconds":8640000,"appName":["Firefox"],"channel":["default"]}
14:54:36 INFO - 1413928476812 Browser.Experiments.Experiments DEBUG Experiments #0::evaluateExperiments() - activating experiment experiment-3
14:54:36 INFO - 1413928476812 Browser.Experiments.Experiments TRACE ExperimentEntry #6::start() for experiment-3
14:54:36 INFO - 1413928476813 Browser.Experiments.Experiments TRACE ExperimentEntry #6::reconcileAddonState()
14:54:36 INFO - 1413928476814 Browser.Experiments.Experiments INFO ExperimentEntry #6::reconcileAddonState() - Installing add-on.
14:54:36 INFO - 1413928476827 DeferredSave.extensions.json DEBUG Starting write
14:54:36 INFO - 1413928476834 addons.xpi DEBUG Download started for http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi to file /tmp/tmp-u2s.xpi
14:54:36 INFO - 1413928476836 addons.xpi DEBUG Download of http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi completed.
14:54:36 INFO - 1413928476840 addons.repository DEBUG cacheAddons: enabled false IDs ["test-experiment1@experiments.mozilla.org"]
14:54:36 INFO - 1413928476842 Browser.Experiments.Experiments TRACE ExperimentEntry #6::_installAddon() - onDownloadEnded for experiment-3
14:54:36 INFO - 1413928476844 Browser.Experiments.Experiments TRACE ExperimentEntry #6::_installAddon() - onInstallStarted for experiment-3
14:54:36 INFO - 1413928476851 Browser.Experiments.Experiments TRACE Experiments #0::onInstallStarted() - test-experiment1@experiments.mozilla.org
14:54:36 INFO - 1413928476852 Browser.Experiments.Experiments INFO Experiments #0::onInstallStarted allowing install because add-on ID tracked by us.
14:54:36 INFO - 1413928476853 addons.xpi DEBUG Starting install of test-experiment1@experiments.mozilla.org from http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi
14:54:36 INFO - 1413928476863 DeferredSave.extensions.json DEBUG Write succeeded
14:54:36 INFO - 1413928476885 addons.xpi DEBUG Addon test-experiment1@experiments.mozilla.org will be installed as a packed xpi
14:54:36 INFO - 1413928476901 addons.xpi INFO Mapping test-experiment1@experiments.mozilla.org to /tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi
14:54:36 INFO - 1413928476903 addons.xpi-utils DEBUG Make addon app-profile:test-experiment1@experiments.mozilla.org visible
14:54:36 INFO - 1413928476904 DeferredSave.extensions.json DEBUG Save changes
14:54:36 INFO - 1413928476905 DeferredSave.extensions.json DEBUG Save changes
14:54:36 INFO - 1413928476906 addons.xpi DEBUG XPIStates adding add-on test-experiment1@experiments.mozilla.org in app-profile: /tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi
14:54:36 INFO - 1413928476906 addons.xpi DEBUG Updating XPIState for {"id":"test-experiment1@experiments.mozilla.org","syncGUID":"9fo42QERdZ7x","location":"app-profile","version":"1.0","type":"experiment","internalName":null,"updateURL":null,"updateKey":null,"optionsURL":null,"optionsType":null,"aboutURL":null,"iconURL":null,"icon64URL":null,"defaultLocale":{"name":"Test Experiment 1","description":"Test Description","creator":null,"homepageURL":null},"visible":true,"active":false,"userDisabled":true,"appDisabled":false,"descriptor":"/tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi","installDate":1413928476842,"updateDate":1413928476842,"applyBackgroundUpdates":0,"bootstrap":true,"size":460,"sourceURI":"http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi","releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"hasBinaryComponents":false,"strictCompatibility":true,"locales":[],"targetApplications":[],"targetPlatforms":[]}
14:54:36 INFO - 1413928476906 addons.xpi DEBUG getModTime: Recursive scan of test-experiment1@experiments.mozilla.org
14:54:36 INFO - 1413928476907 DeferredSave.extensions.json DEBUG Save changes
14:54:36 INFO - 1413928476907 DeferredSave.extensions.json DEBUG Save changes
14:54:36 INFO - 1413928476912 addons.xpi DEBUG Loading bootstrap scope from /tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi
14:54:36 INFO - 1413928476914 addons.xpi WARN Error loading bootstrap.js for test-experiment1@experiments.mozilla.org: Error opening input stream (invalid filename?)
14:54:36 INFO - 1413928476918 addons.xpi WARN Add-on test-experiment1@experiments.mozilla.org is missing bootstrap method install
14:54:36 INFO - 1413928476920 addons.xpi DEBUG Install of http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi completed.
14:54:36 INFO - 1413928476921 Browser.Experiments.Experiments TRACE ExperimentEntry #6::_installAddon() - install ended for experiment-3
14:54:36 INFO - 1413928476923 Browser.Experiments.Experiments TRACE ExperimentEntry #6::Add-on is disabled. Enabling.
14:54:36 INFO - 1413928476924 addons.xpi-utils DEBUG Updating active state for add-on test-experiment1@experiments.mozilla.org to true
14:54:36 INFO - 1413928476925 DeferredSave.extensions.json DEBUG Save changes
14:54:36 INFO - 1413928476926 addons.xpi DEBUG Registering manifest for /tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi
14:54:36 INFO - 1413928476927 addons.xpi WARN Add-on test-experiment1@experiments.mozilla.org is missing bootstrap method startup
14:54:36 INFO - 1413928476928 Browser.Experiments.Experiments INFO ExperimentEntry #6::onEnabled() for test-experiment1@experiments.mozilla.org
14:54:36 INFO - 1413928476929 addons.xpi DEBUG Updating XPIState for {"id":"test-experiment1@experiments.mozilla.org","syncGUID":"9fo42QERdZ7x","location":"app-profile","version":"1.0","type":"experiment","internalName":null,"updateURL":null,"updateKey":null,"optionsURL":null,"optionsType":null,"aboutURL":null,"iconURL":null,"icon64URL":null,"defaultLocale":{"name":"Test Experiment 1","description":"Test Description","creator":null,"homepageURL":null},"visible":true,"active":true,"userDisabled":true,"appDisabled":false,"descriptor":"/tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi","installDate":1413928476000,"updateDate":1413928476000,"applyBackgroundUpdates":0,"bootstrap":true,"size":460,"sourceURI":"http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi","releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"hasBinaryComponents":false,"strictCompatibility":true,"locales":[],"targetApplications":[],"targetPlatforms":[]}
14:54:36 INFO - 1413928476931 addons.xpi DEBUG Registering manifest for /tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi
14:54:36 INFO - 1413928476932 addons.xpi WARN Add-on test-experiment1@experiments.mozilla.org is missing bootstrap method startup
14:54:36 INFO - 1413928476933 DeferredSave.extensions.json DEBUG Starting timer
14:54:36 INFO - 1413928476951 addons.xpi DEBUG removeTemporaryFile: http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi removing temp file /tmp/tmp-u2s.xpi
14:54:36 INFO - 1413928476954 Browser.Experiments.Experiments TRACE Experiments #0::_saveToCache
14:54:36 INFO - 1413928476997 DeferredSave.extensions.json DEBUG Starting write
14:54:37 INFO - 1413928477000 Browser.Experiments.Experiments DEBUG Experiments #0::_saveToCache saved to /tmp/tmpT2ehgm.mozrunner/experiments.json
14:54:37 INFO - 1413928477003 Browser.Experiments.Experiments TRACE Experiments #0::_main finished, scheduling next run
14:54:37 INFO - 1413928477004 Browser.Experiments.Experiments TRACE Experiments #0::scheduleExperimentEvaluation() - scheduling for 1413928476093, now: 1413496476803
14:54:37 INFO - 1413928477010 Browser.Experiments.Experiments TRACE Experiments #0::disableExperiment()
14:54:37 INFO - 1413928477011 Browser.Experiments.Experiments TRACE Experiments #0::_run
14:54:37 INFO - 1413928477012 Browser.Experiments.Experiments TRACE Experiments #0::_main iteration
14:54:37 INFO - 1413928477014 Browser.Experiments.Experiments TRACE Experiments #0::_evaluateExperiments
14:54:37 INFO - 1413928477018 Browser.Experiments.Experiments TRACE ExperimentEntry #6::isApplicable() - now=1413496476.803, randomValue=0.06821292060147821, data={"id":"experiment-3","xpiURL":"http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi","xpiHash":"IRRELEVANT","startTime":1413410076.803,"endTime":1414792476.803,"maxActiveSeconds":8640000,"appName":["Firefox"],"channel":["default"]}
14:54:37 INFO - 1413928477019 Browser.Experiments.Experiments TRACE ExperimentEntry #6::stop() - id=experiment-3, terminationKind=experiment-3
14:54:37 INFO - 1413928477020 Browser.Experiments.Experiments TRACE ExperimentEntry #6::reconcileAddonState()
14:54:37 INFO - 1413928477022 Browser.Experiments.Experiments INFO ExperimentEntry #6::reconcileAddonState() - Uninstalling add-on for inactive experiment: test-experiment1@experiments.mozilla.org
14:54:37 INFO - 1413928477025 addons.xpi WARN Add-on test-experiment1@experiments.mozilla.org is missing bootstrap method shutdown
14:54:37 INFO - 1413928477026 addons.xpi DEBUG Removing manifest for /tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi
14:54:37 INFO - 1413928477034 addons.xpi WARN Add-on test-experiment1@experiments.mozilla.org is missing bootstrap method uninstall
14:54:37 INFO - 1413928477036 addons.xpi DEBUG uninstallAddon: flushing jar cache /tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi for addon test-experiment1@experiments.mozilla.org
14:54:37 INFO - 1413928477037 DeferredSave.extensions.json DEBUG Save changes
14:54:37 INFO - 1413928477038 DeferredSave.extensions.json DEBUG Data changed while write in progress
14:54:37 INFO - 1413928477039 addons.xpi DEBUG Removing XPIState for app-profile:test-experiment1@experiments.mozilla.org
14:54:37 INFO - 1413928477042 Browser.Experiments.Experiments TRACE Experiments #0::onUninstalled() - addon id: test-experiment1@experiments.mozilla.org
14:54:37 INFO - 1413928477043 Browser.Experiments.Experiments TRACE Experiments #0::matches pending uninstall
14:54:37 INFO - 1413928477054 Browser.Experiments.Experiments WARN ExperimentEntry #6::stop() - unknown terminationKind experiment-3
14:54:37 INFO - 1413928477056 Browser.Experiments.Experiments TRACE ExperimentEntry #6::isApplicable() - now=1413496476.803, randomValue=0.06821292060147821, data={"id":"experiment-3","xpiURL":"http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi","xpiHash":"IRRELEVANT","startTime":1413410076.803,"endTime":1414792476.803,"maxActiveSeconds":8640000,"appName":["Firefox"],"channel":["default"]}
14:54:37 INFO - 1413928477058 Browser.Experiments.Experiments TRACE ExperimentEntry #5::isApplicable() - now=1413496476.803, randomValue=0.6159184771708407, data={"id":"experiment-2","xpiURL":"http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi","xpiHash":"IRRELEVANT","startTime":1413924876.34,"endTime":1413932076.34,"maxActiveSeconds":600,"appName":["Firefox"],"channel":["default"]}
14:54:37 INFO - 1413928477059 Browser.Experiments.Experiments TRACE ExperimentEntry #4::isApplicable() - now=1413496476.803, randomValue=0.9051111768413012, data={"id":"experiment-1","xpiURL":"http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi","xpiHash":"IRRELEVANT","startTime":1413924875.533,"endTime":1413932075.533,"maxActiveSeconds":600,"appName":["Firefox"],"channel":["default"]}
14:54:37 INFO - 1413928477061 Browser.Experiments.Experiments TRACE PreviousExperimentProvider #3::updateExperimentList() - adding experiment-3
14:54:37 INFO - 1413928477073 Browser.Experiments.Experiments TRACE Experiments #0::_saveToCache
14:54:37 INFO - 1413928477246 DeferredSave.extensions.json DEBUG Write succeeded
14:54:37 INFO - 1413928477249 DeferredSave.extensions.json DEBUG Starting timer
14:54:37 INFO - 1413928477290 Browser.Experiments.Experiments DEBUG Experiments #0::_saveToCache saved to /tmp/tmpT2ehgm.mozrunner/experiments.json
14:54:37 INFO - 1413928477291 Browser.Experiments.Experiments TRACE Experiments #0::_main finished, scheduling next run
14:54:37 INFO - 1413928477293 Browser.Experiments.Experiments TRACE Experiments #0::scheduleExperimentEvaluation() - scheduling for 1413928476093, now: 1413496476803
14:54:37 INFO - 1413928477300 Browser.Experiments.Experiments TRACE Experiments #0::_updateExperiments() - experiments: {"version":1,"experiments":[{"id":"experiment-4","xpiURL":"http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi","xpiHash":"IRRELEVANT","startTime":1413924877.3,"endTime":1413932077.3,"maxActiveSeconds":600,"appName":["Firefox"],"channel":["default"]}]}
14:54:37 INFO - 1413928477301 Browser.Experiments.Experiments TRACE ExperimentEntry #7::isManifestDataValid() - data: {"id":"experiment-4","xpiURL":"http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi","xpiHash":"IRRELEVANT","startTime":1413924877.3,"endTime":1413932077.3,"maxActiveSeconds":600,"appName":["Firefox"],"channel":["default"]}
14:54:37 INFO - 1413928477303 Browser.Experiments.Experiments TRACE Experiments #0::_run
14:54:37 INFO - 1413928477304 Browser.Experiments.Experiments TRACE Experiments #0::_main iteration
14:54:37 INFO - 1413928477306 Browser.Experiments.Experiments TRACE Experiments #0::_evaluateExperiments
14:54:37 INFO - 1413928477309 Browser.Experiments.Experiments TRACE ExperimentEntry #7::isApplicable() - now=1413928477.3, randomValue=0.15339392739459712, data={"id":"experiment-4","xpiURL":"http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi","xpiHash":"IRRELEVANT","startTime":1413924877.3,"endTime":1413932077.3,"maxActiveSeconds":600,"appName":["Firefox"],"channel":["default"]}
14:54:37 INFO - 1413928477311 Browser.Experiments.Experiments DEBUG Experiments #0::evaluateExperiments() - activating experiment experiment-4
14:54:37 INFO - 1413928477312 Browser.Experiments.Experiments TRACE ExperimentEntry #7::start() for experiment-4
14:54:37 INFO - 1413928477313 Browser.Experiments.Experiments TRACE ExperimentEntry #7::reconcileAddonState()
14:54:37 INFO - 1413928477314 Browser.Experiments.Experiments INFO ExperimentEntry #7::reconcileAddonState() - Installing add-on.
14:54:37 INFO - 1413928477320 DeferredSave.extensions.json DEBUG Starting write
14:54:37 INFO - 1413928477336 addons.xpi DEBUG Download started for http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi to file /tmp/tmp-r4j.xpi
14:54:37 INFO - 1413928477338 addons.xpi DEBUG Download of http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi completed.
14:54:37 INFO - 1413928477344 addons.repository DEBUG cacheAddons: enabled false IDs ["test-experiment1@experiments.mozilla.org"]
14:54:37 INFO - 1413928477346 Browser.Experiments.Experiments TRACE ExperimentEntry #7::_installAddon() - onDownloadEnded for experiment-4
14:54:37 INFO - 1413928477347 Browser.Experiments.Experiments TRACE ExperimentEntry #7::_installAddon() - onInstallStarted for experiment-4
14:54:37 INFO - 1413928477353 Browser.Experiments.Experiments TRACE Experiments #0::onInstallStarted() - test-experiment1@experiments.mozilla.org
14:54:37 INFO - 1413928477354 Browser.Experiments.Experiments INFO Experiments #0::onInstallStarted allowing install because add-on ID tracked by us.
14:54:37 INFO - 1413928477355 addons.xpi DEBUG Starting install of test-experiment1@experiments.mozilla.org from http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi
14:54:37 INFO - 1413928477358 DeferredSave.extensions.json DEBUG Write succeeded
14:54:37 INFO - 1413928477379 addons.xpi DEBUG Addon test-experiment1@experiments.mozilla.org will be installed as a packed xpi
14:54:37 INFO - 1413928477437 addons.xpi INFO Mapping test-experiment1@experiments.mozilla.org to /tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi
14:54:37 INFO - 1413928477439 addons.xpi-utils DEBUG Make addon app-profile:test-experiment1@experiments.mozilla.org visible
14:54:37 INFO - 1413928477440 DeferredSave.extensions.json DEBUG Save changes
14:54:37 INFO - 1413928477441 DeferredSave.extensions.json DEBUG Save changes
14:54:37 INFO - 1413928477442 addons.xpi DEBUG XPIStates adding add-on test-experiment1@experiments.mozilla.org in app-profile: /tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi
14:54:37 INFO - 1413928477443 addons.xpi DEBUG Updating XPIState for {"id":"test-experiment1@experiments.mozilla.org","syncGUID":"glRVpfAv_-4_","location":"app-profile","version":"1.0","type":"experiment","internalName":null,"updateURL":null,"updateKey":null,"optionsURL":null,"optionsType":null,"aboutURL":null,"iconURL":null,"icon64URL":null,"defaultLocale":{"name":"Test Experiment 1","description":"Test Description","creator":null,"homepageURL":null},"visible":true,"active":false,"userDisabled":true,"appDisabled":false,"descriptor":"/tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi","installDate":1413928477346,"updateDate":1413928477346,"applyBackgroundUpdates":0,"bootstrap":true,"size":460,"sourceURI":"http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi","releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"hasBinaryComponents":false,"strictCompatibility":true,"locales":[],"targetApplications":[],"targetPlatforms":[]}
14:54:37 INFO - 1413928477444 addons.xpi DEBUG getModTime: Recursive scan of test-experiment1@experiments.mozilla.org
14:54:37 INFO - 1413928477445 DeferredSave.extensions.json DEBUG Save changes
14:54:37 INFO - 1413928477446 DeferredSave.extensions.json DEBUG Save changes
14:54:37 INFO - 1413928477448 addons.xpi DEBUG Loading bootstrap scope from /tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi
14:54:37 INFO - 1413928477451 addons.xpi WARN Error loading bootstrap.js for test-experiment1@experiments.mozilla.org: Error opening input stream (invalid filename?)
14:54:37 INFO - 1413928477452 addons.xpi WARN Add-on test-experiment1@experiments.mozilla.org is missing bootstrap method install
14:54:37 INFO - 1413928477454 addons.xpi DEBUG Install of http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi completed.
14:54:37 INFO - 1413928477455 Browser.Experiments.Experiments TRACE ExperimentEntry #7::_installAddon() - install ended for experiment-4
14:54:37 INFO - 1413928477457 Browser.Experiments.Experiments TRACE ExperimentEntry #7::Add-on is disabled. Enabling.
14:54:37 INFO - 1413928477458 addons.xpi-utils DEBUG Updating active state for add-on test-experiment1@experiments.mozilla.org to true
14:54:37 INFO - 1413928477459 DeferredSave.extensions.json DEBUG Save changes
14:54:37 INFO - 1413928477460 addons.xpi DEBUG Registering manifest for /tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi
14:54:37 INFO - 1413928477461 addons.xpi WARN Add-on test-experiment1@experiments.mozilla.org is missing bootstrap method startup
14:54:37 INFO - 1413928477462 Browser.Experiments.Experiments INFO ExperimentEntry #7::onEnabled() for test-experiment1@experiments.mozilla.org
14:54:37 INFO - 1413928477463 addons.xpi DEBUG Updating XPIState for {"id":"test-experiment1@experiments.mozilla.org","syncGUID":"glRVpfAv_-4_","location":"app-profile","version":"1.0","type":"experiment","internalName":null,"updateURL":null,"updateKey":null,"optionsURL":null,"optionsType":null,"aboutURL":null,"iconURL":null,"icon64URL":null,"defaultLocale":{"name":"Test Experiment 1","description":"Test Description","creator":null,"homepageURL":null},"visible":true,"active":true,"userDisabled":true,"appDisabled":false,"descriptor":"/tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi","installDate":1413928477000,"updateDate":1413928477000,"applyBackgroundUpdates":0,"bootstrap":true,"size":460,"sourceURI":"http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi","releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"hasBinaryComponents":false,"strictCompatibility":true,"locales":[],"targetApplications":[],"targetPlatforms":[]}
14:54:37 INFO - 1413928477465 addons.xpi DEBUG Registering manifest for /tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi
14:54:37 INFO - 1413928477466 addons.xpi WARN Add-on test-experiment1@experiments.mozilla.org is missing bootstrap method startup
14:54:37 INFO - 1413928477467 DeferredSave.extensions.json DEBUG Starting timer
14:54:37 INFO - 1413928477482 addons.xpi DEBUG removeTemporaryFile: http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi removing temp file /tmp/tmp-r4j.xpi
14:54:37 INFO - 1413928477486 Browser.Experiments.Experiments TRACE Experiments #0::_saveToCache
14:54:37 INFO - 1413928477532 DeferredSave.extensions.json DEBUG Starting write
14:54:37 INFO - 1413928477536 Browser.Experiments.Experiments DEBUG Experiments #0::_saveToCache saved to /tmp/tmpT2ehgm.mozrunner/experiments.json
14:54:37 INFO - 1413928477539 Browser.Experiments.Experiments TRACE Experiments #0::_main finished, scheduling next run
14:54:37 INFO - 1413928477540 Browser.Experiments.Experiments TRACE Experiments #0::scheduleExperimentEvaluation() - scheduling for 1413929077300, now: 1413928477300
14:54:37 INFO - 1413928477768 addons.xpi DEBUG Updating XPIState for {"id":"test-experiment1@experiments.mozilla.org","syncGUID":"glRVpfAv_-4_","location":"app-profile","version":"1.0","type":"experiment","internalName":null,"updateURL":null,"updateKey":null,"optionsURL":null,"optionsType":null,"aboutURL":null,"iconURL":null,"icon64URL":null,"defaultLocale":{"name":"Test Experiment 1","description":"Test Description","creator":null,"homepageURL":null},"visible":true,"active":true,"userDisabled":true,"appDisabled":false,"descriptor":"/tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi","installDate":1413928477000,"updateDate":1413928477000,"applyBackgroundUpdates":0,"bootstrap":true,"size":460,"sourceURI":"http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi","releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"hasBinaryComponents":false,"strictCompatibility":true,"locales":[],"targetApplications":[],"targetPlatforms":[]}
14:54:37 INFO - 1413928477775 Browser.Experiments.Experiments TRACE Experiments #0::updateManifest()
14:54:37 INFO - 1413928477775 Browser.Experiments.Experiments TRACE Experiments #0::_run
14:54:37 INFO - 1413928477777 Browser.Experiments.Experiments TRACE Experiments #0::_main iteration
14:54:37 INFO - 1413928477778 Browser.Experiments.Experiments TRACE Experiments #0::_loadManifest
14:54:37 INFO - 1413928477779 Browser.Experiments.Experiments TRACE Experiments #0::httpGetRequest(http://127.0.0.1:8888/experiments-dummy/manifest)
14:54:37 INFO - 1413928477856 DeferredSave.extensions.json DEBUG Write succeeded
14:54:37 INFO - 1413928477863 Browser.Experiments.Experiments ERROR Experiments #0::httpGetRequest::onLoad() - Request to http://127.0.0.1:8888/experiments-dummy/manifest returned status 404
14:54:37 INFO - 1413928477866 Browser.Experiments.Experiments ERROR Experiments #0::_loadManifest - failure to fetch/parse manifest (continuing anyway): Error: Experiments - XHR status for http://127.0.0.1:8888/experiments-dummy/manifest is 404
14:54:37 INFO - 1413928477867 Browser.Experiments.Experiments TRACE Experiments #0::_evaluateExperiments
14:54:37 INFO - 1413928477871 Browser.Experiments.Experiments TRACE ExperimentEntry #7::isApplicable() - now=1413928477.3, randomValue=0.15339392739459712, data={"id":"experiment-4","xpiURL":"http://example.com/browser/toolkit/mozapps/extensions/test/browser/addons/browser_experiment1.xpi","xpiHash":"IRRELEVANT","startTime":1413924877.3,"endTime":1413932077.3,"maxActiveSeconds":600,"appName":["Firefox"],"channel":["default"]}
14:54:37 INFO - 1413928477872 Browser.Experiments.Experiments TRACE Experiments #0::uninit: started
14:54:37 INFO - 1413928477872 Browser.Experiments.Experiments TRACE Experiments #0::uninit: finished with _loadTask
14:54:37 INFO - 1413928477872 Browser.Experiments.Experiments TRACE Experiments #0::uninit: no previous shutdown
14:54:37 INFO - 1413928477874 Browser.Experiments.Experiments TRACE Experiments #0::Unregistering instance with Addon Manager.
14:54:37 INFO - 1413928477875 Browser.Experiments.Experiments TRACE Experiments #0::Removing install listener from add-on manager.
14:54:37 INFO - 1413928477875 Browser.Experiments.Experiments TRACE Experiments #0::Removing addon listener from add-on manager.
14:54:37 INFO - 1413928477875 Browser.Experiments.Experiments TRACE Experiments #0::Finished unregistering with addon manager.
14:54:37 INFO - 1413928477875 Browser.Experiments.Experiments TRACE Experiments #0::Unregistering previous experiment add-on provider.
14:54:37 INFO - 1413928477879 addons.manager DEBUG Unregistering shutdown blocker for PreviousExperimentProvider
14:54:37 INFO - 1413928477880 addons.manager DEBUG Calling shutdown blocker for PreviousExperimentProvider
14:54:37 INFO - 1413928477880 Browser.Experiments.Experiments TRACE PreviousExperimentProvider #3::shutdown()
14:54:37 INFO - 1413928477883 Browser.Experiments.Experiments TRACE Experiments #0::uninit: waiting on _mainTask
14:54:37 INFO - 1413928477884 Browser.Experiments.Experiments TRACE ExperimentEntry #7::reconcileAddonState()
14:54:37 INFO - 1413928477886 Browser.Experiments.Experiments TRACE Experiments #0::_main finished, scheduling next run
14:54:37 INFO - 1413928477887 Browser.Experiments.Experiments INFO Experiments #0::Completed uninitialization.
14:54:37 INFO - 1413928477888 Browser.Experiments.Experiments TRACE Experiments #0::enabled=true, true
14:54:37 INFO - 1413928477891 Browser.Experiments.Experiments TRACE Experiments #0::Registering instance with Addon Manager.
14:54:37 INFO - 1413928477892 Browser.Experiments.Experiments TRACE Experiments #0::Registering previous experiment add-on provider.
14:54:37 INFO - 1413928477893 Browser.Experiments.Experiments TRACE PreviousExperimentProvider #4::startup()
14:54:37 INFO - 1413928477894 addons.manager DEBUG Registering shutdown blocker for PreviousExperimentProvider
14:54:37 INFO - 1413928477896 Browser.Experiments.Experiments TRACE Experiments #0::_loadFromCache
14:54:37 INFO - 1413928477913 Browser.Experiments.Experiments TRACE Experiments #0::_loadTask finished ok
14:54:37 INFO - 1413928477914 Browser.Experiments.Experiments TRACE Experiments #0::_run
14:54:37 INFO - 1413928477916 Browser.Experiments.Experiments TRACE Experiments #0::_main iteration
14:54:37 INFO - 1413928477917 Browser.Experiments.Experiments TRACE Experiments #0::_evaluateExperiments
14:54:37 INFO - 1413928477919 Browser.Experiments.Experiments WARN Experiments #0::_evaluateExperiments() - unknown add-ons in AddonManager: test-experiment1@experiments.mozilla.org
14:54:37 INFO - 1413928477923 addons.xpi WARN Add-on test-experiment1@experiments.mozilla.org is missing bootstrap method shutdown
14:54:37 INFO - 1413928477924 addons.xpi DEBUG Removing manifest for /tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi
14:54:37 INFO - 1413928477932 addons.xpi WARN Add-on test-experiment1@experiments.mozilla.org is missing bootstrap method uninstall
14:54:37 INFO - 1413928477934 addons.xpi DEBUG uninstallAddon: flushing jar cache /tmp/tmpT2ehgm.mozrunner/extensions/test-experiment1@experiments.mozilla.org.xpi for addon test-experiment1@experiments.mozilla.org
14:54:37 INFO - 1413928477936 DeferredSave.extensions.json DEBUG Save changes
14:54:37 INFO - 1413928477937 addons.xpi DEBUG Removing XPIState for app-profile:test-experiment1@experiments.mozilla.org
14:54:37 INFO - 1413928477940 Browser.Experiments.Experiments TRACE Experiments #0::onUninstalled() - addon id: test-experiment1@experiments.mozilla.org
14:54:37 INFO - 1413928477941 DeferredSave.extensions.json DEBUG Starting timer
14:54:37 INFO - 1413928477948 Browser.Experiments.Experiments TRACE Experiments #0::_main finished, scheduling next run
14:54:38 INFO - Manager window unload handler
14:54:38 INFO - 1413928478304 DeferredSave.extensions.json DEBUG Starting write
14:54:38 INFO - 519 INFO TEST-OK | chrome://mochitests/content/browser/toolkit/mozapps/extensions/test/browser/test-window/browser_experiments.js | took 3627ms
David, do you have time to look at this?
Flags: needinfo?(dteller)
Let's try this.
Flags: needinfo?(dteller)
Attachment #8575251 - Flags: review?(gfritzsche)
Georg?
Flags: needinfo?(gfritzsche)
Checking.
Flags: needinfo?(gfritzsche)
Comment on attachment 8575251 [details] [diff] [review]
Don't update the manifest when the experiment is off

Review of attachment 8575251 [details] [diff] [review]:
-----------------------------------------------------------------

::: browser/experiments/Experiments.jsm
@@ +420,5 @@
>    QueryInterface: XPCOMUtils.generateQI([Ci.nsITimerCallback, Ci.nsIObserver]),
>  
> +  /**
> +   * `true` if this experiment is currently setup (has been fully initialized
> +   * and not uninitialized yet).

"if the experiment manager is"
... Experiments is the "manager" instance that controls experiment running, updates, ...
Attachment #8575251 - Flags: review?(gfritzsche) → review+
https://hg.mozilla.org/mozilla-central/rev/5c0cc88b465e
Status: NEW → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Whiteboard: [fixed-in-fx-team]
Target Milestone: --- → Firefox 39
Please request Aurora approval on this when you get a chance.
Flags: needinfo?(dteller)
Comment on attachment 8583075 [details] [diff] [review]
Don't update the manifest when the experiment is off, v2

Approval Request Comment
[Feature/regressing bug #]: bug 974009
[User impact if declined]: I believe none, it's just an intermittent orange polluting treeherder.
[Describe test coverage new/current, TreeHerder]: Landed last week without problem.
[Risks and why]: None that I can think of.
[String/UUID change made/needed]: None.
Flags: needinfo?(dteller)
Attachment #8583075 - Flags: approval-mozilla-aurora?
Attachment #8583075 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Product: Firefox Health Report → Firefox Health Report Graveyard
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: