Closed Bug 1696772 Opened 2 months ago Closed 2 months ago

Windows multi-instance lock becomes unusable when closed by one of several open instances

Categories

(Toolkit :: Application Update, defect, P1)

defect

Tracking

()

RESOLVED FIXED
89 Branch
Tracking Status
firefox-esr78 --- unaffected
firefox86 --- wontfix
firefox87 --- wontfix
firefox88 --- wontfix
firefox89 --- fixed

People

(Reporter: nalexander, Assigned: agashlin)

References

(Regression)

Details

(Keywords: regression)

Attachments

(1 file)

I discovered this while testing Bug 1695797. It's a little fiddly, so let me try to explain.

Suppose I have xpcshell launch a background task: another process, but one that uses the same multi-instance lock location, namely XREExeF.path as it's app location. If I have the background task resetLock(XREExeF.path), the ReleaseMultiInstanceLock() succeeds but the OpenMultiInstanceLock(...) fails. The exact error is that CreateFileW fails with GetLastError() == 5, which is a generic ERROR_ACCESS_DENIED.

This behaviour appears to be specific to XREExeF.path, suggesting that one of the two processes is opening that location in such a way as to foil taking the multi-instance lock later on. That is, if I have the xpcshell harness resetLock to some random location, and then have the launched background task resetLock(location) a few times, everything is fine.

I don't specifically need this functionality for anything, since only tests will be resetting the multi-instance lock, and since it seems very specific to re-opening the multi-instance lock from within a Firefox process.

Here's a log of a test where I've added lots of logging:

