Closed Bug 1322722 Opened 5 years ago Closed 5 years ago

on windows 7, some xpcshell tests fail when running in taskcluster and trying to delete files

Categories

(Taskcluster :: General, defect)

defect
Not set
normal

Tracking

(Not tracked)

RESOLVED FIXED
mozilla53

People

(Reporter: jmaher, Unassigned)

References

Details

Attachments

(2 files, 2 obsolete files)

when pushing to try to run tests on windows 7 in tc, I see some failures in xpcshell:
https://treeherder.mozilla.org/#/jobs?repo=try&author=jmaher@mozilla.com&filter-tier=1&filter-tier=2&filter-tier=3&filter-searchStr=xpcshell%207&selectedJob=32453109

I am focused on the 7th chunk here, this is failing consistently and it follows a simple pattern:
TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | xpcshell-unpack.ini:toolkit/mozapps/extensions/test/xpcshell/test_bootstrap.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | xpcshell-unpack.ini:toolkit/mozapps/extensions/test/xpcshell/test_bootstrap.js | run_test_9 - NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIFile.remove]
TEST-UNEXPECTED-FAIL | xpcshell-unpack.ini:toolkit/mozapps/extensions/test/xpcshell/test_dictionary.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | xpcshell-unpack.ini:toolkit/mozapps/extensions/test/xpcshell/test_dictionary.js | run_test_9 - NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIFile.remove]
TEST-UNEXPECTED-FAIL | xpcshell-unpack.ini:toolkit/mozapps/extensions/test/xpcshell/test_langpack.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | xpcshell-unpack.ini:toolkit/mozapps/extensions/test/xpcshell/test_langpack.js | run_test_9/< - [run_test_9/< : 317] null != null
Return code: 1


In looking at the raw logs (debug here):
https://queue.taskcluster.net/v1/task/Fe3HBfdeSC2hLpEgGwSULg/runs/0/artifacts/public/logs/live_backing.log

