fix: better error messages and failed execution info

cmd/kubectl-testkube/commands/scripts/common.go

@@ -75,11 +75,11 @@ func watchLogs(id string, client client.Client) {
 		if execution.ExecutionResult.IsCompleted() {
 			fmt.Println()
 
-			uiShellCommandBlock(id)
+			uiShellGetExecution(id)
 
 			return
 		}
 	}
 
-	uiShellCommandBlock(id)
+	uiShellGetExecution(id)
 }

cmd/kubectl-testkube/commands/scripts/execution_renderer.go

@@ -7,6 +7,7 @@ import (
 	"text/template"
 
 	"github.com/kubeshop/testkube/pkg/api/v1/testkube"
+	"github.com/kubeshop/testkube/pkg/ui"
 	"github.com/spf13/cobra"
 )
 
@@ -77,14 +78,14 @@ func (r ExecutionRawRenderer) Watch(execution testkube.Execution, writer io.Writ
 	return err
 }
 
+// TODO fix this - introduce some common data interface for rendering such objects
+// renderers need to be simplified and render Execution should be in one place (not many as now)
+// - move all logic from execution, start, watch here to show final execution
 func (r ExecutionRawRenderer) renderDetails(execution testkube.Execution, writer io.Writer) error {
-	_, err := fmt.Fprintf(writer, "Name: %s, Status: %s, Duration: %s\n",
-		execution.Name,
-		*execution.ExecutionResult.Status,
-		execution.CalculateDuration(),
-	)
-
-	return err
+	ui.Writer = writer
+	uiPrintStatus(execution)
+	uiShellGetExecution(execution.Id)
+	return nil
 }
 
 func GetExecutionRenderer(cmd *cobra.Command) ExecutionRenderer {

cmd/kubectl-testkube/commands/scripts/start.go

@@ -55,7 +55,8 @@ func NewStartScriptCmd() *cobra.Command {
 				DownloadArtifacts(execution.Id, downloadDir, client)
 			}
 
-			uiShellCommandBlock(execution.Id)
+			uiShellGetExecution(execution.Id)
+			uiShellWatchExecution(execution.Id)
 		},
 	}
 
