update console output to include duration for exceptions, and verify …

…exception printing in output tests
heckj · Dec 31, 2024 · b4a5aeb · b4a5aeb
1 parent db789fe
commit b4a5aeb
Show file tree

Hide file tree

Showing 3 changed files with 58 additions and 2 deletions.
diff --git a/Sources/Formic/Engine/CommandExecutionResult.swift b/Sources/Formic/Engine/CommandExecutionResult.swift
@@ -78,16 +78,19 @@ extension CommandExecutionResult {
                 if includeEmoji {
                     stringOutput.append(" ")
                 }
+                stringOutput.append("[\(formattedDuration)] ")
                 stringOutput.append("exception: \(exception)")
             } else if output.returnCode != 0 {
                 stringOutput.append("command: \(command), rc=\(output.returnCode), retries=\(retries)")
+                stringOutput.append("[\(formattedDuration)] ")
                 if let errorOutput = output.stderrString {
                     stringOutput.append("\nSTDERR: \(errorOutput)")
                 } else {
                     stringOutput.append(" No STDERR output.")
                 }
             } else {
                 stringOutput.append("command: \(command), rc=\(output.returnCode), retries=\(retries)")
+                stringOutput.append("[\(formattedDuration)] ")
             }
         case .verbose(emoji: let includeEmoji):
             // Reports host, command, duration, the result code, and stdout on success, or stderr on failure.