Here is a big clip from the log file:
15:17:37     INFO -  TEST-START | toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js
15:17:41  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js | xpcshell return code: 0
15:17:41     INFO -  TEST-INFO took 3926ms
15:17:41     INFO -  >>>>>>>
15:17:41     INFO -  PROCESS | 5396 | [5396] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file z:/build/build/src/toolkit/crashreporter/nsExceptionHandler.cpp, line 2813
15:17:41     INFO -  PROCESS | 5396 | [5396] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file z:/build/build/src/xpcom/base/nsSystemInfo.cpp, line 116
15:17:41     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
15:17:41     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
15:17:41     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
15:17:41     INFO -  running event loop
15:17:41     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js | Starting setup
15:17:41     INFO -  (xpcshell/head.js) | test setup pending (2)
15:17:41     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js | setup - [setup : 807] true == true
15:17:41     INFO -  PROCESS | 5396 | [5396] WARNING: This method is lossy. Use GetCanonicalPath !: file z:/build/build/src/xpcom/io/nsLocalFileWin.cpp, line 3576
15:17:41     INFO -  PROCESS | 5396 | 1481296658544	addons.manager	DEBUG	Application has been upgraded
15:17:41     INFO -  PROCESS | 5396 | 1481296658630	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider"]
15:17:41     INFO -  PROCESS | 5396 | 1481296658637	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/LightweightThemeManager.jsm: ["LightweightThemeManager"]
15:17:41     INFO -  PROCESS | 5396 | 1481296658650	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/GMPProvider.jsm
15:17:41     INFO -  PROCESS | 5396 | 1481296658656	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/PluginProvider.jsm
15:17:41     INFO -  PROCESS | 5396 | 1481296658657	addons.manager	DEBUG	Starting provider: XPIProvider
15:17:41     INFO -  PROCESS | 5396 | 1481296658658	addons.xpi	DEBUG	startup
15:17:41     INFO -  PROCESS | 5396 | 1481296658660	addons.xpi	INFO	SystemAddonInstallLocation directory is missing
15:17:41     INFO -  PROCESS | 5396 | 1481296658662	addons.xpi	INFO	Mapping tel-system-xpi@tests.mozilla.org to z:\\task\\build\\xpc-profile-j3g1gc\\sysfeatures\\app0\\tel-system-xpi@tests.mozilla.org.xpi
15:17:41     INFO -  PROCESS | 5396 | 1481296658665	addons.xpi	DEBUG	checkForChanges
15:17:41     INFO -  PROCESS | 5396 | 1481296658667	addons.xpi	INFO	SystemAddonInstallLocation directory is missing
15:17:41     INFO -  PROCESS | 5396 | 1481296658668	addons.xpi	DEBUG	Loaded add-on state from prefs: {}
15:17:41     INFO -  PROCESS | 5396 | 1481296658671	addons.xpi	DEBUG	New add-on tel-system-xpi@tests.mozilla.org in app-system-defaults
15:17:41     INFO -  PROCESS | 5396 | 1481296658674	addons.xpi	DEBUG	getModTime: Recursive scan of tel-system-xpi@tests.mozilla.org
15:17:41     INFO -  PROCESS | 5396 | 1481296658677	addons.xpi	DEBUG	getInstallState changed: true, state: {"app-system-defaults":{"tel-system-xpi@tests.mozilla.org":{"d":"z:\\\\task\\\\build\\\\xpc-profile-j3g1gc\\\\sysfeatures\\\\app0\\\\tel-system-xpi@tests.mozilla.org.xpi","st":1481296658240}}}
15:17:41     INFO -  PROCESS | 5396 | 1481296658699	addons.xpi-utils	DEBUG	Opening XPI database z:\\task\\build\\xpc-profile-j3g1gc\\extensions.json
15:17:41     INFO -  PROCESS | 5396 | 1481296658703	addons.xpi-utils	DEBUG	New add-on tel-system-xpi@tests.mozilla.org installed in app-system-defaults
15:17:41     INFO -  PROCESS | 5396 | 1481296658750	DeferredSave.extensions.json	DEBUG	Save changes
15:17:41     INFO -  PROCESS | 5396 | 1481296658757	addons.manager	DEBUG	Registering startup change 'installed' for tel-system-xpi@tests.mozilla.org
15:17:41     INFO -  PROCESS | 5396 | 1481296658759	addons.xpi	DEBUG	Loading bootstrap scope from z:\\task\\build\\xpc-profile-j3g1gc\\sysfeatures\\app0\\tel-system-xpi@tests.mozilla.org.xpi
15:17:41     INFO -  PROCESS | 5396 | 1481296658791	addons.xpi	WARN	Error loading bootstrap.js for tel-system-xpi@tests.mozilla.org: Error opening input stream (invalid filename?): jar:file:///z:/task/build/xpc-profile-j3g1gc/sysfeatures/app0/tel-system-xpi@tests.mozilla.org.xpi!/bootstrap.js
15:17:41     INFO -  PROCESS | 5396 | 1481296658793	addons.xpi	WARN	Add-on tel-system-xpi@tests.mozilla.org is missing bootstrap method install
15:17:41     INFO -  PROCESS | 5396 | 1481296658793	addons.xpi-utils	DEBUG	Make addon app-system-defaults:tel-system-xpi@tests.mozilla.org visible
15:17:41     INFO -  PROCESS | 5396 | 1481296658795	DeferredSave.extensions.json	DEBUG	Save changes
15:17:41     INFO -  PROCESS | 5396 | 1481296658797	addons.xpi	DEBUG	Updating XPIState for {"id":"tel-system-xpi@tests.mozilla.org","syncGUID":"{9fbfbbf2-49a7-45fa-850e-56cbb2f081d6}","location":"app-system-defaults","version":"1.0","type":"extension","internalName":null,"updateURL":null,"updateKey":null,"optionsURL":null,"optionsType":null,"aboutURL":null,"icons":{},"iconURL":null,"icon64URL":null,"defaultLocale":{"name":"XPI Telemetry System Add-on Test","description":"A system addon which is shipped with Firefox.","creator":null,"homepageURL":null},"visible":true,"active":true,"userDisabled":false,"appDisabled":false,"descriptor":"z:\\\\task\\\\build\\\\xpc-profile-j3g1gc\\\\sysfeatures\\\\app0\\\\tel-system-xpi@tests.mozilla.org.xpi","installDate":1481296658240,"updateDate":1481296658240,"applyBackgroundUpdates":1,"bootstrap":true,"skinnable":false,"size":729,"sourceURI":null,"releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"hasBinaryComponents":false,"strictCompatibility":false,"locales":[],"targetApplications":[{"id":"toolkit@mozilla.org","minVersion":"0","maxVersion":"*"}],"targetPlatforms":[],"multiprocessCompatible":false,"seen":true,"dependencies":[],"hasEmbeddedWebExtension":false,"mpcOptedOut":false}
15:17:41     INFO -  PROCESS | 5396 | 1481296658798	addons.xpi	DEBUG	getModTime: Recursive scan of tel-system-xpi@tests.mozilla.org
15:17:41     INFO -  PROCESS | 5396 | 1481296658800	DeferredSave.extensions.json	DEBUG	Save changes
15:17:41     INFO -  PROCESS | 5396 | 1481296658800	addons.xpi	DEBUG	Updating database with changes to installed add-ons
15:17:41     INFO -  PROCESS | 5396 | 1481296658800	addons.xpi-utils	DEBUG	Updating add-on states
15:17:41     INFO -  PROCESS | 5396 | 1481296658804	addons.xpi	DEBUG	Registering manifest for z:\\task\\build\\xpc-profile-j3g1gc\\sysfeatures\\app0\\tel-system-xpi@tests.mozilla.org.xpi
15:17:41     INFO -  PROCESS | 5396 | 1481296658804	addons.xpi	WARN	Add-on tel-system-xpi@tests.mozilla.org is missing bootstrap method startup
15:17:41     INFO -  PROCESS | 5396 | 1481296658813	addons.manager	DEBUG	Registering shutdown blocker for XPIProvider
15:17:41     INFO -  PROCESS | 5396 | 1481296658814	addons.manager	DEBUG	Provider finished startup: XPIProvider
15:17:41     INFO -  PROCESS | 5396 | 1481296658814	addons.manager	DEBUG	Starting provider: LightweightThemeManager
15:17:41     INFO -  PROCESS | 5396 | 1481296658815	addons.manager	DEBUG	Registering shutdown blocker for LightweightThemeManager
15:17:41     INFO -  PROCESS | 5396 | 1481296658816	addons.manager	DEBUG	Provider finished startup: LightweightThemeManager
15:17:41     INFO -  PROCESS | 5396 | 1481296658817	addons.manager	DEBUG	Starting provider: GMPProvider
15:17:41     INFO -  PROCESS | 5396 | 1481296658844	addons.manager	DEBUG	Registering shutdown blocker for GMPProvider
15:17:41     INFO -  PROCESS | 5396 | 1481296658845	addons.manager	DEBUG	Provider finished startup: GMPProvider
15:17:41     INFO -  PROCESS | 5396 | 1481296658845	addons.manager	DEBUG	Starting provider: PluginProvider
15:17:41     INFO -  PROCESS | 5396 | 1481296658845	addons.manager	DEBUG	Registering shutdown blocker for PluginProvider
15:17:41     INFO -  PROCESS | 5396 | 1481296658846	addons.manager	DEBUG	Provider finished startup: PluginProvider
15:17:41     INFO -  PROCESS | 5396 | 1481296658853	addons.manager	DEBUG	Completed startup sequence
15:17:41     INFO -  PROCESS | 5396 | [5396] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file z:/build/build/src/extensions/cookie/nsPermissionManager.cpp, line 2637
15:17:41     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
15:17:41     INFO -  PROCESS | 5396 | 1481296658940	DeferredSave.extensions.json	DEBUG	Starting timer
15:17:41     INFO -  Unexpected exception NS_ERROR_FILE_NOT_FOUND: Component returned failure code: 0x80520012 (NS_ERROR_FILE_NOT_FOUND) [nsIFileOutputStream.init]
15:17:41     INFO -  spoofAttributionData@Z:/task/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js:320:5
15:17:41     INFO -  setup@Z:/task/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js:843:5
15:17:41     INFO -  _run_next_test@Z:\task\build\tests\xpcshell\head.js:1566:9
15:17:41     INFO -  run@Z:\task\build\tests\xpcshell\head.js:713:9
15:17:41     INFO -  _do_main@Z:\task\build\tests\xpcshell\head.js:210:5
15:17:41     INFO -  _execute_test@Z:\task\build\tests\xpcshell\head.js:545:5
15:17:41     INFO -  @-e:1:1
15:17:41     INFO -  exiting test
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658544	addons.manager	DEBUG	Application has been upgraded"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658630	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider"]"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658637	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/LightweightThemeManager.jsm: ["LightweightThemeManager"]"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658650	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/GMPProvider.jsm"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658656	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/PluginProvider.jsm"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658657	addons.manager	DEBUG	Starting provider: XPIProvider"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658658	addons.xpi	DEBUG	startup"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658660	addons.xpi	INFO	SystemAddonInstallLocation directory is missing"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658662	addons.xpi	INFO	Mapping tel-system-xpi@tests.mozilla.org to z:\\task\\build\\xpc-profile-j3g1gc\\sysfeatures\\app0\\tel-system-xpi@tests.mozilla.org.xpi"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658665	addons.xpi	DEBUG	checkForChanges"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658667	addons.xpi	INFO	SystemAddonInstallLocation directory is missing"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658668	addons.xpi	DEBUG	Loaded add-on state from prefs: {}"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658671	addons.xpi	DEBUG	New add-on tel-system-xpi@tests.mozilla.org in app-system-defaults"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658674	addons.xpi	DEBUG	getModTime: Recursive scan of tel-system-xpi@tests.mozilla.org"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658677	addons.xpi	DEBUG	getInstallState changed: true, state: {"app-system-defaults":{"tel-system-xpi@tests.mozilla.org":{"d":"z:\\\\task\\\\build\\\\xpc-profile-j3g1gc\\\\sysfeatures\\\\app0\\\\tel-system-xpi@tests.mozilla.org.xpi","st":1481296658240}}}"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658699	addons.xpi-utils	DEBUG	Opening XPI database z:\\task\\build\\xpc-profile-j3g1gc\\extensions.json"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658703	addons.xpi-utils	DEBUG	New add-on tel-system-xpi@tests.mozilla.org installed in app-system-defaults"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658750	DeferredSave.extensions.json	DEBUG	Save changes"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658757	addons.manager	DEBUG	Registering startup change 'installed' for tel-system-xpi@tests.mozilla.org"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658759	addons.xpi	DEBUG	Loading bootstrap scope from z:\\task\\build\\xpc-profile-j3g1gc\\sysfeatures\\app0\\tel-system-xpi@tests.mozilla.org.xpi"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658791	addons.xpi	WARN	Error loading bootstrap.js for tel-system-xpi@tests.mozilla.org: Error opening input stream (invalid filename?): jar:file:///z:/task/build/xpc-profile-j3g1gc/sysfeatures/app0/tel-system-xpi@tests.mozilla.org.xpi!/bootstrap.js"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658793	addons.xpi	WARN	Add-on tel-system-xpi@tests.mozilla.org is missing bootstrap method install"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658793	addons.xpi-utils	DEBUG	Make addon app-system-defaults:tel-system-xpi@tests.mozilla.org visible"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658795	DeferredSave.extensions.json	DEBUG	Save changes"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658797	addons.xpi	DEBUG	Updating XPIState for {"id":"tel-system-xpi@tests.mozilla.org","syncGUID":"{9fbfbbf2-49a7-45fa-850e-56cbb2f081d6}","location":"app-system-defaults","version":"1.0","type":"extension","internalName":null,"updateURL":null,"updateKey":null,"optionsURL":null,"optionsType":null,"aboutURL":null,"icons":{},"iconURL":null,"icon64URL":null,"defaultLocale":{"name":"XPI Telemetry System Add-on Test","description":"A system addon which is shipped with Firefox.","creator":null,"homepageURL":null},"visible":true,"active":true,"userDisabled":false,"appDisabled":false,"descriptor":"z:\\\\task\\\\build\\\\xpc-profile-j3g1gc\\\\sysfeatures\\\\app0\\\\tel-system-xpi@tests.mozilla.org.xpi","installDate":1481296658240,"updateDate":1481296658240,"applyBackgroundUpdates":1,"bootstrap":true,"skinnable":false,"size":729,"sourceURI":null,"releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"hasBinaryComponents":false,"strictCompatibility":false,"locales":[],"targetApplications":[{"id":"toolkit@mozilla.org","minVersion":"0","maxVersion":"*"}],"targetPlatforms":[],"multiprocessCompatible":false,"seen":true,"dependencies":[],"hasEmbeddedWebExtension":false,"mpcOptedOut":false}"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658798	addons.xpi	DEBUG	getModTime: Recursive scan of tel-system-xpi@tests.mozilla.org"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658800	DeferredSave.extensions.json	DEBUG	Save changes"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658800	addons.xpi	DEBUG	Updating database with changes to installed add-ons"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658800	addons.xpi-utils	DEBUG	Updating add-on states"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658804	addons.xpi	DEBUG	Registering manifest for z:\\task\\build\\xpc-profile-j3g1gc\\sysfeatures\\app0\\tel-system-xpi@tests.mozilla.org.xpi"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658804	addons.xpi	WARN	Add-on tel-system-xpi@tests.mozilla.org is missing bootstrap method startup"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658813	addons.manager	DEBUG	Registering shutdown blocker for XPIProvider"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658814	addons.manager	DEBUG	Provider finished startup: XPIProvider"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658814	addons.manager	DEBUG	Starting provider: LightweightThemeManager"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658815	addons.manager	DEBUG	Registering shutdown blocker for LightweightThemeManager"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658816	addons.manager	DEBUG	Provider finished startup: LightweightThemeManager"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658817	addons.manager	DEBUG	Starting provider: GMPProvider"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658844	addons.manager	DEBUG	Registering shutdown blocker for GMPProvider"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658845	addons.manager	DEBUG	Provider finished startup: GMPProvider"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658845	addons.manager	DEBUG	Starting provider: PluginProvider"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658845	addons.manager	DEBUG	Registering shutdown blocker for PluginProvider"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658846	addons.manager	DEBUG	Provider finished startup: PluginProvider"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658853	addons.manager	DEBUG	Completed startup sequence"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658940	DeferredSave.extensions.json	DEBUG	Starting timer"
15:17:41     INFO -  PROCESS | 5396 | 1481296658964	DeferredSave.extensions.json	DEBUG	Starting write
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658964	DeferredSave.extensions.json	DEBUG	Starting write"
15:17:41     INFO -  PROCESS | 5396 | 1481296658974	addons.xpi	WARN	Add-on tel-system-xpi@tests.mozilla.org is missing bootstrap method shutdown
15:17:41     INFO -  PROCESS | 5396 | 1481296658980	addons.manager	DEBUG	shutdown
15:17:41     INFO -  PROCESS | 5396 | 1481296658981	addons.manager	DEBUG	Calling shutdown blocker for XPIProvider
15:17:41     INFO -  PROCESS | 5396 | 1481296658982	addons.xpi	DEBUG	shutdown
15:17:41     INFO -  PROCESS | 5396 | 1481296658982	addons.xpi-utils	DEBUG	shutdown
15:17:41     INFO -  PROCESS | 5396 | 1481296658984	addons.manager	DEBUG	Calling shutdown blocker for LightweightThemeManager
15:17:41     INFO -  PROCESS | 5396 | 1481296658985	addons.manager	DEBUG	Calling shutdown blocker for GMPProvider
15:17:41     INFO -  PROCESS | 5396 | 1481296658994	addons.manager	DEBUG	Calling shutdown blocker for PluginProvider
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658974	addons.xpi	WARN	Add-on tel-system-xpi@tests.mozilla.org is missing bootstrap method shutdown"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658980	addons.manager	DEBUG	shutdown"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658981	addons.manager	DEBUG	Calling shutdown blocker for XPIProvider"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658982	addons.xpi	DEBUG	shutdown"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658982	addons.xpi-utils	DEBUG	shutdown"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658984	addons.manager	DEBUG	Calling shutdown blocker for LightweightThemeManager"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658985	addons.manager	DEBUG	Calling shutdown blocker for GMPProvider"
15:17:41     INFO -  PROCESS | 5396 | 1481296659003	DeferredSave.extensions.json	DEBUG	Write succeeded
15:17:41     INFO -  PROCESS | 5396 | 1481296659003	addons.xpi-utils	DEBUG	XPI Database saved, setting schema version preference to 19
15:17:41     INFO -  PROCESS | 5396 | 1481296659004	addons.xpi	DEBUG	Notifying XPI shutdown observers
15:17:41     INFO -  PROCESS | 5396 | 1481296659019	addons.manager	DEBUG	Async provider shutdown done
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296658994	addons.manager	DEBUG	Calling shutdown blocker for PluginProvider"
15:17:41     INFO -  PROCESS | 5396 | [5396] WARNING: cannot post event if not initialized: file z:/build/build/src/netwerk/protocol/http/nsHttpConnectionMgr.cpp, line 232
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296659003	DeferredSave.extensions.json	DEBUG	Write succeeded"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296659003	addons.xpi-utils	DEBUG	XPI Database saved, setting schema version preference to 19"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296659004	addons.xpi	DEBUG	Notifying XPI shutdown observers"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296659019	addons.manager	DEBUG	Async provider shutdown done"
15:17:41     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "1481296659024	Toolkit.Telemetry	ERROR	TelemetrySend::shutdown - failed to remove observer for idle-daily: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIObserverService.removeObserver]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: resource://gre/modules/TelemetrySend.jsm :: TelemetrySendImpl.shutdown< :: line 636"  data: no] Stack trace: TelemetrySendImpl.shutdown<()@resource://gre/modules/TelemetrySend.jsm:636 < TaskImpl_run()@resource://gre/modules/Task.jsm:319 < TaskImpl()@resource://gre/modules/Task.jsm:277 < asyncFunction()@resource://gre/modules/Task.jsm:252 < shutdown()@resource://gre/modules/TelemetrySend.jsm:195 < Z:/task/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/head.js:311 < _execute_test()@Z:\\task\\build\\tests\\xpcshell\\head.js:607 < -e:1" {file: "resource://gre/modules/Log.jsm" line: 753}]
15:17:41     INFO -  App_append@resource://gre/modules/Log.jsm:753:9
15:17:41     INFO -  log@resource://gre/modules/Log.jsm:389:7
15:17:41     INFO -  getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:504:44
15:17:41     INFO -  error@resource://gre/modules/Log.jsm:397:5
15:17:41     INFO -  TelemetrySendImpl.shutdown<@resource://gre/modules/TelemetrySend.jsm:638:9
15:17:41     INFO -  TaskImpl_run@resource://gre/modules/Task.jsm:319:42
15:17:41     INFO -  TaskImpl@resource://gre/modules/Task.jsm:277:3
15:17:41     INFO -  asyncFunction@resource://gre/modules/Task.jsm:252:14
15:17:41     INFO -  shutdown@resource://gre/modules/TelemetrySend.jsm:195:12
15:17:41     INFO -  @Z:/task/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/head.js:311:29
15:17:41     INFO -  _execute_test@Z:\\task\\build\\tests\\xpcshell\\head.js:607:16
15:17:41     INFO -  @-e:1:1
15:17:41     INFO -  "
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296659028	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::shutdown"
15:17:41     INFO -  "CONSOLE_MESSAGE: (info) 1481296659029	Toolkit.Telemetry	TRACE	TelemetrySend::promisePendingPingActivity - Waiting for ping task"
15:17:41     INFO -  PROCESS | 5396 | [5396] WARNING: '!compMgr', file z:/build/build/src/xpcom/glue/nsComponentManagerUtils.cpp, line 63
15:17:41     INFO -  PROCESS | 5396 | [5396] WARNING: OOPDeinit() without successful OOPInit(): file z:/build/build/src/toolkit/crashreporter/nsExceptionHandler.cpp, line 3485
15:17:41     INFO -  PROCESS | 5396 | [5396] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file z:/build/build/src/xpcom/base/nsTraceRefcnt.cpp, line 172
15:17:41     INFO -  PROCESS | 5396 | [5396] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file z:/build/build/src/xpcom/base/nsTraceRefcnt.cpp, line 172
15:17:41     INFO -  PROCESS | 5396 | nsStringStats
15:17:41     INFO -  PROCESS | 5396 |  => mAllocCount:          18260
15:17:41     INFO -  PROCESS | 5396 |  => mReallocCount:          550
15:17:41     INFO -  PROCESS | 5396 |  => mFreeCount:           18260
15:17:41     INFO -  PROCESS | 5396 |  => mShareCount:          14088
15:17:41     INFO -  PROCESS | 5396 |  => mAdoptCount:            824
15:17:41     INFO -  PROCESS | 5396 |  => mAdoptFreeCount:        824
15:17:41     INFO -  PROCESS | 5396 |  => Process ID: 5396, Thread ID: 6968
15:17:41     INFO -  <<<<<<<


