Add a timeout when initializing the Podman client (broken Podman shou…

…ld not affect `odo dev` on cluster) (#6808)

* Add test highlighting the issue and setting the expectations

* Add a timeout of 1s to the 'podman version' command

This command is called at dependency injection time to initialize a (nil-able) Podman client,
even if users won't use Podman at all.
As discussed, this command is supposed to be
quite fast to return, hence this timeout of 1 second.

Initially, we were using cmd.Output to get the command output,
but as reported in [1], cmd.Output does not respect the context timeout.
This explains the workaround of reading from both stdout and stderr pipes,
*and* relying on cmd.Wait() to close those pipes properly when the program exits
(either as expected or when the timeout is reached).

[1] golang/go#57129

Co-authored-by: Philippe Martin <phmartin@redhat.com>

* Log the errors returned at dependency injection time when the optional Kubernetes/Podman clients could not be initialized

This helps debug such potential issues instead of swallowing the errors.

* Make the timeout configurable via the 'PODMAN_CMD_INIT_TIMEOUT' env var

This will allow setting a different value for environments like
in GitHub where the Podman client would take slightly more time to return
(I guess because of we are running a lot of Podman commands in parallel?).

* Increase the timeout for Podman tests to an arbitrary value of 10s

Some tests did not pass because the Podman client did not
initialize in 1s; I guess because we are running a lot of Podman commands in parallel?
This should hopefully improve this situation.

* fixup! Add a timeout of 1s to the 'podman version' command

---------

Co-authored-by: Philippe Martin <phmartin@redhat.com>

docs/website/docs/overview/configure.md

@@ -183,6 +183,7 @@ Options here are mostly used for debugging and testing `odo` behavior.
 |-------------------------------------|--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|---------------|--------------------------------------------|
 | `PODMAN_CMD`                        | The command executed to run the local podman binary. `podman` by default                                                                                                                                                                                                                                                                                                       | v2.4.2        | `podman`                                   |
 | `DOCKER_CMD`                        | The command executed to run the local docker binary. `docker` by default                                                                                                                                                                                                                                                                                                       | v2.4.2        | `docker`                                   |
+| `PODMAN_CMD_INIT_TIMEOUT`           | Timeout for initializing the Podman client. `1s` by default                                                                                                                                                                                                                                                                                                                    | v3.11.0       | `5s`                                       |
 | `ODO_LOG_LEVEL`                     | Useful for setting a log level to be used by `odo` commands. Takes precedence over the `-v` flag.                                                                                                                                                                                                                                                                              | v1.0.2        | 3                                          |
 | `ODO_DISABLE_TELEMETRY`             | Useful for disabling [telemetry collection](https://github.com/redhat-developer/odo/blob/main/USAGE_DATA.md). **Deprecated in v3.2.0**. Use `ODO_TRACKING_CONSENT` instead.                                                                                                                                                                                                    | v2.1.0        | `true`                                     |
 | `GLOBALODOCONFIG`                   | Useful for setting a different location of global preference file `preference.yaml`.                                                                                                                                                                                                                                                                                           | v0.0.19       | `~/.config/odo/preference.yaml`            |

pkg/config/config.go

@@ -2,25 +2,27 @@ package config
 
 import (
 	"context"
+	"time"
 
 	"github.com/sethvargo/go-envconfig"
 )
 
 type Configuration struct {
-	DevfileProxy                  *string  `env:"DEVFILE_PROXY,noinit"`
-	DockerCmd                     string   `env:"DOCKER_CMD,default=docker"`
-	Globalodoconfig               *string  `env:"GLOBALODOCONFIG,noinit"`
-	OdoDebugTelemetryFile         *string  `env:"ODO_DEBUG_TELEMETRY_FILE,noinit"`
-	OdoDisableTelemetry           *bool    `env:"ODO_DISABLE_TELEMETRY,noinit"`
-	OdoLogLevel                   *int     `env:"ODO_LOG_LEVEL,noinit"`
-	OdoTrackingConsent            *string  `env:"ODO_TRACKING_CONSENT,noinit"`
-	PodmanCmd                     string   `env:"PODMAN_CMD,default=podman"`
-	TelemetryCaller               string   `env:"TELEMETRY_CALLER,default="`
-	OdoExperimentalMode           bool     `env:"ODO_EXPERIMENTAL_MODE,default=false"`
-	PushImages                    bool     `env:"ODO_PUSH_IMAGES,default=true"`
-	OdoContainerBackendGlobalArgs []string `env:"ODO_CONTAINER_BACKEND_GLOBAL_ARGS,noinit,delimiter=;"`
-	OdoImageBuildArgs             []string `env:"ODO_IMAGE_BUILD_ARGS,noinit,delimiter=;"`
-	OdoContainerRunArgs           []string `env:"ODO_CONTAINER_RUN_ARGS,noinit,delimiter=;"`
+	DevfileProxy                  *string       `env:"DEVFILE_PROXY,noinit"`
+	DockerCmd                     string        `env:"DOCKER_CMD,default=docker"`
+	Globalodoconfig               *string       `env:"GLOBALODOCONFIG,noinit"`
+	OdoDebugTelemetryFile         *string       `env:"ODO_DEBUG_TELEMETRY_FILE,noinit"`
+	OdoDisableTelemetry           *bool         `env:"ODO_DISABLE_TELEMETRY,noinit"`
+	OdoLogLevel                   *int          `env:"ODO_LOG_LEVEL,noinit"`
+	OdoTrackingConsent            *string       `env:"ODO_TRACKING_CONSENT,noinit"`
+	PodmanCmd                     string        `env:"PODMAN_CMD,default=podman"`
+	PodmanCmdInitTimeout          time.Duration `env:"PODMAN_CMD_INIT_TIMEOUT,default=1s"`
+	TelemetryCaller               string        `env:"TELEMETRY_CALLER,default="`
+	OdoExperimentalMode           bool          `env:"ODO_EXPERIMENTAL_MODE,default=false"`
+	PushImages                    bool          `env:"ODO_PUSH_IMAGES,default=true"`
+	OdoContainerBackendGlobalArgs []string      `env:"ODO_CONTAINER_BACKEND_GLOBAL_ARGS,noinit,delimiter=;"`
+	OdoImageBuildArgs             []string      `env:"ODO_IMAGE_BUILD_ARGS,noinit,delimiter=;"`
+	OdoContainerRunArgs           []string      `env:"ODO_CONTAINER_RUN_ARGS,noinit,delimiter=;"`
 }
 
 // GetConfiguration initializes a Configuration for odo by using the system environment.

pkg/odo/genericclioptions/clientset/clientset.go

@@ -13,6 +13,7 @@ package clientset
 
 import (
 	"github.com/spf13/cobra"
+	"k8s.io/klog"
 
 	"github.com/redhat-developer/odo/pkg/configAutomount"
 	"github.com/redhat-developer/odo/pkg/dev/kubedev"
@@ -182,6 +183,7 @@ func Fetch(command *cobra.Command, platform string) (*Clientset, error) {
 			if isDefined(command, KUBERNETES) && !isDefined(command, KUBERNETES_NULLABLE) {
 				return nil, err
 			}
+			klog.V(3).Infof("no Kubernetes client initialized: %v", err)
 			dep.KubernetesClient = nil
 		}
 
@@ -193,6 +195,7 @@ func Fetch(command *cobra.Command, platform string) (*Clientset, error) {
 			if isDefined(command, PODMAN) || platform == commonflags.PlatformPodman {
 				return nil, podman.NewPodmanNotFoundError(err)
 			}
+			klog.V(3).Infof("no Podman client initialized: %v", err)
 			dep.PodmanClient = nil
 		}
 	}

pkg/podman/interface.go

@@ -1,6 +1,8 @@
 package podman
 
 import (
+	"context"
+
 	corev1 "k8s.io/api/core/v1"
 
 	"github.com/redhat-developer/odo/pkg/api"
@@ -36,5 +38,5 @@ type Client interface {
 
 	ListAllComponents() ([]api.ComponentAbstract, error)
 
-	Version() (SystemVersionReport, error)
+	Version(ctx context.Context) (SystemVersionReport, error)
 }

pkg/podman/podman.go

@@ -6,6 +6,7 @@ import (
 	"fmt"
 	"os/exec"
 	"strings"
+	"time"
 
 	envcontext "github.com/redhat-developer/odo/pkg/config/context"
 	"github.com/redhat-developer/odo/pkg/platform"
@@ -18,6 +19,7 @@ import (
 
 type PodmanCli struct {
 	podmanCmd                   string
+	podmanCmdInitTimeout        time.Duration
 	containerRunGlobalExtraArgs []string
 	containerRunExtraArgs       []string
 }
@@ -30,10 +32,11 @@ func NewPodmanCli(ctx context.Context) (*PodmanCli, error) {
 	// Check if podman is available in the system
 	cli := &PodmanCli{
 		podmanCmd:                   envcontext.GetEnvConfig(ctx).PodmanCmd,
+		podmanCmdInitTimeout:        envcontext.GetEnvConfig(ctx).PodmanCmdInitTimeout,
 		containerRunGlobalExtraArgs: envcontext.GetEnvConfig(ctx).OdoContainerBackendGlobalArgs,
 		containerRunExtraArgs:       envcontext.GetEnvConfig(ctx).OdoContainerRunArgs,
 	}
-	version, err := cli.Version()
+	version, err := cli.Version(ctx)
 	if err != nil {
 		return nil, err
 	}

pkg/podman/version.go

@@ -1,9 +1,14 @@
 package podman
 
 import (
+	"bytes"
+	"context"
 	"encoding/json"
+	"errors"
 	"fmt"
 	"os/exec"
+	"sync"
+	"time"
 
 	"k8s.io/klog"
 )
@@ -23,20 +28,92 @@ type SystemVersionReport struct {
 	Client *Version `json:",omitempty"`
 }
 
-func (o *PodmanCli) Version() (SystemVersionReport, error) {
-	cmd := exec.Command(o.podmanCmd, "version", "--format", "json")
+// Version returns the version of the Podman client.
+func (o *PodmanCli) Version(ctx context.Context) (SystemVersionReport, error) {
+	// Because Version is used at the very beginning of odo, when resolving and injecting dependencies (for commands that might require the Podman client),
+	// it is expected to return in a timely manner (hence this configurable timeout).
+	// This is to avoid situations like the one described in https://github.com/redhat-developer/odo/issues/6575
+	// (where a podman CLI that takes too long to respond affects the "odo dev" command, even if the user did not intend to use the Podman platform).
+	ctxWithTimeout, cancel := context.WithTimeout(ctx, o.podmanCmdInitTimeout)
+	defer cancel()
+
+	cmd := exec.CommandContext(ctxWithTimeout, o.podmanCmd, "version", "--format", "json")
 	klog.V(3).Infof("executing %v", cmd.Args)
-	out, err := cmd.Output()
+
+	// Because cmd.Output() does not respect the context timeout (see https://github.com/golang/go/issues/57129),
+	// we are reading from the connected pipes instead.
+	stdoutPipe, err := cmd.StdoutPipe()
 	if err != nil {
-		if exiterr, ok := err.(*exec.ExitError); ok {
-			err = fmt.Errorf("%s: %s", err, string(exiterr.Stderr))
-		}
 		return SystemVersionReport{}, err
 	}
-	var result SystemVersionReport
-	err = json.Unmarshal(out, &result)
+	stderrPipe, err := cmd.StderrPipe()
+	if err != nil {
+		return SystemVersionReport{}, err
+	}
+
+	err = cmd.Start()
 	if err != nil {
 		return SystemVersionReport{}, err
 	}
+
+	var wg sync.WaitGroup
+	wg.Add(3)
+
+	var result SystemVersionReport
+	go func() {
+		defer wg.Done()
+		// Reading from the pipe is a blocking call, hence this goroutine.
+		// The goroutine will exit after the pipe is closed or the command exits;
+		// these will be triggered by cmd.Wait() either after the timeout expires or the command finished.
+		err = json.NewDecoder(stdoutPipe).Decode(&result)
+		if err != nil {
+			klog.V(3).Infof("unable to decode output: %v", err)
+		}
+	}()
+
+	var stderr string
+	go func() {
+		defer wg.Done()
+		var buf bytes.Buffer
+		_, rErr := buf.ReadFrom(stderrPipe)
+		if rErr != nil {
+			klog.V(7).Infof("unable to read from stderr pipe: %v", rErr)
+		}
+		stderr = buf.String()
+	}()
+
+	var wErr error
+	go func() {
+		defer wg.Done()
+		// cmd.Wait() will block until the timeout expires or the program started by cmd exits.
+		// It will then close all resources associated with cmd,
+		// including the stdout and stderr pipes above, which will in turn terminate the goroutines spawned above.
+		wErr = cmd.Wait()
+	}()
+
+	// Wait until all we are sure all previous goroutines are done
+	wg.Wait()
+
+	if wErr != nil {
+		ctxErr := ctxWithTimeout.Err()
+		if ctxErr != nil {
+			msg := "error"
+			if errors.Is(ctxErr, context.DeadlineExceeded) {
+				msg = fmt.Sprintf("timeout (%s)", o.podmanCmdInitTimeout.Round(time.Second).String())
+			}
+			wErr = fmt.Errorf("%s while waiting for Podman version: %s: %w", msg, ctxErr, wErr)
+		}
+		if exitErr, ok := wErr.(*exec.ExitError); ok {
+			wErr = fmt.Errorf("%s: %s", wErr, string(exitErr.Stderr))
+		}
+		if err != nil {
+			wErr = fmt.Errorf("%s: (%w)", wErr, err)
+		}
+		if stderr != "" {
+			wErr = fmt.Errorf("%w: %s", wErr, stderr)
+		}
+		return SystemVersionReport{}, fmt.Errorf("%v. Please check the output of the following command: %v", wErr, cmd.Args)
+	}
+
 	return result, nil
 }

pkg/segment/context/context.go

@@ -150,7 +150,7 @@ func setPlatformCluster(ctx context.Context, client kclient.ClientInterface) {
 
 func setPlatformPodman(ctx context.Context, client podman.Client) {
 	setContextProperty(ctx, Platform, "podman")
-	version, err := client.Version()
+	version, err := client.Version(ctx)
 	if err != nil {
 		klog.V(3).Info(fmt.Errorf("unable to get podman version: %w", err))
 		return

tests/helper/helper_filesystem.go

@@ -238,8 +238,15 @@ func copyDir(src string, dst string, info os.FileInfo) error {
 // path is the path to the required file
 // fileContent is the content to be written to the given file
 func CreateFileWithContent(path string, fileContent string) error {
+	return CreateFileWithContentAndPerm(path, fileContent, 0600)
+}
+
+// CreateFileWithContentAndPerm creates a file at the given path using the given file permissions, and writes the given content.
+// path is the path to the required file
+// fileContent is the content to be written to the given file
+func CreateFileWithContentAndPerm(path string, fileContent string, perm os.FileMode) error {
 	// create and open file if not exists
-	var file, err = os.OpenFile(path, os.O_RDWR|os.O_CREATE, 0600)
+	var file, err = os.OpenFile(path, os.O_RDWR|os.O_CREATE, perm)
 	if err != nil {
 		return err
 	}

tests/helper/helper_generic.go

@@ -214,6 +214,18 @@ func CommonBeforeEach() CommonVar {
 		os.Setenv("KUBECONFIG", kubeconfig.Name())
 
 		if NeedsPodman(specLabels) {
+			originalPodmanCmdInitTimeout, present := os.LookupEnv("PODMAN_CMD_INIT_TIMEOUT")
+			DeferCleanup(func() {
+				var resetErr error
+				if present {
+					resetErr = os.Setenv("PODMAN_CMD_INIT_TIMEOUT", originalPodmanCmdInitTimeout)
+				} else {
+					resetErr = os.Unsetenv("PODMAN_CMD_INIT_TIMEOUT")
+				}
+				Expect(resetErr).ShouldNot(HaveOccurred())
+			})
+			Expect(os.Setenv("PODMAN_CMD_INIT_TIMEOUT", "10s")).ShouldNot(HaveOccurred())
+
 			// Generate a dedicated containers.conf with a specific namespace
 			GenerateAndSetContainersConf(commonVar.ConfigDir)
 		}

tests/integration/cmd_dev_test.go

@@ -3,8 +3,10 @@ package integration
 import (
 	"bufio"
 	"encoding/json"
+	"errors"
 	"fmt"
 	"io"
+	"io/fs"
 	"net/http"
 	"net/http/httptest"
 	"os"
@@ -80,6 +82,44 @@ var _ = Describe("odo dev command tests", func() {
 			errOut := helper.Cmd("odo", "dev", "--platform", "podman").WithEnv("PODMAN_CMD=echo").ShouldFail().Err()
 			Expect(errOut).To(ContainSubstring("unable to access podman"))
 		})
+
+		It("should start on cluster even if Podman client takes long to initialize", func() {
+			if runtime.GOOS == "windows" {
+				Skip("skipped on Windows as it requires Unix permissions")
+			}
+			_, err := os.Stat("/bin/bash")
+			if errors.Is(err, fs.ErrNotExist) {
+				Skip("skipped because bash executable not found")
+			}
+
+			// odo dev on cluster should not wait for the Podman client to initialize properly, if this client takes very long.
+			// See https://github.com/redhat-developer/odo/issues/6575.
+			// StartDevMode will time out if Podman client takes too long to initialize.
+			delayer := filepath.Join(commonVar.Context, "podman-cmd-delayer")
+			err = helper.CreateFileWithContentAndPerm(delayer, `#!/bin/bash
+
+echo Delaying command execution... >&2
+sleep 7200
+echo "$@"
+`, 0755)
+			Expect(err).ShouldNot(HaveOccurred())
+
+			var devSession helper.DevSession
+			var stderrBytes []byte
+			devSession, _, stderrBytes, _, err = helper.StartDevMode(helper.DevSessionOpts{
+				RunOnPodman: false,
+				CmdlineArgs: []string{"-v", "3"},
+				EnvVars: []string{
+					"PODMAN_CMD=" + delayer,
+					"PODMAN_CMD_INIT_TIMEOUT=1s",
+				},
+			})
+			Expect(err).ShouldNot(HaveOccurred())
+			defer devSession.Kill()
+
+			Expect(string(stderrBytes)).Should(MatchRegexp("timeout \\([^()]+\\) while waiting for Podman version"))
+		})
+
 		When("using a default namespace", func() {
 			BeforeEach(func() {
 				commonVar.CliRunner.SetProject("default")