Repository: metal3-io/baremetal-operator (go)

Issue:
Power off fails for drivers that don't support Soft power off
When an ironic driver doesn't support soft power off, we are supposed to fall back to doing a hard power off. This was inadvertently broken by #841. Now when the driver doesn't support soft power off we end up returning a 'transient' error and retrying in an infinite loop.

Pull request description:
Fix fallback for ironic drivers that don't support soft power off
Fix a regression in #841 that caused ironic drivers that don't support soft power off (such as Fujitsu when the agent is not available) to fail in an infinite loop instead of falling back to a hard power off.

Also clean up the code so it is much less arcane.

Fixes #984

Patch:
diff --git a/pkg/provisioner/ironic/errors.go b/pkg/provisioner/ironic/errors.go
deleted file mode 100644
index 8a69c0cb..00000000
--- a/pkg/provisioner/ironic/errors.go
+++ /dev/null
@@ -1,19 +0,0 @@
-package ironic
-
-// SoftPowerOffUnsupportedError is returned when the BMC does not
-// support soft power off.
-type SoftPowerOffUnsupportedError struct {
-}
-
-func (e SoftPowerOffUnsupportedError) Error() string {
-	return "soft power off is unsupported on BMC"
-}
-
-// HostLockedError is returned when the BMC host is
-// locked.
-type HostLockedError struct {
-}
-
-func (e HostLockedError) Error() string {
-	return "BMC host is locked"
-}
diff --git a/pkg/provisioner/ironic/ironic.go b/pkg/provisioner/ironic/ironic.go
index 65b3e726..35a4a831 100644
--- a/pkg/provisioner/ironic/ironic.go
+++ b/pkg/provisioner/ironic/ironic.go
@@ -32,9 +32,9 @@ var (
 
 const (
 	// See nodes.Node.PowerState for details
-	powerOn              = "power on"
-	powerOff             = "power off"
-	softPowerOff         = "soft power off"
+	powerOn              = string(nodes.PowerOn)
+	powerOff             = string(nodes.PowerOff)
+	softPowerOff         = string(nodes.SoftPowerOff)
 	powerNone            = "None"
 	nameSeparator        = "~"
 	customDeployPriority = 80
@@ -193,11 +193,11 @@ func (p *ironicProvisioner) nodeHasAssignedPort(ironicNode *nodes.Node) (bool, e
 	}
 
 	if empty {
-		p.debugLog.Info("node has no assigned port", "node", ironicNode.UUID)
+		p.debugLog.Info("node has no assigned port")
 		return false, nil
 	}
 
-	p.debugLog.Info("node has assigned port", "node", ironicNode.UUID)
+	p.debugLog.Info("node has assigned port")
 	return true, nil
 }
 
@@ -213,7 +213,7 @@ func (p *ironicProvisioner) isAddressAllocatedToPort(address string) (bool, erro
 		return false, nil
 	}
 
-	p.debugLog.Info("address is allocated to port", "address", address, "node", allPorts[0].NodeUUID)
+	p.debugLog.Info("address is allocated to port", "address", address)
 	return true, nil
 }
 