what seems interesting is that I believe we are hitting a file not found message:
Unexpected exception NS_ERROR_FILE_NOT_FOUND: Component returned failure code: 0x80520012 (NS_ERROR_FILE_NOT_FOUND) [nsIFileOutputStream.init]

in the above case this seems to be in the addons initialization.

I am not sure of the root cause here or a full set o patterns, I think a bit more analysis of the logs/tests could yield a much clearer next step.
Blocks: 1280474
looking in detail at test_dictionary.js, I can reproduce the same error on my local win10 machine.  This is ideal :)

I see in bug 591780, we added a lot of code to test_dictionary.js, and for some reason I see access denied when trying to delete:
c:\\Users\\elvis\\mozilla-inbound\\obj-i686-pc-mingw32\\temp\\xpc-profile-sgfqh6\\extensions\\ab-CD@dictionaries.addons.mozilla.org\\dictionaries\\ab-CD.dic

oddly that goes away when the harness cleans itself up- and me as a local user has access to the file for all permissions.  According to nsiFile, I have read access, but not write access to the file, that might be part of the problem.

A few thoughts:
1) my local system could have different settings for dictionaries and language options
2) possibly the file system on win10 is different than we have for win7 on buildbot
3) some other reason which I am not aware of, maybe timing of addons and permissions

