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.

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?

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 :(

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

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.

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.

Try this. Everything passes locally for me.

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.

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 ???

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.

(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

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?

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.

sorry about that, here is a link with the job selected: https://treeherder.mozilla.org/#/jobs?repo=try&revision=91fcf1e0d7f0ab2f3af781eac8db558580871e31&filter-tier=1&filter-tier=2&filter-tier=3&selectedJob=33052454

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

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?

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:)

:mossop, would it be possible to get these patches up for review and deployed?

Comment on attachment 8820373 [details] [diff] [review] telemetry patch Can you review this Matt?

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...

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!

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.

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