@@ -236,7 +236,7 @@ func (p *ironicProvisioner) findExistingHost(bootMACAddress string) (ironicNode
 		ironicNode, err = nodes.Get(p.client, nodeName).Extract()
 		switch err.(type) {
 		case nil:
-			p.debugLog.Info("found existing node by name", "name", nodeName, "node", ironicNode.UUID)
+			p.debugLog.Info("found existing node by name")
 			return ironicNode, nil
 		case gophercloud.ErrDefault404:
 			p.log.Info(
@@ -261,7 +261,7 @@ func (p *ironicProvisioner) findExistingHost(bootMACAddress string) (ironicNode
 		ironicNode, err = nodes.Get(p.client, nodeUUID).Extract()
 		switch err.(type) {
 		case nil:
-			p.debugLog.Info("found existing node by MAC", "MAC", bootMACAddress, "node", ironicNode.UUID, "name", ironicNode.Name)
+			p.debugLog.Info("found existing node by ID")
 
 			// If the node has a name, this means we didn't find it above.
 			if ironicNode.Name != "" {
@@ -271,10 +271,10 @@ func (p *ironicProvisioner) findExistingHost(bootMACAddress string) (ironicNode
 			return ironicNode, nil
 		case gophercloud.ErrDefault404:
 			return nil, errors.Wrap(err,
-				fmt.Sprintf("port %s exists but linked node doesn't %s", bootMACAddress, nodeUUID))
+				fmt.Sprintf("port exists but linked node doesn't %s", nodeUUID))
 		default:
 			return nil, errors.Wrap(err,
-				fmt.Sprintf("port %s exists but failed to find linked node by ID %s", bootMACAddress, nodeUUID))
+				fmt.Sprintf("port exists but failed to find linked node by ID %s", nodeUUID))
 		}
 	} else {
 		p.log.Info("port with address doesn't exist", "MAC", bootMACAddress)
@@ -1487,6 +1487,20 @@ func (p *ironicProvisioner) Detach() (result provisioner.Result, err error) {
 	return p.Delete()
 }
 
+// softPowerOffUnsupportedError is returned when the BMC does not
+// support soft power off.
+type softPowerOffUnsupportedError struct {
+	cause error
+}
+
+func (e softPowerOffUnsupportedError) Unwrap() error {
+	return e.cause
+}
+
+func (e softPowerOffUnsupportedError) Error() string {
+	return "soft power off is unsupported on BMC"
+}
+
 func (p *ironicProvisioner) changePower(ironicNode *nodes.Node, target nodes.TargetPowerState) (result provisioner.Result, err error) {
 	p.log.Info("changing power state")
 
@@ -1501,7 +1515,7 @@ func (p *ironicProvisioner) changePower(ironicNode *nodes.Node, target nodes.Tar
 	powerStateOpts := nodes.PowerStateOpts{
 		Target: target,
 	}
-	if target == softPowerOff {
+	if target == nodes.SoftPowerOff {
 		powerStateOpts.Timeout = int(softPowerOffTimeout.Seconds())
 	}
 
@@ -1513,19 +1527,25 @@ func (p *ironicProvisioner) changePower(ironicNode *nodes.Node, target nodes.Tar
 	switch changeResult.Err.(type) {
 	case nil:
 		p.log.Info("power change OK")
+		event := map[nodes.TargetPowerState]struct{ Event, Reason string }{
+			nodes.PowerOn:      {Event: "PowerOn", Reason: "Host powered on"},
+			nodes.PowerOff:     {Event: "PowerOff", Reason: "Host powered off"},
+			nodes.SoftPowerOff: {Event: "PowerOff", Reason: "Host soft powered off"},
+		}[target]
+		p.publisher(event.Event, event.Reason)
 		return operationContinuing(0)
 	case gophercloud.ErrDefault409:
 		p.log.Info("host is locked, trying again after delay", "delay", powerRequeueDelay)
-		result, _ = retryAfterDelay(powerRequeueDelay)
-		return result, HostLockedError{}
+		return retryAfterDelay(powerRequeueDelay)
 	case gophercloud.ErrDefault400:
 		// Error 400 Bad Request means target power state is not supported by vendor driver
-		p.log.Info("power change error", "message", changeResult.Err)
-		return result, SoftPowerOffUnsupportedError{}
-	default:
-		p.log.Info("power change error", "message", changeResult.Err)
-		return transientError(errors.Wrap(changeResult.Err, "failed to change power state"))
+		if target == nodes.SoftPowerOff {
+			changeResult.Err = softPowerOffUnsupportedError{changeResult.Err}
+		}
 	}
+	p.log.Info("power change error", "message", changeResult.Err)
+	return transientError(errors.Wrap(changeResult.Err,
+		fmt.Sprintf("failed to %s node", target)))
 }
 
 // PowerOn ensures the server is powered on independently of any image
@@ -1551,16 +1571,7 @@ func (p *ironicProvisioner) PowerOn(force bool) (result provisioner.Result, err
 			return operationFailed(fmt.Sprintf("PowerOn operation failed: %s",
 				ironicNode.LastError))
 		}
-		if result, err = p.changePower(ironicNode, nodes.PowerOn); err == nil {
-			p.publisher("PowerOn", "Host powered on")
-			return result, nil
-		}
-		switch err.(type) {
-		case HostLockedError:
-			return retryAfterDelay(powerRequeueDelay)
-		default:
-			return transientError(errors.Wrap(err, "failed to PowerOn node"))
-		}
+		return p.changePower(ironicNode, nodes.PowerOn)
 	}
 	return result, nil
 }
@@ -1570,55 +1581,6 @@ func (p *ironicProvisioner) PowerOn(force bool) (result provisioner.Result, err
 func (p *ironicProvisioner) PowerOff(rebootMode metal3v1alpha1.RebootMode, force bool) (result provisioner.Result, err error) {
 	p.log.Info(fmt.Sprintf("ensuring host is powered off (mode: %s)", rebootMode))
 
-	if rebootMode == metal3v1alpha1.RebootModeSoft {
-		return p.softPowerOff()
-	}
-	// Reboot mode is hard or force flag is set
-	return p.hardPowerOff(force)
-}
-
-// hardPowerOff sends 'power off' request to BM node and waits for the result
-func (p *ironicProvisioner) hardPowerOff(force bool) (result provisioner.Result, err error) {
-	p.log.Info("ensuring host is powered off by \"hard power off\" command")
-
-	ironicNode, err := p.getNode()
-	if err != nil {
-		return transientError(err)
-	}
-
-	if ironicNode.PowerState != powerOff {
-		if ironicNode.LastError != "" && !force {
-			p.log.Info("hard power off error", "msg", ironicNode.LastError)
-			return operationFailed(ironicNode.LastError)
-		}
-		if ironicNode.TargetPowerState == powerOff {
-			p.log.Info("waiting for power status to change")
-			return operationContinuing(powerRequeueDelay)
-		}
-		result, err = p.changePower(ironicNode, nodes.PowerOff)
-		if err != nil {
-			switch err.(type) {
-			case HostLockedError:
-				return retryAfterDelay(powerRequeueDelay)
-			default:
-				return transientError(errors.Wrap(err, "failed to power off host"))
-			}
-		}
-		p.publisher("PowerOff", "Host powered off")
-		return result, err
-	}
-
-	return operationComplete()
-}
-
-// softPowerOff sends 'soft power off' request to BM node.
-// If soft power off is not supported, the request ends with an error.
-// Otherwise the request ends with no error and the result should be
-// checked later via node fields "power_state", "target_power_state"
-// and "last_error".
-func (p *ironicProvisioner) softPowerOff() (result provisioner.Result, err error) {
-	p.log.Info("ensuring host is powered off by \"soft power off\" command")
-
 	ironicNode, err := p.getNode()
 	if err != nil {
 		return transientError(err)
@@ -1632,24 +1594,23 @@ func (p *ironicProvisioner) softPowerOff() (result provisioner.Result, err error
 			return operationContinuing(powerRequeueDelay)
 		}
 		// If the target state is unset while the last error is set,
-		// then the last execution of soft power off has failed.
-		if targetState == "" && ironicNode.LastError != "" {
-			p.log.Info("soft power off error", "msg", ironicNode.LastError)
+		// then the last execution of power off has failed.
+		if targetState == "" && ironicNode.LastError != "" && !force {
+			p.log.Info("power off error", "msg", ironicNode.LastError)
 			return operationFailed(ironicNode.LastError)
 		}
-		result, err = p.changePower(ironicNode, nodes.SoftPowerOff)
-		if err != nil {
-			switch err.(type) {
-			case HostLockedError:
-				return retryAfterDelay(powerRequeueDelay)
-			default:
-				return transientError(errors.Wrap(err, "failed to power off host"))
+
+		if rebootMode == metal3v1alpha1.RebootModeSoft && !force {
+			result, err = p.changePower(ironicNode, nodes.SoftPowerOff)
+			if !errors.As(err, &softPowerOffUnsupportedError{}) {
+				return result, err
 			}
 		}
-		p.publisher("PowerOff", "Host soft powered off")
+		// Reboot mode is hard, force flag is set, or soft power off is not supported
+		return p.changePower(ironicNode, nodes.PowerOff)
 	}
 
-	return result, nil
+	return operationComplete()
 }
 
 func ironicNodeName(objMeta metav1.ObjectMeta) string {


Test patch:
diff --git a/pkg/provisioner/ironic/power_test.go b/pkg/provisioner/ironic/power_test.go
index 0a899d5f..628f6cf0 100644
--- a/pkg/provisioner/ironic/power_test.go
+++ b/pkg/provisioner/ironic/power_test.go
@@ -1,6 +1,7 @@
 package ironic
 
 import (
+	"errors"
 	"net/http"
 	"testing"
 	"time"
@@ -144,7 +145,8 @@ func TestPowerOn(t *testing.T) {
 }
 
 func TestPowerOff(t *testing.T) {
-
+	hardPowerOffReason := "Host powered off"
+	softPowerOffReason := "Host soft powered off"
 	nodeUUID := "33ce8659-7400-4c68-9535-d10766f07a58"
 	cases := []struct {
 		name   string
@@ -155,6 +157,7 @@ func TestPowerOff(t *testing.T) {
 		expectedError        bool
 		expectedRequestAfter int
 		expectedErrorResult  bool
+		expectedReason       string
 		rebootMode           metal3v1alpha1.RebootMode
 	}{
 		{
@@ -178,29 +181,28 @@ func TestPowerOff(t *testing.T) {
 			name: "power-off normal",
 			ironic: testserver.NewIronic(t).WithDefaultResponses().Node(nodes.Node{
 				PowerState:           powerOn,
-				TargetPowerState:     powerOn,
 				TargetProvisionState: "",
 				UUID:                 nodeUUID,
 			}),
-			expectedDirty: true,
-			rebootMode:    metal3v1alpha1.RebootModeSoft,
+			rebootMode:     metal3v1alpha1.RebootModeSoft,
+			expectedDirty:  true,
+			expectedReason: softPowerOffReason,
 		},
 		{
 			name: "power-off hard",
 			ironic: testserver.NewIronic(t).WithDefaultResponses().Node(nodes.Node{
 				PowerState:           powerOn,
-				TargetPowerState:     powerOn,
 				TargetProvisionState: "",
 				UUID:                 nodeUUID,
 			}),
-			expectedDirty: true,
-			rebootMode:    metal3v1alpha1.RebootModeHard,
+			expectedDirty:  true,
+			rebootMode:     metal3v1alpha1.RebootModeHard,
+			expectedReason: hardPowerOffReason,
 		},
 		{
 			name: "power-off wait for Provisioning state",
 			ironic: testserver.NewIronic(t).Ready().Node(nodes.Node{
 				PowerState:           powerOn,
-				TargetPowerState:     powerOn,
 				TargetProvisionState: string(nodes.TargetDeleted),
 				UUID:                 nodeUUID,
 			}),
@@ -211,7 +213,6 @@ func TestPowerOff(t *testing.T) {
 			name: "power-off wait for locked host",
 			ironic: testserver.NewIronic(t).Ready().Node(nodes.Node{
 				PowerState:           powerOn,
-				TargetPowerState:     powerOn,
 				TargetProvisionState: "",
 				UUID:                 nodeUUID,
 			}).WithNodeStatesPower(nodeUUID, http.StatusConflict).WithNodeStatesPowerUpdate(nodeUUID, http.StatusConflict),
@@ -222,19 +223,18 @@ func TestPowerOff(t *testing.T) {
 			name: "power-off soft with force",
 			ironic: testserver.NewIronic(t).WithDefaultResponses().Node(nodes.Node{
 				PowerState:           powerOn,
-				TargetPowerState:     powerOn,
 				TargetProvisionState: "",
 				UUID:                 nodeUUID,
 			}),
-			rebootMode:    metal3v1alpha1.RebootModeSoft,
-			force:         true,
-			expectedDirty: true,
+			rebootMode:     metal3v1alpha1.RebootModeSoft,
+			force:          true,
+			expectedDirty:  true,
+			expectedReason: hardPowerOffReason,
 		},
 		{
 			name: "power-off hard with LastError",
 			ironic: testserver.NewIronic(t).WithDefaultResponses().Node(nodes.Node{
 				PowerState:           powerOn,
-				TargetPowerState:     powerOn,
 				TargetProvisionState: "",
 				UUID:                 nodeUUID,
 				LastError:            "hard power off failed",
@@ -247,14 +247,14 @@ func TestPowerOff(t *testing.T) {
 			name: "power-off hard with force",
 			ironic: testserver.NewIronic(t).WithDefaultResponses().Node(nodes.Node{
 				PowerState:           powerOn,
-				TargetPowerState:     powerOn,
 				TargetProvisionState: "",
 				UUID:                 nodeUUID,
 				LastError:            "hard power off failed",
 			}),
-			rebootMode:    metal3v1alpha1.RebootModeHard,
-			force:         true,
-			expectedDirty: true,
+			rebootMode:     metal3v1alpha1.RebootModeHard,
+			force:          true,
+			expectedDirty:  true,
+			expectedReason: hardPowerOffReason,
 		},
 	}
 
@@ -273,7 +273,10 @@ func TestPowerOff(t *testing.T) {
 
 			host := makeHost()
 			host.Status.Provisioning.ID = nodeUUID
-			publisher := func(reason, message string) {}
+			var eventReasons []string
+			publisher := func(reason, message string) {
+				eventReasons = append(eventReasons, message)
+			}
 			auth := clients.AuthConfig{Type: clients.NoAuth}
 			prov, err := newProvisionerWithSettings(host, bmc.Credentials{}, publisher,
 				tc.ironic.Endpoint(), auth, inspector.Endpoint(), auth,
@@ -295,7 +298,52 @@ func TestPowerOff(t *testing.T) {
 			if tc.expectedErrorResult {
 				assert.Contains(t, result.ErrorMessage, "hard power off failed")
 			}
-
+			if tc.expectedReason != "" {
+				assert.Len(t, eventReasons, 1)
+				assert.Contains(t, eventReasons, tc.expectedReason)
+			} else {
+				assert.Empty(t, eventReasons)
+			}
 		})
 	}
 }
+
+func TestSoftPowerOffFallback(t *testing.T) {
+	nodeUUID := "33ce8659-7400-4c68-9535-d10766f07a58"
+	node := nodes.Node{
+		PowerState: powerOn,
+		UUID:       nodeUUID,
+	}
+	ironic := testserver.NewIronic(t).Ready().Node(node).WithNodeStatesPowerUpdate(nodeUUID, http.StatusBadRequest)
+	ironic.Start()
+	defer ironic.Stop()
+	inspector := testserver.NewInspector(t).Ready()
+	inspector.Start()
+	defer inspector.Stop()
+
+	host := makeHost()
+	host.Status.Provisioning.ID = nodeUUID
+	var eventReasons []string
+	publisher := func(reason, message string) {
+		eventReasons = append(eventReasons, message)
+	}
+	auth := clients.AuthConfig{Type: clients.NoAuth}
+	prov, err := newProvisionerWithSettings(host, bmc.Credentials{}, publisher,
+		ironic.Endpoint(), auth, inspector.Endpoint(), auth,
+	)
+	if err != nil {
+		t.Fatalf("could not create provisioner: %s", err)
+	}
+
+	_, err = prov.PowerOff(metal3v1alpha1.RebootModeSoft, false)
+	assert.Error(t, err)
+	assert.False(t, errors.As(err, &softPowerOffUnsupportedError{}))
+
+	_, err = prov.changePower(&node, nodes.PowerOff)
+	assert.Error(t, err)
+	assert.False(t, errors.As(err, &softPowerOffUnsupportedError{}))
+
+	_, err = prov.changePower(&node, nodes.SoftPowerOff)
+	assert.Error(t, err)
+	assert.True(t, errors.As(err, &softPowerOffUnsupportedError{}))
+}
diff --git a/pkg/provisioner/ironic/validatemanagementaccess_test.go b/pkg/provisioner/ironic/validatemanagementaccess_test.go
index a5c0a306..bfcc5b7e 100644
--- a/pkg/provisioner/ironic/validatemanagementaccess_test.go
+++ b/pkg/provisioner/ironic/validatemanagementaccess_test.go
@@ -604,7 +604,7 @@ func TestValidateManagementAccessExistingPortWithWrongUUID(t *testing.T) {
 	}
 
 	_, _, err = prov.ValidateManagementAccess(provisioner.ManagementAccessData{}, false, false)
-	assert.EqualError(t, err, "failed to find existing host: port 11:11:11:11:11:11 exists but linked node doesn't random-wrong-id: Resource not found")
+	assert.EqualError(t, err, "failed to find existing host: port exists but linked node doesn't random-wrong-id: Resource not found")
 }
 
 func TestValidateManagementAccessExistingPortButHasName(t *testing.T) {