script: Fix lack of newline on retried command in logs

and show the amount of time it took until retries succeeded.

Before:

    scripttest.go:72: # Test command retrying and the flag parsing when retrying.
        # The 'retrytest' command should run two times and the flags
        # should not be lost.> * retrytest --not-empty=xyz abc
    scripttest.go:72:  (0.010s)
        (command "* retrytest --not-empty=xyz abc" failed, retrying in 10ms...)
        (command "* retrytest --not-empty=xyz abc" succeeded after 1 retries)
    --- PASS: TestAll/retry (0.01s)

After:

    scripttest.go:72: # Test command retrying and the flag parsing when retrying.
        # The 'retrytest' command should run two times and the flags
        # should not be lost.
        > * retrytest --not-empty=xyz abc
        retrytest called
    scripttest.go:72: (command "* retrytest --not-empty=xyz abc" failed, retrying in 10ms...)
        retrytest called
    scripttest.go:72: (command "* retrytest --not-empty=xyz abc" succeeded after 1 retries in 0.010s)
    --- PASS: TestAll/retry (0.01s)

Signed-off-by: Jussi Maki <[email protected]>

Author: joamaki

Diff for: script/engine.go

@@ -341,12 +341,20 @@ func (e *Engine) Execute(s *State, file string, script *bufio.Reader, log io.Wri
 		err = e.runCommand(s, cmd, impl)
 		if err != nil {
 			if cmd.want == successRetryOnFailure || cmd.want == failureRetryOnSuccess {
+				retryStart := sectionStart
+
+				// Clear the section start to avoid the deferred endSection() printing a timestamp.
+				sectionStart = time.Time{}
+
+				// Append the new line that section start omitted and flush the log.
+				io.WriteString(log, "\n")
+				s.FlushLog()
+
 				// Command wants retries. Retry the whole section
 				backoff := exponentialBackoff{max: maxRetryInterval, interval: retryInterval}
 				for err != nil {
-					s.FlushLog()
 					retryDuration := backoff.get()
-					s.Logf("(command %q failed, retrying in %s...)\n", line, retryDuration)
+					fmt.Fprintf(log, "(command %q failed, retrying in %s...)\n", line, retryDuration)
 					select {
 					case <-s.Context().Done():
 						s.RetryCount = 0
@@ -360,9 +368,11 @@ func (e *Engine) Execute(s *State, file string, script *bufio.Reader, log io.Wri
 							break
 						}
 					}
+					s.FlushLog()
 				}
-				s.Logf("(command %q succeeded after %d retries)\n", line, s.RetryCount)
+				fmt.Fprintf(log, "(command %q succeeded after %d retries in %.3fs)\n", line, s.RetryCount, time.Since(retryStart).Seconds())
 				s.RetryCount = 0
+				return nil
 			} else {
 				if stop := (stopError{}); errors.As(err, &stop) {
 					// Since the 'stop' command halts execution of the entire script,

Diff for: script/scripttest/scripttest_test.go

@@ -46,6 +46,7 @@ func TestAll(t *testing.T) {
 				},
 			},
 			func(s *script.State, args ...string) (script.WaitFunc, error) {
+				s.Logf("retrytest called")
 				notEmpty, err := s.Flags.GetString("not-empty")
 				if err != nil {
 					return nil, err