feat: timeout the postStart hook commands

Signed-off-by: Oleksii Kurinnyi <[email protected]>

Author: akurinnoy

apis/controller/v1alpha1/devworkspaceoperatorconfig_types.go

@@ -189,6 +189,16 @@ type WorkspaceConfig struct {
 	RuntimeClassName *string `json:"runtimeClassName,omitempty"`
 	// CleanupCronJobConfig defines configuration options for a cron job that automatically cleans up stale DevWorkspaces.
 	CleanupCronJob *CleanupCronJobConfig `json:"cleanupCronJob,omitempty"`
+	// PostStartTimeout defines the maximum duration the PostStart hook can run
+	// before it is automatically failed. This timeout is used for the postStart lifecycle hook
+	// that is used to run commands in the workspace container. The timeout is specified in seconds.
+	// If not specified, the timeout is disabled (0 seconds).
+	// +kubebuilder:validation:Minimum=0
+	// +kubebuilder:default:=0
+	// +kubebuilder:validation:Optional
+	// +kubebuilder:validation:Type=integer
+	// +kubebuilder:validation:Format=int32
+	PostStartTimeout *int32 `json:"postStartTimeout,omitempty"`
 }
 
 type WebhookConfig struct {

controllers/workspace/devworkspace_controller.go

@@ -327,7 +327,9 @@ func (r *DevWorkspaceReconciler) Reconcile(ctx context.Context, req ctrl.Request
 		&workspace.Spec.Template,
 		workspace.Config.Workspace.ContainerSecurityContext,
 		workspace.Config.Workspace.ImagePullPolicy,
-		workspace.Config.Workspace.DefaultContainerResources)
+		workspace.Config.Workspace.DefaultContainerResources,
+		workspace.Config.Workspace.PostStartTimeout,
+	)
 	if err != nil {
 		return r.failWorkspace(workspace, fmt.Sprintf("Error processing devfile: %s", err), metrics.ReasonBadRequest, reqLogger, &reconcileStatus), nil
 	}

pkg/config/sync.go

@@ -431,6 +431,10 @@ func mergeConfig(from, to *controller.OperatorConfiguration) {
 				to.Workspace.CleanupCronJob.Schedule = from.Workspace.CleanupCronJob.Schedule
 			}
 		}
+
+		if from.Workspace.PostStartTimeout != nil {
+			to.Workspace.PostStartTimeout = from.Workspace.PostStartTimeout
+		}
 	}
 }
 

pkg/library/container/container.go