@@ -71,6 +72,8 @@ func NewStartScriptCmd() *cobra.Command {
 func uiPrintStatus(execution testkube.Execution) {
 	result := execution.ExecutionResult
 
+	ui.NL()
+
 	switch true {
 	case result.IsQueued():
 		ui.Warn("Script queued for execution")
@@ -79,26 +82,32 @@ func uiPrintStatus(execution testkube.Execution) {
 		ui.Warn("Script execution started")
 
 	case result.IsSuccesful():
-		fmt.Println(result.Output)
+		ui.Info(result.Output)
 		duration := execution.EndTime.Sub(execution.StartTime)
 		ui.Success("Script execution completed with sucess in " + duration.String())
 
 	case result.IsFailed():
-		fmt.Println(result.ErrorMessage)
+		ui.Warn("Test script execution failed:")
+		ui.Info(result.ErrorMessage)
 		ui.Errf("Script execution failed")
 		os.Exit(1)
 	}
 
 	ui.NL()
 }
 
-func uiShellCommandBlock(id string) {
+func uiShellGetExecution(id string) {
 	ui.ShellCommand(
 		"Use following command to get script execution details",
 		"kubectl testkube scripts execution "+id,
 	)
+
+	ui.NL()
+}
+
+func uiShellWatchExecution(id string) {
 	ui.ShellCommand(
-		"or watch script execution until complete",
+		"Watch script execution until complete",
 		"kubectl testkube scripts watch "+id,
 	)
 

internal/app/api/v1/executions.go

@@ -226,7 +226,6 @@ func (s TestKubeAPI) GetExecutionHandler() fiber.Handler {
 			}
 		}
 
-		s.Log.Infow("get script execution request", "id", scriptID, "executionID", executionID)
 		s.Log.Debugw("get script execution request - debug", "execution", execution)
 
 		return c.JSON(execution)

pkg/jobs/jobclient.go

@@ -145,6 +145,9 @@ func (c *JobClient) LaunchK8sJob(image string, repo result.Repository, execution
 	podsClient := c.ClientSet.CoreV1().Pods(c.Namespace)
 	ctx := context.Background()
 
+	// init result
+	result = testkube.NewPendingExecutionResult()
+
 	jsn, err := json.Marshal(execution)
 	if err != nil {
 		return result.Err(err), err
@@ -167,35 +170,39 @@ func (c *JobClient) LaunchK8sJob(image string, repo result.Repository, execution
 		if pod.Status.Phase != v1.PodRunning && pod.Labels["job-name"] == execution.Id {
 			// async wait for complete status or error
 			go func() {
+				l := c.Log.With("executionID", execution.Id)
 				// save stop time
 				defer func() {
+					l.Debug("stopping execution")
 					execution.Stop()
 					repo.EndExecution(ctx, execution.Id, execution.EndTime, execution.CalculateDuration())
 				}()
 
 				// wait for complete
-				if err := wait.PollImmediate(time.Second, time.Duration(0)*time.Second, k8sclient.HasPodSucceeded(c.ClientSet, pod.Name, c.Namespace)); err != nil {
+				l.Debug("poll immediate waiting for pod to succeed")
+				if err := wait.PollImmediate(pollInterval, pollTimeout, IsPodReady(c.ClientSet, pod.Name, c.Namespace)); err != nil {
 					// continue on poll err and try to get logs later
-					c.Log.Errorw("poll immediate error", "error", err)
+					l.Errorw("poll immediate error", "error", err)
 				}
+				l.Debug("poll immediate end")
 
 				var logs []byte
 				logs, err = c.GetPodLogs(pod.Name)
 				if err != nil {
-					c.Log.Errorw("get pod logs error", "error", err)
+					l.Errorw("get pod logs error", "error", err)
 					repo.UpdateResult(ctx, execution.Id, result.Err(err))
 					return
 				}
 
 				// parse job ouput log (JSON stream)
 				result, _, err := output.ParseRunnerOutput(logs)
 				if err != nil {
-					c.Log.Errorw("parse ouput error", "error", err)
+					l.Errorw("parse ouput error", "error", err)
 					repo.UpdateResult(ctx, execution.Id, result.Err(err))
 					return
 				}
 
-				c.Log.Infow("execution completed saving result", "executionId", execution.Id, "status", result.Status)
+				l.Infow("execution completed saving result", "status", result.Status)
 				repo.UpdateResult(ctx, execution.Id, result)
 			}()
 		}
@@ -234,39 +241,27 @@ func (c *JobClient) TailJobLogs(id string, logs chan []byte) (err error) {
 	for _, pod := range pods.Items {
 		if pod.Labels["job-name"] == id {
 
-			l := c.Log.With("namespace", pod.Namespace, "pod", pod.Name)
+			l := c.Log.With("podNamespace", pod.Namespace, "podName", pod.Name, "podStatus", pod.Status)
 
 			switch pod.Status.Phase {
 
 			case v1.PodRunning:
-				l.Debug("Tailing pod logs immediately")
+				l.Debug("tailing pod logs: immediately")
 				return c.TailPodLogs(ctx, pod.Name, logs)
 
 			case v1.PodFailed:
 				err := fmt.Errorf("can't get pod logs, pod failed: %s/%s", pod.Namespace, pod.Name)
 				l.Errorw(err.Error())
-				return err
+				return c.GetLastLogLineError(ctx, pod.Namespace, pod.Name)
 
 			default:
-				l.Debugw("Waiting for pod to be ready")
+				l.Debugw("tailing job logs: Waiting for pod to be ready")
 				if err = wait.PollImmediate(pollInterval, pollTimeout, IsPodReady(c.ClientSet, pod.Name, c.Namespace)); err != nil {
 					l.Errorw("poll immediate error when tailing logs", "error", err)
-					log, err := c.GetPodLogError(ctx, pod.Name)
-					if err != nil {
-						return fmt.Errorf("GetPodLogs error: %w", err)
-					}
-
-					l.Debugw("poll immediete log", "log", string(log))
-					entry, err := output.GetLogEntry(log)
-					if err != nil {
-						return fmt.Errorf("GetLogEntry error: %w", err)
-					}
-					close(logs)
-
-					return fmt.Errorf("last log entry: %s", entry.String())
+					return c.GetLastLogLineError(ctx, pod.Namespace, pod.Name)
 				}
 
-				l.Debug("Tailing pod logs")
+				l.Debug("tailing pod logs")
 				return c.TailPodLogs(ctx, pod.Name, logs)
 			}
 		}
@@ -275,6 +270,23 @@ func (c *JobClient) TailJobLogs(id string, logs chan []byte) (err error) {
 	return
 }
 
+func (c *JobClient) GetLastLogLineError(ctx context.Context, podNamespace, podName string) error {
+	l := c.Log.With("pod", podName, "namespace", podNamespace)
+	log, err := c.GetPodLogError(ctx, podName)
+	if err != nil {
+		return fmt.Errorf("getPodLogs error: %w", err)
+	}
+
+	l.Debugw("log", "got last log bytes", string(log)) // in case distorted log bytes
+	entry, err := output.GetLogEntry(log)
+	if err != nil {
+		return fmt.Errorf("GetLogEntry error: %w", err)
+	}
+
+	c.Log.Errorw("got last log entry", "log", entry.String())
+	return fmt.Errorf("error from last log entry: %s", entry.String())
+}
+
 func (c *JobClient) GetPodLogs(podName string, logLinesCount ...int64) (logs []byte, err error) {
 	count := int64(100)
 	if len(logLinesCount) > 0 {

pkg/runner/output/parser.go

@@ -57,7 +57,7 @@ func ParseRunnerOutput(b []byte) (result testkube.ExecutionResult, logs []string
 			}
 
 		case TypeError:
-			result = testkube.ExecutionResult{ErrorMessage: log.Content}
+			result = testkube.NewErrorExecutionResult(fmt.Errorf(log.Content))
 
 		case TypeLogEvent, TypeLogLine:
 			logs = append(logs, log.Content)

pkg/ui/errors.go

@@ -17,7 +17,7 @@ func printAndExit(item string, exitOnError bool, errors ...error) {
 	if len(errors) > 0 && hasErrors(errors...) {
 		for _, err := range errors {
 			if err != nil {
-				fmt.Printf("%s %s (error: %s)\n\n", LightRed("⨯"), Red(item), err)
+				fmt.Fprintf(Writer, "%s %s (error: %s)\n\n", LightRed("⨯"), Red(item), err)
 				if exitOnError {
 					os.Exit(1)
 				}
@@ -26,22 +26,22 @@ func printAndExit(item string, exitOnError bool, errors ...error) {
 	}
 
 	if Verbose {
-		fmt.Printf("%s %s\n", Blue("\xE2\x9C\x94"), Green(item))
+		fmt.Fprintf(Writer, "%s %s\n", Blue("\xE2\x9C\x94"), Green(item))
 	}
 }
 
 func WarnOnError(item string, errors ...error) {
 	if len(errors) > 0 && hasErrors(errors...) {
 		for _, err := range errors {
 			if err != nil {
-				fmt.Printf("%s %s (error: %s)\n\n", LightYellow("⨯"), Yellow(item), err)
+				fmt.Fprintf(Writer, "%s %s (error: %s)\n\n", LightYellow("⨯"), Yellow(item), err)
 				return
 			}
 		}
 	}
 
 	if Verbose {
-		fmt.Printf("%s %s\n", Blue("\xE2\x9C\x94"), Green(item))
+		fmt.Fprintf(Writer, "%s %s\n", Blue("\xE2\x9C\x94"), Green(item))
 	}
 }
 

pkg/ui/logo.go

@@ -15,11 +15,11 @@ var logo = `
 `
 
 func Logo() {
-	fmt.Print(Blue(logo))
-	fmt.Println()
+	fmt.Fprint(Writer, Blue(logo))
+	fmt.Fprintln(Writer)
 }
 
 func LogoNoColor() {
-	fmt.Print(logo)
-	fmt.Println()
+	fmt.Fprint(Writer, logo)
+	fmt.Fprintln(Writer)
 }