:mossop, I see you were a reviewer of this code originally- could you help me figure this out or help me find someone who could work with me?
Flags: needinfo?(dtownsend)
By far the most common cause of these kinds of problems on Windows is a background service watching the filesystem and locking new files open when they appear on disk to do some kind of indexing. Think anti-virus realtime protection, backup tools, search indexing. All of these watch for new files, open them to read them then close them. They race against our code which tries to delete them almost immediately after creating them and Windows won't let you delete a file that another process has open. You can often use process monitor to watch the filesystem to catch what is doing it.

I'd like to help further but right now the test fails in a different place for me, probably for the same reasons but I'm failing to find what the problem is :(
Flags: needinfo?(dtownsend)
interesting- I suspect this is quite difficult to work around.  I did put a long delay in before calling the delete with no luck.  I did try removing indexing and windows defender from running- still no luck.  I suspect there is something else I am overlooking- I will hack on this some more next week.
using process monitor (filter on path contains ab-cd.dic) I see this failing, but only see xpcshell and python accessing the file (after turning off windows defender- yay for procmon for clarifying that).

while I get a CANNOT_DELETE for xpcshell, I determined it wasn't a timing issue- in fact, I can wait a minute and try again with the same failure, but python can delete it successfully immediately afterwards.

To top it off, I looked at the file via explorer, and I see that it is marked as read-only, not sure if that is the problem, or if xpcshell runs with limited permissions for the filesystem (even though it is creating the file?!?)

I suspect there is something else going on here, I am sort of at a loss for what I could do next.
i can confirm that the taskcluster windows workers have the indexing service disabled and there is no antivirus installed or running.

a lot of the python in-tree code for file deletion uses a retry mechanism as well as a remove-read-only-file-attribute mechanism (eg: https://dxr.mozilla.org/mozilla-central/source/browser/components/migration/tests/marionette/test_refresh_firefox.py#334). do the xpcshell processes make use of these mechanisms?
I have tried retrying up to 5 times with no success locally.

:grenade, do you know if we have Windows Defender fully disabled?  That has anti-malware/virus support built in for both win7/win10.
In comment 1, you mention that the harness cleanup can take care of this and that the file is marked read-only.  I think the salient question in comment 5 was whether xpcshell is removing the read-only attribute:

        def handleRemoveReadonly(func, path, exc):
            excvalue = exc[1]
            if func in (os.rmdir, os.remove) and excvalue.errno == errno.EACCES:
                os.chmod(path, stat.S_IRWXU| stat.S_IRWXG| stat.S_IRWXO) # 0777
                func(path)
            else:
                raise

Windows Defender is disabled in your reproduction of the issue, so it can't be the cause of the problem.
I am not sure I understand comment 7.  Somehow this works in buildbot windows 7, I am trying to reproduce this locally on windows 10 which is not a production environment, but I get the same failure locally as in taskcluster.  We could have windows defender running in taskcluster, although one should question if we want that running or not.
i can confirm that windefend is also disabled:

C:\Users\GenericWorker.I-053F6DB8550C4>sc query windefend

SERVICE_NAME: windefend
        TYPE               : 20  WIN32_SHARE_PROCESS
        STATE              : 1  STOPPED
        WIN32_EXIT_CODE    : 1077  (0x435)
        SERVICE_EXIT_CODE  : 0  (0x0)
        CHECKPOINT         : 0x0
        WAIT_HINT          : 0x0

C:\Users\GenericWorker.I-053F6DB8550C4>sc query wsearch

SERVICE_NAME: wsearch
        TYPE               : 10  WIN32_OWN_PROCESS
        STATE              : 1  STOPPED
        WIN32_EXIT_CODE    : 1077  (0x435)
        SERVICE_EXIT_CODE  : 0  (0x0)
        CHECKPOINT         : 0x0
        WAIT_HINT          : 0x0
                     
                                                       
Attached patch wallpaper patch (obsolete) — Splinter Review
So this hack gets things working locally for me on Windows 10. Does it work for you and in automation?

I don't understand what is really going wrong. Zip extraction is supposed to set file permissions based on those contained in the zip file and I've verified that the zip file contains files that are writeable. For some reason though after extraction the files are read-only so forcing them to be writeable lets the test work.
Attachment #8819952 - Flags: feedback?(jmaher)
locally this fixed test_dictionary.js, but test_langpack.js is still failing, I pushed to try to see what remains and will update the bug soon.
Comment on attachment 8819952 [details] [diff] [review]
wallpaper patch

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

this did the trick on try server as well.

I also followed this logic and fixed test_langpack.js with this change:
diff --git a/toolkit/mozapps/extensions/internal/XPIProvider.jsm b/toolkit/mozapps/extensions/internal/XPIProvider.jsm
--- a/toolkit/mozapps/extensions/internal/XPIProvider.jsm
+++ b/toolkit/mozapps/extensions/internal/XPIProvider.jsm
@@ -464,17 +464,17 @@ SafeInstallOperation.prototype = {
     try {
       if (aCopy) {
         newFile.copyTo(aTargetDirectory, null);
         // copyTo does not update the nsIFile with the new.
         newFile = aTargetDirectory.clone();
         newFile.append(aFile.leafName);
         // Windows roaming profiles won't properly sync directories if a new file
         // has an older lastModifiedTime than a previous file, so update.
-        newFile.lastModifiedTime = Date.now();
+//        newFile.lastModifiedTime = Date.now();
       }
       else {
         newFile.moveTo(aTargetDirectory, null);
       }
     }
     catch (e) {
       logger.error("Failed to " + (aCopy ? "copy" : "move") + " file " + aFile.path +
             " to " + aTargetDirectory.path, e);



possibly this should give us a hint about what is going wrong and how we could fix it.  I haven't been able to fix the other tests easily with a similar hack though.
Attachment #8819952 - Flags: feedback?(jmaher) → feedback+
Attached patch wallpaper patch (obsolete) — Splinter Review
Try this. Everything passes locally for me.
Attachment #8819952 - Attachment is obsolete: true
Attachment #8820034 - Flags: feedback?(jmaher)
Attached patch wallpaper patchSplinter Review
Looks like this is the minimal patch needed. What filesystems do we use in our test slaves? I'm wondering if the difference is between NTFS and FAT filesystems where the tests are run.
Attachment #8820034 - Attachment is obsolete: true
Attachment #8820034 - Flags: feedback?(jmaher)
Attachment #8820067 - Flags: feedback?(jmaher)
this patch is working for me locally :)  I have pushed to try to see what is going on.

As for the filesystem, I am not sure- :grenade should be able to help determine if we are using FAT or NTFS or ???
Flags: needinfo?(rthijssen)
Comment on attachment 8820067 [details] [diff] [review]
wallpaper patch

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

this looks a lot better than the previous patch and it works for all the tests in the extensions directory:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=c1126a8aaaf8c355967bbd020d1037edd5ab553b&filter-tier=1&filter-tier=2&filter-tier=3

There is one more issue to sort out in the telemetry directory- I can work on narrowing that down and maybe applying similar techniques.  Possibly when we hear from :grenade on the file system type we can feel more comfortable doing this type of "wallpapering" of permissions, or make a better choice if needed.

Thanks for putting this together, it is good to make our tests work more reliably in various environments.
Attachment #8820067 - Flags: feedback?(jmaher) → feedback+
(In reply to Joel Maher ( :jmaher) from comment #16)
> Comment on attachment 8820067 [details] [diff] [review]
> wallpaper patch
> 
> Review of attachment 8820067 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> this looks a lot better than the previous patch and it works for all the
> tests in the extensions directory:
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=c1126a8aaaf8c355967bbd020d1037edd5ab553b&filter-
> tier=1&filter-tier=2&filter-tier=3
> 
> There is one more issue to sort out in the telemetry directory- I can work
> on narrowing that down and maybe applying similar techniques.  Possibly when
> we hear from :grenade on the file system type we can feel more comfortable
> doing this type of "wallpapering" of permissions, or make a better choice if
> needed.
> 
> Thanks for putting this together, it is good to make our tests work more
> reliably in various environments.

Yeah, there is nothing wrong with taking this patch as such, it's just quite confusing that we need it. I can't see any reason locally why things are behaving as they are.
fs is ntfs for all tc win
Flags: needinfo?(rthijssen)
The last failure is here:
https://dxr.mozilla.org/mozilla-central/source/toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js?q=path%3Atest_TelemetryEnvironment.js&redirect_type=single#320

related to an attribution file- we are trying to open it and it doesn't exist.  I suspect this attribution file is created after signing firefox (hence the name "postSigningData", and for taskcluster builds right now we are not signing firefox.

:mhowell, can you shed some light about when the postSigningData file is created, either before or after signing?
Flags: needinfo?(mhowell)
That line actually attempts to create the file. Normally it would be created by the installer, so the test has to make its own.

Can you link the failure that you're talking about? I can't seem to find it on try.
Flags: needinfo?(mhowell) → needinfo?(jmaher)
I have to confess to being stumped. I can't get this test to act up locally on my Win10 box. FILE_NOT_FOUND doesn't make any sense when creating a file. I see from [0] that NS_ERROR_FILE_NOT_FOUND is also mapped to the Windows errors PATH_NOT_FOUND, INVALID_DRIVE, and NOT_READY. The first two can't be it, because I can see from the added logging that the path is right, and the drive with the user profile on it can't very well be invalid. That leaves ERROR_NOT_READY, which as far as I can tell should only happen to regular files when the volume is locked, and that can't be either. So I have to come back to comment 2; even though we're pretty sure Windows Defender and the indexing service aren't running, I can't think of anything that can cause this except for something intercepting the CreateFile call.

Also, it looks like this is _only_ failing in Taskcluster, is that right? That would point to something odd going on in that environment.

[0] https://dxr.mozilla.org/mozilla-central/rev/567894f026558e6dada617a3998f29aed06ac7d8/xpcom/io/nsLocalFileWin.cpp#422
Attached patch telemetry patchSplinter Review
I wonder if it's possible that C:\Users\GenericWorker\AppData\Local\mozilla\firefox doesn't exist when we attempt to create that file? This patch makes sure to create all the directories along the way and closes the stream after it's done. Does it help?
Attachment #8820373 - Flags: feedback?(jmaher)
Ooh. I bet that's it. I ran into that when I wrote the test for the module that this telemetry code calls and had to make sure the directory got created there [https://dxr.mozilla.org/mozilla-central/rev/567894f026558e6dada617a3998f29aed06ac7d8/browser/modules/test/xpcshell/test_AttributionCode.js#52]. Can't believe I forgot about that.
I have it up on try server, I will let you know in ~1 hour when the tests are finished.
Comment on attachment 8820373 [details] [diff] [review]
telemetry patch

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

this works great!  Thanks for finding that:)
Attachment #8820373 - Flags: feedback?(jmaher) → feedback+
Duplicate of this bug: 1304040
:mossop, would it be possible to get these patches up for review and deployed?
Flags: needinfo?(dtownsend)
Comment on attachment 8820373 [details] [diff] [review]
telemetry patch

Can you review this Matt?
Flags: needinfo?(dtownsend)
Attachment #8820373 - Flags: review?(mhowell)
Comment on attachment 8820067 [details] [diff] [review]
wallpaper patch

Sure would be nice to know why we need these changes but if it helps green up automation...
Attachment #8820067 - Flags: review?(rhelmer)
Comment on attachment 8820373 [details] [diff] [review]
telemetry patch

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

Yep, that should do it. Good catch, and thanks!
Attachment #8820373 - Flags: review?(mhowell) → review+
Comment on attachment 8820067 [details] [diff] [review]
wallpaper patch

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

Ugh, but I read the bug and agree, this looks safe to do while we figure out the underlying cause.
Attachment #8820067 - Flags: review?(rhelmer) → review+
Pushed by dtownsend@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/c618f28ab699
Fix file permissions errors on taskcluster test runs by forcing extracted permissions to not be read only. r=rhelmer
https://hg.mozilla.org/integration/mozilla-inbound/rev/f9ac48b9d765
Ensure that the directory for the postSigningData file exists before attempting to write it. r=mhowell
https://hg.mozilla.org/mozilla-central/rev/c618f28ab699
https://hg.mozilla.org/mozilla-central/rev/f9ac48b9d765
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla53
You need to log in before you can comment on or make changes to this bug.