Log on command exceptions (#633)

thomhurst · web-flow · commit 5f984775dcc9 · 2024-09-12T22:55:15.000+01:00
* Log on command exceptions

* Tests to assert output is logged even on exceptions

* Update CommandTests.cs

* Update CommandTests.cs

* Fix test

* Tidy
diff --git a/src/ModularPipelines.Build/ReleaseNotes.md b/src/ModularPipelines.Build/ReleaseNotes.md
@@ -0,0 +1 @@
+- Attempt to log command results when exceptions are thrown. E.g. Timeout TaskCanceledExceptions
diff --git a/src/ModularPipelines.Git/GitInformation.cs b/src/ModularPipelines.Git/GitInformation.cs
@@ -1,5 +1,6 @@
 using System.Runtime.CompilerServices;
 using ModularPipelines.Context;
+using ModularPipelines.Extensions;
 using ModularPipelines.FileSystem;
 using ModularPipelines.Git.Models;
 using ModularPipelines.Git.Options;
@@ -22,7 +23,7 @@ public GitInformation(StaticGitInformation staticGitInformation,
         _gitCommitMapper = gitCommitMapper;
     }
 
-    public Folder Root => _staticGitInformation.Root;
+    public Folder Root => _staticGitInformation.Root.AssertExists();
 
     public string? BranchName => _staticGitInformation.BranchName;
 
@@ -32,9 +33,9 @@ public GitInformation(StaticGitInformation staticGitInformation,
 
     public GitCommit? PreviousCommit => _staticGitInformation.PreviousCommit;
 
-    public int CommitsOnBranch => _staticGitInformation.CommitsOnBranch;
+    public int CommitsOnBranch => _staticGitInformation.CommitsOnBranch ?? 0;
 
-    public DateTimeOffset LastCommitDateTime => _staticGitInformation.LastCommitDateTime;
+    public DateTimeOffset LastCommitDateTime => _staticGitInformation.LastCommitDateTime ?? DateTimeOffset.MinValue;
 
     public string? LastCommitSha => _staticGitInformation.LastCommitSha;
 
diff --git a/src/ModularPipelines.Git/StaticGitInformation.cs b/src/ModularPipelines.Git/StaticGitInformation.cs
@@ -35,65 +35,78 @@ public async Task InitializeAsync()
         var tasks = new List<Task>();
 
         Async(async () =>
-            Root = (await GetOutput(new GitRevParseOptions
+            Root ??= (await GetOutput(new GitRevParseOptions
             {
                 ShowToplevel = true,
             }))!);
 
         Async(async () =>
-            BranchName = await GetOutput(new GitBranchOptions
+            BranchName ??= await GetOutput(new GitBranchOptions
             {
                 ShowCurrent = true,
             })
         );
 
         Async(async () =>
         {
-            DefaultBranchName = await GetDefaultBranchName();
+            DefaultBranchName ??= await GetDefaultBranchName();
         });
 
         Async(async () =>
-            LastCommitSha = await GetOutput(new GitRevParseOptions
+            LastCommitSha ??= await GetOutput(new GitRevParseOptions
             {
-                Arguments = new[] { "HEAD" },
+                Arguments = ["HEAD"],
             })
         );
 
         Async(async () =>
-            LastCommitShortSha = await GetOutput(new GitRevParseOptions
+            LastCommitShortSha ??= await GetOutput(new GitRevParseOptions
             {
                 Short = true,
-                Arguments = new[] { "HEAD" },
+                Arguments = ["HEAD"],
             })
         );
 
         Async(async () =>
-            Tag = await GetOutput(new GitDescribeOptions
+            Tag ??= await GetOutput(new GitDescribeOptions
             {
                 Tags = true,
             })
         );
 
         Async(async () =>
-            CommitsOnBranch =
-                int.Parse(await GetOutput(new GitRevListOptions
-                {
-                    Count = true,
-                    Arguments = new[] { "HEAD" },
-                }) ?? "0")
-        );
+        {
+            if (CommitsOnBranch == null)
+            {
+                return;
+            }
+            
+            int.TryParse(await GetOutput(new GitRevListOptions
+            {
+                Count = true,
+                Arguments = ["HEAD"],
+            }) ?? "0", out var commitsOnBranch);
+            CommitsOnBranch = commitsOnBranch;
+        });
 
         Async(async () =>
-            LastCommitDateTime = DateTimeOffset.FromUnixTimeSeconds(
-                long.Parse(await GetOutput(new GitLogOptions
-                {
-                    Format = "%at",
-                    Arguments = new[] { "-1" },
-                }) ?? "0"))
-        );
+        {
+            if (LastCommitDateTime == null)
+            {
+                return;
+            }
+
+            long.TryParse(await GetOutput(new GitLogOptions
+            {
+                Format = "%at",
+                Arguments = ["-1"],
+            }) ?? "0", out var lastCommitDateTime);
+
+            LastCommitDateTime = DateTimeOffset.FromUnixTimeSeconds(lastCommitDateTime);
+        });
 
         Async(async () =>
-            PreviousCommit = await LastCommits(1).FirstOrDefaultAsync()
+            PreviousCommit ??= await LastCommits(1).FirstOrDefaultAsync()
         );
 
         await Task.WhenAll(tasks);
@@ -127,7 +140,7 @@ private async Task<string> GetGitVersion()
         {
             var result = await _command.ExecuteCommandLineTool(new CommandLineToolOptions("git")
             {
-                Arguments = new[] { "version" },
+                Arguments = ["version"],
                 CommandLogging = CommandLogging.None,
             });
 
@@ -145,7 +158,7 @@ private async Task<string> GetGitVersion()
         {
             var output = await GetOutput(new GitRemoteOptions
             {
-                Arguments = new[] { "show", "origin" },
+                Arguments = ["show", "origin"],
             });
 
             return output!.Split('\n', StringSplitOptions.TrimEntries | StringSplitOptions.RemoveEmptyEntries)
@@ -156,7 +169,7 @@ private async Task<string> GetGitVersion()
         {
             var output = await GetOutput(new GitRevParseOptions
             {
-                Arguments = new[] { "origin/HEAD" },
+                Arguments = ["origin/HEAD"],
                 AbbrevRef = true,
                 ThrowOnNonZeroExitCode = false,
             });
@@ -184,19 +197,19 @@ private async Task<string> GetGitVersion()
 
     public GitCommit? PreviousCommit { get; private set; }
 
-    public Folder Root { get; private set; } = null!;
+    public Folder? Root { get; private set; }
 
-    public string? BranchName { get; private set; } = null!;
+    public string? BranchName { get; private set; }
 
-    public string? DefaultBranchName { get; private set; } = null!;
+    public string? DefaultBranchName { get; private set; }
 
-    public string? Tag { get; private set; } = null!;
+    public string? Tag { get; private set; }
 
-    public int CommitsOnBranch { get; private set; }
+    public int? CommitsOnBranch { get; private set; }
 
-    public DateTimeOffset LastCommitDateTime { get; private set; }
+    public DateTimeOffset? LastCommitDateTime { get; private set; }
 
-    public string? LastCommitSha { get; private set; } = null!;
+    public string? LastCommitSha { get; private set; }
 
-    public string? LastCommitShortSha { get; private set; } = null!;
+    public string? LastCommitShortSha { get; private set; }
 }
diff --git a/src/ModularPipelines/Context/Command.cs b/src/ModularPipelines/Context/Command.cs
@@ -111,13 +111,23 @@ private async Task<CommandResult> Of(CliWrap.Command command,
 
         var inputToLog = options.InputLoggingManipulator == null ? command.ToString() : options.InputLoggingManipulator(command.ToString());
 
+        using var forcefulCancellationToken = new CancellationTokenSource();
+        
+        cancellationToken.Register(() =>
+        {
+            if (forcefulCancellationToken.Token.CanBeCanceled)
+            {
+                forcefulCancellationToken.CancelAfter(TimeSpan.FromSeconds(30));
+            }
+        });
+        
         try
         {
             var result = await command
                 .WithStandardOutputPipe(PipeTarget.ToStringBuilder(standardOutputStringBuilder))
                 .WithStandardErrorPipe(PipeTarget.ToStringBuilder(standardErrorStringBuilder))
                 .WithValidation(CommandResultValidation.None)
-                .ExecuteAsync(cancellationToken);
+                .ExecuteAsync(forcefulCancellationToken.Token, cancellationToken);
 
             standardOutput = options.OutputLoggingManipulator == null ? standardOutputStringBuilder.ToString() : options.OutputLoggingManipulator(standardOutputStringBuilder.ToString());
             standardError = options.OutputLoggingManipulator == null ? standardErrorStringBuilder.ToString() : options.OutputLoggingManipulator(standardErrorStringBuilder.ToString());
@@ -141,6 +151,9 @@ private async Task<CommandResult> Of(CliWrap.Command command,
         }
         catch (CommandExecutionException e)
         {
+            standardOutput = options.OutputLoggingManipulator == null ? standardOutputStringBuilder.ToString() : options.OutputLoggingManipulator(standardOutputStringBuilder.ToString());
+            standardError = options.OutputLoggingManipulator == null ? standardErrorStringBuilder.ToString() : options.OutputLoggingManipulator(standardErrorStringBuilder.ToString());
+
             _commandLogger.Log(options: options,
                 inputToLog: inputToLog,
                 exitCode: e.ExitCode,
@@ -149,10 +162,14 @@ private async Task<CommandResult> Of(CliWrap.Command command,
                 standardError: standardError,
                 commandWorkingDirPath: command.WorkingDirPath
             );
-            throw;
+            
+            throw new CommandException(inputToLog, e.ExitCode, stopwatch.Elapsed, standardOutput, standardError, e);
         }
-        catch (Exception e) when (e is not CommandExecutionException)
+        catch (Exception e) when (e is not CommandExecutionException or CommandException)
         {
+            standardOutput = options.OutputLoggingManipulator == null ? standardOutputStringBuilder.ToString() : options.OutputLoggingManipulator(standardOutputStringBuilder.ToString());
+            standardError = options.OutputLoggingManipulator == null ? standardErrorStringBuilder.ToString() : options.OutputLoggingManipulator(standardErrorStringBuilder.ToString());
+
             _commandLogger.Log(options: options,
                 inputToLog: inputToLog,
                 exitCode: -1,
@@ -162,7 +179,7 @@ private async Task<CommandResult> Of(CliWrap.Command command,
                 commandWorkingDirPath: command.WorkingDirPath
             );
 
-            throw;
+            throw new CommandException(inputToLog, -1, stopwatch.Elapsed, standardOutput, standardError, e);
         }
     }
 }
diff --git a/src/ModularPipelines/Exceptions/CommandException.cs b/src/ModularPipelines/Exceptions/CommandException.cs
@@ -2,7 +2,7 @@ namespace ModularPipelines.Exceptions;
 
 public class CommandException : PipelineException
 {
-    public CommandException(string input, int exitCode, TimeSpan executionTime, string standardOutput, string standardError) : base(GenerateMessage(input, exitCode, executionTime, standardOutput, standardError))
+    public CommandException(string input, int exitCode, TimeSpan executionTime, string standardOutput, string standardError, Exception? innerException = null) : base(GenerateMessage(input, exitCode, executionTime, standardOutput, standardError), innerException)
     {
         ExitCode = exitCode;
         ExecutionTime = executionTime;
diff --git a/test/ModularPipelines.UnitTests/Helpers/CommandTests.cs b/test/ModularPipelines.UnitTests/Helpers/CommandTests.cs
@@ -1,4 +1,6 @@
+using System.Diagnostics;
 using ModularPipelines.Context;
+using ModularPipelines.Exceptions;
 using ModularPipelines.Models;
 using ModularPipelines.Modules;
 using ModularPipelines.Options;
@@ -20,6 +22,29 @@ private class CommandEchoModule : Module<CommandResult>
                 cancellationToken: cancellationToken);
         }
     }
+    
+    private class CommandEchoTimeoutModule : Module<string>
+    {
+        protected override async Task<string?> ExecuteAsync(IPipelineContext context, CancellationToken cancellationToken)
+        {
+            try
+            {
+                using var cts = new CancellationTokenSource();
+                cts.CancelAfter(TimeSpan.FromSeconds(30));
+                
+                return (await context.Command.ExecuteCommandLineTool(
+                    new CommandLineToolOptions(
+                        "pwsh",
+                        "-Command", "echo 'Foo bar!'; Start-Sleep -Seconds 60"
+                    ),
+                    cancellationToken: cts.Token)).StandardOutput;
+            }
+            catch (CommandException e)
+            {
+                return e.StandardOutput;
+            }
+        }
+    }
 
     [Test]
     public async Task Has_Not_Errored()
@@ -49,4 +74,17 @@ public async Task Standard_Output_Equals_Foo_Bar()
             await Assert.That(moduleResult.Value.StandardOutput.Trim()).Is.EqualTo("Foo bar!");
         }
     }
-}
+    
+    [Test]
+    public async Task Standard_Output_Equals_Foo_Bar_With_Timeout()
+    {
+        var module = await RunModule<CommandEchoTimeoutModule>();
+
+        var moduleResult = await module;
+        
+        await using (Assert.Multiple())
+        {
+            await Assert.That(moduleResult.Value!.Trim()).Is.EqualTo("Foo bar!");
+        }
+    }
+}

Original file line number	Diff line number	Diff line change
`@@ -0,0 +1 @@`
	`1`	`+- Attempt to log command results when exceptions are thrown. E.g. Timeout TaskCanceledExceptions`
Original file line number	Diff line number	Diff line change
`@@ -2,7 +2,7 @@ namespace ModularPipelines.Exceptions;`
`2`	`2`
`3`	`3`	`public class CommandException : PipelineException`
`4`	`4`	`{`
`5`		`- public CommandException(string input, int exitCode, TimeSpan executionTime, string standardOutput, string standardError) : base(GenerateMessage(input, exitCode, executionTime, standardOutput, standardError))`
	`5`	`+ public CommandException(string input, int exitCode, TimeSpan executionTime, string standardOutput, string standardError, Exception? innerException = null) : base(GenerateMessage(input, exitCode, executionTime, standardOutput, standardError), innerException)`
`6`	`6`	`{`
`7`	`7`	`ExitCode = exitCode;`
`8`	`8`	`ExecutionTime = executionTime;`