Repository: threefoldtech/zos (go)

Issue:
Node sets power state to Down when power management is not enabled
While investigating a minting issue reported by a farmer, I noticed that the power target and power state for the affected nodes was repeatedly set to "Down" when the nodes did not actually shutdown because power management is not enabled. During the same period, the node was sending uptime reports.

Here is a sample of the logs:

```
2023-05-16 18:42:37 | [+] powerd: 2023-05-16T16:42:37Z info ignoring shutdown because power-management is not enabled
2023-05-16 18:42:24 | [-] powerd: 2023/05/16 16:42:24 Connecting to wss://02.tfchain.grid.tf/...
2023-05-16 18:42:24 | [+] noded: 2023-05-16T16:42:24Z info got power target change event node=4139
```

The reason for connecting to TF Chain is not shown, but it seems that this is to set the node's power state to "Down".

Reviewing the [code](https://github.com/threefoldtech/zos/blob/cf9e816109a9dc0baf3a445aa8c39146cbef92ea/pkg/power/power.go#L137) that handles this, it looks like the power state is set before calling the shutdown routine where the check is then executed for whether power management is enabled. The power state is not subsequently set to "Up".

What I don't understand is why the node was setting it's power state repeatedly to "Down", despite the [check](https://github.com/threefoldtech/zos/blob/cf9e816109a9dc0baf3a445aa8c39146cbef92ea/pkg/power/power.go#L140) to only execute this when the state is "Up". I wonder if there's an issue with how the power state is retrieved from TF Chain.

Here are the events I queried from TF Chain for this node (all power state and target events):

Time stamp | Date/Time | Event
-- | -- | --
1684341150 | 5/17/2023 16:32:30 | change_power_state to Down
1684341144 | 5/17/2023 16:32:24 | change_power_target to Down
1684337250 | 5/17/2023 15:27:30 | change_power_state to Down
1684337244 | 5/17/2023 15:27:24 | change_power_target to Down
1684333350 | 5/17/2023 14:22:30 | change_power_state to Down
1684333344 | 5/17/2023 14:22:24 | change_power_target to Down
1684329450 | 5/17/2023 13:17:30 | change_power_state to Down
1684329444 | 5/17/2023 13:17:24 | change_power_target to Down
1684325556 | 5/17/2023 12:12:36 | change_power_state to Down
1684325550 | 5/17/2023 12:12:30 | change_power_target to Down
1684321650 | 5/17/2023 11:07:30 | change_power_state to Down
1684321644 | 5/17/2023 11:07:24 | change_power_target to Down
1684317750 | 5/17/2023 10:02:30 | change_power_state to Down
1684317744 | 5/17/2023 10:02:24 | change_power_target to Down
1684313850 | 5/17/2023 8:57:30 | change_power_state to Down
1684313844 | 5/17/2023 8:57:24 | change_power_target to Down
1684309950 | 5/17/2023 7:52:30 | change_power_state to Down
1684309944 | 5/17/2023 7:52:24 | change_power_target to Down
1684306050 | 5/17/2023 6:47:30 | change_power_state to Down
1684306044 | 5/17/2023 6:47:24 | change_power_target to Down
1684302150 | 5/17/2023 5:42:30 | change_power_state to Down
1684302144 | 5/17/2023 5:42:24 | change_power_target to Down
1684298250 | 5/17/2023 4:37:30 | change_power_state to Down
1684298244 | 5/17/2023 4:37:24 | change_power_target to Down
1684294350 | 5/17/2023 3:32:30 | change_power_state to Down
1684294344 | 5/17/2023 3:32:24 | change_power_target to Down
1684290450 | 5/17/2023 2:27:30 | change_power_state to Down
1684290444 | 5/17/2023 2:27:24 | change_power_target to Down
1684286550 | 5/17/2023 1:22:30 | change_power_state to Down
1684286544 | 5/17/2023 1:22:24 | change_power_target to Down
1684282650 | 5/17/2023 0:17:30 | change_power_state to Down
1684282644 | 5/17/2023 0:17:24 | change_power_target to Down
1684278750 | 5/16/2023 23:12:30 | change_power_state to Down
1684278744 | 5/16/2023 23:12:24 | change_power_target to Down
1684274850 | 5/16/2023 22:07:30 | change_power_state to Down
1684274844 | 5/16/2023 22:07:24 | change_power_target to Down
1684270950 | 5/16/2023 21:02:30 | change_power_state to Down
1684270944 | 5/16/2023 21:02:24 | change_power_target to Down
1684267050 | 5/16/2023 19:57:30 | change_power_state to Down
1684267044 | 5/16/2023 19:57:24 | change_power_target to Down
1684263150 | 5/16/2023 18:52:30 | change_power_state to Down
1684263144 | 5/16/2023 18:52:24 | change_power_target to Down
1684259250 | 5/16/2023 17:47:30 | change_power_state to Down
1684259244 | 5/16/2023 17:47:24 | change_power_target to Down
1684255356 | 5/16/2023 16:42:36 | change_power_state to Down
1684255344 | 5/16/2023 16:42:24 | change_power_target to Down
1684213698 | 5/16/2023 5:08:18 | change_power_target to Up
1684211598 | 5/16/2023 4:33:18 | change_power_target to Up



Pull request:
make sure node state is kept up if nodes can't shutdown
There is also a fix for when ctx is cancelled in events streams

fixes #2018

Patch:
diff --git a/pkg/events/redis.go b/pkg/events/redis.go
index d08fa8c8..84a6d621 100644
--- a/pkg/events/redis.go
+++ b/pkg/events/redis.go
@@ -236,6 +236,7 @@ func (r *RedisConsumer) consumer(ctx context.Context, stream string, ch reflect.
 	logger := log.With().Str("stream", stream).Logger()
 	go func() {
 		defer con.Close()
+		defer ch.Close()
 
 		for {
 			messages, err := r.pop(con, group, stream)
diff --git a/pkg/power/power.go b/pkg/power/power.go
index 3c40b283..834ef8e7 100644
--- a/pkg/power/power.go
+++ b/pkg/power/power.go
@@ -126,8 +126,7 @@ func (p *PowerServer) syncSelf() error {
 	// if target is down, we make sure state is down, then shutdown
 
 	if power.Target.IsUp {
-		if power.State.IsDown {
-			_, err = cl.SetNodePowerState(p.identity, true)
+		if err := p.setNodePowerState(cl, true); err != nil {
 			return errors.Wrap(err, "failed to set state to up")
 		}
 
@@ -137,9 +136,8 @@ func (p *PowerServer) syncSelf() error {
 	// now the target must be down.
 	// we need to shutdown
 
-	if power.State.IsUp {
-		_, err = cl.SetNodePowerState(p.identity, false)
-		return errors.Wrap(err, "failed to set state to up")
+	if err := p.setNodePowerState(cl, false); err != nil {
+		return errors.Wrap(err, "failed to set state to down")
 	}
 
 	// otherwise node need to get back to sleep.
@@ -220,7 +218,7 @@ func (p *PowerServer) event(event *pkg.PowerTargetChangeEvent) error {
 
 	if event.NodeID == p.node && event.Target.IsDown {
 		// we need to shutdown!
-		if _, err := cl.SetNodePowerState(p.identity, false); err != nil {
+		if err := p.setNodePowerState(cl, false); err != nil {
 			return errors.Wrap(err, "failed to set node power state to down")
 		}
 
@@ -237,6 +235,43 @@ func (p *PowerServer) event(event *pkg.PowerTargetChangeEvent) error {
 	return nil
 }
 
+// setNodePowerState sets the node power state as provided or to up if power mgmt is
+// not enabled on this node.
+// this function makes sure to compare the state with on chain state to not do
+// un-necessary transactions.
+func (p *PowerServer) setNodePowerState(cl *substrate.Substrate, up bool) error {
+
+	/*
+		if power is not enabled, the node state should always be up
+		otherwise update the state to the correct value
+
+		| enabled | up | result|
+		| 0       | 0  | 1     |
+		| 0       | 1  | 1     |
+		| 1       | 0  | 0     |
+		| 1       | 1  | 1     |
+
+		this simplifies as below:
+	*/
+
+	up = !p.enabled || up
+	power, err := cl.GetPowerTarget(p.node)
+
+	if err != nil {
+		return errors.Wrap(err, "failed to check power state")
+	}
+
+	// only update the chain if it's different from actual value.
+	if power.State.IsUp == up {
+		return nil
+	}
+
+	log.Info().Bool("state", up).Msg("setting node power state")
+	// this to make sure node state is fixed also for nodes
+	_, err = cl.SetNodePowerState(p.identity, up)
+	return err
+}
+
 func (p *PowerServer) recv(ctx context.Context) error {
 	log.Info().Msg("listening for power events")
 	stream, err := p.consumer.PowerTargetChange(ctx)
diff --git a/pkg/provision/engine.go b/pkg/provision/engine.go
index 51dd8c20..cb09c2f5 100644
--- a/pkg/provision/engine.go
+++ b/pkg/provision/engine.go
@@ -15,6 +15,7 @@ import (
 	substrate "github.com/threefoldtech/tfchain/clients/tfchain-client-go"
 	"github.com/threefoldtech/zos/pkg"
 	"github.com/threefoldtech/zos/pkg/gridtypes"
+	"github.com/threefoldtech/zos/pkg/gridtypes/zos"
 )
 
 // EngineOption interface
@@ -867,10 +868,42 @@ func (e *NativeEngine) uninstallDeployment(ctx context.Context, dl *gridtypes.De
 
 }
 
+func getZmountSize(wl *gridtypes.Workload) (gridtypes.Unit, error) {
+	data, err := wl.WorkloadData()
+	if err != nil {
+		return 0, err
+	}
+	zmount, ok := data.(*zos.ZMount)
+	if !ok {
+		return 0, fmt.Errorf("failed to get workload data as a zmount '%v'", data)
+	}
+	return zmount.Size, nil
+}
+
+func sortZmountWorkloads(workloads []*gridtypes.WorkloadWithID) {
+	sort.Slice(workloads, func(i, j int) bool {
+		sizeI, err := getZmountSize(workloads[i].Workload)
+		if err != nil {
+			return false
+		}
+
+		sizeJ, err := getZmountSize(workloads[j].Workload)
+		if err != nil {
+			return false
+		}
+
+		return sizeI > sizeJ
+	})
+}
+
 func (e *NativeEngine) installDeployment(ctx context.Context, getter gridtypes.WorkloadGetter) {
 	for _, typ := range e.order {
 		workloads := getter.ByType(typ)
 
+		if typ == zos.ZMountType {
+			sortZmountWorkloads(workloads)
+		}
+
 		for _, wl := range workloads {
 			if err := e.installWorkload(ctx, wl); err != nil {
 				log.Error().Err(err).Stringer("id", wl.ID).Msg("failed to install workload")


Test patch:
diff --git a/pkg/provision/engine_test.go b/pkg/provision/engine_test.go
index e9f2765c..177f6bf0 100644
--- a/pkg/provision/engine_test.go
+++ b/pkg/provision/engine_test.go
@@ -1,5 +1,14 @@
 package provision
 
+import (
+	"encoding/json"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/threefoldtech/zos/pkg/gridtypes"
+	"github.com/threefoldtech/zos/pkg/gridtypes/zos"
+)
+
 // func TestEngine(t *testing.T) {
 // 	td, err := ioutil.TempDir("", "")
 // 	require.NoError(t, err)
@@ -68,3 +77,64 @@ package provision
 // 	assert.EqualValues(t, 1, workloads.ZDBNamespace)
 // 	assert.EqualValues(t, 0, workloads.K8sVM)
 // }
+
+func TestGetZmountSize(t *testing.T) {
+	t.Run("invalid type", func(t *testing.T) {
+		wl := gridtypes.WorkloadWithID{
+			Workload: &gridtypes.Workload{Type: "invalid"},
+		}
+		_, err := getZmountSize(wl.Workload)
+		assert.Error(t, err)
+	})
+	t.Run("different data type", func(t *testing.T) {
+		wl := gridtypes.WorkloadWithID{
+			Workload: &gridtypes.Workload{Type: zos.ZDBType, Data: json.RawMessage(`{"size": 10}`)},
+		}
+		_, err := getZmountSize(wl.Workload)
+		assert.Error(t, err)
+	})
+	t.Run("valid data", func(t *testing.T) {
+		wl := gridtypes.WorkloadWithID{
+			Workload: &gridtypes.Workload{Type: zos.ZMountType, Data: json.RawMessage(`{"size": 10}`)},
+		}
+		size, err := getZmountSize(wl.Workload)
+		assert.NoError(t, err)
+		assert.Equal(t, size, gridtypes.Unit(10))
+	})
+
+}
+
+func TestSortZmountWorkloads(t *testing.T) {
+	workloads := []*gridtypes.WorkloadWithID{
+		{Workload: &gridtypes.Workload{
+			Type: zos.ZMountType,
+			Data: json.RawMessage(`{"size": 10}`),
+		}},
+		{Workload: &gridtypes.Workload{
+			Type: zos.ZMountType,
+			Data: json.RawMessage(`{"size": 30}`),
+		}},
+		{Workload: &gridtypes.Workload{
+			Type: zos.ZMountType,
+			Data: json.RawMessage(`{"size": 20}`),
+		}},
+	}
+
+	expectedWorkloads := []*gridtypes.WorkloadWithID{
+		{Workload: &gridtypes.Workload{
+			Type: zos.ZMountType,
+			Data: json.RawMessage(`{"size": 30}`),
+		}},
+		{Workload: &gridtypes.Workload{
+			Type: zos.ZMountType,
+			Data: json.RawMessage(`{"size": 20}`),
+		}},
+		{Workload: &gridtypes.Workload{
+			Type: zos.ZMountType,
+			Data: json.RawMessage(`{"size": 10}`),
+		}},
+	}
+
+	sortZmountWorkloads(workloads)
+	assert.Equal(t, expectedWorkloads, workloads)
+}