8000 Windows: wait for processes started as user by derrickstolee · Pull Request #348 · microsoft/scalar · GitHub
[go: up one dir, main page]
More Web Proxy on the site http://driver.im/
Skip to content

Windows: wait for processes started as user #348

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 2 commits into from
Mar 6, 2020

Conversation

derrickstolee
Copy link
Contributor
@derrickstolee derrickstolee commented Mar 6, 2020

When running background maintenance from the service, we want to wait
for the process to finish to guarantee we do not have multiple
maintenance activities running at the same time. However, we have a
custom runner to launch the scalar run processes. This runner does
not properly wait for the process to end, so we quickly launch all of
the maintenance activities at once. This can be particularly bad after
opening a laptop after a long sleep.

It is reasonable that we were not waiting before, because this is the
same way that we launch the Scalar.Service.UI executable, and we
cannot wait for that to close.

By adding a wait (only in the case of maintenance verbs), we will
actually ensure that only one maintenance activity runs at a time.

Resolves the root cause of #328.

For evidence that this changes how this works, here is how the old service would run several config steps at startup:

[2020-03-05 15:56:38.4144 -05:00] MaintenanceTask.Execute (Start) {"UserId":"S-1-5-21-124525095-708259637-1543119021-1592205","SessionId":1,"task":"Config","Message":"Executing maintenance task"}
[2020-03-05 15:56:38.5188 -05:00] Information {"Message":"Starting auto upgrade checks."}
[2020-03-05 15:56:38.5537 -05:00] RunMaintenanceTaskForRepos_CallingMaintenance {"task":"config","UserId":"S-1-5-21-124525095-708259637-1543119021-1592205","SessionId":1,"NormalizedRepoRoot":"C:\\_git\\t\\scalar","rootPath":"C:\\"}
[2020-03-05 15:56:39.3643 -05:00] Information {"Message":"Started process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\t\\scalar\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 61192"}
[2020-03-05 15:56:39.3679 -05:00] RunMaintenanceTaskForRepos_CallingMaintenance {"task":"config","UserId":"S-1-5-21-124525095-708259637-1543119021-1592205","SessionId":1,"NormalizedRepoRoot":"
8000
C:\\_git\\office","rootPath":"C:\\"}
[2020-03-05 15:56:39.3798 -05:00] Information {"Message":"Started process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\office\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 26388"}
[2020-03-05 15:56:39.3842 -05:00] RunMaintenanceTaskForRepos_CallingMaintenance {"task":"config","UserId":"S-1-5-21-124525095-708259637-1543119021-1592205","SessionId":1,"NormalizedRepoRoot":"C:\\_git\\t\\os","rootPath":"C:\\"}
[2020-03-05 15:56:39.3944 -05:00] Information {"Message":"Started process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\t\\os\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 36288"}
[2020-03-05 15:56:39.3973 -05:00] RunMaintenanceTaskForRepos_CallingMaintenance {"task":"config","UserId":"S-1-5-21-124525095-708259637-1543119021-1592205","SessionId":1,"NormalizedRepoRoot":"C:\\_git\\vscode","rootPath":"C:\\"}
[2020-03-05 15:56:39.4074 -05:00] Information {"Message":"Started process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\vscode\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 46004"}
[2020-03-05 15:56:39.4098 -05:00] RunMaintenanceTaskForRepos_CallingMaintenance {"task":"config","UserId":"S-1-5-21-124525095-708259637-1543119021-1592205","SessionId":1,"NormalizedRepoRoot":"C:\\_git\\os","rootPath":"C:\\"}
[2020-03-05 15:56:39.4211 -05:00] Information {"Message":"Started process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\os\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 32584"}
[2020-03-05 15:56:39.4234 -05:00] RunMaintenanceTaskForRepos_CallingMaintenance {"task":"config","UserId":"S-1-5-21-124525095-708259637-1543119021-1592205","SessionId":1,"NormalizedRepoRoot":"C:\\_git\\AzureDevOps","rootPath":"C:\\"}
[2020-03-05 15:56:39.4333 -05:00] Information {"Message":"Started process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\AzureDevOps\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 44020"}
[2020-03-05 15:56:39.4356 -05:00] RunMaintenanceTaskForRepos_CallingMaintenance {"task":"config","UserId":"S-1-5-21-124525095-708259637-1543119021-1592205","SessionId":1,"NormalizedRepoRoot":"C:\\_git\\git","rootPath":"C:\\"}
[2020-03-05 15:56:39.4481 -05:00] Information {"Message":"Started process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\git\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 31332"}
[2020-03-05 15:56:39.4505 -05:00] RunMaintenanceTaskForRepos_MaintenanceSummary {"task":"config","UserId":"S-1-5-21-124525095-708259637-1543119021-1592205","SessionId":1,"NormalizedRepoRoot":"C:\\_git\\git","rootPath":"C:\\","reposInRegistryForUser":7,"reposSkipped":0,"reposSuccessfullyRemoved":0,"repoRemovalFailures":0,"reposMaintained":7,"maintenancePaused":false}
[2020-03-05 15:56:39.4594 -05:00] MaintenanceTask.Execute (Stop) {"DurationMs":1038}

and here is the new service:

[2020-03-06 08:43:42.4694 -05:00] MaintenanceTask.Execute (Start) {"UserId":"S-1-5-21-124525095-708259637-1543119021-1592205","SessionId":1,"task":"Config","Message":"Executing maintenance task"}
[2020-03-06 08:43:42.4861 -05:00] Information {"Message":"Starting auto upgrade checks."}
[2020-03-06 08:43:42.6021 -05:00] RunMaintenanceTaskForRepos_CallingMaintenance {"task":"config","UserId":"S-1-5-21-124525095-708259637-1543119021-1592205","SessionId":1,"NormalizedRepoRoot":"C:\\_git\\t\\scalar","rootPath":"C:\\"}
[2020-03-06 08:43:42.7170 -05:00] Information {"Message":"Started process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\t\\scalar\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 48472"}
[2020-03-06 08:43:46.4853 -05:00] Information {"Message":"Finished process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\t\\scalar\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 48472"}
[2020-03-06 08:43:46.4877 -05:00] RunMaintenanceTaskForRepos_CallingMaintenance {"task":"config","UserId":"S-1-5-21-124525095-708259637-1543119021-1592205","SessionId":1,"NormalizedRepoRoot":"C:\\_git\\office","rootPath":"C:\\"}
[2020-03-06 08:43:46.4986 -05:00] Information {"Message":"Started process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\office\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 32948"}
[2020-03-06 08:43:49.9659 -05:00] Information {"Message":"Finished process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\office\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 32948"}
[2020-03-06 08:43:49.9685 -05:00] RunMaintenanceTaskForRepos_CallingMaintenance {"task":"config","UserId":"S-1-5-21-124525095-708259637-1543119021-1592205","SessionId":1,"NormalizedRepoRoot":"C:\\_git\\t\\os","rootPath":"C:\\"}
[2020-03-06 08:43:49.9827 -05:00] Information {"Message":"Started process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\t\\os\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 44528"}
[2020-03-06 08:43:53.8194 -05:00] Information {"Message":"Finished process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\t\\os\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 44528"}
[2020-03-06 08:43:53.8220 -05:00] RunMaintenanceTaskForRepos_CallingMaintenance {"task":"config","UserId":"S-1-5-21-124525095-708259637-1543119021-1592205","SessionId":1,"NormalizedRepoRoot":"C:\\_git\\vscode","rootPath":"C:\\"}
[2020-03-06 08:43:53.8336 -05:00] Information {"Message":"Started process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\vscode\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 25068"}
[2020-03-06 08:43:57.6310 -05:00] Information {"Message":"Finished process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\vscode\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 25068"}
[2020-03-06 08:43:57.6333 -05:00] RunMaintenanceTaskForRepos_CallingMaintenance {"task":"config","UserId":"S-1-5-21-124525095-708259637-1543119021-1592205","SessionId":1,"NormalizedRepoRoot":"C:\\_git\\os","rootPath":"C:\\"}
[2020-03-06 08:43:57.6428 -05:00] Information {"Message":"Started process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\os\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 62984"}
[2020-03-06 08:44:01.3540 -05:00] Information {"Message":"Finished process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\os\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 62984"}
[2020-03-06 08:44:01.3558 -05:00] RunMaintenanceTaskForRepos_CallingMaintenance {"task":"config","UserId":"S-1-5-21-124525095-708259637-1543119021-1592205","SessionId":1,"NormalizedRepoRoot":"C:\\_git\\AzureDevOps","rootPath":"C:\\"}
[2020-03-06 08:44:01.3656 -05:00] Information {"Message":"Started process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\AzureDevOps\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 25300"}
[2020-03-06 08:44:04.9083 -05:00] Information {"Message":"Finished process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\AzureDevOps\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 25300"}
[2020-03-06 08:44:04.9098 -05:00] RunMaintenanceTaskForRepos_CallingMaintenance {"task":"config","UserId":"S-1-5-21-124525095-708259637-1543119021-1592205","SessionId":1,"NormalizedRepoRoot":"C:\\_git\\git","rootPath":"C:\\"}
[2020-03-06 08:44:04.9195 -05:00] Information {"Message":"Started process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\git\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 48832"}
[2020-03-06 08:44:08.6765 -05:00] Information {"Message":"Finished process 'C:\\Program Files\\Scalar\\Scalar.exe run config \"C:\\_git\\git\" --internal_use_only {\"ServiceName\":null,\"StartedByService\":true}' with Id 48832"}
[2020-03-06 08:44:08.6783 -05:00] RunMaintenanceTaskForRepos_MaintenanceSummary {"task":"config","UserId":"S-1-5-21-124525095-708259637-1543119021-1592205","SessionId":1,"NormalizedRepoRoot":"C:\\_git\\git","rootPath":"C:\\","reposInRegistryForUser":7,"reposSkipped":0,"reposSuccessfullyRemoved":0,"repoRemovalFailures":0,"reposMaintained":7,"maintenancePaused":false}
[2020-03-06 08:44:08.6842 -05:00] MaintenanceTask.Execute (Stop) {"DurationMs":26210}

Notice that before, these steps all launched in about 1.0
seconds, but actually waiting for the processes to complete
takes 26 seconds.

When running background maintenance from the service, we want to wait
for the process to finish to guarantee we do not have multiple
maintenance activities running at the same time. However, we have a
custom runner to launch the `scalar run` processes. This runner does
not properly wait for the process to end, so we quickly launch all of
the maintenance activities at once. This can be particularly bad after
opening a laptop after a long sleep.

By adding a wait, we will actually ensure that only one maintenance
activity runs at a time.

Resolves the root cause of microsoft#328

Signed-off-by: Derrick Stolee <dstolee@microsoft.com>
@derrickstolee derrickstolee added bug correctness issues platform:windows Affects Windows only labels Mar 6, 2020
Copy link
Member
@kewillford kewillford left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Approved with some suggestions. Is there anything that needs to be done for the non windows side? Are there any tests we can write for this?

@derrickstolee
Copy link
Contributor Author

Approved with some suggestions. Is there anything that needs to be done for the non windows side?

Thankfully, the Mac verb runner waits for the process to complete.

Are there any tests we can write for this?

The only thing I can think about is to somehow have the runner launch a process that waits for X seconds before returning, then timing how long the method takes. This seems like a problematic way to test.

Signed-off-by: Derrick Stolee <dstolee@microsoft.com>
@jeffhostetler
Copy link
Contributor

you could launch a process that waits in a loop while a lockfile on disk exists and then exit. have the tester create the lockfile and then do a waitforsingleobject with a timeout loop and delete the lockfile at some point. have the test confirm the the child exits after but not before that.

or just let the child do a long sleep and have the tester send a SIGHUP or SIGTERM.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug correctness issues platform:windows Affects Windows only
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants
0