Pipe automount's stdout and stderr to logging

automount's stdout and stderr are now piped to driver's logging.

Two new cmd parameters added:
* --automount-startup-timeout
* --automount-unmount-timeout

Log level 4 enables automount verbose logging.
Log level 5 enables CVMFS client debug logging.

Author: gman0

cmd/csi-cvmfsplugin/main.go

@@ -64,6 +64,9 @@ var (
 
 	hasAlienCache        = flag.Bool("has-alien-cache", false, "CVMFS client is using alien cache volume")
 	startAutomountDaemon = flag.Bool("start-automount-daemon", true, "start automount daemon when initializing CVMFS CSI driver")
+
+	automountDaemonStartupTimeoutSeconds   = flag.Int("automount-startup-timeout", 5, "number of seconds to wait for automount daemon to start up before exiting")
+	automountDaemonUnmountAfterIdleSeconds = flag.Int("automount-unmount-timeout", -1, "number of seconds of idle time after which an autofs-managed CVMFS mount will be unmounted. '0' means never unmount, '-1' leaves automount default option.")
 )
 
 func printVersion() {
@@ -106,6 +109,9 @@ func main() {
 
 		StartAutomountDaemon: *startAutomountDaemon,
 		HasAlienCache:        *hasAlienCache,
+
+		AutomountDaemonStartupTimeoutSeconds:   *automountDaemonStartupTimeoutSeconds,
+		AutomountDaemonUnmountAfterIdleSeconds: *automountDaemonUnmountAfterIdleSeconds,
 	})
 
 	if err != nil {

deployments/helm/cvmfs-csi/templates/nodeplugin-daemonset.yaml

@@ -48,6 +48,8 @@ spec:
             - --endpoint=$(CSI_ENDPOINT)
             - --drivername=$(CSI_DRIVERNAME)
             - --start-automount-daemon={{ .Values.startAutomountDaemon }}
+            - --automount-startup-timeout={{ .Values.automountDaemonStartupTimeout }}
+            - --automount-unmount-timeout={{ .Values.automountDaemonStartupTimeout }}
             - --role=identity,node
             {{- if .Values.cache.alien.enabled }}
             - --has-alien-cache

deployments/helm/cvmfs-csi/values.yaml

@@ -245,6 +245,12 @@ cvmfsCSIPluginSocketFile: csi.sock
 # of the daemon using this switch.
 startAutomountDaemon: true
 
+# Number of seconds to wait for automount daemon to start up before exiting.
+automountDaemonStartupTimeout: 5
+# Number of seconds of idle time after which an autofs-managed CVMFS mount will
+# be unmounted. '0' means never unmount, '-1' leaves automount default option.
+automountDaemonUnmountTimeout: -1
+
 # Chart name overrides.
 nameOverride: ""
 fullNameOverride: ""

docs/deploying.md

@@ -60,5 +60,7 @@ CVMFS CSI driver executable accepts following set of command line arguments:
 |`--nodeid`|_none, required_|(string value) Unique identifier of the node on which the CVMFS CSI node plugin pod is running. Should be set to the value of `Pod.spec.nodeName`.|
 |`--has-alien-cache`|_false_|(boolean value) CVMFS client is using alien cache volume. The volume will be `chmod`'d with correct permissions.|
 |`--start-automount-daemon`|_true_|(boolean value) Whether CVMFS CSI nodeplugin Pod should run automount daemon. This is required for automounts to work. If however worker nodes are already running automount daemon (e.g. as a systemd service), you may disable running yet another instance of the daemon using this switch.|
+|`automount-startup-timeout`|_5_|number of seconds to wait for automount daemon to start up before exiting|
+|`automount-unmount-timeout`|_-1_|number of seconds of idle time after which an autofs-managed CVMFS mount will be unmounted. '0' means never unmount, '-1' leaves automount default option.|
 |`--role`|_none, required_|Enable driver service role (comma-separated list or repeated `--role` flags). Allowed values are: `identity`, `node`, `controller`.|
 |`--version`|_false_|(boolean value) Print driver version and exit.|

internal/cvmfs/driver/driver.go

@@ -17,12 +17,15 @@
 package driver
 
 import (
+	"bufio"
 	"bytes"
 	"context"
 	"fmt"
 	"os"
 	goexec "os/exec"
 	"strings"
+	"syscall"
+	"time"
 
 	"github.com/cernops/cvmfs-csi/internal/cvmfs/controller"
 	"github.com/cernops/cvmfs-csi/internal/cvmfs/identity"
@@ -67,6 +70,16 @@ type (
 
 		// Role under which will the driver operate.
 		Roles map[ServiceRole]bool
+
+		// How many seconds to wait for automount daemon to start up,
+		// and /cvmfs mountpoint to become available.
+		AutomountDaemonStartupTimeoutSeconds int
+
+		// After how many seconds of inactivity of an autofs-managed mount
+		// should the volume be unmounted, i.e. automount --timeout <value>.
+		// 0: Never unmount.
+		// -1: Leave automount's default timeout.
+		AutomountDaemonUnmountAfterIdleSeconds int
 	}
 
 	// Driver holds CVMFS-CSI driver runtime state.
@@ -230,7 +243,7 @@ func setupCvmfs(o *Opts) error {
 
 	if o.StartAutomountDaemon {
 		// Start the automount daemon.
-		if _, err := exec.CombinedOutput(goexec.Command("automount")); err != nil {
+		if err := automountRunner(o); err != nil {
 			return fmt.Errorf("failed to start automount daemon: %v", err)
 		}
 	}
@@ -243,3 +256,97 @@ func setupCvmfs(o *Opts) error {
 
 	return nil
 }
+
+func automountRunner(o *Opts) error {
+	args := []string{
+		"--foreground",
+	}
+
+	if log.LevelEnabled(log.LevelDebug) {
+		// Enable automount verbose logging.
+		args = append(args, "--verbose")
+	}
+
+	if log.LevelEnabled(log.LevelTrace) {
+		// automount passes -O options to the underlying fs mounts.
+		// Enable CVMFS debug logging.
+		args = append(args, "-O", "debug")
+	}
+
+	if o.AutomountDaemonUnmountAfterIdleSeconds != -1 {
+		args = append(args, fmt.Sprintf("--timeout=%d", o.AutomountDaemonUnmountAfterIdleSeconds))
+	}
+
+	cmd := goexec.Command("automount", args...)
+
+	// Set-up piping output for stdout and stderr to driver's logging.
+
+	outp, err := cmd.StdoutPipe()
+	if err != nil {
+		return err
+	}
+	cmd.Stderr = cmd.Stdout
+
+	// Run automount.
+
+	log.Infof("Starting automount daemon prog=%s args=%v", cmd.Path, cmd.Args)
+	if err := cmd.Start(); err != nil {
+		return err
+	}
+	log.Infof("Started automount daemon PID %d", cmd.Process.Pid)
+
+	scanner := bufio.NewScanner(outp)
+	scanner.Split(bufio.ScanLines)
+
+	go func() {
+		// Log and wait.
+
+		for scanner.Scan() {
+			log.Infof("automount[%d]: %s", cmd.Process.Pid, scanner.Text())
+		}
+
+		cmd.Wait()
+
+		if cmd.ProcessState.ExitCode() != 0 {
+			panic(fmt.Sprintf("automount[%d] has exited unexpectedly: %s", cmd.Process.Pid, cmd.ProcessState))
+		}
+
+		log.Infof("automount[%d] has exited: %s", cmd.Process.Pid, cmd.ProcessState)
+	}()
+
+	// Wait until autofs is mounted under /cvmfs.
+
+	retryFor := func(attempts int, f func() (bool, error)) error {
+		trial := 0
+		for trial < attempts {
+			res, err := f()
+
+			if err != nil {
+				return err
+			}
+
+			if res {
+				return nil
+			}
+
+			trial++
+			time.Sleep(1 * time.Second)
+		}
+
+		return fmt.Errorf("timed-out while waiting for autofs to be mounted")
+	}
+
+	const autofsStatfsType = 0x187
+
+	err = retryFor(o.AutomountDaemonStartupTimeoutSeconds, func() (bool, error) {
+		statfs := syscall.Statfs_t{}
+		err = syscall.Statfs("/cvmfs", &statfs)
+		if err != nil {
+			return false, err
+		}
+
+		return statfs.Type == autofsStatfsType, nil
+	})
+
+	return nil
+}

internal/log/log.go

@@ -28,9 +28,9 @@ const (
 	ReqIDContextKey = "Req-ID"
 
 	// klog verbosity levels.
-	levelInfo  = 0
-	levelDebug = 4
-	levelTrace = 5
+	LevelInfo  = 0
+	LevelDebug = 4
+	LevelTrace = 5
 )
 
 func tryPrependReqID(ctx context.Context, logMsg string) string {
@@ -42,59 +42,63 @@ func tryPrependReqID(ctx context.Context, logMsg string) string {
 	return logMsg
 }
 
+func LevelEnabled(level int) bool {
+	return klog.V(klog.Level(level)).Enabled()
+}
+
 func Infof(format string, args ...interface{}) {
-	klog.V(levelInfo).InfofDepth(1, format, args...)
+	klog.V(LevelInfo).InfofDepth(1, format, args...)
 }
 
 func InfofWithContext(ctx context.Context, format string, args ...interface{}) {
-	klog.V(levelInfo).InfofDepth(1, tryPrependReqID(ctx, format), args...)
+	klog.V(LevelInfo).InfofDepth(1, tryPrependReqID(ctx, format), args...)
 }
 
 func InfofDepth(depth int, format string, args ...interface{}) {
-	klog.V(levelInfo).InfofDepth(depth, format, args...)
+	klog.V(LevelInfo).InfofDepth(depth, format, args...)
 }
 
 func InfofWithContextDepth(ctx context.Context, depth int, format string, args ...interface{}) {
-	klog.V(levelInfo).InfofDepth(depth, tryPrependReqID(ctx, format), args...)
+	klog.V(LevelInfo).InfofDepth(depth, tryPrependReqID(ctx, format), args...)
 }
 
 func Debugf(format string, args ...interface{}) {
-	klog.V(levelDebug).InfofDepth(1, format, args...)
+	klog.V(LevelDebug).InfofDepth(1, format, args...)
 }
 
 func DebugfWithContext(ctx context.Context, format string, args ...interface{}) {
-	if klog.V(levelDebug).Enabled() {
-		klog.V(levelDebug).InfofDepth(1, tryPrependReqID(ctx, format), args...)
+	if klog.V(LevelDebug).Enabled() {
+		klog.V(LevelDebug).InfofDepth(1, tryPrependReqID(ctx, format), args...)
 	}
 }
 
 func DebugfDepth(depth int, format string, args ...interface{}) {
-	klog.V(levelDebug).InfofDepth(depth, format, args...)
+	klog.V(LevelDebug).InfofDepth(depth, format, args...)
 }
 
 func DebugfWithContextDepth(ctx context.Context, depth int, format string, args ...interface{}) {
-	if klog.V(levelDebug).Enabled() {
-		klog.V(levelDebug).InfofDepth(depth, tryPrependReqID(ctx, format), args...)
+	if klog.V(LevelDebug).Enabled() {
+		klog.V(LevelDebug).InfofDepth(depth, tryPrependReqID(ctx, format), args...)
 	}
 }
 
 func Tracef(format string, args ...interface{}) {
-	klog.V(levelTrace).InfofDepth(1, format, args...)
+	klog.V(LevelTrace).InfofDepth(1, format, args...)
 }
 
 func TracefWithContext(ctx context.Context, format string, args ...interface{}) {
-	if klog.V(levelDebug).Enabled() {
-		klog.V(levelDebug).InfofDepth(1, tryPrependReqID(ctx, format), args...)
+	if klog.V(LevelDebug).Enabled() {
+		klog.V(LevelDebug).InfofDepth(1, tryPrependReqID(ctx, format), args...)
 	}
 }
 
 func TracefDepth(depth int, format string, args ...interface{}) {
-	klog.V(levelTrace).InfofDepth(depth, format, args...)
+	klog.V(LevelTrace).InfofDepth(depth, format, args...)
 }
 
 func TracefWithContextDepth(ctx context.Context, depth int, format string, args ...interface{}) {
-	if klog.V(levelDebug).Enabled() {
-		klog.V(levelDebug).InfofDepth(depth, tryPrependReqID(ctx, format), args...)
+	if klog.V(LevelDebug).Enabled() {
+		klog.V(LevelDebug).InfofDepth(depth, tryPrependReqID(ctx, format), args...)
 	}
 }