util: use context.Context for logging in ExecCommand

All calls to util.ExecCommand() now pass the context.Context. In some
cases this is not possible or needed, and util.ExecCommand() will not
log the command.

This should make debugging easier when command executions fail.

Signed-off-by: Niels de Vos <ndevos@redhat.com>

internal/cephfs/util.go

@@ -31,12 +31,12 @@ import (
 type volumeID string
 
 func execCommandErr(ctx context.Context, program string, args ...string) error {
-	_, _, err := util.ExecCommand(program, args...)
+	_, _, err := util.ExecCommand(ctx, program, args...)
 	return err
 }
 
 func execCommandJSON(ctx context.Context, v interface{}, program string, args ...string) error {
-	stdout, _, err := util.ExecCommand(program, args...)
+	stdout, _, err := util.ExecCommand(ctx, program, args...)
 	if err != nil {
 		return err
 	}

internal/cephfs/volume.go

@@ -52,6 +52,7 @@ func getVolumeRootPathCephDeprecated(volID volumeID) string {
 
 func getVolumeRootPathCeph(ctx context.Context, volOptions *volumeOptions, cr *util.Credentials, volID volumeID) (string, error) {
 	stdout, stderr, err := util.ExecCommand(
+		ctx,
 		"ceph",
 		"fs",
 		"subvolume",

internal/cephfs/volumemounter.go

@@ -167,7 +167,7 @@ func mountFuse(ctx context.Context, mountPoint string, cr *util.Credentials, vol
 		args = append(args, "--client_mds_namespace="+volOptions.FsName)
 	}
 
-	_, stderr, err := util.ExecCommand("ceph-fuse", args[:]...)
+	_, stderr, err := util.ExecCommand(ctx, "ceph-fuse", args[:]...)
 	if err != nil {
 		return err
 	}

internal/rbd/rbd_attach.go

@@ -77,14 +77,14 @@ type nbdDeviceInfo struct {
 
 // rbdGetDeviceList queries rbd about mapped devices and returns a list of rbdDeviceInfo
 // It will selectively list devices mapped using krbd or nbd as specified by accessType.
-func rbdGetDeviceList(accessType string) ([]rbdDeviceInfo, error) {
+func rbdGetDeviceList(ctx context.Context, accessType string) ([]rbdDeviceInfo, error) {
 	// rbd device list --format json --device-type [krbd|nbd]
 	var (
 		rbdDeviceList []rbdDeviceInfo
 		nbdDeviceList []nbdDeviceInfo
 	)
 
-	stdout, _, err := util.ExecCommand(rbd, "device", "list", "--format="+"json", "--device-type", accessType)
+	stdout, _, err := util.ExecCommand(ctx, rbd, "device", "list", "--format="+"json", "--device-type", accessType)
 	if err != nil {
 		return nil, fmt.Errorf("error getting device list from rbd for devices of type (%s): (%v)", accessType, err)
 	}
@@ -122,7 +122,7 @@ func findDeviceMappingImage(ctx context.Context, pool, image string, useNbdDrive
 		accessType = accessTypeNbd
 	}
 
-	rbdDeviceList, err := rbdGetDeviceList(accessType)
+	rbdDeviceList, err := rbdGetDeviceList(ctx, accessType)
 	if err != nil {
 		klog.Warningf(util.Log(ctx, "failed to determine if image (%s/%s) is mapped to a device (%v)"), pool, image, err)
 		return "", false
@@ -159,13 +159,13 @@ func checkRbdNbdTools() bool {
 	_, err := os.Stat(fmt.Sprintf("/sys/module/%s", moduleNbd))
 	if os.IsNotExist(err) {
 		// try to load the module
-		_, _, err = util.ExecCommand("modprobe", moduleNbd)
+		_, _, err = util.ExecCommand(context.TODO(), "modprobe", moduleNbd)
 		if err != nil {
 			util.ExtendedLogMsg("rbd-nbd: nbd modprobe failed with error %v", err)
 			return false
 		}
 	}
-	if _, _, err := util.ExecCommand(rbdTonbd, "--version"); err != nil {
+	if _, _, err := util.ExecCommand(context.TODO(), rbdTonbd, "--version"); err != nil {
 		util.ExtendedLogMsg("rbd-nbd: running rbd-nbd --version failed with error %v", err)
 		return false
 	}
@@ -229,7 +229,7 @@ func createPath(ctx context.Context, volOpt *rbdVolume, cr *util.Credentials) (s
 		mapOptions = append(mapOptions, "--read-only")
 	}
 	// Execute map
-	stdout, stderr, err := util.ExecCommand(rbd, mapOptions...)
+	stdout, stderr, err := util.ExecCommand(ctx, rbd, mapOptions...)
 	if err != nil {
 		klog.Warningf(util.Log(ctx, "rbd: map error %v, rbd output: %s"), err, string(stderr))
 		// unmap rbd image if connection timeout
@@ -306,7 +306,7 @@ func detachRBDImageOrDeviceSpec(ctx context.Context, imageOrDeviceSpec string, i
 	}
 	options := []string{"unmap", "--device-type", accessType, imageOrDeviceSpec}
 
-	_, stderr, err := util.ExecCommand(rbd, options...)
+	_, stderr, err := util.ExecCommand(ctx, rbd, options...)
 	if err != nil {
 		// Messages for krbd and nbd differ, hence checking either of them for missing mapping
 		// This is not applicable when a device path is passed in

internal/rbd/rbd_util.go

@@ -303,7 +303,7 @@ func addRbdManagerTask(ctx context.Context, pOpts *rbdVolume, arg []string) (boo
 	args = append(args, arg...)
 	util.DebugLog(ctx, "executing %v for image (%s) using mon %s, pool %s", args, pOpts.RbdImageName, pOpts.Monitors, pOpts.Pool)
 	supported := true
-	_, stderr, err := util.ExecCommand("ceph", args...)
+	_, stderr, err := util.ExecCommand(ctx, "ceph", args...)
 
 	if err != nil {
 		switch {
@@ -872,7 +872,9 @@ func (rv *rbdVolume) updateVolWithImageInfo(cr *util.Credentials) error {
 	// rbd --format=json info [image-spec | snap-spec]
 	var imgInfo imageInfo
 
-	stdout, stderr, err := util.ExecCommand("rbd",
+	stdout, stderr, err := util.ExecCommand(
+		context.TODO(),
+		"rbd",
 		"-m", rv.Monitors,
 		"--id", cr.ID,
 		"--keyfile="+cr.KeyFile,
@@ -1046,7 +1048,7 @@ func resizeRBDImage(rbdVol *rbdVolume, cr *util.Credentials) error {
 	volSzMiB := fmt.Sprintf("%dM", util.RoundOffVolSize(rbdVol.VolSize))
 
 	args := []string{"resize", rbdVol.String(), "--size", volSzMiB, "--id", cr.ID, "-m", mon, "--keyfile=" + cr.KeyFile}
-	_, stderr, err := util.ExecCommand("rbd", args...)
+	_, stderr, err := util.ExecCommand(context.TODO(), "rbd", args...)
 
 	if err != nil {
 		return fmt.Errorf("failed to resize rbd image (%w), command output: %s", err, string(stderr))
@@ -1114,7 +1116,9 @@ type snapshotInfo struct {
 func (rv *rbdVolume) listSnapshots(ctx context.Context, cr *util.Credentials) ([]snapshotInfo, error) {
 	// rbd snap ls <image> --pool=<pool-name> --all --format=json
 	var snapInfo []snapshotInfo
-	stdout, stderr, err := util.ExecCommand("rbd",
+	stdout, stderr, err := util.ExecCommand(
+		ctx,
+		"rbd",
 		"-m", rv.Monitors,
 		"--id", cr.ID,
 		"--keyfile="+cr.KeyFile,

internal/util/cephcmds.go

@@ -30,8 +30,10 @@ import (
 // InvalidPoolID used to denote an invalid pool.
 const InvalidPoolID int64 = -1
 
-// ExecCommand executes passed in program with args and returns separate stdout and stderr streams.
+// ExecCommand executes passed in program with args and returns separate stdout
-func ExecCommand(program string, args ...string) (stdout, stderr []byte, err error) {
+// and stderr streams. In case ctx is not set to context.TODO(), the command
+// will be logged after it was executed.
+func ExecCommand(ctx context.Context, program string, args ...string) (stdout, stderr []byte, err error) {
 	var (
 		cmd           = exec.Command(program, args...) // #nosec:G204, commands executing not vulnerable.
 		sanitizedArgs = StripSecretInArgs(args)
@@ -43,8 +45,15 @@ func ExecCommand(program string, args ...string) (stdout, stderr []byte, err err
 	cmd.Stderr = &stderrBuf
 
 	if err := cmd.Run(); err != nil {
-		return stdoutBuf.Bytes(), stderrBuf.Bytes(), fmt.Errorf("an error (%v)"+
+		err = fmt.Errorf("an error (%w) occurred while running %s args: %v", err, program, sanitizedArgs)
-			" occurred while running %s args: %v", err, program, sanitizedArgs)
+		if ctx != context.TODO() {
+			UsefulLog(ctx, "%s", err)
+		}
+		return stdoutBuf.Bytes(), stderrBuf.Bytes(), err
+	}
+
+	if ctx != context.TODO() {
+		UsefulLog(ctx, "command succeeded: %s %v", program, sanitizedArgs)
 	}
 
 	return stdoutBuf.Bytes(), nil, nil