diff --git a/src/shared/Core/Authentication/AuthenticationBase.cs b/src/shared/Core/Authentication/AuthenticationBase.cs index ae228c35b4..d700f815f4 100644 --- a/src/shared/Core/Authentication/AuthenticationBase.cs +++ b/src/shared/Core/Authentication/AuthenticationBase.cs @@ -43,7 +43,7 @@ protected AuthenticationBase(ICommandContext context) // authentication helper's messages. Context.Trace.Flush(); - var process = ChildProcess.Start(Context.Trace2, procStartInfo); + var process = ChildProcess.Start(Context.Trace2, procStartInfo, Trace2ProcessClass.UIHelper); if (process is null) { throw new Exception($"Failed to start helper process: {path} {args}"); diff --git a/src/shared/Core/ChildProcess.cs b/src/shared/Core/ChildProcess.cs index af1b450790..a2c2223de3 100644 --- a/src/shared/Core/ChildProcess.cs +++ b/src/shared/Core/ChildProcess.cs @@ -11,6 +11,7 @@ public class ChildProcess : DisposableObject private DateTimeOffset _startTime; private DateTimeOffset _exitTime => Process.ExitTime; + private ProcessStartInfo _startInfo => Process.StartInfo; private int _id => Process.Id; @@ -19,13 +20,12 @@ public class ChildProcess : DisposableObject public StreamWriter StandardInput => Process.StandardInput; public StreamReader StandardOutput => Process.StandardOutput; public StreamReader StandardError => Process.StandardError; - public int Id => Process.Id; public int ExitCode => Process.ExitCode; - public static ChildProcess Start(ITrace2 trace2, ProcessStartInfo startInfo) + public static ChildProcess Start(ITrace2 trace2, ProcessStartInfo startInfo, Trace2ProcessClass processClass) { var childProc = new ChildProcess(trace2, startInfo); - childProc.Start(); + childProc.Start(processClass); return childProc; } @@ -33,12 +33,25 @@ public ChildProcess(ITrace2 trace2, ProcessStartInfo startInfo) { _trace2 = trace2; Process = new Process() { StartInfo = startInfo }; + Process.Exited += ProcessOnExited; } - public void Start() + public void Start(Trace2ProcessClass processClass) { ThrowIfDisposed(); + // Record the time just before the process starts, since: + // (1) There is no event related to Start as there is with Exit. + // (2) Using Process.StartTime causes a race condition that leads + // to an exception if the process finishes executing before the + // variable is passed to Trace2. + _startTime = DateTimeOffset.UtcNow; Process.Start(); + _trace2.WriteChildStart( + _startTime, + processClass, + _startInfo.UseShellExecute, + _startInfo.FileName, + _startInfo.Arguments); } public void WaitForExit() => Process.WaitForExit(); @@ -47,7 +60,20 @@ public void Start() protected override void ReleaseManagedResources() { + Process.Exited -= ProcessOnExited; Process.Dispose(); base.ReleaseUnmanagedResources(); } + + private void ProcessOnExited(object sender, EventArgs e) + { + if (sender is Process) + { + double elapsedTime = (_exitTime - _startTime).TotalSeconds; + _trace2.WriteChildExit( + elapsedTime, + _id, + Process.ExitCode); + } + } } diff --git a/src/shared/Core/Diagnostics/GitDiagnostic.cs b/src/shared/Core/Diagnostics/GitDiagnostic.cs index 97063b4a30..e09f091ddf 100644 --- a/src/shared/Core/Diagnostics/GitDiagnostic.cs +++ b/src/shared/Core/Diagnostics/GitDiagnostic.cs @@ -25,7 +25,7 @@ protected override Task RunInternalAsync(StringBuilder log, IList log.Append("Listing all Git configuration..."); ChildProcess configProc = CommandContext.Git.CreateProcess("config --list --show-origin"); - configProc.Start(); + configProc.Start(Trace2ProcessClass.Git); // To avoid deadlocks, always read the output stream first and then wait // TODO: don't read in all the data at once; stream it string gitConfig = configProc.StandardOutput.ReadToEnd().TrimEnd(); diff --git a/src/shared/Core/Git.cs b/src/shared/Core/Git.cs index 8f5a4a61cb..7c96c829ec 100644 --- a/src/shared/Core/Git.cs +++ b/src/shared/Core/Git.cs @@ -90,7 +90,7 @@ public GitVersion Version { using (var git = CreateProcess("version")) { - git.Start(); + git.Start(Trace2ProcessClass.Git); string data = git.StandardOutput.ReadToEnd(); git.WaitForExit(); @@ -120,7 +120,7 @@ public string GetCurrentRepository() { using (var git = CreateProcess("rev-parse --absolute-git-dir")) { - git.Start(); + git.Start(Trace2ProcessClass.Git); string data = git.StandardOutput.ReadToEnd(); git.WaitForExit(); @@ -141,7 +141,7 @@ public IEnumerable GetRemotes() { using (var git = CreateProcess("remote -v show")) { - git.Start(); + git.Start(Trace2ProcessClass.Git); // To avoid deadlocks, always read the output stream first and then wait // TODO: don't read in all the data at once; stream it string data = git.StandardOutput.ReadToEnd(); diff --git a/src/shared/Core/GitConfiguration.cs b/src/shared/Core/GitConfiguration.cs index 4217f533e1..9603b2db52 100644 --- a/src/shared/Core/GitConfiguration.cs +++ b/src/shared/Core/GitConfiguration.cs @@ -129,7 +129,7 @@ public void Enumerate(GitConfigurationLevel level, GitConfigurationEnumerationCa string levelArg = GetLevelFilterArg(level); using (ChildProcess git = _git.CreateProcess($"config --null {levelArg} --list")) { - git.Start(); + git.Start(Trace2ProcessClass.Git); // To avoid deadlocks, always read the output stream first and then wait // TODO: don't read in all the data at once; stream it string data = git.StandardOutput.ReadToEnd(); @@ -198,7 +198,7 @@ public bool TryGet(GitConfigurationLevel level, GitConfigurationType type, strin string typeArg = GetCanonicalizeTypeArg(type); using (ChildProcess git = _git.CreateProcess($"config --null {levelArg} {typeArg} {QuoteCmdArg(name)}")) { - git.Start(); + git.Start(Trace2ProcessClass.Git); // To avoid deadlocks, always read the output stream first and then wait // TODO: don't read in all the data at once; stream it string data = git.StandardOutput.ReadToEnd(); @@ -236,7 +236,7 @@ public void Set(GitConfigurationLevel level, string name, string value) string levelArg = GetLevelFilterArg(level); using (ChildProcess git = _git.CreateProcess($"config {levelArg} {QuoteCmdArg(name)} {QuoteCmdArg(value)}")) { - git.Start(); + git.Start(Trace2ProcessClass.Git); git.WaitForExit(); switch (git.ExitCode) @@ -257,7 +257,7 @@ public void Add(GitConfigurationLevel level, string name, string value) string levelArg = GetLevelFilterArg(level); using (ChildProcess git = _git.CreateProcess($"config {levelArg} --add {QuoteCmdArg(name)} {QuoteCmdArg(value)}")) { - git.Start(); + git.Start(Trace2ProcessClass.Git); git.WaitForExit(); switch (git.ExitCode) @@ -278,7 +278,7 @@ public void Unset(GitConfigurationLevel level, string name) string levelArg = GetLevelFilterArg(level); using (ChildProcess git = _git.CreateProcess($"config {levelArg} --unset {QuoteCmdArg(name)}")) { - git.Start(); + git.Start(Trace2ProcessClass.Git); git.WaitForExit(); switch (git.ExitCode) @@ -302,7 +302,7 @@ public IEnumerable GetAll(GitConfigurationLevel level, GitConfigurationT using (ChildProcess git = _git.CreateProcess(gitArgs)) { - git.Start(); + git.Start(Trace2ProcessClass.Git); // To avoid deadlocks, always read the output stream first and then wait // TODO: don't read in all the data at once; stream it string data = git.StandardOutput.ReadToEnd(); @@ -344,7 +344,7 @@ public IEnumerable GetRegex(GitConfigurationLevel level, GitConfiguratio using (ChildProcess git = _git.CreateProcess(gitArgs)) { - git.Start(); + git.Start(Trace2ProcessClass.Git); // To avoid deadlocks, always read the output stream first and then wait // TODO: don't read in all the data at once; stream it string data = git.StandardOutput.ReadToEnd(); @@ -386,7 +386,7 @@ public void ReplaceAll(GitConfigurationLevel level, string name, string valueReg using (ChildProcess git = _git.CreateProcess(gitArgs)) { - git.Start(); + git.Start(Trace2ProcessClass.Git); git.WaitForExit(); switch (git.ExitCode) @@ -413,7 +413,7 @@ public void UnsetAll(GitConfigurationLevel level, string name, string valueRegex using (ChildProcess git = _git.CreateProcess(gitArgs)) { - git.Start(); + git.Start(Trace2ProcessClass.Git); git.WaitForExit(); switch (git.ExitCode) diff --git a/src/shared/Core/PlatformUtils.cs b/src/shared/Core/PlatformUtils.cs index 1837da8f0b..6f8cb8689e 100644 --- a/src/shared/Core/PlatformUtils.cs +++ b/src/shared/Core/PlatformUtils.cs @@ -338,7 +338,7 @@ private static string GetOSVersion(ITrace2 trace2) using (var swvers = new ChildProcess(trace2, psi)) { - swvers.Start(); + swvers.Start(Trace2ProcessClass.Other); swvers.WaitForExit(); if (swvers.ExitCode == 0) @@ -359,7 +359,7 @@ private static string GetOSVersion(ITrace2 trace2) using (var uname = new ChildProcess(trace2, psi)) { - uname.Start(); + uname.Start(Trace2ProcessClass.Other); uname.Process.WaitForExit(); if (uname.ExitCode == 0) diff --git a/src/shared/Core/Trace2.cs b/src/shared/Core/Trace2.cs index 05bf5d297c..7ba44d3d28 100644 --- a/src/shared/Core/Trace2.cs +++ b/src/shared/Core/Trace2.cs @@ -20,7 +20,20 @@ public enum Trace2Event { Version = 0, Start = 1, - Exit = 2 + Exit = 2, + ChildStart = 3, + ChildExit = 4 +} + +/// +/// Classifications of processes invoked by GCM. +/// +public enum Trace2ProcessClass +{ + None = 0, + UIHelper = 1, + Git = 2, + Other = 3 } public class Trace2Settings @@ -61,6 +74,45 @@ public interface ITrace2 : IDisposable void Stop(int exitCode, [System.Runtime.CompilerServices.CallerFilePath] string filePath = "", [System.Runtime.CompilerServices.CallerLineNumber] int lineNumber = 0); + + /// + /// Writes information related to startup of child process to trace writer. + /// + /// Time at which child process began executing. + /// Process classification. + /// Specifies whether or not OS shell was used to start the process. + /// Name of application running in child process. + /// Arguments specific to the child process. + /// The child process's session id. + /// Path of the file this method is called from. + /// Line number of file this method is called from. + void WriteChildStart(DateTimeOffset startTime, + Trace2ProcessClass processClass, + bool useShell, + string appName, + string argv, + [System.Runtime.CompilerServices.CallerFilePath] + string filePath = "", + [System.Runtime.CompilerServices.CallerLineNumber] + int lineNumber = 0); + + /// + /// Writes information related to exit of child process to trace writer. + /// + /// Runtime of child process. + /// Id of exiting process. + /// Process exit code. + /// The child process's session id. + /// Path of the file this method is called from. + /// Line number of file this method is called from. + void WriteChildExit( + double elapsedTime, + int pid, + int code, + [System.Runtime.CompilerServices.CallerFilePath] + string filePath = "", + [System.Runtime.CompilerServices.CallerLineNumber] + int lineNumber = 0); } public class Trace2 : DisposableObject, ITrace2 @@ -77,6 +129,8 @@ public class Trace2 : DisposableObject, ITrace2 private string _sid; private bool _initialized; + // Increment with each new child process that is tracked + private int _childProcCounter = 0; public Trace2(ICommandContext commandContext) { @@ -119,6 +173,79 @@ public void Stop(int exitCode, string filePath, int lineNumber) WriteExit(exitCode, filePath, lineNumber); } + public void WriteChildStart(DateTimeOffset startTime, + Trace2ProcessClass processClass, + bool useShell, + string appName, + string argv, + string filePath = "", + int lineNumber = 0) + { + // Some child processes are started before TRACE2 can be initialized. + // Since certain dependencies are not available until initialization, + // we must immediately return if this method is invoked prior to + // initialization. + if (!_initialized) + { + return; + } + + // Always add name of the application the process is executing + var procArgs = new List() + { + Path.GetFileName(appName) + }; + + // If the process has arguments, append them. + if (!string.IsNullOrEmpty(argv)) + { + procArgs.AddRange(argv.Split(' ')); + } + + WriteMessage(new ChildStartMessage() + { + Event = Trace2Event.ChildStart, + Sid = _sid, + Time = startTime, + File = Path.GetFileName(filePath).ToLower(), + Line = lineNumber, + Id = ++_childProcCounter, + Classification = processClass, + UseShell = useShell, + Argv = procArgs + }); + } + + public void WriteChildExit( + double elapsedTime, + int pid, + int code, + string filePath = "", + int lineNumber = 0) + { + // Some child processes are started before TRACE2 can be initialized. + // Since certain dependencies are not available until initialization, + // we must immediately return if this method is invoked prior to + // initialization. + if (!_initialized) + { + return; + } + + WriteMessage(new ChildExitMessage() + { + Event = Trace2Event.ChildExit, + Sid = _sid, + Time = DateTimeOffset.UtcNow, + File = Path.GetFileName(filePath).ToLower(), + Line = lineNumber, + Id = _childProcCounter, + Pid = pid, + Code = code, + ElapsedTime = elapsedTime + }); + } + protected override void ReleaseManagedResources() { lock (_writersLock) @@ -415,3 +542,63 @@ public override string ToNormalString() return BuildNormalString($"elapsed:{ElapsedTime} code:{Code}"); } } + +public class ChildStartMessage : Trace2Message +{ + [JsonProperty("child_id", Order = 7)] + public long Id { get; set; } + + [JsonProperty("child_class", Order = 8)] + public Trace2ProcessClass Classification { get; set; } + + [JsonProperty("use_shell", Order = 9)] + public bool UseShell { get; set; } + + [JsonProperty("argv", Order = 10)] + public IList Argv { get; set; } + + public override string ToJson() + { + return JsonConvert.SerializeObject(this, + new StringEnumConverter(typeof(SnakeCaseNamingStrategy)), + new IsoDateTimeConverter() + { + DateTimeFormat = TimeFormat + }); + } + + public override string ToNormalString() + { + return BuildNormalString($"[{Id}] {string.Join(" ", Argv)}"); + } +} + +public class ChildExitMessage : Trace2Message +{ + [JsonProperty("child_id", Order = 7)] + public long Id { get; set; } + + [JsonProperty("pid", Order = 8)] + public int Pid { get; set; } + + [JsonProperty("code", Order = 9)] + public int Code { get; set; } + + [JsonProperty("t_rel", Order = 10)] + public double ElapsedTime { get; set; } + + public override string ToJson() + { + return JsonConvert.SerializeObject(this, + new StringEnumConverter(typeof(SnakeCaseNamingStrategy)), + new IsoDateTimeConverter() + { + DateTimeFormat = TimeFormat + }); + } + + public override string ToNormalString() + { + return BuildNormalString($"[{Id}] pid:{Pid} code:{Code} elapsed:{ElapsedTime}"); + } +} diff --git a/src/shared/TestInfrastructure/GitTestUtilities.cs b/src/shared/TestInfrastructure/GitTestUtilities.cs index 094ccc37a5..e99a00e009 100644 --- a/src/shared/TestInfrastructure/GitTestUtilities.cs +++ b/src/shared/TestInfrastructure/GitTestUtilities.cs @@ -29,7 +29,7 @@ public static string GetGitPath() using (var which = new ChildProcess(new NullTrace2(), psi)) { - which.Start(); + which.Start(Trace2ProcessClass.None); which.WaitForExit(); if (which.ExitCode != 0) @@ -80,7 +80,7 @@ public static GitResult ExecGit(string repositoryPath, string workingDirectory, procInfo.Environment["GIT_DIR"] = repositoryPath; - var proc = ChildProcess.Start(new NullTrace2(), procInfo); + var proc = ChildProcess.Start(new NullTrace2(), procInfo, Trace2ProcessClass.None); if (proc is null) { throw new Exception("Failed to start Git process"); diff --git a/src/shared/TestInfrastructure/Objects/NullTrace.cs b/src/shared/TestInfrastructure/Objects/NullTrace.cs index ae3154ef68..c1c5ac7a51 100644 --- a/src/shared/TestInfrastructure/Objects/NullTrace.cs +++ b/src/shared/TestInfrastructure/Objects/NullTrace.cs @@ -63,6 +63,23 @@ public class NullTrace2 : ITrace2 string fileName, int lineNumber) { } + public void WriteChildStart(DateTimeOffset startTime, + Trace2ProcessClass processClass, + bool useShell, + string appName, + string argv, + string filePath = "", + int lineNumber = 0) { } + + public void WriteChildExit( + double elapsedTime, + int pid, + int code, + string filePath = "", + int lineNumber = 0) { } + + public string SetSid() { return ""; } + #endregion #region IDisposable