Fixes unhandled exception on trace if process cannot start

[dramos020]

Fixes #3381. This was occuring because the tool was still trying to call Process.HasExited even though an exception was thrown when trying to start the process. Fixed by maintaining a boolean that indicates that a process was successfully started and only tries to kill the process at the end if it was successfully started.

Here is the solution's output when an invalid file is given:

PS C:\code\diagnostics\artifacts\bin\dotnet-trace\Debug\netcoreapp3.1> ./dotnet-trace collect -- garbage
No profile or providers specified, defaulting to trace profile 'cpu-sampling'

Provider Name                           Keywords            Level               Enabled By
Microsoft-DotNETCore-SampleProfiler     0x0000F00000000000  Informational(4)    --profile
Microsoft-Windows-DotNETRuntime         0x00000014C14FCCBD  Informational(4)    --profile

Launching: garbage
Cannot start target process: garbage
System.ComponentModel.Win32Exception (2): An error occurred trying to start process 'garbage' with working directory 'C:\code\diagnostics\artifacts\bin\dotnet-trace\Debug\netcoreapp3.1'. The system cannot find the file specified.
   at System.Diagnostics.Process.StartWithCreateProcess(ProcessStartInfo startInfo)
   at System.Diagnostics.Process.Start()
   at Microsoft.Internal.Common.Utils.ProcessLauncher.Start(String diagnosticTransportName, CancellationToken ct, Boolean showChildIO, Boolean printLaunchCommand) in C:\code\diagnostics\src\Tools\Common\ReversedServerHelpers\ReversedServerHelpers.cs:line 99
[ERROR] System.InvalidOperationException: Failed to start 'garbage '.
   at Microsoft.Internal.Common.Utils.DiagnosticsClientBuilder.Build(CancellationToken ct, Int32 processId, String diagnosticPort, Boolean showChildIO, Boolean printLaunchCommand) in C:\code\diagnostics\src\Tools\Common\ReversedServerHelpers\ReversedServerHelpers.cs:line 219
   at Microsoft.Diagnostics.Tools.Trace.CollectCommandHandler.Collect(CancellationToken ct, IConsole console, Int32 processId, FileInfo output, UInt32 buffersize, String providers, String profile, TraceFileFormat format, TimeSpan duration, String clrevents, String clreventlevel, String name, String diagnosticPort, Boolean showchildio, Boolean resumeRuntime) in C:\code\diagnostics\src\Tools\dotnet-trace\CommandLine\Commands\CollectCommand.cs:line 169

Here is the solution's output when working with a valid .exe file:

PS C:\code\diagnostics\artifacts\bin\dotnet-trace\Debug\netcoreapp3.1> ./dotnet-trace collect -- C:\code\RuntimeTesting\bin\Debug\net6.0\RuntimeTesting.exe
No profile or providers specified, defaulting to trace profile 'cpu-sampling'

Provider Name                           Keywords            Level               Enabled By
Microsoft-DotNETCore-SampleProfiler     0x0000F00000000000  Informational(4)    --profile
Microsoft-Windows-DotNETRuntime         0x00000014C14FCCBD  Informational(4)    --profile

Launching: C:\code\RuntimeTesting\bin\Debug\net6.0\RuntimeTesting.exe
Process        : C:\code\RuntimeTesting\bin\Debug\net6.0\RuntimeTesting.exe
Output File    : C:\code\diagnostics\artifacts\bin\dotnet-trace\Debug\netcoreapp3.1\RuntimeTesting.exe_20220923_155320.nettrace

[00:00:00:00]   Recording trace 397.686  (KB)
Press <Enter> or <Ctrl+C> to exit...

Trace completed.
Process exited with code '0'.

[hoyosjs]

You might want to consider a step further. Is printing the exception to console in

diagnostics/src/Tools/Common/ReversedServerHelpers/ReversedServerHelpers.cs

Line 104 in 1bdd90c

Console.WriteLine(e.ToString());

really useful to users?

[noahfalk]

Glad you were able to find the issue but I recommend we change how the fix is implemented.

[dramos020]

Took the suggestion from Noah to move processStarted bool to be managed inside the ProcessLauncher in order to minimize coupling. Also changed the printing of exceptions when the process does not start properly to only print the message instead. This makes it clearer that the exception was caught and only displays information useful to most users. Failures now look like this:

PS C:\code\diagnostics\artifacts\bin\dotnet-trace\Debug\netcoreapp3.1> ./dotnet-trace collect -- garbage
No profile or providers specified, defaulting to trace profile 'cpu-sampling'

Provider Name                           Keywords            Level               Enabled By
Microsoft-DotNETCore-SampleProfiler     0x0000F00000000000  Informational(4)    --profile
Microsoft-Windows-DotNETRuntime         0x00000014C14FCCBD  Informational(4)    --profile

