From 894e6795cf29fff9c66483bd1a399124692778b5 Mon Sep 17 00:00:00 2001 From: Jan Safranek Date: Tue, 10 Sep 2019 14:31:28 +0200 Subject: [PATCH] Log all executed iscsiadm commands We sometimes face issues with iSCSI PVs and it's hard to guess what's going on without iscsiadm commands logged. Using level 5 (iscsiadm output can be long sometimes) and explicitly avoiding logging of CHAP passwords. In addition, log which path failed to appear after timeout, so the admin can see which portals are not providing devices. --- pkg/volume/iscsi/iscsi_util.go | 47 ++++++++++++++++++++++------------ 1 file changed, 31 insertions(+), 16 deletions(-) diff --git a/pkg/volume/iscsi/iscsi_util.go b/pkg/volume/iscsi/iscsi_util.go index ebc0dee3903..07b87b8dbe0 100644 --- a/pkg/volume/iscsi/iscsi_util.go +++ b/pkg/volume/iscsi/iscsi_util.go @@ -18,6 +18,7 @@ package iscsi import ( "encoding/json" + "errors" "fmt" "io/ioutil" "os" @@ -86,7 +87,7 @@ func updateISCSIDiscoverydb(b iscsiDiskMounter, tp string) error { if !b.chapDiscovery { return nil } - out, err := b.exec.Run("iscsiadm", "-m", "discoverydb", "-t", "sendtargets", "-p", tp, "-I", b.Iface, "-o", "update", "-n", "discovery.sendtargets.auth.authmethod", "-v", "CHAP") + out, err := execWithLog(b, "iscsiadm", "-m", "discoverydb", "-t", "sendtargets", "-p", tp, "-I", b.Iface, "-o", "update", "-n", "discovery.sendtargets.auth.authmethod", "-v", "CHAP") if err != nil { return fmt.Errorf("iscsi: failed to update discoverydb with CHAP, output: %v", string(out)) } @@ -94,6 +95,7 @@ func updateISCSIDiscoverydb(b iscsiDiskMounter, tp string) error { for _, k := range chapSt { v := b.secret[k] if len(v) > 0 { + // explicitly not using execWithLog so secrets are not logged out, err := b.exec.Run("iscsiadm", "-m", "discoverydb", "-t", "sendtargets", "-p", tp, "-I", b.Iface, "-o", "update", "-n", k, "-v", v) if err != nil { return fmt.Errorf("iscsi: failed to update discoverydb key %q error: %v", k, string(out)) @@ -108,7 +110,7 @@ func updateISCSINode(b iscsiDiskMounter, tp string) error { return nil } - out, err := b.exec.Run("iscsiadm", "-m", "node", "-p", tp, "-T", b.Iqn, "-I", b.Iface, "-o", "update", "-n", "node.session.auth.authmethod", "-v", "CHAP") + out, err := execWithLog(b, "iscsiadm", "-m", "node", "-p", tp, "-T", b.Iqn, "-I", b.Iface, "-o", "update", "-n", "node.session.auth.authmethod", "-v", "CHAP") if err != nil { return fmt.Errorf("iscsi: failed to update node with CHAP, output: %v", string(out)) } @@ -116,6 +118,7 @@ func updateISCSINode(b iscsiDiskMounter, tp string) error { for _, k := range chapSess { v := b.secret[k] if len(v) > 0 { + // explicitly not using execWithLog so secrets are not logged out, err := b.exec.Run("iscsiadm", "-m", "node", "-p", tp, "-T", b.Iqn, "-I", b.Iface, "-o", "update", "-n", k, "-v", v) if err != nil { return fmt.Errorf("iscsi: failed to update node session key %q error: %v", k, string(out)) @@ -279,7 +282,7 @@ func (util *ISCSIUtil) AttachDisk(b iscsiDiskMounter) (string, error) { var iscsiTransport string var lastErr error - out, err := b.exec.Run("iscsiadm", "-m", "iface", "-I", b.InitIface, "-o", "show") + out, err := execWithLog(b, "iscsiadm", "-m", "iface", "-I", b.InitIface, "-o", "show") if err != nil { klog.Errorf("iscsi: could not read iface %s error: %s", b.InitIface, string(out)) return "", err @@ -323,7 +326,7 @@ func (util *ISCSIUtil) AttachDisk(b iscsiDiskMounter) (string, error) { klog.V(4).Infof("Could not get SCSI host number for portal %s, will attempt login", tp) // build discoverydb and discover iscsi target - b.exec.Run("iscsiadm", "-m", "discoverydb", "-t", "sendtargets", "-p", tp, "-I", b.Iface, "-o", "new") + execWithLog(b, "iscsiadm", "-m", "discoverydb", "-t", "sendtargets", "-p", tp, "-I", b.Iface, "-o", "new") // update discoverydb with CHAP secret err = updateISCSIDiscoverydb(b, tp) @@ -332,10 +335,10 @@ func (util *ISCSIUtil) AttachDisk(b iscsiDiskMounter) (string, error) { continue } - out, err = b.exec.Run("iscsiadm", "-m", "discoverydb", "-t", "sendtargets", "-p", tp, "-I", b.Iface, "--discover") + out, err = execWithLog(b, "iscsiadm", "-m", "discoverydb", "-t", "sendtargets", "-p", tp, "-I", b.Iface, "--discover") if err != nil { // delete discoverydb record - b.exec.Run("iscsiadm", "-m", "discoverydb", "-t", "sendtargets", "-p", tp, "-I", b.Iface, "-o", "delete") + execWithLog(b, "iscsiadm", "-m", "discoverydb", "-t", "sendtargets", "-p", tp, "-I", b.Iface, "-o", "delete") lastErr = fmt.Errorf("iscsi: failed to sendtargets to portal %s output: %s, err %v", tp, string(out), err) continue } @@ -348,16 +351,16 @@ func (util *ISCSIUtil) AttachDisk(b iscsiDiskMounter) (string, error) { } // login to iscsi target - out, err = b.exec.Run("iscsiadm", "-m", "node", "-p", tp, "-T", b.Iqn, "-I", b.Iface, "--login") + out, err = execWithLog(b, "iscsiadm", "-m", "node", "-p", tp, "-T", b.Iqn, "-I", b.Iface, "--login") if err != nil { // delete the node record from database - b.exec.Run("iscsiadm", "-m", "node", "-p", tp, "-I", b.Iface, "-T", b.Iqn, "-o", "delete") + execWithLog(b, "iscsiadm", "-m", "node", "-p", tp, "-I", b.Iface, "-T", b.Iqn, "-o", "delete") lastErr = fmt.Errorf("iscsi: failed to attach disk: Error: %s (%v)", string(out), err) continue } // in case of node failure/restart, explicitly set to manual login so it doesn't hang on boot - out, err = b.exec.Run("iscsiadm", "-m", "node", "-p", tp, "-T", b.Iqn, "-o", "update", "-n", "node.startup", "-v", "manual") + out, err = execWithLog(b, "iscsiadm", "-m", "node", "-p", tp, "-T", b.Iqn, "-o", "update", "-n", "node.startup", "-v", "manual") if err != nil { // don't fail if we can't set startup mode, but log warning so there is a clue klog.Warningf("Warning: Failed to set iSCSI login mode to manual. Error: %v", err) @@ -400,9 +403,10 @@ func (util *ISCSIUtil) AttachDisk(b iscsiDiskMounter) (string, error) { } if exist := waitForPathToExist(&devicePath, deviceDiscoveryTimeout, iscsiTransport); !exist { - klog.Errorf("Could not attach disk: Timeout after %ds", deviceDiscoveryTimeout) + msg := fmt.Sprintf("Timed out waiting for device at path %s after %ds", devicePath, deviceDiscoveryTimeout) + klog.Error(msg) // update last error - lastErr = fmt.Errorf("Could not attach disk: Timeout after %ds", deviceDiscoveryTimeout) + lastErr = errors.New(msg) continue } else { devicePaths[tp] = devicePath @@ -412,7 +416,7 @@ func (util *ISCSIUtil) AttachDisk(b iscsiDiskMounter) (string, error) { if len(devicePaths) == 0 { // No path attached, report error and stop trying. kubelet will try again in a short while // delete cloned iface - b.exec.Run("iscsiadm", "-m", "iface", "-I", b.Iface, "-o", "delete") + execWithLog(b, "iscsiadm", "-m", "iface", "-I", b.Iface, "-o", "delete") klog.Errorf("iscsi: failed to get any path for iscsi disk, last err seen:\n%v", lastErr) return "", fmt.Errorf("failed to get any path for iscsi disk, last err seen:\n%v", lastErr) } @@ -856,7 +860,7 @@ func cloneIface(b iscsiDiskMounter) error { return fmt.Errorf("iscsi: cannot clone iface with same name: %s", b.InitIface) } // get pre-configured iface records - out, err := b.exec.Run("iscsiadm", "-m", "iface", "-I", b.InitIface, "-o", "show") + out, err := execWithLog(b, "iscsiadm", "-m", "iface", "-I", b.InitIface, "-o", "show") if err != nil { lastErr = fmt.Errorf("iscsi: failed to show iface records: %s (%v)", string(out), err) return lastErr @@ -870,7 +874,7 @@ func cloneIface(b iscsiDiskMounter) error { // update initiatorname params["iface.initiatorname"] = b.InitiatorName // create new iface - out, err = b.exec.Run("iscsiadm", "-m", "iface", "-I", b.Iface, "-o", "new") + out, err = execWithLog(b, "iscsiadm", "-m", "iface", "-I", b.Iface, "-o", "new") if err != nil { exit, ok := err.(utilexec.ExitError) if ok && exit.ExitStatus() == iscsiadmErrorSessExists { @@ -882,9 +886,9 @@ func cloneIface(b iscsiDiskMounter) error { } // update new iface records for key, val := range params { - _, err = b.exec.Run("iscsiadm", "-m", "iface", "-I", b.Iface, "-o", "update", "-n", key, "-v", val) + _, err = execWithLog(b, "iscsiadm", "-m", "iface", "-I", b.Iface, "-o", "update", "-n", key, "-v", val) if err != nil { - b.exec.Run("iscsiadm", "-m", "iface", "-I", b.Iface, "-o", "delete") + execWithLog(b, "iscsiadm", "-m", "iface", "-I", b.Iface, "-o", "delete") lastErr = fmt.Errorf("iscsi: failed to update iface records: %s (%v). iface(%s) will be used", string(out), err, b.InitIface) break } @@ -958,3 +962,14 @@ func ignoreExitCodes(err error, ignoredExitCodes ...int) error { } return err } + +func execWithLog(b iscsiDiskMounter, cmd string, args ...string) ([]byte, error) { + start := time.Now() + out, err := b.exec.Run(cmd, args...) + if klog.V(5) { + d := time.Now().Sub(start) + klog.V(5).Infof("Executed %s %v in %v, err: %v", cmd, args, d, err) + klog.V(5).Infof("Output: %s", string(out)) + } + return out, err +}