@@ -45,7 +45,7 @@ import (
 // rewritten as Volumes are added to PodAdditions, in order to support e.g. using one PVC to hold all volumes
 //
 // Note: Requires DevWorkspace to be flattened (i.e. the DevWorkspace contains no Parent or Components of type Plugin)
-func GetKubeContainersFromDevfile(workspace *dw.DevWorkspaceTemplateSpec, securityContext *corev1.SecurityContext, pullPolicy string, defaultResources *corev1.ResourceRequirements) (*v1alpha1.PodAdditions, error) {
+func GetKubeContainersFromDevfile(workspace *dw.DevWorkspaceTemplateSpec, securityContext *corev1.SecurityContext, pullPolicy string, defaultResources *corev1.ResourceRequirements, postStartTimeout *int32) (*v1alpha1.PodAdditions, error) {
 	if !flatten.DevWorkspaceIsFlattened(workspace, nil) {
 		return nil, fmt.Errorf("devfile is not flattened")
 	}
@@ -77,7 +77,7 @@ func GetKubeContainersFromDevfile(workspace *dw.DevWorkspaceTemplateSpec, securi
 		podAdditions.Containers = append(podAdditions.Containers, *k8sContainer)
 	}
 
-	if err := lifecycle.AddPostStartLifecycleHooks(workspace, podAdditions.Containers); err != nil {
+	if err := lifecycle.AddPostStartLifecycleHooks(workspace, podAdditions.Containers, postStartTimeout); err != nil {
 		return nil, err
 	}
 

pkg/library/lifecycle/poststart.go

@@ -21,12 +21,20 @@ import (
 	corev1 "k8s.io/api/core/v1"
 )
 
-const redirectOutputFmt = `{
-%s
-} 1>/tmp/poststart-stdout.txt 2>/tmp/poststart-stderr.txt
+const (
+	// `tee` both stdout and stderr to files and to the main output streams.
+	redirectOutputFmt = `{
+  # This script block ensures its exit code is preserved
+  # while its stdout and stderr are tee'd.
+  _script_to_run() {
+    %s # This will be replaced by scriptWithTimeout
+  }
+  _script_to_run
+} 1> >(tee -a "/tmp/poststart-stdout.txt") 2> >(tee -a "/tmp/poststart-stderr.txt" >&2)
 `
+)
 
-func AddPostStartLifecycleHooks(wksp *dw.DevWorkspaceTemplateSpec, containers []corev1.Container) error {
+func AddPostStartLifecycleHooks(wksp *dw.DevWorkspaceTemplateSpec, containers []corev1.Container, postStartTimeout *int32) error {
 	if wksp.Events == nil || len(wksp.Events.PostStart) == 0 {
 		return nil
 	}
@@ -54,7 +62,7 @@ func AddPostStartLifecycleHooks(wksp *dw.DevWorkspaceTemplateSpec, containers []
 			return fmt.Errorf("failed to process postStart event %s: %w", commands[0].Id, err)
 		}
 
-		postStartHandler, err := processCommandsForPostStart(commands)
+		postStartHandler, err := processCommandsForPostStart(commands, postStartTimeout)
 		if err != nil {
 			return fmt.Errorf("failed to process postStart event %s: %w", commands[0].Id, err)
 		}
@@ -79,27 +87,64 @@ func AddPostStartLifecycleHooks(wksp *dw.DevWorkspaceTemplateSpec, containers []
 //	  - |
 //	    cd <workingDir>
 //	    <commandline>
-func processCommandsForPostStart(commands []dw.Command) (*corev1.LifecycleHandler, error) {
-	var dwCommands []string
+func processCommandsForPostStart(commands []dw.Command, postStartTimeout *int32) (*corev1.LifecycleHandler, error) {
+	var commandScriptLines []string
 	for _, command := range commands {
 		execCmd := command.Exec
 		if len(execCmd.Env) > 0 {
 			return nil, fmt.Errorf("env vars in postStart command %s are unsupported", command.Id)
 		}
+		var singleCommandParts []string
 		if execCmd.WorkingDir != "" {
-			dwCommands = append(dwCommands, fmt.Sprintf("cd %s", execCmd.WorkingDir))
+			// Safely quote the working directory path
+			safeWorkingDir := strings.ReplaceAll(execCmd.WorkingDir, "'", `'\''`)
+			singleCommandParts = append(singleCommandParts, fmt.Sprintf("cd '%s'", safeWorkingDir))
+		}
+		if execCmd.CommandLine != "" {
+			singleCommandParts = append(singleCommandParts, execCmd.CommandLine)
+		}
+		if len(singleCommandParts) > 0 {
+			commandScriptLines = append(commandScriptLines, strings.Join(singleCommandParts, " && "))
 		}
-		dwCommands = append(dwCommands, execCmd.CommandLine)
 	}
 
-	joinedCommands := strings.Join(dwCommands, "\n")
+	originalUserScript := strings.Join(commandScriptLines, "\n")
+
+	scriptToExecute := "set -e\n" + originalUserScript
+	escapedUserScript := strings.ReplaceAll(scriptToExecute, "'", `'\''`)
+
+	scriptWithTimeout := fmt.Sprintf(`
+export POSTSTART_TIMEOUT_DURATION="%d"
+export POSTSTART_KILL_AFTER_DURATION="5"
+
+echo "[postStart hook] Executing commands with timeout: ${POSTSTART_TIMEOUT_DURATION} s, kill after: ${POSTSTART_KILL_AFTER_DURATION} s" >&2
+
+# Run the user's script under the 'timeout' utility.
+timeout --preserve-status --kill-after="${POSTSTART_KILL_AFTER_DURATION}" "${POSTSTART_TIMEOUT_DURATION}" /bin/sh -c '%s'
+exit_code=$?
+
+# Check the exit code from 'timeout'
+if [ $exit_code -eq 143 ]; then # 128 + 15 (SIGTERM)
+  echo "[postStart hook] Commands terminated by SIGTERM (likely timed out after ${POSTSTART_TIMEOUT_DURATION}s). Exit code 143." >&2
+elif [ $exit_code -eq 137 ]; then # 128 + 9 (SIGKILL)
+  echo "[postStart hook] Commands forcefully killed by SIGKILL (likely after --kill-after ${POSTSTART_KILL_AFTER_DURATION}s expired). Exit code 137." >&2
+elif [ $exit_code -ne 0 ]; then # Catches any other non-zero exit code, including 124
+  echo "[postStart hook] Commands failed with exit code $exit_code." >&2
+else
+  echo "[postStart hook] Commands completed successfully within the time limit." >&2
+fi
+
+exit $exit_code
+`, *postStartTimeout, escapedUserScript)
+
+	finalScriptForHook := fmt.Sprintf(redirectOutputFmt, scriptWithTimeout)
 
 	handler := &corev1.LifecycleHandler{
 		Exec: &corev1.ExecAction{
 			Command: []string{
 				"/bin/sh",
 				"-c",
-				fmt.Sprintf(redirectOutputFmt, joinedCommands),
+				finalScriptForHook,
 			},
 		},
 	}

pkg/library/status/check.go

@@ -18,6 +18,7 @@ package status
 import (
 	"context"
 	"fmt"
+	"regexp"
 	"strings"
 
 	"github.com/devfile/devworkspace-operator/pkg/common"
@@ -145,10 +146,15 @@ func CheckPodEvents(pod *corev1.Pod, workspaceID string, ignoredEvents []string,
 		if maxCount, isUnrecoverableEvent := unrecoverablePodEventReasons[ev.Reason]; isUnrecoverableEvent {
 			if !checkIfUnrecoverableEventIgnored(ev.Reason, ignoredEvents) && getEventCount(ev) >= maxCount {
 				var msg string
+				eventMessage := ev.Message // Original Kubelet message from the event
+				if ev.Reason == "FailedPostStartHook" {
+					eventMessage = getConcisePostStartFailureMessage(ev.Message)
+				}
+
 				if getEventCount(ev) > 1 {
-					msg = fmt.Sprintf("Detected unrecoverable event %s %d times: %s.", ev.Reason, getEventCount(ev), ev.Message)
+					msg = fmt.Sprintf("Detected unrecoverable event %s %d times: %s", ev.Reason, getEventCount(ev), eventMessage)
 				} else {
-					msg = fmt.Sprintf("Detected unrecoverable event %s: %s.", ev.Reason, ev.Message)
+					msg = fmt.Sprintf("Detected unrecoverable event %s: %s", ev.Reason, eventMessage)
 				}
 				return msg, nil
 			}
@@ -157,22 +163,110 @@ func CheckPodEvents(pod *corev1.Pod, workspaceID string, ignoredEvents []string,
 	return "", nil
 }
 
+// getConcisePostStartFailureMessage tries to parse the Kubelet's verbose message
+// for a PostStartHookError into a more user-friendly one.
+func getConcisePostStartFailureMessage(kubeletMsg string) string {
+
+	/* regexes for specific messages from our postStart script's output */
+
+	// matches: "[postStart hook] Commands terminated by SIGTERM (likely timed out after ...s). Exit code 143."
+	reTerminatedSigterm := regexp.MustCompile(`(\[postStart hook\] Commands terminated by SIGTERM \(likely timed out after [^)]+?\)\. Exit code 143\.)`)
+
+	// matches: "[postStart hook] Commands forcefully killed by SIGKILL (likely after --kill-after ...s expired). Exit code 137."
+	reKilledSigkill := regexp.MustCompile(`(\[postStart hook\] Commands forcefully killed by SIGKILL \(likely after --kill-after [^)]+?\)\. Exit code 137\.)`)
+
+	// matches: "[postStart hook] Commands failed with exit code ..." (for any other script-reported non-zero exit code)
+	reGenericFailedExitCode := regexp.MustCompile(`(\[postStart hook\] Commands failed with exit code \d+\.)`)
+
+	// regex to capture Kubelet's explicit message field content if it exists
+	reKubeletInternalMessage := regexp.MustCompile(`message:\s*"([^"]*)"`)
+
+	// regex to capture Kubelet's reported exit code for the hook command
+	reKubeletExitCode := regexp.MustCompile(`exited with (\d+):`)
+
+	/* 1: check Kubelet's explicit `message: "..."` field for the specific output */
+
+	kubeletInternalMsgMatch := reKubeletInternalMessage.FindStringSubmatch(kubeletMsg)
+	if len(kubeletInternalMsgMatch) > 1 && kubeletInternalMsgMatch[1] != "" {
+		internalMsg := kubeletInternalMsgMatch[1]
+		if match := reTerminatedSigterm.FindString(internalMsg); match != "" {
+			return match
+		}
+		if match := reKilledSigkill.FindString(internalMsg); match != "" {
+			return match
+		}
+		if match := reGenericFailedExitCode.FindString(internalMsg); match != "" {
+			return match
+		}
+	}
+
+	/* 2: parse Kubelet's reported exit code for the entire hook command */
+
+	matchesKubeletExitCode := reKubeletExitCode.FindStringSubmatch(kubeletMsg)
+	if len(matchesKubeletExitCode) > 1 {
+		exitCodeStr := matchesKubeletExitCode[1]
+		var exitCode int
+		fmt.Sscanf(exitCodeStr, "%d", &exitCode)
+
+		// generate messages indicating the source is Kubelet's reported exit code
+		if exitCode == 143 { // SIGTERM
+			return "[postStart hook] Commands terminated by SIGTERM due to timeout"
+		} else if exitCode == 137 { // SIGKILL
+			return "[postStart hook] Commands forcefully killed by SIGKILL due to timeout"
+		} else if exitCode != 0 { // Other non-zero exit codes (e.g., 124, 127)
+			return fmt.Sprintf("[postStart hook] Commands failed (Kubelet reported exit code %s)", exitCodeStr)
+		}
+	}
+
+	/* 3: try to match specific script outputs against the *entire* Kubelet message */
+
+	if match := reTerminatedSigterm.FindString(kubeletMsg); match != "" {
+		return match
+	}
+	if match := reKilledSigkill.FindString(kubeletMsg); match != "" {
+		return match
+	}
+	if match := reGenericFailedExitCode.FindString(kubeletMsg); match != "" {
+		return match
+	}
+
+	/* 4: fallback */
+
+	return "[postStart hook] failed with an unknown error (see pod events or container logs for more details)"
+}
+
 func CheckContainerStatusForFailure(containerStatus *corev1.ContainerStatus, ignoredEvents []string) (ok bool, reason string) {
 	if containerStatus.State.Waiting != nil {
+		// Explicitly check for PostStartHookError
+		if containerStatus.State.Waiting.Reason == "PostStartHookError" { // Kubelet uses this reason
+			conciseMsg := getConcisePostStartFailureMessage(containerStatus.State.Waiting.Message)
+			return checkIfUnrecoverableEventIgnored("FailedPostStartHook", ignoredEvents), conciseMsg
+		}
+		// Check against other generic failure reasons
 		for _, failureReason := range containerFailureStateReasons {
 			if containerStatus.State.Waiting.Reason == failureReason {
-				return checkIfUnrecoverableEventIgnored(containerStatus.State.Waiting.Reason, ignoredEvents), containerStatus.State.Waiting.Reason
+				return checkIfUnrecoverableEventIgnored(containerStatus.State.Waiting.Reason, ignoredEvents),
+					containerStatus.State.Waiting.Reason
 			}
 		}
 	}
 
 	if containerStatus.State.Terminated != nil {
+		// Check if termination was due to a generic error, which might include postStart issues
+		// if the container failed to run.
+		if containerStatus.State.Terminated.Reason == "Error" || containerStatus.State.Terminated.Reason == "ContainerCannotRun" {
+			return checkIfUnrecoverableEventIgnored(containerStatus.State.Terminated.Reason, ignoredEvents),
+				fmt.Sprintf("%s: %s", containerStatus.State.Terminated.Reason, containerStatus.State.Terminated.Message)
+		}
+		// Check against other generic failure reasons for terminated state
 		for _, failureReason := range containerFailureStateReasons {
 			if containerStatus.State.Terminated.Reason == failureReason {
-				return checkIfUnrecoverableEventIgnored(containerStatus.State.Terminated.Reason, ignoredEvents), containerStatus.State.Terminated.Reason
+				return checkIfUnrecoverableEventIgnored(containerStatus.State.Terminated.Reason, ignoredEvents),
+					containerStatus.State.Terminated.Reason
 			}
 		}
 	}
+
 	return true, ""
 }