env MOZ_LOG=nsUpdateSyncManager:5 MOZCONFIG=mozconfig-browser-compile MOZ_DISABLE_STACK_FIX=1 ./mach test --headless c:/Users/nalexander/Mozilla/gecko/toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js
WARNING: No stack-fixing will occur because MOZ_DISABLE_STACK_FIX is set
 0:18.97 INFO Found node at c:\Users\nalexander\.mozbuild\node\node.EXE
 0:18.97 INFO Found moz-http2 at c:\Users\nalexander\Mozilla\gecko\testing\xpcshell\moz-http2\moz-http2.js
 0:19.28 WARNING Http3 server not found at c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile\dist\bin\http3server.exe. Tests requiring http/3 will fail.
 0:19.28 INFO Running tests sequentially.
 0:19.28 SUITE_START: xpcshell - running 1 tests
 0:19.30 INFO profile dir is c:\users\nalexa~1\appdata\local\temp\firefox\xpcshellprofile
 0:19.31 TEST_START: toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js
 0:19.31 INFO toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js | full command: [u'c:\\Users\\nalexander\\Mozilla\\objdirs\\objdir-browser-compile\\dist\\bin\\xpcshell.exe', '-g', u'c:\\Users\\nalexander\\Mozilla\\objdirs\\objdir-browser-compile\\dist\\bin', '-a', u'c:\\Users\\nalexander\\Mozilla\\objdirs\\objdir-browser-compile\\dist\\bin\\browser', '-m', '-e', 'const _HEAD_JS_PATH = "c:/Users/nalexander/Mozilla/gecko/testing/xpcshell/head.js";', '-e', u'const _MOZINFO_JS_PATH = "c:\\\\users\\\\nalexa~1\\\\appdata\\\\local\\\\temp\\\\firefox\\\\xpcshellprofile\\\\mozinfo.json";', '-e', u'const _PREFS_FILE = "c:\\\\Users\\\\nalexander\\\\Mozilla\\\\objdirs\\\\objdir-browser-compile\\\\temp\\\\user.js";', '-e', u'const _TESTING_MODULES_DIR = "c:\\\\Users\\\\nalexander\\\\Mozilla\\\\objdirs\\\\objdir-browser-compile\\\\_tests\\\\modules\\\\";', '-f', 'c:\\Users\\nalexander\\Mozilla\\gecko\\testing\\xpcshell\\head.js', '-p', u'c:\\Users\\nalexander\\Mozilla\\objdirs\\objdir-browser-compile\\temp\\xpc-plugins-fnqegi', '-e', u'const _HEAD_FILES = ["c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile/_tests/xpcshell/toolkit/components/backgroundtasks/tests/xpcshell/head.js"];', '-e', 'const _JSDEBUGGER_PORT = 0;', '-e', u'const _TEST_FILE = ["c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile/_tests/xpcshell/toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js"];', '-e', u'const _TEST_NAME = "toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js";', '-e', '_execute_test(); quit(0);']
 0:19.31 INFO toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js | current directory: u'c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile/_tests/xpcshell/toolkit/components/backgroundtasks/tests/xpcshell'
 0:19.31 INFO toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js | environment: ['MOZ_DEVELOPER_REPO_DIR=c:/Users/nalexander/Mozilla/gecko', 'XPCOM_DEBUG_BREAK=stack-and-abort', 'MOZ_DISABLE_SOCKET_PROCESS=1', 'MOZ_CRASHREPORTER=1', u'XPCSHELL_TEST_PROFILE_DIR=c:\\users\\nalexa~1\\appdata\\local\\temp\\firefox\\xpcshellprofile', 'MOZHTTP2_PORT=65401', 'MOZ_DISABLE_SOCKET_PROCESS_SANDBOX=1', 'PATH=c:\\mozilla-build\\python;c:\\mozilla-build\\python\\Scripts;c:\\mozilla-build\\python3;c:\\mozilla-build\\python3\\Scripts;c:\\mozilla-build\\bin;c:\\mozilla-build\\msys\\local\\bin;c:\\mozilla-build\\msys\\bin;c:\\mozilla-build\\nsis-3.01;c:\\Windows\\System32\\Wbem;c:\\Windows\\System32\\WindowsPowerShell\\v1.0\\;c:\\Windows\\System32\\OpenSSH\\;c:\\Program Files\\dotnet\\;c:\\Program Files\\Microsoft SQL Server\\130\\Tools\\Binn\\;c:\\Program Files\\Microsoft SQL Server\\Client SDK\\ODBC\\170\\Tools\\Binn\\;c:\\ProgramData\\chocolatey\\bin;c:\\Git\\mingw64\\bin;c:\\Git\\cmd;c:\\Users\\nalexander\\.cargo\\bin;c:\\Users\\nalexander\\AppData\\Local\\Microsoft\\WindowsApps;c:\\LLVM\\bin;c:\\Users\\nalexander\\AppData\\Roaming\\emax64\\libexec\\emacs\\28.0.50\\x86_64-w64-mingw32;c:\\Windows\\system32;c:\\Windows;c:\\Program Files (x86)\\Microsoft Visual Studio\\2019\\Community\\VC\\Tools\\MSVC\\14.25.28610\\bin\\Hostx64\\x64;c:\\Users\\nalexander\\Mozilla\\objdirs\\objdir-browser-compile\\dist\\bin', 'MOZ_WEBRENDER=0', 'MOZ_DISABLE_CONTENT_SANDBOX=1', 'MOZ_HEADLESS=1', 'MOZ_DISABLE_NONLOCAL_CONNECTIONS=1', 'DISPLAY=77', 'MOZNODE_EXEC_PORT=65402', 'MOZ_CRASHREPORTER_NO_REPORT=1', u'XPCSHELL_TEST_TEMP_DIR=c:\\Users\\nalexander\\Mozilla\\objdirs\\objdir-browser-compile\\temp\\xpc-other-ne65_h']
 0:19.31 INFO toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js | as shell command: (cd c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile/_tests/xpcshell/toolkit/components/backgroundtasks/tests/xpcshell; MOZ_DEVELOPER_REPO_DIR=c:/Users/nalexander/Mozilla/gecko XPCOM_DEBUG_BREAK=stack-and-abort MOZ_DISABLE_SOCKET_PROCESS=1 MOZ_CRASHREPORTER=1 'XPCSHELL_TEST_PROFILE_DIR=c:\users\nalexa~1\appdata\local\temp\firefox\xpcshellprofile' MOZHTTP2_PORT=65401 MOZ_DISABLE_SOCKET_PROCESS_SANDBOX=1 'PATH=c:\mozilla-build\python;c:\mozilla-build\python\Scripts;c:\mozilla-build\python3;c:\mozilla-build\python3\Scripts;c:\mozilla-build\bin;c:\mozilla-build\msys\local\bin;c:\mozilla-build\msys\bin;c:\mozilla-build\nsis-3.01;c:\Windows\System32\Wbem;c:\Windows\System32\WindowsPowerShell\v1.0\;c:\Windows\System32\OpenSSH\;c:\Program Files\dotnet\;c:\Program Files\Microsoft SQL Server\130\Tools\Binn\;c:\Program Files\Microsoft SQL Server\Client SDK\ODBC\170\Tools\Binn\;c:\ProgramData\chocolatey\bin;c:\Git\mingw64\bin;c:\Git\cmd;c:\Users\nalexander\.cargo\bin;c:\Users\nalexander\AppData\Local\Microsoft\WindowsApps;c:\LLVM\bin;c:\Users\nalexander\AppData\Roaming\emax64\libexec\emacs\28.0.50\x86_64-w64-mingw32;c:\Windows\system32;c:\Windows;c:\Program Files (x86)\Microsoft Visual Studio\2019\Community\VC\Tools\MSVC\14.25.28610\bin\Hostx64\x64;c:\Users\nalexander\Mozilla\objdirs\objdir-browser-compile\dist\bin' MOZ_WEBRENDER=0 MOZ_DISABLE_CONTENT_SANDBOX=1 MOZ_HEADLESS=1 MOZ_DISABLE_NONLOCAL_CONNECTIONS=1 DISPLAY=77 MOZNODE_EXEC_PORT=65402 MOZ_CRASHREPORTER_NO_REPORT=1 'XPCSHELL_TEST_TEMP_DIR=c:\Users\nalexander\Mozilla\objdirs\objdir-browser-compile\temp\xpc-other-ne65_h' 'c:\Users\nalexander\Mozilla\objdirs\objdir-browser-compile\dist\bin\xpcshell.exe' -g 'c:\Users\nalexander\Mozilla\objdirs\objdir-browser-compile\dist\bin' -a 'c:\Users\nalexander\Mozilla\objdirs\objdir-browser-compile\dist\bin\browser' -m -e 'const _HEAD_JS_PATH = "c:/Users/nalexander/Mozilla/gecko/testing/xpcshell/head.js";' -e 'const _MOZINFO_JS_PATH = "c:\\users\\nalexa~1\\appdata\\local\\temp\\firefox\\xpcshellprofile\\mozinfo.json";' -e 'const _PREFS_FILE = "c:\\Users\\nalexander\\Mozilla\\objdirs\\objdir-browser-compile\\temp\\user.js";' -e 'const _TESTING_MODULES_DIR = "c:\\Users\\nalexander\\Mozilla\\objdirs\\objdir-browser-compile\\_tests\\modules\\";' -f 'c:\Users\nalexander\Mozilla\gecko\testing\xpcshell\head.js' -p 'c:\Users\nalexander\Mozilla\objdirs\objdir-browser-compile\temp\xpc-plugins-fnqegi' -e 'const _HEAD_FILES = ["c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile/_tests/xpcshell/toolkit/components/backgroundtasks/tests/xpcshell/head.js"];' -e 'const _JSDEBUGGER_PORT = 0;' -e 'const _TEST_FILE = ["c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile/_tests/xpcshell/toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js"];' -e 'const _TEST_NAME = "toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js";' -e '_execute_test(); quit(0);')
 0:19.55 pid:18440 Full command: [u'c:\\Users\\nalexander\\Mozilla\\objdirs\\objdir-browser-compile\\dist\\bin\\xpcshell.exe', '-g', u'c:\\Users\\nalexander\\Mozilla\\objdirs\\objdir-browser-compile\\dist\\bin', '-a', u'c:\\Users\\nalexander\\Mozilla\\objdirs\\objdir-browser-compile\\dist\\bin\\browser', '-m', '-e', 'const _HEAD_JS_PATH = "c:/Users/nalexander/Mozilla/gecko/testing/xpcshell/head.js";', '-e', u'const _MOZINFO_JS_PATH = "c:\\\\users\\\\nalexa~1\\\\appdata\\\\local\\\\temp\\\\firefox\\\\xpcshellprofile\\\\mozinfo.json";', '-e', u'const _PREFS_FILE = "c:\\\\Users\\\\nalexander\\\\Mozilla\\\\objdirs\\\\objdir-browser-compile\\\\temp\\\\user.js";', '-e', u'const _TESTING_MODULES_DIR = "c:\\\\Users\\\\nalexander\\\\Mozilla\\\\objdirs\\\\objdir-browser-compile\\\\_tests\\\\modules\\\\";', '-f', 'c:\\Users\\nalexander\\Mozilla\\gecko\\testing\\xpcshell\\head.js', '-p', u'c:\\Users\\nalexander\\Mozilla\\objdirs\\objdir-browser-compile\\temp\\xpc-plugins-fnqegi', '-e', u'const _HEAD_FILES = ["c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile/_tests/xpcshell/toolkit/components/backgroundtasks/tests/xpcshell/head.js"];', '-e', 'const _JSDEBUGGER_PORT = 0;', '-e', u'const _TEST_FILE = ["c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile/_tests/xpcshell/toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js"];', '-e', u'const _TEST_NAME = "toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js";', '-e', '_execute_test(); quit(0);']
