CLOUDP-189434 Using Wait Steps instead of risky Steps (#1332)

* CLOUDP-189434 Using Wait Steps instead of risky Steps

* Added more context in the comment

Author: slaskawi

cmd/readiness/main.go

@@ -10,7 +10,6 @@ import (
 	"github.com/mongodb/mongodb-kubernetes-operator/pkg/readiness/config"
 	"github.com/mongodb/mongodb-kubernetes-operator/pkg/readiness/headless"
 	"github.com/mongodb/mongodb-kubernetes-operator/pkg/readiness/health"
-	"github.com/mongodb/mongodb-kubernetes-operator/pkg/util/contains"
 	"go.uber.org/zap/zapcore"
 	"gopkg.in/natefinch/lumberjack.v2"
 
@@ -25,12 +24,9 @@ const (
 	mongodNotReadyIntervalMinutes = time.Minute * 1
 )
 
-var riskySteps []string
 var logger *zap.SugaredLogger
 
 func init() {
-	riskySteps = []string{"WaitAllRsMembersUp", "WaitRsInit", "WaitCanUpdate"}
-
 	// By default, we log to the output (convenient for tests)
 	cfg := zap.NewDevelopmentConfig()
 	log, err := cfg.Build()
@@ -45,8 +41,7 @@ func init() {
 // The logic depends on if the pod is a standard MongoDB or an AppDB one.
 // - If MongoDB: then just the 'statuses[0].IsInGoalState` field is used to learn if the Agent has reached the goal
 // - if AppDB: the 'mmsStatus[0].lastGoalVersionAchieved' field is compared with the one from mounted automation config
-// Additionally if the previous check hasn't returned 'true' the "deadlock" case is checked to make sure the Agent is
-// not waiting for the other members.
+// Additionally if the previous check hasn't returned 'true' an additional check for wait steps is being performed
 func isPodReady(conf config.Config) (bool, error) {
 	healthStatus, err := parseHealthStatus(conf.HealthStatusReader)
 	if err != nil {
@@ -55,8 +50,8 @@ func isPodReady(conf config.Config) (bool, error) {
 	}
 
 	// The 'statuses' file can be empty only for OM Agents
-	if len(healthStatus.Healthiness) == 0 && !isHeadlessMode() {
-		logger.Info("'statuses' is empty. We assume there is no automation config for the agent yet.")
+	if len(healthStatus.Statuses) == 0 && !isHeadlessMode() {
+		logger.Debug("'statuses' is empty. We assume there is no automation config for the agent yet. Returning ready.")
 		return true, nil
 	}
 
@@ -73,33 +68,35 @@ func isPodReady(conf config.Config) (bool, error) {
 	}
 
 	if inGoalState && inReadyState {
-		logger.Info("Agent has reached goal state")
+		logger.Info("The Agent has reached goal state. Returning ready.")
 		return true, nil
 	}
 
 	// Fallback logic: the agent is not in goal state and got stuck in some steps
-	if !inGoalState && hasDeadlockedSteps(healthStatus) {
+	if !inGoalState && isOnWaitingStep(healthStatus) {
+		logger.Info("The Agent is on wait Step. Returning ready.")
 		return true, nil
 	}
 
+	logger.Info("Reached the end of the check. Returning not ready.")
 	return false, nil
 }
 
-// hasDeadlockedSteps returns true if the agent is stuck on waiting for the other agents
-func hasDeadlockedSteps(health health.Status) bool {
-	currentStep := findCurrentStep(health.ProcessPlans)
+// isOnWaitingStep returns true if the agent is stuck on waiting for the other Agents or something else to happen.
+func isOnWaitingStep(health health.Status) bool {
+	currentStep := findCurrentStep(health.MmsStatus)
 	if currentStep != nil {
-		return isDeadlocked(currentStep)
+		return isWaitStep(currentStep)
 	}
 	return false
 }
 
-// findCurrentStep returns the step which seems to be run by the Agent now. The step is always in the last plan
-// (see https://github.com/10gen/ops-manager-kubernetes/pull/401#discussion_r333071555) so we iterate over all the steps
-// there and find the last step which has "Started" non nil
-// (indeed this is not the perfect logic as sometimes the agent doesn't update the 'Started' as well - see
-// 'health-status-ok.json', but seems it works for finding deadlocks still
-// noinspection GoNilness
+// findCurrentStep returns the step which the Agent is working now.
+// The algorithm (described in https://github.com/10gen/ops-manager-kubernetes/pull/401#discussion_r333071555):
+//   - Obtain the latest plan (the last one in the plans array)
+//   - Find the last step, which has Started not nil and Completed nil. The Steps are processed as a tree in a BFS fashion.
+//     The last element is very likely to be the Step the Agent is performing at the moment. There are some chances that
+//     this is a waiting step, use isWaitStep to verify this.
 func findCurrentStep(processStatuses map[string]health.MmsDirectorStatus) *health.StepStatus {
 	var currentPlan *health.PlanStatus
 	if len(processStatuses) == 0 {
@@ -111,13 +108,14 @@ func findCurrentStep(processStatuses map[string]health.MmsDirectorStatus) *healt
 		logger.Errorf("Only one process status is expected but got %d!", len(processStatuses))
 		return nil
 	}
+
 	// There is always only one process managed by the Agent - so there will be only one loop
-	for k, v := range processStatuses {
-		if len(v.Plans) == 0 {
-			logger.Errorf("The process %s doesn't contain any plans!", k)
+	for processName, processStatus := range processStatuses {
+		if len(processStatus.Plans) == 0 {
+			logger.Errorf("The process %s doesn't contain any plans!", processName)
 			return nil
 		}
-		currentPlan = v.Plans[len(v.Plans)-1]
+		currentPlan = processStatus.Plans[len(processStatus.Plans)-1]
 	}
 
 	if currentPlan.Completed != nil {
@@ -129,7 +127,7 @@ func findCurrentStep(processStatuses map[string]health.MmsDirectorStatus) *healt
 	var lastStartedStep *health.StepStatus
 	for _, m := range currentPlan.Moves {
 		for _, s := range m.Steps {
-			if s.Started != nil {
+			if s.Started != nil && s.Completed == nil {
 				lastStartedStep = s
 			}
 		}
@@ -138,12 +136,23 @@ func findCurrentStep(processStatuses map[string]health.MmsDirectorStatus) *healt
 	return lastStartedStep
 }
 
-func isDeadlocked(status *health.StepStatus) bool {
+// isWaitStep returns true is the Agent is currently waiting for something to happen.
+//
+// Most of the time, the Agent waits for an initialization by other member of the cluster. In such case,
+// holding the rollout does not improve the overall system state. Even if the probe returns true too quickly
+// the worst thing that can happen is a short service interruption, which is still better than full service outage.
+//
+// The 15 seconds explanation:
+//   - The status file is written every 10s but the Agent processes steps independently of it
+//   - In order to avoid reacting on a newly added wait Step (as they can naturally go away), we're giving the Agent
+//     at least 15 sends to spend on that Step.
+//   - This hopefully prevents the Probe from flipping False to True too quickly.
+func isWaitStep(status *health.StepStatus) bool {
 	// Some logic behind 15 seconds: the health status file is dumped each 10 seconds, so we are sure that if the agent
 	// has been in the step for 10 seconds - this means it is waiting for the other hosts, and they are not available
 	fifteenSecondsAgo := time.Now().Add(time.Duration(-15) * time.Second)
-	if contains.String(riskySteps, status.Step) && status.Completed == nil && status.Started.Before(fifteenSecondsAgo) {
-		logger.Infof("Indicated a possible deadlock, status: %s, started at %s but hasn't finished "+
+	if status.IsWaitStep && status.Completed == nil && status.Started.Before(fifteenSecondsAgo) {
+		logger.Debugf("Indicated a wait Step, status: %s, started at %s but hasn't finished "+
 			"yet. Marking the probe as ready", status.Step, status.Started.Format(time.RFC3339))
 		return true
 	}
@@ -160,7 +169,7 @@ func isInGoalState(health health.Status, conf config.Config) (bool, error) {
 // performCheckOMMode does a general check if the Agent has reached the goal state - must be called when Agent is in
 // "OM mode"
 func performCheckOMMode(health health.Status) bool {
-	for _, v := range health.Healthiness {
+	for _, v := range health.Statuses {
 		logger.Debug(v)
 		if v.IsInGoalState {
 			return true
@@ -231,10 +240,10 @@ func main() {
 // isInReadyState checks the MongoDB Server state. It returns true if the mongod process is up and its state
 // is PRIMARY or SECONDARY.
 func isInReadyState(health health.Status) bool {
-	if len(health.Healthiness) == 0 {
+	if len(health.Statuses) == 0 {
 		return true
 	}
-	for _, processHealth := range health.Healthiness {
+	for _, processHealth := range health.Statuses {
 		// We know this loop should run only once, in Kubernetes there's
 		// only 1 server managed per host.
 		if !processHealth.ExpectedToBeUp {