Launching: garbage
Cannot start target process: garbage
An error occurred trying to start process 'garbage' with working directory 'C:\code\diagnostics\artifacts\bin\dotnet-trace\Debug\netcoreapp3.1'. The system cannot find the file specified.
[ERROR] Failed to start 'garbage '.

[noahfalk]

LGTM with the one other change I commented inline

[noahfalk]

Rather than letting the code handle the error here we can refactor this slightly to get more useful error handling behavior.

1. Move the CommandLineErrorException to the Tools/Common code and remove the "Counters" from
   the namespace. This type can be generally useful and has nothing specific to counters.
   https://github.dev/dotnet/diagnostics/blob/main/src/Tools/dotnet-counters/CommandLineErrorException.cs

2. Instead of having ProcessLauncher.Start() print to the console on error, let it throw CommandLineErrorException instead and put the text it would have written to the console in the Exception message.

3. Then add a catch clause for the CommandLineErrorException that will print out that message in DiagnosticsServerRouterRunner.runRouter(...) and CollectCommandHandler.Collect(...). For example in Collect(...)

// these are errors we anticipated and we know the error message will make sense to
// print to the console
catch(CommandLineErrorException e)
{
    Console.Error.WriteLine("[ERROR] " + e.Message);
    collectionStopped = true;
    ret = ReturnCode.TracingError;
}
// these errors could be anything and the messages may not make sense without context
// add the stack trace to help diagnose even though its ugly. Ideally no errors would
// get here.
catch(Exception e)
{
    Console.Error.WriteLine(e.ToString());
    collectionStopped = true;
    ret = ReturnCode.TracingError;
}

Give that a shot and see if it produces a better looking result?

[dramos020]

I did this for CollectCommandHandler.Collect() and the output would look like this:

No profile or providers specified, defaulting to trace profile 'cpu-sampling'

Provider Name                           Keywords            Level               Enabled By
Microsoft-DotNETCore-SampleProfiler     0x0000F00000000000  Informational(4)    --profile
Microsoft-Windows-DotNETRuntime         0x00000014C14FCCBD  Informational(4)    --profile

Launching: garbage
[ERROR] Cannot start target process: garbage

I'm still not sure though why would add a catch clause for a CommandLineErrorException in DiagnosticsServerRouterRunner.runRouter(). I don't think Process.Start() ever gets called here. DiagnosticsServerRouterRunner.Start() and Router.Start() get called, both of which don't throw a CommandLineException.

[noahfalk]

I was under the impression that runRouter() calls OnRouterStarted() (here) and OnRouterStarted calls ProcessLauncher.Start() (here)

If I got that wrong my underlying intent is if ds-router calls ProcessLauncher.Start() anywhere then we should figure out what is the callstack where that call occurs and make sure the CommandLineErrorException will be caught.

[noahfalk]

Can we also add this to the CommandLineErrorException message? "An error occurred trying to start process 'garbage' with working directory 'C:\code\diagnostics\artifacts\bin\dotnet-trace\Debug\netcoreapp3.1'. The system cannot find the file specified. I assume this part of the text is coming from the Exception.Message property on the exception that is thrown by Process.Start()?

[dramos020]

I see, I hadn't checked OnRouterStarted() and I see the Process.Start() call now. I'll add the catch clause to runRouter().

Also, the message property from the exception thrown by Process.Start() is actually only:

The system cannot find the file specified.

Don't know if we still want to add it to the CommandLineErrorException message.

[dramos020]

Also, do you think we really need a separate catch statement for CommandLineErrorExceptions for runRouter()? The catch statement that is currently in place only sends the exception message for all exceptions. Unless we want to change it to log only the message for CommandLineErrorExceptions and the entire ToString() for all other exceptions.

[noahfalk]

@davmason - I've gotten tied up with some 1st party conf stuff and feel bad having the discussion delayed on me. I'm happy for you and Daniel to make the call together. Worst case we can always can always tweak the behavior later.

[davmason]

@dramos020 I think we should do what Noah suggested a few comments back and take the exception message from Process.Start and wrap it in a little extra text:

throw new CommandLineErrorException($"An error occurred trying to start process '{processName}' with working directory '{workingDir}'. {orginalException.Message}.");

Then we don't have to have to add a new handler for runRouter

[dramos020]

The error message now looks like this:

PS C:\code\diagnostics\artifacts\bin\dotnet-trace\Debug\netcoreapp3.1> ./dotnet-trace collect -- garbage
No profile or providers specified, defaulting to trace profile 'cpu-sampling'

Provider Name                           Keywords            Level               Enabled By
Microsoft-DotNETCore-SampleProfiler     0x0000F00000000000  Informational(4)    --profile
Microsoft-Windows-DotNETRuntime         0x00000014C14FCCBD  Informational(4)    --profile

Launching: garbage
[ERROR] An error occured trying to start process garbage with working directory C:\code\diagnostics\artifacts\bin\dotnet-trace\Debug\netcoreapp3.1. The system cannot find the file specified.

[noahfalk]

Looks great! 👍