Fix slow docker warning logic

Author: skartikey

pkg/drivers/kic/oci/cli_runner.go

@@ -150,16 +150,6 @@ func runCmd(cmd *exec.Cmd, warnSlow ...bool) (*RunResult, error) {
 		warnTime = 3 * time.Second
 	}
 
-	ctx, cancel := context.WithTimeout(context.Background(), killTime)
-	defer cancel()
-
-	if warn { // convert exec.Command to with context
-		cmdWithCtx := exec.CommandContext(ctx, cmd.Args[0], cmd.Args[1:]...)
-		cmdWithCtx.Stdout = cmd.Stdout // copying the original command
-		cmdWithCtx.Stderr = cmd.Stderr
-		cmd = cmdWithCtx
-	}
-
 	rr := &RunResult{Args: cmd.Args}
 	klog.Infof("Run: %v", rr.Command())
 
@@ -182,31 +172,84 @@ func runCmd(cmd *exec.Cmd, warnSlow ...bool) (*RunResult, error) {
 	cmd.Stderr = errb
 
 	start := time.Now()
-	err := cmd.Run()
-	elapsed := time.Since(start)
-	if warn && !out.JSON && !suppressDockerMessage() {
-		if elapsed > warnTime {
-			warnLock.Lock()
-			_, ok := alreadyWarnedCmds[rr.Command()]
-			if !ok {
-				alreadyWarnedCmds[rr.Command()] = true
-			}
-			warnLock.Unlock()
+	var err error
+
+	if warn {
+		// Use a more robust approach with proper timeout handling
+		ctx, cancel := context.WithTimeout(context.Background(), killTime)
+		defer cancel()
 
-			if !ok {
-				out.WarningT(`Executing "{{.command}}" took an unusually long time: {{.duration}}`, out.V{"command": rr.Command(), "duration": elapsed})
-				// Don't show any restarting hint, when running podman locally (on linux, with sudo). Only when having a service.
-				if cmd.Args[0] != "sudo" {
-					out.ErrT(style.Tip, `Restarting the {{.name}} service may improve performance.`, out.V{"name": cmd.Args[0]})
+		// Create command with context for proper cancellation
+		cmdWithCtx := exec.CommandContext(ctx, cmd.Args[0], cmd.Args[1:]...)
+		cmdWithCtx.Stdout = cmd.Stdout
+		cmdWithCtx.Stderr = cmd.Stderr
+		cmdWithCtx.Env = cmd.Env
+		cmdWithCtx.Dir = cmd.Dir
+
+		// Channel to track completion
+		done := make(chan error, 1)
+		var warnTimer *time.Timer
+
+		// Start the command in a goroutine
+		go func() {
+			done <- cmdWithCtx.Run()
+		}()
+
+		// Set up warning timer
+		if !out.JSON && !suppressDockerMessage() {
+			warnTimer = time.AfterFunc(warnTime, func() {
+				warnLock.Lock()
+				_, ok := alreadyWarnedCmds[rr.Command()]
+				if !ok {
+					alreadyWarnedCmds[rr.Command()] = true
+					warnLock.Unlock()
+
+					// Show immediate warning that the operation is slow
+					out.WarningT(`"{{.command}}" is taking an unusually long time to respond, please be patient.`, out.V{"command": rr.Command()})
+					// Don't show any restarting hint, when running podman locally (on linux, with sudo). Only when having a service.
+					if cmd.Args[0] != "sudo" {
+						out.ErrT(style.Tip, `If this continues to hang, consider restarting the {{.name}} service.`, out.V{"name": cmd.Args[0]})
+					}
+				} else {
+					warnLock.Unlock()
 				}
-			}
+			})
 		}
 
-		if ctx.Err() == context.DeadlineExceeded {
-			return rr, context.DeadlineExceeded
+		// Wait for completion or timeout
+		select {
+		case err = <-done:
+			// Command completed normally
+			if warnTimer != nil {
+				warnTimer.Stop()
+			}
+		case <-ctx.Done():
+			// Command timed out
+			if warnTimer != nil {
+				warnTimer.Stop()
+			}
+
+			// Kill the process if it's still running
+			if cmdWithCtx.Process != nil {
+				klog.Warningf("Killing slow %s process after %v timeout", rr.Command(), killTime)
+				cmdWithCtx.Process.Kill()
+			}
+
+			out.WarningT(`"{{.command}}" took too long to respond (>{{.duration}}) and was terminated.`, out.V{"command": rr.Command(), "duration": killTime})
+			if cmd.Args[0] != "sudo" {
+				out.ErrT(style.Tip, `Consider restarting the {{.name}} service if this problem persists.`, out.V{"name": cmd.Args[0]})
+			}
+
+			return rr, fmt.Errorf("command timed out after %v: %s", killTime, rr.Command())
 		}
+	} else {
+		// Run without timeout for non-critical operations
+		err = cmd.Run()
 	}
 
+	elapsed := time.Since(start)
+
+	// Log completion information
 	if ex, ok := err.(*exec.ExitError); ok {
 		klog.Warningf("%s returned with exit code %d", rr.Command(), ex.ExitCode())
 		rr.ExitCode = ex.ExitCode()

pkg/drivers/kic/oci/oci.go

@@ -41,54 +41,61 @@ import (
 )
 
 // DeleteContainersByLabel deletes all containers that have a specific label
-// if there no containers found with the given 	label, it will return nil
+// if there no containers found with the given label, it will return nil
 func DeleteContainersByLabel(ociBin string, label string) []error {
 	var deleteErrs []error
 	ctx := context.Background()
-	cs, err := ListContainersByLabel(ctx, ociBin, label)
+
+	// Enable slow warning for container listing during delete operations
+	cs, err := ListContainersByLabel(ctx, ociBin, label, true)
 	if err != nil {
-		return []error{fmt.Errorf("listing containers by label %q", label)}
+		return []error{fmt.Errorf("listing containers by label %q: %v", label, err)}
 	}
 
 	if len(cs) == 0 {
 		return nil
 	}
 
 	for _, c := range cs {
-		_, err := ContainerStatus(ociBin, c)
+		// Enable slow warning for container status check
+		_, err := ContainerStatus(ociBin, c, true)
 		// only try to delete if docker/podman inspect returns
 		// if it doesn't it means docker daemon is stuck and needs restart
 		if err != nil {
 			deleteErrs = append(deleteErrs, errors.Wrapf(err, "delete container %s: %s daemon is stuck. please try again", c, ociBin))
 			klog.Errorf("%s daemon seems to be stuck. please try restarting your %s :%v", ociBin, ociBin, err)
 			continue
 		}
+
 		if err := ShutDown(ociBin, c); err != nil {
 			klog.Infof("couldn't shut down %s (might be okay): %v ", c, err)
 		}
 
-		if _, err := runCmd(exec.Command(ociBin, "rm", "-f", "-v", c)); err != nil {
+		// Enable slow warning for container removal
+		if _, err := runCmd(exec.Command(ociBin, "rm", "-f", "-v", c), true); err != nil {
 			deleteErrs = append(deleteErrs, errors.Wrapf(err, "delete container %s: output %s", c, err))
 		}
-
 	}
 	return deleteErrs
 }
 
 // DeleteContainer deletes a container by ID or Name
 func DeleteContainer(ctx context.Context, ociBin string, name string) error {
-	_, err := ContainerStatus(ociBin, name)
+	// Enable slow warning for container status check
+	_, err := ContainerStatus(ociBin, name, true)
 	if err == context.DeadlineExceeded {
-		out.WarningT("{{.ocibin}} is taking an unusually long time to respond, consider restarting {{.ocibin}}", out.V{"ociBin": ociBin})
+		out.WarningT("{{.ocibin}} is taking an unusually long time to respond, consider restarting {{.ocibin}}", out.V{"ocibin": ociBin})
 	} else if err != nil {
 		klog.Warningf("error getting container status, will try to delete anyways: %v", err)
 	}
+
 	// try to delete anyways
 	if err := ShutDown(ociBin, name); err != nil {
 		klog.Infof("couldn't shut down %s (might be okay): %v ", name, err)
 	}
 
-	if _, err := runCmd(exec.CommandContext(ctx, ociBin, "rm", "-f", "-v", name)); err != nil {
+	// Enable slow warning for container removal
+	if _, err := runCmd(exec.CommandContext(ctx, ociBin, "rm", "-f", "-v", name), true); err != nil {
 		return errors.Wrapf(err, "delete %s", name)
 	}
 	return nil
@@ -368,7 +375,12 @@ func ContainerID(ociBin string, nameOrID string) (string, error) {
 
 // ContainerExists checks if container name exists (either running or exited)
 func ContainerExists(ociBin string, name string, warnSlow ...bool) (bool, error) {
-	rr, err := runCmd(exec.Command(ociBin, "ps", "-a", "--format", "{{.Names}}"), warnSlow...)
+	shouldWarn := false
+	if len(warnSlow) > 0 {
+		shouldWarn = warnSlow[0]
+	}
+
+	rr, err := runCmd(exec.Command(ociBin, "ps", "-a", "--format", "{{.Names}}"), shouldWarn)
 	if err != nil {
 		return false, err
 	}
@@ -540,7 +552,13 @@ func withPortMappings(portMappings []PortMapping) createOpt {
 
 // ListContainersByLabel returns all the container names with a specified label
 func ListContainersByLabel(ctx context.Context, ociBin string, label string, warnSlow ...bool) ([]string, error) {
-	rr, err := runCmd(exec.CommandContext(ctx, ociBin, "ps", "-a", "--filter", fmt.Sprintf("label=%s", label), "--format", "{{.Names}}"), warnSlow...)
+	// Default to enabling warnings for container listing operations during critical operations like delete
+	shouldWarn := false
+	if len(warnSlow) > 0 {
+		shouldWarn = warnSlow[0]
+	}
+
+	rr, err := runCmd(exec.CommandContext(ctx, ociBin, "ps", "-a", "--filter", fmt.Sprintf("label=%s", label), "--format", "{{.Names}}"), shouldWarn)
 	if err != nil {
 		return nil, err
 	}
@@ -619,7 +637,12 @@ func PointToHostPodman() error {
 
 // ContainerRunning returns running state of a container
 func ContainerRunning(ociBin string, name string, warnSlow ...bool) (bool, error) {
-	rr, err := runCmd(exec.Command(ociBin, "container", "inspect", name, "--format={{.State.Running}}"), warnSlow...)
+	shouldWarn := false
+	if len(warnSlow) > 0 {
+		shouldWarn = warnSlow[0]
+	}
+
+	rr, err := runCmd(exec.Command(ociBin, "container", "inspect", name, "--format={{.State.Running}}"), shouldWarn)
 	if err != nil {
 		return false, err
 	}
@@ -628,8 +651,13 @@ func ContainerRunning(ociBin string, name string, warnSlow ...bool) (bool, error
 
 // ContainerStatus returns status of a container running,exited,...
 func ContainerStatus(ociBin string, name string, warnSlow ...bool) (state.State, error) {
+	shouldWarn := false
+	if len(warnSlow) > 0 {
+		shouldWarn = warnSlow[0]
+	}
+
 	cmd := exec.Command(ociBin, "container", "inspect", name, "--format={{.State.Status}}")
-	rr, err := runCmd(cmd, warnSlow...)
+	rr, err := runCmd(cmd, shouldWarn)
 	o := strings.TrimSpace(rr.Stdout.String())
 	switch o {
 	case "configured":

pkg/minikube/delete/delete.go

@@ -47,15 +47,16 @@ func PossibleLeftOvers(ctx context.Context, cname string, driverName string) {
 
 	klog.Infof("deleting possible leftovers for %s (driver=%s) ...", cname, driverName)
 	delLabel := fmt.Sprintf("%s=%s", oci.ProfileLabelKey, cname)
-	cs, err := oci.ListContainersByLabel(ctx, bin, delLabel)
+
+	// Enable slow warning for container listing during delete operations
+	cs, err := oci.ListContainersByLabel(ctx, bin, delLabel, true)
 	if err == nil && len(cs) > 0 {
 		for _, c := range cs {
 			out.Step(style.DeletingHost, `Deleting container "{{.name}}" ...`, out.V{"name": cname})
 			err := oci.DeleteContainer(ctx, bin, c)
 			if err != nil { // it will error if there is no container to delete
 				klog.Errorf("error deleting container %q. You may want to delete it manually :\n%v", cname, err)
 			}
-
 		}
 	}