Closed Bug 715746 Opened 14 years ago Closed 13 years ago

Intermittent toolkit\mozapps\update\test_svc\unit\test_0000_bootstrap_svc.js failure in head_update.js | failed: X == succeeded, where x is one of (7, 36, 46, 47, 48)

Categories

(Toolkit :: Application Update, defect)

Product:
Toolkit
Component:
Application Update
Platform:
x86_64
Windows 7
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla23

People

(Reporter: bbondy, Assigned: bbondy)

References

Details

(Keywords: intermittent-failure)

Attachments

(3 files, 10 obsolete files)

Patch v2. (already landed)
2.28 KB, patch
robert.strong.bugs
: review+
Details | Diff | Splinter Review
Patch v3 - Allow updates while callback is in use, but try to lock if possible
5.42 KB, patch
bbondy
: review+
Details | Diff | Splinter Review
Patch v6 - tests
24.75 KB, patch
bbondy
: review+
Details | Diff | Splinter Review
About one out of 100 times I've seen an intermittent orange failure with error state failed: 7 == succeeded. 7 means write error. I've actually only seen it 2-3 times on elm and they were always with the bootstrap 0000 test. I previously had different errors for each return point of write errors and it was with the callback open in particular. So in particular the error is from this part of the updater.cpp code: > // CreateFileW will fail if the callback executable is already in use. Since > // it isn't possible to update write the status file and return. > if (callbackFile == INVALID_HANDLE_VALUE) { > LOG(("NS_main: file in use - failed to exclusively open executable " \ > "file: " LOG_S "\n", argv[callbackIndex])); > LogFinish(); > WriteStatusFile(WRITE_ERROR); > NS_tremove(gCallbackBackupPath); > EXIT_WHEN_ELEVATED(elevatedLockFilePath, updateLockFileHandle, 1); > LaunchCallbackApp(argv[4], I have not seen this on m-c yet, but I think it will pop-up eventually.
A strange thing is we have no special handling of this code from the service, nor of the callback from the service code.
Summary: Intermittent service xpcshell test orange with failed: 7 == succeeded → Intermittent toolkit\mozapps\update\test_svc\unit\test_0000_bootstrap_svc.js failure in head_update.js | failed: 7 == succeeded
Making sure that people will find this if it happens on our Tinderboxes.
Blocks: 438871
Whiteboard: [orange]
I think Felipe Gomes got this same thing, he sent me his update.status and it shows failed: 7. CC'ing him. His maintenanceservice.log file shows that updater.exe returned an error. His update.log shows: SOURCE DIRECTORY C:\Users\Felipe\AppData\Local\Mozilla\Firefox\Nightly\updates\0 DESTINATION DIRECTORY C:\Program Files (x86)\Nightly NS_main: file in use - failed to exclusively open executable file: C:\Program Files (x86)\Nightly\firefox.exe He mentioned he did not have any other profiles open that he knows of. He is running Win7 x64.
Regarding comment 11, it could happen if he started the app, the update process started to happen, and he opened again right at the exact right time. All within say 1second. We do lock the file from being re-opened during update, but if you re-open at exactly the right time (with and without the service) then that could happen. That doesn't explain the intermittent test failure though, so still pondering.
I also tried manually adding a couple second firefox.exe sleep shutdown after launching updater.exe unelevated (which in turn runs the service to do the update). The update works correctly even with this sleep. I don't see anything wrong with the existing wait for PID code inside the unelevated updater which seems to have worked based on my test: > __int64 pid = _wtoi64(argv[3]); > if (pid != 0) { > HANDLE parent = OpenProcess(SYNCHRONIZE, false, (DWORD) pid); > // May return NULL if the parent process has already gone away. > // Otherwise, wait for the parent process to exit before starting the > // update. > if (parent) { > DWORD result = WaitForSingleObject(parent, 5000); > CloseHandle(parent); > if (result != WAIT_OBJECT_0) > return 1; > } > }
So I think the idea of the timed wait in the first place is in case the synchronization wait returns but the process is still in use by Windows. For some reason maybe this takes a bit longer when the service is in use. I tried to increase this wait and also I added some extra logging that would have been great to have when Felipe got the problem. I'll try this out on elm with a ton of xpcshell test restarts. There is no callback locking specific code introduced in the service so I'm hoping a slightly longer wait is all that's needed to fix this.
Comment on attachment 587418 [details] [diff] [review] Patch v1. Improve logging, wait longer. This appears to be fixed here: https://tbpl.mozilla.org/?tree=Elm&rev=6baa33f888c8 I don't really like the code around here in general, but it is just adjusting the parameters of an existing hack presumably made for the same reason. Also the logging will help if someone ever gets this again.
Attachment #587418 - Flags: review?(robert.bugzilla)
Comment on attachment 587418 [details] [diff] [review] Patch v1. Improve logging, wait longer. ># HG changeset patch ># Parent dd5bdbc4ff5c9f0bfbde47825a650ca8578acffc ># User Brian R. Bondy <netzen@gmail.com> >Bug 715746 - Intermittent toolkit\mozapps\update\test_svc\unit\test_0000_bootstrap_svc.js failure in head_update.js | failed: 7 == succeeded > >diff --git a/toolkit/mozapps/update/updater/updater.cpp b/toolkit/mozapps/update/updater/updater.cpp >--- a/toolkit/mozapps/update/updater/updater.cpp >+++ b/toolkit/mozapps/update/updater/updater.cpp >@@ -1967,37 +1967,39 @@ int NS_main(int argc, NS_tchar **argv) > sizeof(gCallbackBackupPath)/sizeof(gCallbackBackupPath[0]), > NS_T("%s" CALLBACK_BACKUP_EXT), argv[callbackIndex]); > NS_tremove(gCallbackBackupPath); > CopyFileW(argv[callbackIndex], gCallbackBackupPath, false); > > // Since the process may be signaled as exited by WaitForSingleObject before > // the release of the executable image try to lock the main executable file > // multiple times before giving up. >- int retries = 5; >+ int retries = 10; > do { > // By opening a file handle wihout FILE_SHARE_READ to the callback > // executable, the OS will prevent launching the process while it is > // being updated. > callbackFile = CreateFileW(argv[callbackIndex], > DELETE | GENERIC_WRITE, > // allow delete, rename, and write > FILE_SHARE_DELETE | FILE_SHARE_WRITE, > NULL, OPEN_EXISTING, 0, NULL); > if (callbackFile != INVALID_HANDLE_VALUE) > break; > >- Sleep(50); >+ DWORD lastError = GetLastError(); >+ LOG(("NS_main: callback app open attempt failed. " \ >+ "File: " LOG_S ". Last error: %d\n", argv[callbackIndex], lastError)); Since this could be logged repeatedly include an attempt counter like "attempt # failed" >+ >+ Sleep(100); > } while (--retries); > > // CreateFileW will fail if the callback executable is already in use. Since > // it isn't possible to update write the status file and return. > if (callbackFile == INVALID_HANDLE_VALUE) { >- LOG(("NS_main: file in use - failed to exclusively open executable " \ >- "file: " LOG_S "\n", argv[callbackIndex])); Don't remove this. It is helpful when troubleshooting to know exactly why the update was not applied. > LogFinish(); > WriteStatusFile(WRITE_ERROR); > NS_tremove(gCallbackBackupPath); > EXIT_WHEN_ELEVATED(elevatedLockFilePath, updateLockFileHandle, 1); > LaunchCallbackApp(argv[4], > argc - callbackIndex, > argv + callbackIndex, > usingService);
Attachment #587418 - Flags: review?(robert.bugzilla) → review-
Attachment #587418 - Attachment is obsolete: true
Attachment #587789 - Flags: review?(robert.bugzilla)
Attachment #587789 - Flags: review?(robert.bugzilla) → review+
Unless I am mistaken (I haven't looked at the test flow), another thing that can be done to help troubleshoot is to compare the contents of the update.log when this fails so it appears in the test output.
Good idea I'll post a new task for that for once things slow down with service related bugs.
Pushed to mozilla-inbound: http://hg.mozilla.org/integration/mozilla-inbound/rev/16d8c02193ab
Target Milestone: --- → mozilla12
https://hg.mozilla.org/mozilla-central/rev/16d8c02193ab
Status: NEW → RESOLVED
Closed: 14 years ago
Resolution: --- → FIXED
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Would you say this is reduced but not solved? Thanks for re-opening, it should not be happening on inbound.
Yeah, massively reduced, but the profiling one shouldn't have hit either, profiling auto-merges from m-c on every push so that had had your fix for a week.
ok thanks, I'll try to find a better fix for this which isn't fully based on waiting longer for the callback.
Depends on: 728731
Blocks: 757858
Depends on: 766567
Just an FYI we may see error code 7 for this bug change to 35, 36, or 37 once bug 766567 lands.
Summary: Intermittent toolkit\mozapps\update\test_svc\unit\test_0000_bootstrap_svc.js failure in head_update.js | failed: 7 == succeeded → Intermittent toolkit\mozapps\update\test_svc\unit\test_0000_bootstrap_svc.js failure in head_update.js | failed: 36 == succeeded (or if older code, failed: 7)
Rev3 WINNT 6.1 mozilla-inbound opt test xpcshell on 2012-06-22 11:54:02 PDT for push 372c93939e2b slave: talos-r3-w7-039 https://tbpl.mozilla.org/php/getParsedLog.php?id=12909558&tree=Mozilla-Inbound { TEST-INFO | c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\update\test_svc\unit\test_0000_bootstrap_svc.js | running test ... TEST-UNEXPECTED-FAIL | c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\update\test_svc\unit\test_0000_bootstrap_svc.js | test failed (with xpcshell return code: 0), see following log: >>>>>>> TEST-INFO | (xpcshell/head.js) | test 1 pending TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [shouldRunServiceTest : 1437] Checking if the service exists on this machine. TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [shouldRunServiceTest : 1443] Service exists, return value: 0 TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [setupUpdaterTest : 1850] testing successful removal of the directory used to apply the mar file TEST-PASS | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [setupUpdaterTest : 1852] false == false TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [waitForApplicationStop : 1586] Waiting for maintenanceservice_installer.exe to stop if necessary... TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [waitForApplicationStop : 1586] Waiting for maintenanceservice_tmp.exe to stop if necessary... TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [waitForApplicationStop : 1586] Waiting for maintenanceservice.exe to stop if necessary... TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [waitForServiceStop : 1556] Waiting for service to stop if necessary... TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [waitForServiceStop : 1566] Stopping service... TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [waitForServiceStop : 1580] Service stopped. TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [waitForApplicationStop : 1586] Waiting for maintenanceservice_installer.exe to stop if necessary... TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [waitForApplicationStop : 1586] Waiting for maintenanceservice_tmp.exe to stop if necessary... TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [waitForApplicationStop : 1586] Waiting for maintenanceservice.exe to stop if necessary... TEST-PASS | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [runUpdateUsingService : 1649] pending-service == pending-service TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [runUpdateUsingService : 1664] launching C:\Windows\System32\cmd.exe /D /Q /C c:\talos-slave\test\build\firefox\0000_svc_aus_test_app.exe -no-remote -process-updates -dump-args c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\update\test_svc\unit\app_args_log 1> c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\update\test_svc\unit\0000_svc_app_console_log 2>&1 TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [setEnvironment : 2788] setting the XRE_NO_WINDOWS_CRASH_DIALOG environment variable to 1... previously it didn't exist TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [setEnvironment : 2835] removing the XPCOM_MEM_LEAK_LOG environment variable... previous value c:\users\cltbld\appdata\local\temp\tmpmrhovp\runxpcshelltests_leaks.log TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [setEnvironment : 2842] setting the XPCOM_DEBUG_BREAK environment variable to warn... previous value stack-and-abort TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [setEnvironment : 2853] setting the MOZ_UPDATE_ROOT_OVERRIDE environment variable to c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\update\test_svc\unit\0000_svc_mar TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [setEnvironment : 2859] setting the MOZ_UPDATE_APPDIR_OVERRIDE environment variable to c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\update\test_svc\unit\0000_svc_applyToDir TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [setEnvironment : 2868] setting MOZ_NO_SERVICE_FALLBACK environment variable to 1 TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | copying c:\talos-slave\test\build\firefox\updater.exe to: c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\update\test_svc\unit\0000_svc_applyToDir TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | copying c:\talos-slave\test\build\firefox\maintenanceservice.exe to: c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\update\test_svc\unit\0000_svc_applyToDir TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | copying c:\talos-slave\test\build\firefox\maintenanceservice_installer.exe to: c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\update\test_svc\unit\0000_svc_applyToDir TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [resetEnvironment : 2888] setting the XPCOM_MEM_LEAK_LOG environment variable back to c:\users\cltbld\appdata\local\temp\tmpmrhovp\runxpcshelltests_leaks.log TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [resetEnvironment : 2894] setting the XPCOM_DEBUG_BREAK environment variable back to stack-and-abort TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [resetEnvironment : 2928] removing the XRE_NO_WINDOWS_CRASH_DIALOG environment variable TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [resetEnvironment : 2934] removing the MOZ_UPDATE_ROOT_OVERRIDE environment variable TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [resetEnvironment : 2940] removing the MOZ_UPDATE_APPDIR_OVERRIDE environment variable TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [resetEnvironment : 2950] removing MOZ_NO_SERVICE_FALLBACK environment variable TEST-INFO | (xpcshell/head.js) | test 2 finished TEST-INFO | (xpcshell/head.js) | running event loop TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [timerCallback : 1719] Still waiting to see the succeeded status, got applying for now... TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [waitForApplicationStop : 1586] Waiting for maintenanceservice_installer.exe to stop if necessary... TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [waitForApplicationStop : 1586] Waiting for maintenanceservice_tmp.exe to stop if necessary... TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [waitForApplicationStop : 1586] Waiting for maintenanceservice.exe to stop if necessary... TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [waitForServiceStop : 1556] Waiting for service to stop if necessary... TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [waitForServiceStop : 1566] Stopping service... TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [waitForServiceStop : 1580] Service stopped. TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [waitForApplicationStop : 1586] Waiting for maintenanceservice_installer.exe to stop if necessary... TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [waitForApplicationStop : 1586] Waiting for maintenanceservice_tmp.exe to stop if necessary... TEST-INFO | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | [waitForApplicationStop : 1586] Waiting for maintenanceservice.exe to stop if necessary... TEST-UNEXPECTED-FAIL | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | failed: 36 == succeeded - See following stack: JS frame :: c:\talos-slave\test\build\xpcshell\head.js :: do_throw :: line 440 JS frame :: c:\talos-slave\test\build\xpcshell\head.js :: _do_check_eq :: line 534 JS frame :: c:\talos-slave\test\build\xpcshell\head.js :: do_check_eq :: line 555 JS frame :: c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js :: timerCallback :: line 1726 } edmorley https://tbpl.mozilla.org/php/getParsedLog.php?id=12964181&tree=Mozilla-Inbound Rev3 WINNT 6.1 mozilla-inbound opt test xpcshell on 2012-06-25 01:48:49 slave: talos-r3-w7-063 TEST-UNEXPECTED-FAIL | c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\update\test_svc\unit\test_0000_bootstrap_svc.js | test failed (with xpcshell return code: 0), see following log: TEST-UNEXPECTED-FAIL | c:/talos-slave/test/build/xpcshell/tests/toolkit/mozapps/update/test_svc/unit/head_update.js | failed: 36 == succeeded - See following stack:
Depends on: 794234
Summary: Intermittent toolkit\mozapps\update\test_svc\unit\test_0000_bootstrap_svc.js failure in head_update.js | failed: 36 == succeeded (or if older code, failed: 7) → Intermittent toolkit\mozapps\update\test_svc\unit\test_0000_bootstrap_svc.js failure in head_update.js | failed: X == succeeded, where x is one of (7, 36, 46, 47, 48)
Whiteboard: [orange]
Brian, please may you take a look at this? At the moment, the failure rate of this test is high enough that it will be one of the ones disabled for too many intermittent failures, once I return from vacation in a few days time. Cheers :-)
Flags: needinfo?(netzen)
I think this may actually go away with a bug I'm doing soon for updating in Metro. It will allow the firefox.exe file to renamed out of the way. I'm working on that in early January, if you need to disable this before that lands though I'm ok with that.
Flags: needinfo?(netzen)
(In reply to Brian R. Bondy [:bbondy] from comment #419) > I think this may actually go away with a bug I'm doing soon for updating in > Metro. It will allow the firefox.exe file to renamed out of the way. I'm > working on that in early January, if you need to disable this before that > lands though I'm ok with that. Ah that's great - thank you for the update :-) In which case I'll leave as is for now. Hope you had a good vacation!
Note to self: this is currently around the 40th worst random orange offender.
If you want to disable this I'm fine with it. The metro work was reprioritized and I was moved off of the updating task that I was thinking would help this bug mentioned in Comment 419.
I've been looking at this and would like a go at it before it is disabled.
Assignee: netzen → robert.bugzilla
Status: REOPENED → ASSIGNED
(In reply to Robert Strong [:rstrong] (do not email) from comment #447) > I've been looking at this and would like a go at it before it is disabled. Any luck so far? :)
(In reply to Ryan VanderMeulen [:RyanVM] from comment #479) > (In reply to Robert Strong [:rstrong] (do not email) from comment #447) > > I've been looking at this and would like a go at it before it is disabled. > > Any luck so far? :) Not yet. :( Though I did make progress on / fix / land patches for several other orange bugs in the last month. :) This appears to only be happening around 4 to 5 times per week so I'd like to keep it enabled and it is on my list of bugs to work on.
As per previous discussions, this should fix this issue once and for all. Tested an update on oak with this and it worked great. This is also needed for Metro updates to work properly when both the Desktop and Metro browser are open.
Assignee: robert.bugzilla → netzen
Attachment #736910 - Flags: review?(robert.bugzilla)
Blocks: 833182
No longer depends on: 728731
No longer blocks: 757858
Comment on attachment 736910 [details] [diff] [review] Patch v1 - Allow updates while callback is in use, but try to lock if possible >diff --git a/toolkit/mozapps/update/updater/updater.cpp b/toolkit/mozapps/update/updater/updater.cpp >--- a/toolkit/mozapps/update/updater/updater.cpp >+++ b/toolkit/mozapps/update/updater/updater.cpp >... >@@ -2981,33 +2975,41 @@ int NS_main(int argc, NS_tchar **argv) > targetPath, lastWriteError)); > > Sleep(100); > } while (++retries <= max_retries); > > // CreateFileW will fail if the callback executable is already in use. Since > // it isn't possible to update write the status file and return. Please update this comment and check other comments that may make a similar statement > if (callbackFile == INVALID_HANDLE_VALUE) { >+ bool exitWithCallback = true; lastWriteError is all that is needed. > LOG(("NS_main: file in use - failed to exclusively open executable " \ > "file: " LOG_S, argv[callbackIndex])); > LogFinish(); > if (ERROR_ACCESS_DENIED == lastWriteError) { > WriteStatusFile(WRITE_ERROR_ACCESS_DENIED); >- } else if (ERROR_SHARING_VIOLATION == lastWriteError) { >- WriteStatusFile(possibleWriteError); >+ } else if (ERROR_SHARING_VIOLATION != lastWriteError) { >+ WriteStatusFile(WRITE_ERROR_CALLBACK_APP); > } else { >- WriteStatusFile(WRITE_ERROR_CALLBACK_APP); >+ // Usually we want to lock out read access so another instance cannot >+ // be started. But it seems like we have another instance running, >+ // so allow the update to continue. >+ exitWithCallback = false; >+ LOG(("NS_main: callback in use continuing without exclusive access")); > } I think it is clearer to change the else if to the following. I don't think the comment is necessary here since the LOG text explains it well enough and more detail is available above. } else if (ERROR_SHARING_VIOLATION == lastWriteError) { LOG(("NS_main: callback file is in use, continuing without exclusive access")); } else { WriteStatusFile(WRITE_ERROR_CALLBACK_APP); } >- NS_tremove(gCallbackBackupPath); >- EXIT_WHEN_ELEVATED(elevatedLockFilePath, updateLockFileHandle, 1); >- LaunchCallbackApp(argv[4], >- argc - callbackIndex, >- argv + callbackIndex, >- sUsingService); >- return 1; >+ >+ if (exitWithCallback) { Just use if (ERROR_SHARING_VIOLATION == lastWriteError) { >+ NS_tremove(gCallbackBackupPath); >+ EXIT_WHEN_ELEVATED(elevatedLockFilePath, updateLockFileHandle, 1); >+ LaunchCallbackApp(argv[4], >+ argc - callbackIndex, >+ argv + callbackIndex, >+ sUsingService); >+ return 1; >+ } > } > } > } > I'd like to take a look at the comments again after the patch has been updated.
Attachment #736910 - Flags: review?(robert.bugzilla) → review-
(In reply to Robert Strong [:rstrong] (do not email) from comment #542) >... > > >- NS_tremove(gCallbackBackupPath); > >- EXIT_WHEN_ELEVATED(elevatedLockFilePath, updateLockFileHandle, 1); > >- LaunchCallbackApp(argv[4], > >- argc - callbackIndex, > >- argv + callbackIndex, > >- sUsingService); > >- return 1; > >+ > >+ if (exitWithCallback) { > Just use > if (ERROR_SHARING_VIOLATION == lastWriteError) { Should have been if (ERROR_SHARING_VIOLATION != lastWriteError) {
Attachment #587789 - Attachment description: Patch v2. → Patch v2. (already landed)
Attachment #736910 - Attachment is obsolete: true
Attachment #738146 - Flags: review?(robert.bugzilla)
Brian, I guess that by the removed dependency, you don't expect this to fix bug 757858?
Attached patch Patch v1 - tests (obsolete) — — Splinter Review
So basically this test patch does this: - Consolidates the 0160 unix and windows test (for test and test_svc xpcshell tests) into 1 test. 0161 and 0162 are untouched because they expect the update to fail on windows. This new patch still expects them to fail and expects it to fallback to a normal update.
Attachment #738155 - Flags: review?(robert.bugzilla)
(In reply to Ryan VanderMeulen [:RyanVM] from comment #550) > Brian, I guess that by the removed dependency, you don't expect this to fix > bug 757858? It may be fixed by chance once this is done but I don't plan on focusing on that one in the very near term. I'm not certain it is a strict dependency of this. I think we should evaluate that after this fix lands.
Attached patch Patch v2 - tests (obsolete) — — Splinter Review
Couple of extra test fixes after pushing to aok
Attachment #738155 - Attachment is obsolete: true
Attachment #738155 - Flags: review?(robert.bugzilla)
Attachment #738479 - Flags: review?(robert.bugzilla)
Comment on attachment 738146 [details] [diff] [review] Patch v2 - Allow updates while callback is in use, but try to lock if possible >diff --git a/toolkit/mozapps/update/updater/updater.cpp b/toolkit/mozapps/update/updater/updater.cpp >--- a/toolkit/mozapps/update/updater/updater.cpp >+++ b/toolkit/mozapps/update/updater/updater.cpp >... >@@ -2978,36 +2973,39 @@ int NS_main(int argc, NS_tchar **argv) > lastWriteError = GetLastError(); > LOG(("NS_main: callback app open attempt %d failed. " \ > "File: " LOG_S ". Last error: %d", retries, > targetPath, lastWriteError)); > > Sleep(100); > } while (++retries <= max_retries); > >- // CreateFileW will fail if the callback executable is already in use. Since >- // it isn't possible to update write the status file and return. >+ // CreateFileW will fail if the callback executable is already in use. >+ // We don't fail the update though. > if (callbackFile == INVALID_HANDLE_VALUE) { > LOG(("NS_main: file in use - failed to exclusively open executable " \ > "file: " LOG_S, argv[callbackIndex])); > LogFinish(); >- if (ERROR_ACCESS_DENIED == lastWriteError) { >- WriteStatusFile(WRITE_ERROR_ACCESS_DENIED); >- } else if (ERROR_SHARING_VIOLATION == lastWriteError) { >- WriteStatusFile(possibleWriteError); >+ >+ if (lastWriteError == ERROR_SHARING_VIOLATION) { >+ LOG(("NS_main: callback in use continuing without exclusive access")); nit: callback in use, continuing without exclusive access > } else { >- WriteStatusFile(WRITE_ERROR_CALLBACK_APP); >+ if (lastWriteError == ERROR_ACCESS_DENIED) >+ WriteStatusFile(WRITE_ERROR_ACCESS_DENIED); >+ else >+ WriteStatusFile(WRITE_ERROR_CALLBACK_APP); braces please
Attachment #738146 - Flags: review?(robert.bugzilla) → review+
Comment on attachment 738479 [details] [diff] [review] Patch v2 - tests Wrong patch
Attachment #738479 - Flags: review?(robert.bugzilla)
Attached patch Patch v2' - Tests (obsolete) — — Splinter Review
Sorry about that, this is the correct patch
Attachment #738479 - Attachment is obsolete: true
Attachment #738642 - Flags: review?(robert.bugzilla)
Attachment #738645 - Flags: review?(robert.bugzilla)
Comment on attachment 738645 [details] [diff] [review] Patch v1 - Cache the hashed value for better startup perf Pretty sure this is the wrong bug
Attachment #738645 - Flags: review?(robert.bugzilla)
Attachment #738645 - Attachment is obsolete: true
Implemented review nits, carried forward r+.
Attachment #738146 - Attachment is obsolete: true
Attachment #738671 - Flags: review+
Comment on attachment 738642 [details] [diff] [review] Patch v2' - Tests >diff --git a/toolkit/mozapps/update/test/unit/test_0160_appInUse_xp_unix_complete.js b/toolkit/mozapps/update/test/unit/test_0160_appInUse_xp_complete.js >rename from toolkit/mozapps/update/test/unit/test_0160_appInUse_xp_unix_complete.js >rename to toolkit/mozapps/update/test/unit/test_0160_appInUse_xp_complete.js Please rename it to test_0160_appInUse_complete.js >--- a/toolkit/mozapps/update/test/unit/test_0160_appInUse_xp_unix_complete.js >+++ b/toolkit/mozapps/update/test/unit/test_0160_appInUse_xp_complete.js >@@ -286,10 +286,16 @@ function checkUpdate() { > let now = Date.now(); > let applyToDir = getApplyDirFile(); > let timeDiff = Math.abs(applyToDir.lastModifiedTime - now); > do_check_true(timeDiff < MAX_TIME_DIFFERENCE); > } > > checkFilesAfterUpdateSuccess(); > >- checkCallbackAppLog(); >+ if (IS_WIN) { >+ logTestInfo("testing tobedeleted directory doesn't exist"); >+ let toBeDeletedDir = getApplyDirFile("tobedeleted", true); >+ do_check_false(toBeDeletedDir.exists()); >+ } >+ >+ waitForFilesInUse(); Are there really files in use that need to be waited on? I ask because the previous windows test called checkCallbackAppLog and now it is calling waitForFilesInUse. >diff --git a/toolkit/mozapps/update/test/unit/xpcshell.ini b/toolkit/mozapps/update/test/unit/xpcshell.ini >--- a/toolkit/mozapps/update/test/unit/xpcshell.ini >+++ b/toolkit/mozapps/update/test/unit/xpcshell.ini >@@ -23,14 +23,16 @@ reason = custom nsIUpdatePrompt > ; Tests that require the updater binary > [include:xpcshell_updater.ini] > skip-if = os == 'android' > ; Platform-specific updater tests > [include:xpcshell_updater_windows.ini] > run-if = os == 'win' > [include:xpcshell_updater_xp_unix.ini] > run-if = os == 'linux' || os == 'mac' || os == 'sunos' >+[test_0160_appInUse_xp_complete.js] >+run-if = os == 'linux' || os == 'sunos' || os == 'win' I am quite certain this test used to run on mac as well. Would be good to check if it also runs on gonk and just not have the line above. There is no mention that the conditionals apply to anything more than the previous test https://developer.mozilla.org/en-US/docs/Writing_xpcshell-based_unit_tests#Adding_your_tests_to_the_xpcshell_manifest >diff --git a/toolkit/mozapps/update/test_svc/unit/test_0160_appInUse_xp_complete_svc.js b/toolkit/mozapps/update/test_svc/unit/test_0160_appInUse_xp_complete_svc.js >new file mode 100644 Difficult to review the actual changes to the test. Also, it should be renamed to test_0160_appInUse_complete_svc.js
Attachment #738642 - Flags: review?(robert.bugzilla) → review-
Attached patch Patch v3 - Tests (obsolete) — — Splinter Review
Implemented review comments on tests patch.
Attachment #738642 - Attachment is obsolete: true
Attachment #740288 - Flags: review?(robert.bugzilla)
Comment on attachment 740288 [details] [diff] [review] Patch v3 - Tests >diff --git a/toolkit/mozapps/update/test/unit/xpcshell.ini b/toolkit/mozapps/update/test/unit/xpcshell.ini >--- a/toolkit/mozapps/update/test/unit/xpcshell.ini >+++ b/toolkit/mozapps/update/test/unit/xpcshell.ini >@@ -23,14 +23,16 @@ reason = custom nsIUpdatePrompt > ; Tests that require the updater binary > [include:xpcshell_updater.ini] > skip-if = os == 'android' > ; Platform-specific updater tests > [include:xpcshell_updater_windows.ini] > run-if = os == 'win' > [include:xpcshell_updater_xp_unix.ini] > run-if = os == 'linux' || os == 'mac' || os == 'sunos' >+[test_0160_appInUse__complete.js] >+ No need for the extra line. While you are here what do you think about removing the "; Platform-specific updater tests" comment. It is more confusing to me than helpful since it implies everything below is a "Platform-specific updater" test and it is already obvious what is and what isn't platform specific. > [test_bug595059.js] > skip-if = toolkit == "gonk" > reason = custom nsIUpdatePrompt > [test_bug794211.js] > [test_bug833708.js] > run-if = toolkit == "gonk" >diff --git a/toolkit/mozapps/update/test_svc/unit/test_0160_appInUse_xp_win_complete_svc.js b/toolkit/mozapps/update/test_svc/unit/test_0160_appInUse_complete_svc.js >rename from toolkit/mozapps/update/test_svc/unit/test_0160_appInUse_xp_win_complete_svc.js >rename to toolkit/mozapps/update/test_svc/unit/test_0160_appInUse_complete_svc.js >--- a/toolkit/mozapps/update/test_svc/unit/test_0160_appInUse_xp_win_complete_svc.js >+++ b/toolkit/mozapps/update/test_svc/unit/test_0160_appInUse_complete_svc.js >@@ -1,237 +1,277 @@ > /* Any copyright is dedicated to the Public Domain. > * http://creativecommons.org/publicdomain/zero/1.0/ > */ > >-/* Application in use complete MAR file patch apply failure test */ >+/* Application in use complete MAR file patch apply success test */ > > const TEST_ID = "0160_svc"; >+// All we care about is that the last modified time has changed so that Mac OS >+// X Launch Services invalidates its cache so the test allows up to one minute >+// difference in the last modified time. >+const MAX_TIME_DIFFERENCE = 60000; Out of curiousity, are the majority of these changes just to make this test as similar to the non service version as possible? I'm ok with that but I'd like to understand your reasons. >... > function run_test() { > if (!shouldRunServiceTest()) { > return; > } > > do_test_pending(); > do_register_cleanup(cleanupUpdaterTest); > > setupUpdaterTest(MAR_COMPLETE_FILE); > > // Launch the callback helper application so it is in use during the update > let callbackApp = getApplyDirFile("a/b/" + gCallbackBinFile); >+ callbackApp.permissions = PERMS_DIRECTORY; > let args = [getApplyDirPath() + "a/b/", "input", "output", "-s", "20"]; > let callbackAppProcess = AUS_Cc["@mozilla.org/process/util;1"]. > createInstance(AUS_Ci.nsIProcess); > callbackAppProcess.init(callbackApp); > callbackAppProcess.run(false, args, args.length); > > do_timeout(TEST_HELPER_TIMEOUT, waitForHelperSleep); > } > > function doUpdate() { > // apply the complete mar >- runUpdateUsingService(STATE_PENDING_SVC, STATE_SUCCEEDED, checkUpdateApplied); >-} >- >-function checkUpdateApplied() { >- setupHelperFinish(); Is setupHelperFinish really not needed in this case and it is needed in all other cases? >+ runUpdateUsingService(STATE_PENDING_SVC, STATE_SUCCEEDED, checkUpdate); > } > > function checkUpdate() { > logTestInfo("testing update.status should be " + STATE_SUCCEEDED); > let updatesDir = do_get_file(TEST_ID + UPDATES_DIR_SUFFIX); >- // The update status format for a failure is failed: # where # is the error >- // code for the failure. >- do_check_eq(readStatusFile(updatesDir).split(": ")[0], STATE_SUCCEEDED); >+ do_check_eq(readStatusFile(updatesDir), STATE_SUCCEEDED); > > checkFilesAfterUpdateSuccess(); >- checkUpdateLogContents(LOG_COMPLETE_SUCCESS); I suspect you removed this because the contents are somewhat different with the code changes than the usual case? I also suspect that it is possible to add it by accounting for those differences in checkUpdateLogContents. > > logTestInfo("testing tobedeleted directory doesn't exist"); > let toBeDeletedDir = getApplyDirFile("tobedeleted", true); > do_check_false(toBeDeletedDir.exists()); > >+ checkCallbackAppLog(); checkCallbackAppLog calls removeCallbackCopy which calls do_test_finished. >+ logTestInfo("DoneChecking callbackappplog"); Is this helpful? If so just add it to checkCallbackAppLog but use better text such as "checkCallbackAppLog finished" > checkCallbackServiceLog(); Also, checkCallbackServiceLog calls removeCallbackCopy which calls do_test_finished. Getting close
Attachment #740288 - Flags: review?(robert.bugzilla) → review-
> Out of curiousity, are the majority of these changes just to make this > test as similar to the non service version as possible? I'm ok with that but > I'd like to understand your reasons. Yes correct. Ehsan originally created the "test_svc" tests as a copy of the "test" tests. Since I now use the Unix one on Windows (since in use succeeds now) I Just did the same as Ehsan did orginally and copied it and made the service related changes.
(In reply to Brian R. Bondy [:bbondy] from comment #572) > > Out of curiousity, are the majority of these changes just to make this > > test as similar to the non service version as possible? I'm ok with that but > > I'd like to understand your reasons. > > Yes correct. Ehsan originally created the "test_svc" tests as a copy of the > "test" tests. Since I now use the Unix one on Windows (since in use > succeeds now) I Just did the same as Ehsan did orginally and copied it and > made the service related changes. Does it make sense to change / clean up the other tests with these changes?
Attached patch Patch v4 - tests (obsolete) — — Splinter Review
> Does it make sense to change / clean up the other tests with these changes? I don't think so, I've updated per the review comments and verified on oak and it still passes. For the check log success call, it was removed because locally for some reason that I couldn't figure out it tries to compare: "ects\mozilla\mozilla-central\objdir_debug\_tests\xpcshell\toolkit\mozapps\update\test_svc\unit\0160_svc_mar UPDATE TYPE complete PREPARE REMOVEFILE precomplete ..." to "UPDATE TYPE complete PREPARE REMOVEFILE precomplete ..." But it doesn't happen on the tinderbox push to oak so I just put the call back in.
Attachment #740288 - Attachment is obsolete: true
Attachment #740536 - Flags: review?(robert.bugzilla)
Comment on attachment 740536 [details] [diff] [review] Patch v4 - tests >--- a/toolkit/mozapps/update/test_svc/unit/test_0160_appInUse_xp_win_complete_svc.js >+++ b/toolkit/mozapps/update/test_svc/unit/test_0160_appInUse_complete_svc.js >@@ -1,235 +1,276 @@ > /* Any copyright is dedicated to the Public Domain. > * http://creativecommons.org/publicdomain/zero/1.0/ > */ > >-/* Application in use complete MAR file patch apply failure test */ >+/* Application in use complete MAR file patch apply success test */ > Please add a comment that this test has code that mirrors test_0160_appInUse_complete.js, the reason why it mirrors, and aren't actually used especially since there are comments that reference Mac OS X, etc. > const TEST_ID = "0160_svc"; >+// All we care about is that the last modified time has changed so that Mac OS >+// X Launch Services invalidates its cache so the test allows up to one minute >+// difference in the last modified time. >+const MAX_TIME_DIFFERENCE = 60000; >... > function doUpdate() { > // apply the complete mar >- runUpdateUsingService(STATE_PENDING_SVC, STATE_SUCCEEDED, checkUpdateApplied); >-} >- >-function checkUpdateApplied() { >- setupHelperFinish(); >+ runUpdateUsingService(STATE_PENDING_SVC, STATE_SUCCEEDED, checkUpdate); > } > > function checkUpdate() { >+ setupHelperFinish(); You can't call setupHelperFinish from checkUpdate since after it has verified that the helper has exited it calls checkUpdate. That is why there is the checkUpdateApplied function which calls setupHelperFinish. >+ > logTestInfo("testing update.status should be " + STATE_SUCCEEDED); > let updatesDir = do_get_file(TEST_ID + UPDATES_DIR_SUFFIX); >- // The update status format for a failure is failed: # where # is the error >- // code for the failure. >- do_check_eq(readStatusFile(updatesDir).split(": ")[0], STATE_SUCCEEDED); >+ do_check_eq(readStatusFile(updatesDir), STATE_SUCCEEDED); > > checkFilesAfterUpdateSuccess(); > checkUpdateLogContents(LOG_COMPLETE_SUCCESS); > > logTestInfo("testing tobedeleted directory doesn't exist"); > let toBeDeletedDir = getApplyDirFile("tobedeleted", true); > do_check_false(toBeDeletedDir.exists()); >
Attachment #740536 - Flags: review?(robert.bugzilla) → review-
> Please add a comment that this test has code that mirrors > test_0160_appInUse_complete.js, the reason why it mirrors, and aren't actually > used especially since there are comments that reference Mac OS X, etc. OK will do. For the reason why it mirrors it instead of just using the same file and running it twice (once with the service and once without), it's just for consistency with how it worked before. I think the whole "test_svc" could be combined with "test" but not in the context of this bug. > You can't call setupHelperFinish from checkUpdate since after it has verified > that the helper has exited it calls checkUpdate. That is why there is the > checkUpdateApplied function which calls setupHelperFinish. Oops k understood.
Attached patch Patch v5 - tests (obsolete) — — Splinter Review
Attachment #740536 - Attachment is obsolete: true
Attachment #740875 - Flags: review?(robert.bugzilla)
FWIW the existence of the test_svc directory is entirely my fault! IIRC there were a bunch of things different in the workflow of these tests which made the refactoring necessary to share much of the code a little non-trivial, but there's definitely no good reason why these tests need to stay separate indefinitely.
Combining them just because they can be combined isn't a good reason as I see it though I am not entirely against it either and having different code paths in the tests make them less comprehensible IMO. For the purpose of the Windows service I also think it made sense to just copy the existing non-service tests and modifying them so they would work under the service in order to have decent test coverage when the service and changes to the service landed. The things that concern me are that there is code that is non Windows in the Windows service tests due to the desire to keep the service and non-service tests the same which lessens comprehension and the desire to keep the service and non-service tests the same in this instance will lend itself towards incorrect assumptions being made when updating tests. Tests are a PITA but they also prevent breakage of app update ending up in the wild so spending some extra time when writing or modifying app update tests is a good thing as I see it.
The IS_MAC and related blocks are in all of the test_svc tests. I'm not against either philosophy of i) keeping copied code similar so differences are easier to spot and diffs are cleaner. or ii) removing stuff that isn't needed. But I'd like to fight to keep it in its current philosophy at the moment and if we want to change that philosophy to do it in another bug so it doesn't hold this up.
(In reply to Brian R. Bondy [:bbondy] from comment #584) > The IS_MAC and related blocks are in all of the test_svc tests. I'm not > against either philosophy of i) keeping copied code similar so differences > are easier to spot and diffs are cleaner. or ii) removing stuff that isn't > needed. > > But I'd like to fight to keep it in its current philosophy at the moment and > if we want to change that philosophy to do it in another bug so it doesn't > hold this up. I'm not asking for a change in the current philosophy and I hope you wouldn't actually "like to fight"... we are all pretty reasonable human beings in these parts! ;)
Comment on attachment 740875 [details] [diff] [review] Patch v5 - tests Assuming test passed on try r=me
Attachment #740875 - Flags: review?(robert.bugzilla) → review+
/me puts away his nunchucks
Going to land this with bug 572162 since I tested both of them together on oak.
(In reply to Brian R. Bondy [:bbondy] from comment #589) > Going to land this with bug 572162 since I tested both of them together on > oak. We ran into some complications in the dependents bugs so I'm reverting oak to m-c tip and testing only this to get it landed first.
Tested these cases manually and everything passes: - Verify that an update from before this patch to after this patch works w/ service - Verify that an update from before this patch to after this patch works w/o service - Verify that and update from before this bug to after this patch gives an error w/ service (first replace fails then falls back to normal replace which also fails with error 47) while a second instance is open. - Verify that an update from before this patch to after this patch gives an error w/o service while a second instance is open. - Verify that an update after this patch to after this patch works w/ service - Verify that an update after this patch to after this patch works w/o service - Verify that an update after this patch to after this patch gives an error w/o service while a second instance is open. - Verify that and update after this patch to after this patch gives an error w/ service (first replace fails then falls back to normal replace which also fails with error 47) while a second instance is open. - Made a small program that disallows FILE_SHARE_DELETE (which is also or renames) and tested an update should give a prompt on startup with an update error, and allow it to be subsequently applied.
Attached patch Patch v6 - tests — — Splinter Review
Re-disabled one of the tests that used to be disabled on android (We had enabled it in hopes it would just work, but doesn't). This all passes try results here: https://tbpl.mozilla.org/?tree=Try&rev=91dc0b7894e2 So it's ready to land. I'll land it on Sunday night though because I have a busy weekend and want to make sure I'm around in case of any problems.
Attachment #740875 - Attachment is obsolete: true
Attachment #742645 - Flags: review+
https://hg.mozilla.org/mozilla-central/rev/1d92e69d8450 https://hg.mozilla.org/mozilla-central/rev/05533d50f2f7
Status: ASSIGNED → RESOLVED
Closed: 14 years ago → 13 years ago
Resolution: --- → FIXED
Target Milestone: mozilla12 → mozilla23
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: