Add additional debug logging to Redfish calls

When tracking down issues on baremetal nodes using remotedirect, it has
been difficult to pinpoint which Redfish calls fail. This change adds
additional debug logging to make the troubleshooting process simpler
during pre-alpha development.

Change-Id: Ic32d34d010c44b2e7e2a4dfe2b623a451ad94019
Signed-off-by: Drew Walters <andrew.walters@att.com>

cmd/baremetal/ejectmedia.go

@@ -45,7 +45,7 @@ func NewEjectMediaCommand(rootSettings *environment.AirshipCTLSettings) *cobra.C
 					return err
 				}
 
-				fmt.Fprintf(cmd.OutOrStdout(), "All media ejected from host %s\n", host.HostName)
+				fmt.Fprintf(cmd.OutOrStdout(), "All media ejected from host '%s'.\n", host.HostName)
 			}
 
 			return nil

cmd/baremetal/poweroff.go

@@ -45,7 +45,7 @@ func NewPowerOffCommand(rootSettings *environment.AirshipCTLSettings) *cobra.Com
 					return err
 				}
 
-				fmt.Fprintf(cmd.OutOrStdout(), "Remote host %s powered off\n", host.HostName)
+				fmt.Fprintf(cmd.OutOrStdout(), "Powered off host '%s'.\n", host.HostName)
 			}
 
 			return nil

cmd/baremetal/poweron.go

@@ -45,7 +45,7 @@ func NewPowerOnCommand(rootSettings *environment.AirshipCTLSettings) *cobra.Comm
 					return err
 				}
 
-				fmt.Fprintf(cmd.OutOrStdout(), "Powered on remote host %s\n", host.HostName)
+				fmt.Fprintf(cmd.OutOrStdout(), "Powered on host '%s'.\n", host.HostName)
 			}
 
 			return nil

cmd/baremetal/powerstatus.go

@@ -46,8 +46,8 @@ func NewPowerStatusCommand(rootSettings *environment.AirshipCTLSettings) *cobra.
 					return err
 				}
 
-				fmt.Fprintf(cmd.OutOrStdout(), "Remote host %s has power status: %s\n", host.HostName,
+				fmt.Fprintf(cmd.OutOrStdout(), "Host '%s' has power status: '%s'\n",
-					powerStatus)
+					host.HostName, powerStatus)
 			}
 
 			return nil

cmd/baremetal/reboot.go

@@ -45,7 +45,7 @@ func NewRebootCommand(rootSettings *environment.AirshipCTLSettings) *cobra.Comma
 					return err
 				}
 
-				fmt.Fprintf(cmd.OutOrStdout(), "Rebooted remote host at %s\n", host.HostName)
+				fmt.Fprintf(cmd.OutOrStdout(), "Rebooted host '%s'.\n", host.HostName)
 			}
 
 			return nil

pkg/remote/redfish/client.go

@@ -94,6 +94,8 @@ func (c *Client) EjectVirtualMedia(ctx context.Context) error {
 		}
 
 		if *vMediaMgr.Inserted == true {
+			log.Debugf("'%s' has virtual media inserted. Attempting to eject.", vMediaMgr.Name)
+
 			var emptyBody map[string]interface{}
 			_, httpResp, err = c.RedfishAPI.EjectVirtualMedia(ctx, managerID, mediaID, emptyBody)
 			if err = ScreenRedfishError(httpResp, err); err != nil {
@@ -124,6 +126,7 @@ func (c *Client) RebootSystem(ctx context.Context) error {
 				return err
 			}
 			if system.PowerState == desiredState {
+				log.Debugf("Node '%s' reached power state '%s'.", c.nodeID, desiredState)
 				return nil
 			}
 			time.Sleep(systemRebootDelay)
@@ -134,12 +137,14 @@ func (c *Client) RebootSystem(ctx context.Context) error {
 		}
 	}
 
+	log.Debugf("Rebooting node '%s': powering off.", c.nodeID)
 	resetReq := redfishClient.ResetRequestBody{}
 
 	// Send PowerOff request
 	resetReq.ResetType = redfishClient.RESETTYPE_FORCE_OFF
 	_, httpResp, err := c.RedfishAPI.ResetSystem(ctx, c.nodeID, resetReq)
 	if err = ScreenRedfishError(httpResp, err); err != nil {
+		log.Debugf("Failed to reboot node '%s': shutdown failure.", c.nodeID)
 		return err
 	}
 
@@ -148,10 +153,13 @@ func (c *Client) RebootSystem(ctx context.Context) error {
 		return err
 	}
 
+	log.Debugf("Rebooting node '%s': powering on.", c.nodeID)
+
 	// Send PowerOn request
 	resetReq.ResetType = redfishClient.RESETTYPE_ON
 	_, httpResp, err = c.RedfishAPI.ResetSystem(ctx, c.nodeID, resetReq)
 	if err = ScreenRedfishError(httpResp, err); err != nil {
+		log.Debugf("Failed to reboot node '%s': startup failure.", c.nodeID)
 		return err
 	}
 
@@ -167,6 +175,8 @@ func (c *Client) SetBootSourceByType(ctx context.Context) error {
 		return err
 	}
 
+	log.Debugf("Setting boot device to '%s'.", vMediaType)
+
 	// Retrieve system information, containing available boot sources
 	system, _, err := c.RedfishAPI.GetSystem(ctx, c.nodeID)
 	if err != nil {
@@ -180,7 +190,12 @@ func (c *Client) SetBootSourceByType(ctx context.Context) error {
 			systemReq := redfishClient.ComputerSystem{}
 			systemReq.Boot.BootSourceOverrideTarget = bootSource
 			_, httpResp, err := c.RedfishAPI.SetSystem(ctx, c.nodeID, systemReq)
-			return ScreenRedfishError(httpResp, err)
+			if err = ScreenRedfishError(httpResp, err); err != nil {
+				return err
+			}
+
+			log.Debug("Successfully set boot device.")
+			return nil
 		}
 	}
 
@@ -190,6 +205,7 @@ func (c *Client) SetBootSourceByType(ctx context.Context) error {
 // SetVirtualMedia injects a virtual media device to an established virtual media ID. This assumes that isoPath is
 // accessible to the redfish server and virtualMedia device is either of type CD or DVD.
 func (c *Client) SetVirtualMedia(ctx context.Context, isoPath string) error {
+	log.Debugf("Inserting virtual media '%s'.", isoPath)
 	// Eject all previously-inserted media
 	if err := c.EjectVirtualMedia(ctx); err != nil {
 		return err
@@ -212,7 +228,12 @@ func (c *Client) SetVirtualMedia(ctx context.Context, isoPath string) error {
 	vMediaReq.Inserted = true
 	_, httpResp, err := c.RedfishAPI.InsertVirtualMedia(ctx, managerID, vMediaID, vMediaReq)
 
-	return ScreenRedfishError(httpResp, err)
+	if err = ScreenRedfishError(httpResp, err); err != nil {
+		return err
+	}
+
+	log.Debug("Successfully set virtual media.")
+	return nil
 }
 
 // SystemPowerOff shuts down a host.

pkg/remote/redfish/utils.go

@@ -110,6 +110,7 @@ func DecodeRawError(rawResponse []byte) (string, error) {
 func GetManagerID(ctx context.Context, api redfishAPI.RedfishAPI, systemID string) (string, error) {
 	system, httpResp, err := api.GetSystem(ctx, systemID)
 	if err = ScreenRedfishError(httpResp, err); err != nil {
+		log.Debugf("Unable to find manager for node '%s'.", systemID)
 		return "", err
 	}
 
@@ -144,6 +145,7 @@ func IsIDInList(idRefList []redfishClient.IdRef, id string) bool {
 
 // GetVirtualMediaID retrieves the ID of a Redfish virtual media resource if it supports type "CD" or "DVD".
 func GetVirtualMediaID(ctx context.Context, api redfishAPI.RedfishAPI, systemID string) (string, string, error) {
+	log.Debug("Searching for compatible media types.")
 	managerID, err := GetManagerID(ctx, api, systemID)
 	if err != nil {
 		return "", "", err
@@ -165,12 +167,15 @@ func GetVirtualMediaID(ctx context.Context, api redfishAPI.RedfishAPI, systemID
 
 		for _, mediaType := range vMedia.MediaTypes {
 			if mediaType == "CD" || mediaType == "DVD" {
+				log.Debugf("Found virtual media type '%s' with ID '%s' on manager '%s'.", mediaType,
+					mediaID, managerID)
 				return mediaID, mediaType, nil
 			}
 		}
 	}
 
-	return "", "", ErrRedfishClient{Message: "Unable to find virtual media with type CD or DVD"}
+	return "", "", ErrRedfishClient{Message: fmt.Sprintf("Manager '%s' does not have virtual media type CD or DVD.",
+		managerID)}
 }
 
 // ScreenRedfishError provides a detailed error message for end user consumption by inspecting all Redfish client

pkg/remote/redfish/vendors/dell/client.go

@@ -71,8 +71,10 @@ type iDRACAPIExtendedInfo struct {
 
 // SetBootSourceByType sets the boot source of the ephemeral node to a virtual CD, "VCD-DVD".
 func (c *Client) SetBootSourceByType(ctx context.Context) error {
+	log.Debug("Setting boot device to 'VCD-DVD'.")
 	managerID, err := redfish.GetManagerID(ctx, c.RedfishAPI, c.NodeID())
 	if err != nil {
+		log.Debugf("Failed to retrieve manager ID for node '%s'.", c.NodeID())
 		return err
 	}
 
@@ -114,6 +116,7 @@ func (c *Client) SetBootSourceByType(ctx context.Context) error {
 		return redfish.ErrRedfishClient{Message: fmt.Sprintf("Unable to set boot device. %v", err)}
 	}
 
+	log.Debug("Successfully set boot device.")
 	defer httpResp.Body.Close()
 
 	return nil

pkg/remote/remote_direct.go

@@ -33,9 +33,9 @@ func (b baremetalHost) DoRemoteDirect(settings *environment.AirshipCTLSettings)
 		return config.ErrMissingConfig{What: "RemoteDirect options not defined in bootstrap config"}
 	}
 
-	log.Debugf("Using ephemeral node %s with BMC Address %s", b.NodeID(), b.BMCAddress)
+	log.Debugf("Bootstrapping ephemeral host '%s' with ID '%s' and BMC Address '%s'.", b.HostName, b.NodeID(),
+		b.BMCAddress)
 
-	// Perform remote direct operations
 	if remoteConfig.IsoURL == "" {
 		return ErrMissingBootstrapInfoOption{What: "isoURL"}
 	}
@@ -45,8 +45,6 @@ func (b baremetalHost) DoRemoteDirect(settings *environment.AirshipCTLSettings)
 		return err
 	}
 
-	log.Debugf("Successfully loaded virtual media: %q", remoteConfig.IsoURL)
-
 	err = b.SetBootSourceByType(b.Context)
 	if err != nil {
 		return err
@@ -57,7 +55,7 @@ func (b baremetalHost) DoRemoteDirect(settings *environment.AirshipCTLSettings)
 		return err
 	}
 
-	log.Debugf("Restarted ephemeral host %s", b.NodeID())
+	log.Printf("Successfully bootstrapped ephemeral host '%s'.", b.HostName)
 
 	return nil
 }

roles/airshipctl-deploy-ephemeral-node/tasks/main.yaml

@@ -12,7 +12,7 @@
 
 - name: deploy ephemeral node using redfish
   command: >-
-    airshipctl baremetal remotedirect
+    airshipctl baremetal remotedirect --debug
 
 - name: check kubectl version
   command: >-