pid:18440 [Parent 18440: Main Thread]: W/nsUpdateSyncManager GetSingleton, !gUpdateSyncManager
 0:19.55 pid:18440 [Parent 18440: Main Thread]: W/nsUpdateSyncManager [bf8a1ee0] nsUpdateSyncManager: 0
 0:19.55 pid:18440 [Parent 18440: Main Thread]: W/nsUpdateSyncManager [bf8a1ee0] OpenLock: mLock: ffffffff, anAppFile: 0
 0:19.55 pid:18440 [Parent 18440: Main Thread]: W/nsUpdateSyncManager [bf8a1ee0] anAppFile is not given
 0:19.55 pid:18440 [Parent 18440: Main Thread]: W/nsUpdateSyncManager [bf8a1ee0] appDirPath is: c:\\Users\\nalexander\\Mozilla\\objdirs\\objdir-browser-compile\\dist\\bin
 0:19.55 pid:18440 [Parent 18440: Main Thread]: E/nsUpdateSyncManager OpenMultiInstanceLock: C:\\ProgramData\\Mozilla\\UpdateLock-6D33A051B88715B6
 0:19.55 pid:18440 [Parent 18440: Main Thread]: E/nsUpdateSyncManager OpenMultiInstanceLock: handle from CreateFileW is 4ac, last error: 0
 0:19.55 pid:18440 [Parent 18440: Main Thread]: E/nsUpdateSyncManager OpenMultiInstanceLock: handle from LockFileEx is 4ac
 0:19.55 pid:18440 [Parent 18440: Main Thread]: E/nsUpdateSyncManager OpenMultiInstanceLock: returning handle 4ac
 0:19.55 pid:18440 [Parent 18440: Main Thread]: W/nsUpdateSyncManager GetSingleton: returning bf8a1ee0
 0:19.55 pid:18440 [Parent 18440: Main Thread]: W/nsUpdateSyncManager [bf8a1ee0] Observe: xpcom-startup
 0:19.59 pid:18440 [Parent 18440, Main Thread] WARNING: Failed to get directory to cache.: file c:/Users/nalexander/Mozilla/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
 0:19.59 pid:18440 [Parent 18440, Main Thread] WARNING: Failed to get directory to cache.: file c:/Users/nalexander/Mozilla/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
 0:19.59 pid:18440 [Parent 18440, Main Thread] WARNING: Failed to get directory to cache.: file c:/Users/nalexander/Mozilla/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
 0:19.59 pid:18440 [Parent 18440, Main Thread] WARNING: Failed to get directory to cache.: file c:/Users/nalexander/Mozilla/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
 0:19.61 pid:18440 [Parent 18440, Main Thread] WARNING: Failed to get directory to cache.: file c:/Users/nalexander/Mozilla/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
 0:19.64 pid:18440 [Parent 18440, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file c:/Users/nalexander/Mozilla/gecko/toolkit/crashreporter/nsExceptionHandler.cpp:2896
 0:19.77 INFO (xpcshell/head.js) | test MAIN run_test pending (1)
 0:19.77 INFO (xpcshell/head.js) | test run_next_test 0 pending (2)
 0:19.77 INFO (xpcshell/head.js) | test MAIN run_test finished (2)
 0:19.77 INFO running event loop
 0:19.77 INFO toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js | Starting test_backgroundtask_update_sync_manager
 0:19.77 INFO (xpcshell/head.js) | test test_backgroundtask_update_sync_manager pending (2)
 0:19.78 PASS test_backgroundtask_update_sync_manager - [test_backgroundtask_update_sync_manager : 23] resource://testing-common is not substituted - {"spec":"file:///c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile/_tests/modules/","prePath":"file://","scheme":"file","userPass":"","username":"","password":"","hostPort":"","host":"","port":-1,"pathQueryRef":"/c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile/_tests/modules/","equals":"function equals() {\\n    [native code]\\n}","schemeIs":"function schemeIs() {\\n    [native code]\\n}","resolve":"function resolve() {\\n    [native code]\\n}","asciiSpec":"file:///c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile/_tests/modules/","asciiHostPort":"","asciiHost":"","ref":"","equalsExceptRef":"function equalsExceptRef() {\\n    [native code]\\n}","specIgnoringRef":"file:///c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile/_tests/modules/","hasRef":false,"filePath":"/c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile/_tests/modules/","query":"","displayHost":"","displayHostPort":"","displaySpec":"file:///c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile/_tests/modules/","displayPrePath":"file://","mutate":"function mutate() {\\n    [native code]\\n}"} == true
 0:19.78 INFO "launching child process c:\\Users\\nalexander\\Mozilla\\objdirs\\objdir-browser-compile\\dist\\bin\\firefox.exe with args: --backgroundtask,update_sync_manager,c:\\Users\\nalexander\\Mozilla\\objdirs\\objdir-browser-compile\\dist\\bin\\xpcshell.exe and extra environment: {"XPCSHELL_TESTING_MODULES_URI":"file:///c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile/_tests/modules/"}"
 0:19.79 INFO (xpcshell/head.js) | test run_next_test 0 finished (2)
 0:19.80 pid:18440 [Parent 18440, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, kKnownEsrVersion) failed with result 0x80004002 (NS_NOINTERFACE): file c:/Users/nalexander/Mozilla/gecko/toolkit/components/resistfingerprinting/nsRFPService.cpp:553
 0:20.27 pid:18440 > *** You are running in background task mode. ***
 0:20.27 pid:18440 > *** You are running in headless mode.
 0:20.30 pid:18440 > [(null) 6100: Main Thread]: W/nsUpdateSyncManager [f71098e0] nsUpdateSyncManager: f71373c0
 0:20.30 pid:18440 > [(null) 6100: Main Thread]: W/nsUpdateSyncManager [f71098e0] OpenLock: mLock: ffffffff, anAppFile: f71373c0
 0:20.30 pid:18440 > [(null) 6100: Main Thread]: W/nsUpdateSyncManager [f71098e0] anAppFile is given
 0:20.30 pid:18440 > [(null) 6100: Main Thread]: W/nsUpdateSyncManager [f71098e0] appDirPath is: c:\\Users\\nalexander\\Mozilla\\objdirs\\objdir-browser-compile\\dist\\bin
 0:20.30 pid:18440 > [(null) 6100: Main Thread]: E/nsUpdateSyncManager OpenMultiInstanceLock: C:\\ProgramData\\Mozilla\\UpdateLock-6D33A051B88715B6
 0:20.30 pid:18440 > [(null) 6100: Main Thread]: E/nsUpdateSyncManager OpenMultiInstanceLock: handle from CreateFileW is 334, last error: b7
 0:20.30 pid:18440 > [(null) 6100: Main Thread]: E/nsUpdateSyncManager OpenMultiInstanceLock: handle from LockFileEx is 334
 0:20.30 pid:18440 > [(null) 6100: Main Thread]: E/nsUpdateSyncManager OpenMultiInstanceLock: returning handle 334
 0:20.30 pid:18440 > [(null) 6100: Main Thread]: W/nsUpdateSyncManager [f71098e0] IsOtherInstanceRunning: mLock: 334
 0:20.30 pid:18440 > [6100, Main Thread] WARNING: !ShouldProcessUpdates(): other instance is running: file c:/Users/nalexander/Mozilla/gecko/toolkit/xre/nsAppRunner.cpp:4245
 0:20.45 pid:18440 > console.error: BackgroundTasksManager: 
 0:20.45 pid:18440 > 
 0:20.45 pid:18440 > [Parent 6100: Main Thread]: W/nsUpdateSyncManager GetSingleton: returning f71098e0
 0:20.45 pid:18440 > [Parent 6100: Main Thread]: W/nsUpdateSyncManager [f71098e0] ResetLock: mLock: 334, anAppFile: fe5da190
 0:20.45 pid:18440 > [Parent 6100: Main Thread]: E/nsUpdateSyncManager ReleaseMultiInstanceLock: lock is 334, last error: 0
 0:20.45 pid:18440 > [Parent 6100: Main Thread]: W/nsUpdateSyncManager [f71098e0] ResetLock: mLock: ffffffff, anAppFile: fe5da190 (after ReleaseLock)
 0:20.45 pid:18440 > [Parent 6100: Main Thread]: W/nsUpdateSyncManager [f71098e0] OpenLock: mLock: ffffffff, anAppFile: fe5da190
 0:20.45 pid:18440 > [Parent 6100: Main Thread]: W/nsUpdateSyncManager [f71098e0] anAppFile is given
 0:20.45 pid:18440 > [Parent 6100: Main Thread]: W/nsUpdateSyncManager [f71098e0] appDirPath is: c:\\Users\\nalexander\\Mozilla\\objdirs\\objdir-browser-compile\\dist\\bin
 0:20.45 pid:18440 > [Parent 6100: Main Thread]: E/nsUpdateSyncManager OpenMultiInstanceLock: C:\\ProgramData\\Mozilla\\UpdateLock-6D33A051B88715B6
 0:20.45 pid:18440 > [Parent 6100: Main Thread]: E/nsUpdateSyncManager OpenMultiInstanceLock: handle from CreateFileW is ffffffff, last error: 5
 0:20.45 pid:18440 > [Parent 6100: Main Thread]: E/nsUpdateSyncManager OpenMultiInstanceLock: CreateFileW failed, handle is ffffffff, last error: 0
 0:20.45 pid:18440 > [Parent 6100: Main Thread]: E/nsUpdateSyncManager OpenMultiInstanceLock: returning handle ffffffff
 0:20.45 pid:18440 > [Parent 6100: Main Thread]: W/nsUpdateSyncManager [f71098e0] IsOtherInstanceRunning: mLock: ffffffff
 0:20.49 pid:18440 > console.error: BackgroundTasksManager: 
 0:20.49 pid:18440 >   Backgroundtask named 'update_sync_manager' threw exception
 0:20.49 pid:18440 >   Message: [Exception... "Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsIUpdateSyncManager.isOtherInstanceRunning]"  nsresult: "0xc1f30001 (NS_ERROR_NOT_INITIALIZED)"  location: "JS frame :: resource://testing-common/backgroundtasks/BackgroundTask_update_sync_manager.jsm :: runBackgroundTask :: line 20"  data: no]
 0:20.49 pid:18440 >   Stack:
 0:20.49 pid:18440 >     runBackgroundTask@resource://testing-common/backgroundtasks/BackgroundTask_update_sync_manager.jsm:20:30
 0:20.49 pid:18440 > runBackgroundTaskNamed@resource://gre/modules/BackgroundTasksManager.jsm:117:26
 0:20.49 pid:18440 > 
 0:20.52 pid:18440 > [Parent 6100: Main Thread]: W/nsUpdateSyncManager [f71098e0] ~nsUpdateSyncManager: 55045370
 0:20.53 pid:18440 > Parent 6100, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file c:/Users/nalexander/Mozilla/gecko/xpcom/base/nsCycleCollector.cpp:3365
 0:20.53 pid:18440 > Parent 6100, Main Thread] WARNING: OOPDeinit() without successful OOPInit(): file c:/Users/nalexander/Mozilla/gecko/toolkit/crashreporter/nsExceptionHandler.cpp:3352
 0:20.55 pid:18440 > Parent 6100, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file c:/Users/nalexander/Mozilla/gecko/modules/libpref/Preferences.cpp:4377
 0:20.57 FAIL test_backgroundtask_update_sync_manager - [test_backgroundtask_update_sync_manager : 26] Another instance is running - 80 == 3
