Add more logging to CSI

csi/src/controllerserver.go

@@ -8,11 +8,9 @@ import (
     "encoding/json"
     "fmt"
     "strings"
-    "bytes"
     "strconv"
     "time"
     "os"
-    "os/exec"
     "io/ioutil"
 
     "github.com/kubernetes-csi/csi-lib-utils/protosanitizer"
@@ -114,22 +112,6 @@ func GetConnectionParams(params map[string]string) (map[string]string, error)
     return ctxVars, nil
 }
 
-func system(program string, args ...string) ([]byte, []byte, error)
-{
-    klog.Infof("Running "+program+" "+strings.Join(args, " "))
-    c := exec.Command(program, args...)
-    var stdout, stderr bytes.Buffer
-    c.Stdout, c.Stderr = &stdout, &stderr
-    err := c.Run()
-    if (err != nil)
-    {
-        stdoutStr, stderrStr := string(stdout.Bytes()), string(stderr.Bytes())
-        klog.Errorf(program+" "+strings.Join(args, " ")+" failed: %s, status %s\n", stdoutStr+stderrStr, err)
-        return nil, nil, status.Error(codes.Internal, stdoutStr+stderrStr+" (status "+err.Error()+")")
-    }
-    return stdout.Bytes(), stderr.Bytes(), nil
-}
-
 func invokeCLI(ctxVars map[string]string, args []string) ([]byte, error)
 {
     if (ctxVars["configPath"] != "")

csi/src/nodeserver.go

@@ -300,6 +300,7 @@ func (ns *NodeServer) NodeStageVolume(ctx context.Context, req *csi.NodeStageVol
     diskMounter := &mount.SafeFormatAndMount{Interface: ns.mounter, Exec: utilexec.New()}
     if (isBlock)
     {
+        klog.Infof("bind-mounting %s to %s", devicePath, targetPath)
         err = diskMounter.Mount(devicePath, targetPath, "", []string{"bind"})
     }
     else
@@ -329,39 +330,40 @@ func (ns *NodeServer) NodeStageVolume(ctx context.Context, req *csi.NodeStageVol
         readOnly := Contains(opt, "ro")
         if (existingFormat == "" && !readOnly)
         {
-            var cmdOut []byte
             switch fsType
             {
                 case "ext4":
                     args := []string{"-m0", "-Enodiscard,lazy_itable_init=1,lazy_journal_init=1", devicePath}
-                    cmdOut, err = diskMounter.Exec.Command("mkfs.ext4", args...).CombinedOutput()
+                    _, err = systemCombined("mkfs.ext4", args...)
                 case "xfs":
-                    cmdOut, err = diskMounter.Exec.Command("mkfs.xfs", "-K", devicePath).CombinedOutput()
+                    _, err = systemCombined("mkfs.xfs", "-K", devicePath)
             }
             if (err != nil)
             {
-                klog.Errorf("failed to run mkfs error: %v, output: %v", err, string(cmdOut))
                 goto unmap
             }
         }
 
+        klog.Infof("formatting and mounting %s to %s with FS %s, options: %v", devicePath, targetPath, fsType, opt)
         err = diskMounter.FormatAndMount(devicePath, targetPath, fsType, opt)
+        if (err == nil)
+        {
+            klog.Infof("successfully mounted %s to %s", devicePath, targetPath)
+        }
 
         // Try to run online resize on mount.
         // FIXME: Implement online resize. It requires online resize support in vitastor-nbd.
         if (err == nil && existingFormat != "" && !readOnly)
         {
-            var cmdOut []byte
             switch (fsType)
             {
                 case "ext4":
-                    cmdOut, err = diskMounter.Exec.Command("resize2fs", devicePath).CombinedOutput()
+                    _, err = systemCombined("resize2fs", devicePath)
                 case "xfs":
-                    cmdOut, err = diskMounter.Exec.Command("xfs_growfs", devicePath).CombinedOutput()
+                    _, err = systemCombined("xfs_growfs", devicePath)
             }
             if (err != nil)
             {
-                klog.Errorf("failed to run resizefs error: %v, output: %v", err, string(cmdOut))
                 goto unmap
             }
         }

csi/src/utils.go

@@ -4,6 +4,7 @@
 package vitastor
 
 import (
+    "bytes"
     "errors"
     "encoding/json"
     "fmt"
@@ -15,6 +16,8 @@ import (
     "syscall"
 
     "k8s.io/klog"
+    "google.golang.org/grpc/codes"
+    "google.golang.org/grpc/status"
 )
 
 func Contains(list []string, s string) bool
@@ -73,6 +76,10 @@ func checkVduseSupport() bool
             " For VDUSE you need at least Linux 5.15 and the following kernel modules: vdpa, virtio-vdpa, vduse.",
         )
     }
+    else
+    {
+        klog.Infof("VDUSE support enabled successfully")
+    }
     return vduse
 }
 
@@ -97,6 +104,7 @@ func mapNbd(volName string, ctxVars map[string]string, readonly bool) (string, e
     {
         return "", fmt.Errorf("vitastor-nbd did not return the name of NBD device. output: %s", stderr)
     }
+    klog.Infof("Attached volume %s via NBD as %s", volName, dev)
     return dev, err
 }
 
@@ -217,6 +225,7 @@ func mapVduse(stateDir string, volName string, ctxVars map[string]string, readon
                     err = os.WriteFile(stateFile, stateJSON, 0600)
                     if (err == nil)
                     {
+                        klog.Infof("Attached volume %s via VDUSE as %s (VDPA ID %s)", volName, blockdev, vdpaId)
                         return blockdev, vdpaId, nil
                     }
                 }
@@ -299,3 +308,35 @@ func unmapVduseById(stateDir, vdpaId string)
         os.Remove(pidFile)
     }
 }
+
+func system(program string, args ...string) ([]byte, []byte, error)
+{
+    klog.Infof("Running "+program+" "+strings.Join(args, " "))
+    c := exec.Command(program, args...)
+    var stdout, stderr bytes.Buffer
+    c.Stdout, c.Stderr = &stdout, &stderr
+    err := c.Run()
+    if (err != nil)
+    {
+        stdoutStr, stderrStr := string(stdout.Bytes()), string(stderr.Bytes())
+        klog.Errorf(program+" "+strings.Join(args, " ")+" failed: %s\nOutput:\n%s", err, stdoutStr+stderrStr)
+        return nil, nil, status.Error(codes.Internal, stdoutStr+stderrStr+" (status "+err.Error()+")")
+    }
+    return stdout.Bytes(), stderr.Bytes(), nil
+}
+
+func systemCombined(program string, args ...string) ([]byte, error)
+{
+    klog.Infof("Running "+program+" "+strings.Join(args, " "))
+    c := exec.Command(program, args...)
+    var out bytes.Buffer
+    c.Stdout, c.Stderr = &out, &out
+    err := c.Run()
+    if (err != nil)
+    {
+        outStr := string(out.Bytes())
+        klog.Errorf(program+" "+strings.Join(args, " ")+" failed: %s, status %s\n", outStr, err)
+        return nil, status.Error(codes.Internal, outStr+" (status "+err.Error()+")")
+    }
+    return out.Bytes(), nil
+}