@@ -98,6 +101,7 @@ extension CommandExecutionResult {
                 if includeEmoji {
                     stringOutput.append(" ")
                 }
+                stringOutput.append("[\(formattedDuration)] ")
                 stringOutput.append("exception: \(exception)")
             } else if output.returnCode != 0 {
                 stringOutput.append("[\(formattedDuration)] ")
@@ -125,6 +129,7 @@ extension CommandExecutionResult {
                 if includeEmoji {
                     stringOutput.append(" ")
                 }
+                stringOutput.append("[\(formattedDuration)] ")
                 stringOutput.append("exception: \(exception)")
             } else {
                 stringOutput.append("[\(formattedDuration)] ")

diff --git a/Tests/formicTests/CommandExecutionOutputTests.swift b/Tests/formicTests/CommandExecutionOutputTests.swift
@@ -89,117 +89,166 @@ func testConsoleOutputForExecutionOuput() async throws {
     #expect(successResult.consoleOutput(verbosity: .normal(emoji: false)).contains("uname"))
     #expect(successResult.consoleOutput(verbosity: .normal(emoji: false)).contains("rc=0"))
     #expect(successResult.consoleOutput(verbosity: .normal(emoji: false)).contains("retries=0"))
+    #expect(successResult.consoleOutput(verbosity: .normal(emoji: false)).contains("[00:00"))
+    // duration marker
 
     #expect(failureResult.consoleOutput(verbosity: .normal(emoji: true)).contains("❌"))
     #expect(failureResult.consoleOutput(verbosity: .normal(emoji: true)).contains("uname"))
     #expect(failureResult.consoleOutput(verbosity: .normal(emoji: true)).contains("rc=-1"))
     #expect(failureResult.consoleOutput(verbosity: .normal(emoji: true)).contains("retries=0"))
     #expect(failureResult.consoleOutput(verbosity: .normal(emoji: true)).contains("I'm not telling you!"))
+    #expect(successResult.consoleOutput(verbosity: .normal(emoji: true)).contains("[00:00"))
+    // duration marker
 
     #expect(!failureResult.consoleOutput(verbosity: .normal(emoji: false)).contains("❌"))
     #expect(failureResult.consoleOutput(verbosity: .normal(emoji: false)).contains("uname"))
     #expect(failureResult.consoleOutput(verbosity: .normal(emoji: false)).contains("rc=-1"))
     #expect(failureResult.consoleOutput(verbosity: .normal(emoji: false)).contains("retries=0"))
     #expect(failureResult.consoleOutput(verbosity: .normal(emoji: false)).contains("I'm not telling you!"))
+    #expect(failureResult.consoleOutput(verbosity: .normal(emoji: false)).contains("[00:00"))
+    // duration marker
 
     #expect(ignoreFailureResult.consoleOutput(verbosity: .normal(emoji: true)).contains("⚠️"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .normal(emoji: true)).contains("uname"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .normal(emoji: true)).contains("rc=-1"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .normal(emoji: true)).contains("retries=0"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .normal(emoji: true)).contains("I'm not telling you!"))
+    #expect(ignoreFailureResult.consoleOutput(verbosity: .normal(emoji: true)).contains("[00:00"))
+    // duration marker
 
     #expect(!ignoreFailureResult.consoleOutput(verbosity: .normal(emoji: false)).contains("⚠️"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .normal(emoji: false)).contains("uname"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .normal(emoji: false)).contains("rc=-1"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .normal(emoji: false)).contains("retries=0"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .normal(emoji: false)).contains("I'm not telling you!"))
+    #expect(ignoreFailureResult.consoleOutput(verbosity: .normal(emoji: false)).contains("[00:00"))
+    // duration marker
 
     #expect(exceptionResult.consoleOutput(verbosity: .normal(emoji: true)).contains("🚫"))
     #expect(exceptionResult.consoleOutput(verbosity: .normal(emoji: true)).contains("exception reported"))
+    #expect(exceptionResult.consoleOutput(verbosity: .normal(emoji: true)).contains("[00:00"))
+    // duration marker
+
     #expect(!exceptionResult.consoleOutput(verbosity: .normal(emoji: false)).contains("🚫"))
     #expect(exceptionResult.consoleOutput(verbosity: .normal(emoji: false)).contains("exception reported"))
+    #expect(exceptionResult.consoleOutput(verbosity: .normal(emoji: false)).contains("[00:00"))
+    // duration marker
 
     // .verbose
     #expect(successResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("✅"))
     #expect(successResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("uname"))
     #expect(successResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("rc=0"))
     #expect(successResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("retries=0"))
     #expect(successResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("Darwin"))
+    #expect(successResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("[00:00"))
+    // duration marker
 
     #expect(!successResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("✅"))
     #expect(successResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("uname"))
     #expect(successResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("rc=0"))
     #expect(successResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("retries=0"))
-    #expect(successResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("Darwin"))
+    #expect(successResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("Darwin"))
+    #expect(successResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("[00:00"))
+    // duration marker
 
     #expect(failureResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("❌"))
     #expect(failureResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("uname"))
     #expect(failureResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("rc=-1"))
     #expect(failureResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("retries=0"))
     #expect(failureResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("I'm not telling you!"))
+    #expect(failureResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("[00:00"))
+    // duration marker
 
     #expect(!failureResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("❌"))
     #expect(failureResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("uname"))
     #expect(failureResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("rc=-1"))
     #expect(failureResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("retries=0"))
     #expect(failureResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("I'm not telling you!"))
+    #expect(failureResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("[00:00"))
+    // duration marker
 
     #expect(ignoreFailureResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("⚠️"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("uname"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("rc=-1"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("retries=0"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("I'm not telling you!"))
+    #expect(ignoreFailureResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("[00:00"))
+    // duration marker
 
     #expect(!ignoreFailureResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("⚠️"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("uname"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("rc=-1"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("retries=0"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("I'm not telling you!"))
+    #expect(ignoreFailureResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("[00:00"))
+    // duration marker
 
     #expect(exceptionResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("🚫"))
     #expect(exceptionResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("exception reported"))
+    #expect(exceptionResult.consoleOutput(verbosity: .verbose(emoji: true)).contains("[00:00"))
+    // duration marker
+
     #expect(!exceptionResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("🚫"))
     #expect(exceptionResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("exception reported"))
+    #expect(exceptionResult.consoleOutput(verbosity: .verbose(emoji: false)).contains("[00:00"))
+    // duration marker
 
     // .debug
     #expect(successResult.consoleOutput(verbosity: .debug(emoji: true)).contains("✅"))
     #expect(successResult.consoleOutput(verbosity: .debug(emoji: true)).contains("uname"))
     #expect(successResult.consoleOutput(verbosity: .debug(emoji: true)).contains("rc=0"))
     #expect(successResult.consoleOutput(verbosity: .debug(emoji: true)).contains("retries=0"))
     #expect(successResult.consoleOutput(verbosity: .debug(emoji: true)).contains("Darwin"))
+    #expect(successResult.consoleOutput(verbosity: .debug(emoji: true)).contains("[00:00"))
+    // duration marker
 
     #expect(!successResult.consoleOutput(verbosity: .debug(emoji: false)).contains("✅"))
     #expect(successResult.consoleOutput(verbosity: .debug(emoji: false)).contains("uname"))
     #expect(successResult.consoleOutput(verbosity: .debug(emoji: false)).contains("rc=0"))
     #expect(successResult.consoleOutput(verbosity: .debug(emoji: false)).contains("retries=0"))
-    #expect(successResult.consoleOutput(verbosity: .debug(emoji: true)).contains("Darwin"))
+    #expect(successResult.consoleOutput(verbosity: .debug(emoji: false)).contains("Darwin"))
+    #expect(successResult.consoleOutput(verbosity: .debug(emoji: false)).contains("[00:00"))
+    // duration marker
 
     #expect(failureResult.consoleOutput(verbosity: .debug(emoji: true)).contains("❌"))
     #expect(failureResult.consoleOutput(verbosity: .debug(emoji: true)).contains("uname"))
     #expect(failureResult.consoleOutput(verbosity: .debug(emoji: true)).contains("rc=-1"))
     #expect(failureResult.consoleOutput(verbosity: .debug(emoji: true)).contains("retries=0"))
     #expect(failureResult.consoleOutput(verbosity: .debug(emoji: true)).contains("I'm not telling you!"))
+    #expect(failureResult.consoleOutput(verbosity: .debug(emoji: true)).contains("[00:00"))
+    // duration marker
 
     #expect(!failureResult.consoleOutput(verbosity: .debug(emoji: false)).contains("❌"))
     #expect(failureResult.consoleOutput(verbosity: .debug(emoji: false)).contains("uname"))
     #expect(failureResult.consoleOutput(verbosity: .debug(emoji: false)).contains("rc=-1"))
     #expect(failureResult.consoleOutput(verbosity: .debug(emoji: false)).contains("retries=0"))
     #expect(failureResult.consoleOutput(verbosity: .debug(emoji: false)).contains("I'm not telling you!"))
+    #expect(failureResult.consoleOutput(verbosity: .debug(emoji: false)).contains("[00:00"))
+    // duration marker
 
     #expect(ignoreFailureResult.consoleOutput(verbosity: .debug(emoji: true)).contains("⚠️"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .debug(emoji: true)).contains("uname"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .debug(emoji: true)).contains("rc=-1"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .debug(emoji: true)).contains("retries=0"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .debug(emoji: true)).contains("I'm not telling you!"))
+    #expect(ignoreFailureResult.consoleOutput(verbosity: .debug(emoji: false)).contains("[00:00"))
+    // duration marker
 
     #expect(!ignoreFailureResult.consoleOutput(verbosity: .debug(emoji: false)).contains("⚠️"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .debug(emoji: false)).contains("uname"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .debug(emoji: false)).contains("rc=-1"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .debug(emoji: false)).contains("retries=0"))
     #expect(ignoreFailureResult.consoleOutput(verbosity: .debug(emoji: false)).contains("I'm not telling you!"))
+    #expect(ignoreFailureResult.consoleOutput(verbosity: .debug(emoji: false)).contains("[00:00"))
+    // duration marker
 
     #expect(exceptionResult.consoleOutput(verbosity: .debug(emoji: true)).contains("🚫"))
     #expect(exceptionResult.consoleOutput(verbosity: .debug(emoji: true)).contains("exception reported"))
+    #expect(exceptionResult.consoleOutput(verbosity: .debug(emoji: true)).contains("[00:00"))
+    // duration marker
+
     #expect(!exceptionResult.consoleOutput(verbosity: .debug(emoji: false)).contains("🚫"))
     #expect(exceptionResult.consoleOutput(verbosity: .debug(emoji: false)).contains("exception reported"))
+    #expect(exceptionResult.consoleOutput(verbosity: .debug(emoji: false)).contains("[00:00"))
+    // duration marker
 }
diff --git a/Tests/formicTests/EngineTests.swift b/Tests/formicTests/EngineTests.swift
@@ -185,6 +185,8 @@ func testCommandTimeout() async throws {
     #expect(outputFromRun.representsFailure() == true)
     #expect(outputFromRun.output.stderrString == nil)
     #expect(outputFromRun.output.stdoutString == nil)
+    #expect(outputFromRun.duration > .seconds(1))
+    //print(outputFromRun.consoleOutput(verbosity: .debug(emoji: true)))
 }
 
 @Test("verify retry works as expected")