cmd/run: Optimize 'enter' and 'run' for a container getting initialized

Currently, the 'enter' and 'run' commands poll at one second intervals
to check if the Toolbx container's entry point has created the
initialization stamp file to indicate that the container has been
initialized.  This came from the POSIX shell implementation [1], where
it was relatively easier to poll than to use inotify(7) to monitor the
file system.

The problem with polling is that the interval is always going to be
either too short and waste resources or too long and cause delays.  The
current one second interval is sufficiently long to add a noticeable
delay to the 'enter' and 'run' commands.

It will be better to use inotify(7) to monitor the file system, which is
quite easy to do with the Go implementation, so that the commands can
proceed as soon as the initialization stamp file is available, instead
of waiting for the polling interval to pass.

There's a fallback to polling, as before, when the operating system is
suffering from a shortage of resources needed for inotify(7).  This code
path can be forced through the TOOLBX_RUN_USE_POLLING environment
variable for testing.

[1] Commit d3e0f3d
    containers@d3e0f3df06d3f5ac
    containers#305

containers#1070

src/cmd/run.go

@@ -22,15 +22,18 @@ import (
 	"io"
 	"os"
 	"path/filepath"
+	"strconv"
 	"strings"
 	"time"
 
 	"github.com/containers/toolbox/pkg/podman"
 	"github.com/containers/toolbox/pkg/shell"
 	"github.com/containers/toolbox/pkg/term"
 	"github.com/containers/toolbox/pkg/utils"
+	"github.com/fsnotify/fsnotify"
 	"github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
+	"golang.org/x/sys/unix"
 )
 
 var (
@@ -283,25 +286,10 @@ func runCommand(container string,
 		logrus.Debugf("Waiting for container %s to finish initializing", container)
 	}
 
-	toolboxRuntimeDirectory, err := utils.GetRuntimeDirectory(currentUser)
-	if err != nil {
+	if err := ensureContainerIsInitialized(container, entryPointPID); err != nil {
 		return err
 	}
 
-	initializedStampBase := fmt.Sprintf("container-initialized-%d", entryPointPID)
-	initializedStamp := filepath.Join(toolboxRuntimeDirectory, initializedStampBase)
-
-	logrus.Debugf("Checking if initialization stamp %s exists", initializedStamp)
-
-	initializedTimeout := 25 // seconds
-	for i := 0; !utils.PathExists(initializedStamp); i++ {
-		if i == initializedTimeout {
-			return fmt.Errorf("failed to initialize container %s", container)
-		}
-
-		time.Sleep(time.Second)
-	}
-
 	logrus.Debugf("Container %s is initialized", container)
 
 	if err := runCommandWithFallbacks(container,
@@ -536,6 +524,132 @@ func constructExecArgs(container, preserveFDs string,
 	return execArgs
 }
 
+func ensureContainerIsInitialized(container string, entryPointPID int) error {
+	toolboxRuntimeDirectory, err := utils.GetRuntimeDirectory(currentUser)
+	if err != nil {
+		return err
+	}
+
+	initializedStampBase := fmt.Sprintf("container-initialized-%d", entryPointPID)
+	initializedStamp := filepath.Join(toolboxRuntimeDirectory, initializedStampBase)
+	logrus.Debugf("Checking if initialization stamp %s exists", initializedStamp)
+
+	// Optional shortcut for containers that are already initialized
+	if utils.PathExists(initializedStamp) {
+		return nil
+	}
+
+	logrus.Debugf("Setting up initialization timeout for container %s", container)
+	initializedTimeout := time.NewTimer(25 * time.Second)
+	defer initializedTimeout.Stop()
+
+	var usePolling bool
+	if shouldUsePolling() {
+		usePolling = true
+	}
+
+	var watcherForStamp *fsnotify.Watcher
+
+	if !usePolling {
+		logrus.Debugf("Setting up watches for file system events from container %s", container)
+
+		var err error
+		watcherForStamp, err = fsnotify.NewWatcher()
+		if err != nil {
+			if errors.Is(err, unix.EMFILE) || errors.Is(err, unix.ENFILE) || errors.Is(err, unix.ENOMEM) {
+				logrus.Debugf("Setting up watches for file system events: failed to create Watcher: %s",
+					err)
+				logrus.Debug("Using polling instead")
+				usePolling = true
+			} else {
+				return fmt.Errorf("failed to create Watcher: %w", err)
+			}
+		}
+	}
+
+	var watcherForStampErrors chan error
+	var watcherForStampEvents chan fsnotify.Event
+
+	if watcherForStamp != nil {
+		defer watcherForStamp.Close()
+
+		if err := watcherForStamp.Add(toolboxRuntimeDirectory); err != nil {
+			if errors.Is(err, unix.ENOMEM) || errors.Is(err, unix.ENOSPC) {
+				logrus.Debugf("Setting up watches for file system events: failed to add path: %s", err)
+				logrus.Debug("Using polling instead")
+				usePolling = true
+			} else {
+				return fmt.Errorf("failed to add path to Watcher: %w", err)
+			}
+		}
+
+		if !usePolling {
+			watcherForStampErrors = watcherForStamp.Errors
+			watcherForStampEvents = watcherForStamp.Events
+		}
+	}
+
+	var tickerPolling *time.Ticker
+	var tickerPollingCh <-chan time.Time
+
+	if usePolling {
+		logrus.Debugf("Setting up polling ticker for container %s", container)
+
+		tickerPolling = time.NewTicker(time.Second)
+		defer tickerPolling.Stop()
+
+		tickerPollingCh = tickerPolling.C
+	}
+
+	// Initialization could have finished before the Watcher was set up
+	if utils.PathExists(initializedStamp) {
+		return nil
+	}
+
+	logrus.Debug("Listening to file system, ticker and timeout events")
+
+	for {
+		select {
+		case <-initializedTimeout.C:
+			return fmt.Errorf("failed to initialize container %s", container)
+		case time := <-tickerPollingCh:
+			if done := handlePollingTickForStamp(time, initializedStamp); done {
+				return nil
+			}
+		case event := <-watcherForStampEvents:
+			if done := handleFileSystemEventForStamp(event, initializedStamp); done {
+				return nil
+			}
+		case err := <-watcherForStampErrors:
+			logrus.Debugf("Received an error from the file system watcher: %s", err)
+		}
+	}
+
+	// code should not be reached
+}
+
+func handleFileSystemEventForStamp(event fsnotify.Event, initializedStamp string) bool {
+	eventOpString := event.Op.String()
+	logrus.Debugf("Handling file system event: operation %s on %s", eventOpString, event.Name)
+
+	if event.Name == initializedStamp && utils.PathExists(initializedStamp) {
+		return true
+	}
+
+	return false
+}
+
+func handlePollingTickForStamp(time time.Time, initializedStamp string) bool {
+	timeString := time.String()
+	logrus.Debugf("Handling polling tick %s", timeString)
+
+	if utils.PathExists(initializedStamp) {
+		return true
+	}
+
+	return false
+}
+
 func isCommandPresent(container, command string) (bool, error) {
 	logrus.Debugf("Looking up command %s in container %s", command, container)
 
@@ -574,6 +688,19 @@ func isPathPresent(container, path string) (bool, error) {
 	return true, nil
 }
 
+func shouldUsePolling() bool {
+	valueString := os.Getenv("TOOLBX_RUN_USE_POLLING")
+	if valueString == "" {
+		return false
+	}
+
+	if valueBool, err := strconv.ParseBool(valueString); err == nil {
+		return valueBool
+	}
+
+	return true
+}
+
 func startContainer(container string) error {
 	var stderr strings.Builder
 	if err := podman.Start(container, &stderr); err == nil {

test/system/104-run.bats

@@ -40,6 +40,25 @@ teardown() {
   assert_output ""
 }
 
+@test "run: Smoke test with true(1) (using polling fallback)" {
+  local default_container_name
+  default_container_name="$(get_system_id)-toolbox-$(get_system_version)"
+
+  create_default_container
+
+  export TOOLBX_RUN_USE_POLLING=1
+  run --separate-stderr "$TOOLBX" run --verbose true
+
+  assert_success
+  assert_output ""
+
+  # shellcheck disable=SC2154
+  output="$stderr"
+
+  assert_output --partial "Setting up polling ticker for container $default_container_name"
+  refute_output --partial "Setting up watches for file system events from container $default_container_name"
+}
+
 @test "run: Smoke test with false(1)" {
   create_default_container