Merge pull request #348: Windows: wait for processes started as user

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":"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.
This commit is contained in:
Derrick Stolee 2020-03-06 12:09:45 -05:00 коммит произвёл GitHub
Родитель 6d115e0a40 0e53265b56
Коммит e8ea93c786
Не найден ключ, соответствующий данной подписи
Идентификатор ключа GPG: 4AEE18F83AFDEB23
2 изменённых файлов: 14 добавлений и 2 удалений

Просмотреть файл

@ -112,7 +112,7 @@ namespace Scalar.Platform.Windows
/// with the SE_TCB_NAME privilege.
/// </summary>
/// <returns>True on successful process start</returns>
public bool RunAs(string processName, string args)
public bool RunAs(string processName, string args, bool wait = false)
{
IntPtr environment = IntPtr.Zero;
IntPtr duplicate = IntPtr.Zero;
@ -153,6 +153,17 @@ namespace Scalar.Platform.Windows
try
{
this.tracer.RelatedInfo("Started process '{0} {1}' with Id {2}", processName, args, procInfo.ProcessId);
if (wait)
{
WaitForSingleObject(procInfo.ProcessHandle);
this.tracer.RelatedInfo("Finished process '{0} {1}' with Id {2}", processName, args, procInfo.ProcessId);
}
}
catch (Exception e)
{
this.tracer.RelatedError("Error when running process '{0} {1}' with Id {2}: {3}", processName, args, procInfo.ProcessId, e.ToString());
}
finally
{

Просмотреть файл

@ -38,7 +38,8 @@ namespace Scalar.Service
return currentUser.RunAs(
Configuration.Instance.ScalarLocation,
$"run {taskVerbName} \"{repoRoot}\" --{ScalarConstants.VerbParameters.InternalUseOnly} {this.internalVerbJson}");
$"run {taskVerbName} \"{repoRoot}\" --{ScalarConstants.VerbParameters.InternalUseOnly} {this.internalVerbJson}",
wait: true);
}
}
}