ci wait: logging changes, fix the wait-for-rollout function, fix for empty CI_COMMIT_SHA

- log the elapsed time before returning
- change padding around rollout log messages
- fix two possible panics in ciWaitVersionCompare()

cmd/ci_wait.go

@@ -55,6 +55,7 @@ func init() {
 }
 
 func runCiWaitCmd(cmd *cobra.Command, args []string) error {
+	start := time.Now()
 	data := ciWaitBaseURLData{
 		Project: os.Getenv("CI_PROJECT_NAME"),
 		Env:     environmentSuffix,
@@ -126,7 +127,7 @@ func runCiWaitCmd(cmd *cobra.Command, args []string) error {
 	cli.Default.Padding = InitialPadding
 
 	if url == "" {
-		log.Fatal("Could not locate version endpoint")
+		log.Fatalf("Could not locate version endpoint after %s", time.Since(start).Truncate(time.Millisecond))
 	}
 
 	log.WithFields(log.Fields{
@@ -160,25 +161,31 @@ func runCiWaitCmd(cmd *cobra.Command, args []string) error {
 				log.Info("New version is live")
 				seen := 1
 				// optionally wait for the rollout
-				for seen < viper.GetInt("rollout-count") {
+				if viper.GetBool("wait-for-rollout") {
+					cli.Default.Padding = InitialPadding
 					log.WithFields(log.Fields{"seen": seen, "delay": viper.GetDuration("rollout-delay"), "count": viper.GetInt("rollout-count")}).Info("Waiting for rollout")
-					time.Sleep(viper.GetDuration("rollout-delay"))
-					resp, err := hc.Get(url)
-					if err != nil {
-						log.WithError(err).WithField("url", url).Error("Error fetching URL")
-						continue
+					cli.Default.Padding = 2 * InitialPadding
+					for seen < viper.GetInt("rollout-count") {
+						time.Sleep(viper.GetDuration("rollout-delay"))
+						resp, err := hc.Get(url)
+						if err != nil {
+							log.WithError(err).WithField("url", url).Error("Error fetching URL")
+							continue
+						}
+						defer resp.Body.Close()
+						if resp.StatusCode == http.StatusOK && ciWaitVersionCompare(initialBody, newBody, newCommit, newVersion) {
+							seen++
+							log.WithField("seen", seen).Info("NEW")
+							continue
+						}
+						// we consider non-200 statuses and a response with the old version to be failures
+						// reset seen back to 0 and continue
+						seen = 0
+						log.WithField("seen", seen).Warn("OLD")
 					}
-					defer resp.Body.Close()
-					if resp.StatusCode == http.StatusOK && ciWaitVersionCompare(initialBody, newBody, newCommit, newVersion) {
-						seen = +1
-						log.Info("NEW")
-						continue
-					}
-					// we consider non-200 statuses and a response with the old version to be failures
-					// reset seen back to 0 and continue
-					seen = 0
-					log.Warn("OLD")
 				}
+				cli.Default.Padding = InitialPadding
+				log.Infof("Finished after %s", time.Since(start).Truncate(time.Millisecond))
 				return nil
 			} else {
 				log.Warn("No update to version endpoint")
@@ -197,7 +204,7 @@ func runCiWaitCmd(cmd *cobra.Command, args []string) error {
 		"new":     newBody,
 		"commit":  newCommit,
 		"version": newVersion,
-	}).Error("Did not observe an update to the version endpoint")
+	}).Errorf("Did not observe an update to the version endpoint after %s", time.Since(start).Truncate(time.Millisecond))
 
 	return errors.New("Did not observe an update to the version endpoint")
 }
@@ -215,11 +222,15 @@ func ciWaitVersionCompare(initialBody []byte, newBody []byte, commit string, ver
 		return string(initialBody) == string(newBody)
 	}
 
-	// look for long commit
-	for _, k := range ciWaitCommitFields {
-		if v := nb[k]; v != "" {
-			l := len(v.(string))
-			return v == commit[:l]
+	// look for long commit, comparing the first len(commit) characters
+	if commit != "" {
+		for _, k := range ciWaitCommitFields {
+			if v := nb[k]; v != "" {
+				l := len(v.(string))
+				if len(commit) >= l {
+					return v == commit[:l]
+				}
+			}
 		}
 	}
 
@@ -230,5 +241,6 @@ func ciWaitVersionCompare(initialBody []byte, newBody []byte, commit string, ver
 		}
 	}
 
-	return false
+	// all else fails, do a straight string comparison
+	return string(initialBody) == string(newBody)
 }