RunAsync throws when process completes too quickly

[damonbarry]

A race condition was fixed in #15 by getting the process start time sooner (right after the process starts, rather than when it ends). I'm seeing the same exception as in #15 and I think it's because grabbing the start time right after calling process.Start() is still too slow in this case.

Here's a simple .NET Core 2.1 console app (gist) which does not reproduce the problem on my old laptop running Ubuntu, but reproduces it consistently on Raspberry Pi 3 + Rasbian Stretch Lite. However if I slow the command down by inserting a half-second sleep, the problem goes away on the Pi too.

const string Cmd = "systemctl --no-pager show dbus | grep ActiveState=";
string maybeSleep = (args.Length > 0) ? "sleep .5 && " : string.Empty;
string bashArgs = $"-c \"{maybeSleep}{Cmd}\"";
Console.WriteLine($"> bash {bashArgs}");

var info = new ProcessStartInfo
{
    FileName = "bash",
    Arguments = bashArgs,
};

using (ProcessResults result = await ProcessEx.RunAsync(info))
{
    Console.WriteLine($"exit code = {result.ExitCode}");
    Console.WriteLine(string.Join("\n", result.StandardOutput));
}

Here are the results on Pi 3. I used dotnet publish -c Release -f netcoreapp2.1 -r linux-arm . on my desktop to create a self-contained .NET Core app, then deployed it to my device, but you could install the 2.1 SDK and build directly on the Pi:

pi@mypi3:~ $ ./app/run-process-as-task-too-fast SLEEP
> bash -c "sleep .5 && systemctl --no-pager show dbus | grep ActiveState="
exit code = 0
ActiveState=active
pi@mypi3:~ $ ./app/run-process-as-task-too-fast
> bash -c "systemctl --no-pager show dbus | grep ActiveState="

Unhandled Exception: System.ComponentModel.Win32Exception: Unable to retrieve the specified information about the process or thread.  It may have exited or may be privileged.
   at System.Diagnostics.Process.GetStat()
   at System.Diagnostics.Process.get_StartTimeCore()
   at System.Diagnostics.Process.get_StartTime()
   at RunProcessAsTask.ProcessEx.<RunAsync>d__1.MoveNext()
   at run_process_as_task_too_fast.Program.<Main>d__0.MoveNext() in /home/damon/run-process-as-task-too-fast/Program.cs:line 23
   at run_process_as_task_too_fast.Program.<Main>(String[] args)
Aborted

[jamesmanning]

Hi @damonbarry ! Thanks for reporting this.

I think it's because grabbing the start time right after calling process.Start() is still too slow in this case.

So just to make sure I understand, even though we're accessing process.StartTime right after process.Start() has returned, the process has already exited because of how fast it ran (or that it ran effectively synchronously), right?

It looks like the CliWrap project avoids this issue by just grabbing 'Now' after Start returns.

https://github.com/Tyrrrz/CliWrap/blob/master/CliWrap/Cli.cs#L139

That seems less accurate, especially since I would imagine it'd have StartTime being after EndTime in this scenario, but safer in terms of hitting this issue. Grabbing it before calling Start seems a little safer in terms of ensuring it'd at least not be possible for StartTime to be after EndTime, and I'd imagine about the same in terms of accuracy.

@EamonNerbonne What do you think?

[damonbarry]

@jamesmanning that's correct.

I was wondering if you should guard the StartTime access with a try/catch, and in that one narrow case assign StartTime = EndTime? Although introducing try/catch machinery for a super rare condition is a little annoying (actually what's annoying is the behavior of StartTime but what are you gonna do).

[jamesmanning]

@damonbarry this should be fixed now with version 1.2.3 and commit 7507db4

[EamonNerbonne]

Personally I'm not convinced StartTime really has a reason to exists. If I as a caller care about timing (and I often do, for sure), then it's not exactly tricky to get a good enough approximation yourself, and as you can see, the built-in api isn't great to start with, so what exactly we're winning by using that here...

But given the fact that it's in the API already, might as well just to any kind of approximation that's good enough; so DateTime.Now sounds fine. As to the risk of process exit being before start: that could be fixed simply by using DateTime.Now there too. In any case, something tells me it's vanishingly unlikely anybody would actually observe a bug due to end < start: you'd need a really fast process, perhaps one with lots of overhead on .net side (e..g lots of input or output), and given the fast process you still need bad luck to miss observing start, and you need a timer with sufficient resolution such that despite the fast process, a system clock tick has passed between real end and fallback start, and you need client code that actually cares. None of those things seem likely by themselves, let alone all together.

[MaxCheetham]

I'm leaning on agreeing with Eamon with this. I have a project at work that this wraps around and I handle start and end date of processes externally.

[damonbarry]

Confirmed the fix. Thanks @jamesmanning!