c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile/_tests/xpcshell/toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js:test_backgroundtask_update_sync_manager:26
c:\Users\nalexander\Mozilla\gecko\testing\xpcshell\head.js:_do_main:239
c:\Users\nalexander\Mozilla\gecko\testing\xpcshell\head.js:_execute_test:567
-e:null:1
 0:20.57 INFO exiting test
 0:20.57 ERROR Unexpected exception NS_ERROR_ABORT: 
_abort_failed_test@c:\Users\nalexander\Mozilla\gecko\testing\xpcshell\head.js:830:20
do_report_result@c:\Users\nalexander\Mozilla\gecko\testing\xpcshell\head.js:931:5
Assert<@c:\Users\nalexander\Mozilla\gecko\testing\xpcshell\head.js:73:21
proto.report@resource://testing-common/Assert.jsm:233:10
equal@resource://testing-common/Assert.jsm:275:8
test_backgroundtask_update_sync_manager@c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile/_tests/xpcshell/toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js:26:10
_do_main@c:\Users\nalexander\Mozilla\gecko\testing\xpcshell\head.js:239:6
_execute_test@c:\Users\nalexander\Mozilla\gecko\testing\xpcshell\head.js:567:5
@-e:1:1

 0:20.57 INFO exiting test
 0:20.59 pid:18440 [Parent 18440: Main Thread]: W/nsUpdateSyncManager [bf8a1ee0] Observe: xpcom-shutdown
 0:20.59 pid:18440 [Parent 18440: Main Thread]: E/nsUpdateSyncManager ReleaseMultiInstanceLock: lock is 4ac, last error: 0
 0:20.59 pid:18440 [Parent 18440, Main Thread] WARNING: A runnable was posted to a worker that is already shutting down!: file c:/Users/nalexander/Mozilla/gecko/dom/workers/WorkerPrivate.cpp:1442
 0:20.59 pid:18440 [Parent 18440, Main Thread] WARNING: Failed to dispatch offline status change event!: file c:/Users/nalexander/Mozilla/gecko/dom/workers/WorkerPrivate.cpp:1927
 0:20.59 pid:18440 [Parent 18440, Main Thread] WARNING: A runnable was posted to a worker that is already shutting down!: file c:/Users/nalexander/Mozilla/gecko/dom/workers/WorkerPrivate.cpp:1442
 0:20.59 pid:18440 [Parent 18440, Main Thread] WARNING: Failed to dispatch offline status change event!: file c:/Users/nalexander/Mozilla/gecko/dom/workers/WorkerPrivate.cpp:1927
 0:20.66 pid:18440 [Parent 18440: Main Thread]: W/nsUpdateSyncManager [bf8a1ee0] ~nsUpdateSyncManager: 55045370
 0:20.70 pid:18440 [Parent 18440, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file c:/Users/nalexander/Mozilla/gecko/xpcom/base/nsCycleCollector.cpp:3365
 0:20.72 pid:18440 [Parent 18440, Main Thread] WARNING: OOPDeinit() without successful OOPInit(): file c:/Users/nalexander/Mozilla/gecko/toolkit/crashreporter/nsExceptionHandler.cpp:3352
 0:20.72 pid:18440 [Parent 18440, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file c:/Users/nalexander/Mozilla/gecko/modules/libpref/Preferences.cpp:4377
 0:20.72 pid:18440 [Parent 18440, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file c:/Users/nalexander/Mozilla/gecko/xpcom/base/nsTraceRefcnt.cpp:202
 0:20.72 pid:18440 [Parent 18440, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file c:/Users/nalexander/Mozilla/gecko/xpcom/base/nsTraceRefcnt.cpp:202
 0:20.73 TEST_END: Test FAIL, expected PASS. Subtests passed 1/2. Unexpected 1
 0:20.75 INFO INFO | Result summary:
 0:20.75 INFO INFO | Passed: 0
 0:20.75 INFO INFO | Failed: 1
 0:20.75 INFO INFO | Todo: 0
 0:20.75 INFO INFO | Retried: 0
 0:20.75 SUITE_END
 0:20.75 INFO Node moz-http2 server shutting down ...
 0:20.75 
Overall Summary
===============

xpcshell
~~~~~~~~
Ran 3 checks (2 subtests, 1 tests)
Expected results: 1
Unexpected results: 2
  test: 1 (1 fail)
  subtest: 1 (1 fail)

Unexpected Results
------------------
toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js
  FAIL test_backgroundtask_update_sync_manager - [test_backgroundtask_update_sync_manager : 26] Another instance is running - 80 == 3
c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile/_tests/xpcshell/toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js:test_backgroundtask_update_sync_manager:26
c:\Users\nalexander\Mozilla\gecko\testing\xpcshell\head.js:_do_main:239
c:\Users\nalexander\Mozilla\gecko\testing\xpcshell\head.js:_execute_test:567
-e:null:1
  FAIL toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js - xpcshell return code: 0
ERROR Unexpected exception NS_ERROR_ABORT: 
_abort_failed_test@c:\Users\nalexander\Mozilla\gecko\testing\xpcshell\head.js:830:20
do_report_result@c:\Users\nalexander\Mozilla\gecko\testing\xpcshell\head.js:931:5
Assert<@c:\Users\nalexander\Mozilla\gecko\testing\xpcshell\head.js:73:21
proto.report@resource://testing-common/Assert.jsm:233:10
equal@resource://testing-common/Assert.jsm:275:8
test_backgroundtask_update_sync_manager@c:/Users/nalexander/Mozilla/objdirs/objdir-browser-compile/_tests/xpcshell/toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js:26:10
_do_main@c:\Users\nalexander\Mozilla\gecko\testing\xpcshell\head.js:239:6
_execute_test@c:\Users\nalexander\Mozilla\gecko\testing\xpcshell\head.js:567:5
@-e:1:1

I can produce the patch if needed, but I think it's fairly straight-forward to read the log.

mhowell: have you any thoughts about this? I feel like the next step for debugging is to use Process Explorer to dig into the various handles in play, but that's a bridge too far for me...

Flags: needinfo?(mhowell)

Set release status flags based on info from the regressing bug 1553982

Hmm. Yeah, I don't see where it could be getting ERROR_ACCESS_DENIED from. I don't think it can be a permissions issue, which is most often how that error happens. ERROR_SHARING_VIOLATION seems more likely, but I don't know any scenarios for that that make sense either. Another thing I thought of was what would happen if the exclusive lock was held by one process while another is in resetLock, but that would not block it from opening the handle. I think you're right and tracing the sequence of events in ProcMon is the next step.

Flags: needinfo?(mhowell)

For the benefit of release management: this has no user impact that we are aware of. The lock in question is taken very early in Firefox's lifecycle and not released until process death. There is no plausible situation where we would see the same process release and re-take the lock: it really arises only during testing, and even then it's such an odd situation that we might not care to address it.

If you can provide a patch (on top of bug 1695797?) to reproduce this, I can give it a spin in procmon.

Severity: -- → S4
Flags: needinfo?(nalexander)
Priority: -- → P3

(In reply to Adam Gashlin (he/him) [:agashlin] from comment #7)

If you can provide a patch (on top of bug 1695797?) to reproduce this, I can give it a spin in procmon.

Certainly! https://phabricator.services.mozilla.com/D107717 has the patch; run the modified test like:

./mach test toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_update_sync_manager.js

You should see a log similar to the one I posted. I would be quite interested in seeing how you use procmon; maybe after you dig in you could give me a 5-10 minute walkthrough next time we talk?

Flags: needinfo?(nalexander)
Severity: S4 → S3

Adam helped me dig into this with procmon in our 1:1. It turns out... this is Just The Way The FILE_FLAG_DELETE_ON_CLOSE Works.

My understanding is that resetLock(...) will succeed as long as the process isn't re-using a path it already locked. That is, it doesn't stop other processes taking the multi-instance lock, just our own process re-taking the same lock.

Since this only happens in tests, there's nothing more to be done here.

Status: NEW → RESOLVED
Closed: 2 months ago
Resolution: --- → WONTFIX

The incorrect semantics for FILE_FLAG_DELETE_ON_CLOSE is going to bite us here. When a file opened with FILE_FLAG_DELETE_ON_CLOSE is closed, it either gets deleted (if this was the last handle to the last file object referencing the file) or it goes into a delete-pending state. In the delete-pending state, no one anywhere on the system can open the file; they get ERROR_ACCESS_DENIED (that's the win32 code used for the underlying STATUS_DELETE_PENDING). So what can happen is:

  1. The lockfile is opened once (A), creating it
  2. The lockfile is opened again (B), using the existing file
  3. B is reset
    3a. B is released, closing the file, which puts the lockfile in delete-pending since A still has it open
    3b. The file can't be reopened
  4. Any subsequent attempt to open the lockfile (until A is closed) will fail

resetLock(...) seems like it can only succeed if it's the only instance of the lock.

This could cause an issue as follows:

  1. Start Firefox instance A
  2. Start Firefox instance B
  3. Exit Firefox instance B (closing the lockfile and setting it in delete-pending)
  4. Start Firefox instance C (will fail to open the lockfile)
  5. Check for and apply updates in instance A, this will proceed even though instance C is running

Also, because the check fails open, any instance that runs after this will do updates if it can get the update mutex.

Of more immediate concern, given that the background task will regularly be running:

  1. Start Firefox, download and stage an update, leave it running
  2. Background task runs, doesn't update thanks to bug 1624992, but it does open and close the lockfile, which becomes delete-pending
  3. Background task runs again, can't open the lockfile, ShouldProcessUpdates() fails open, update is applied despite Firefox running.

I've demonstrated this with a pending 2021-03-10-21-58-46 Nightly update by running firefox.exe --backgroundtask success twice.

Blocks: 1695797
Status: RESOLVED → REOPENED
Resolution: WONTFIX → ---
Summary: Using `resetLock(XREExeF.path)` on Windows fails to re-open the multi-instance lock → Windows multi-instance lock becomes unusable when closed by one of two open instances

Oh my. Good sleuthing, :agashlin. These lock files are 0 bytes -- can we just remove this pesky FILE_FLAG_DELETE_ON_CLOSE and leave them hanging around?

:mhowell, have you an opinion on this? Perhaps you thought about it when implementing these locks?

Flags: needinfo?(mhowell)

(In reply to Nick Alexander :nalexander [he/him] from comment #11)

Oh my. Good sleuthing, :agashlin. These lock files are 0 bytes -- can we just remove this pesky FILE_FLAG_DELETE_ON_CLOSE and leave them hanging around?

Hm, good question, I don't remember exactly why we were insisting on deleting.

It might work to do something similar to the non-Windows method, check if we're the only instance when closing, and if so delete the file, I think setting FILE_DISPOSITION_DELETE | FILE_DISPOSITION_ON_CLOSE on the object with NtSetInformationFile has that effect? There's still a race, but should be similar in scope to what we've accepted for the non-Windows case. But if we don't need to delete at all then this all becomes simpler.

Yes, I think FILE_FLAG_DELETE_ON_CLOSE can be safely removed; I included it because I always like to clean things up properly wherever possible, but we're talking about a 0-byte file in a private location, the disposition of the file is not relevant state (only the lock is), and as Adam found we already accept possibly not being able to delete the thing on non-Windows. I would say just take it out and don't try to save it.

Flags: needinfo?(mhowell)

(In reply to Adam Gashlin (he/him) [:agashlin] from comment #12)

I think setting FILE_DISPOSITION_DELETE | FILE_DISPOSITION_ON_CLOSE on the object with NtSetInformationFile has that effect?

Scratch this, only available since Windows 10 RS1.

(In reply to Molly Howell (she/her) [:mhowell] from comment #13)

Yes, I think FILE_FLAG_DELETE_ON_CLOSE can be safely removed; I included it because I always like to clean things up properly wherever possible, but we're talking about a 0-byte file in a private location, the disposition of the file is not relevant state (only the lock is), and as Adam found we already accept possibly not being able to delete the thing on non-Windows. I would say just take it out and don't try to save it.

That sounds like the way to go then. Would you be ok with removing it for non-Windows as well, to avoid the complexity of IsOtherInstanceRunning and /proc/self/fd?

(In reply to Adam Gashlin (he/him) [:agashlin] from comment #14)

That sounds like the way to go then. Would you be ok with removing it for non-Windows as well, to avoid the complexity of IsOtherInstanceRunning and /proc/self/fd?

Yeah, I think that should be okay.

Assignee: nobody → agashlin
Severity: S3 → S2
Priority: P3 → P1
Summary: Windows multi-instance lock becomes unusable when closed by one of two open instances → Windows multi-instance lock becomes unusable when closed by one of several open instances

This seems likely to impact the effectiveness of bug 1553982, and we'll need it fixed as a prerequisite for background updates.

Assignee: agashlin → nalexander

We might make the uninstaller delete this file as well.

I think I'll have the time for this after all, thanks though!

Assignee: nalexander → agashlin

I've settled on only removing the flag for Windows rather than forcing parity by a) removing the deletion for non-Windows or b) adding a check for exclusive and delete to Windows as well. I think removing in the uninstaller is sufficient, and I didn't want to expand the scope of testing for this beyond the necessary Windows fix.

FILE_FLAG_DELETE_ON_CLOSE had the wrong semantics, rendering the lock
file unusable after it had been closed once.

Delete the lock file in the uninstaller as a simple alternative (given that
the lock file is not in a temporary location on Windows).

For a test I returned to the older form of
test_backgroundtask_update_sync_manager which initially exposed the issue:
It expects the background task to be able to detect the xpcshell instance
after running resetLock, which failed before this fix.

Depends on D108899

Pushed by agashlin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/57b176bfcc8f
Don't use FILE_FLAG_DELETE_ON_CLOSE for multi-instance locks. r=nalexander,application-update-reviewers.
Status: REOPENED → RESOLVED
Closed: 2 months ago2 months ago
Resolution: --- → FIXED
Target Milestone: --- → 89 Branch
You need to log in before you can comment on or make changes to this bug.