functional-tester/tester: clean up logging

Signed-off-by: Gyuho Lee <gyuhox@gmail.com>

tools/functional-tester/tester/cluster.go

@@ -568,8 +568,6 @@ func (clus *Cluster) DestroyEtcdAgents() {
 		clus.logger.Info("closed connection to agent", zap.String("agent-address", clus.Members[i].AgentAddr), zap.Error(err))
 	}
 
-	// TODO: closing stresser connections to etcd
-
 	if clus.testerHTTPServer != nil {
 		clus.logger.Info("closing tester HTTP server", zap.String("tester-address", clus.Tester.TesterAddr))
 		ctx, cancel := context.WithTimeout(context.Background(), 3*time.Second)
@@ -604,7 +602,7 @@ func (clus *Cluster) WaitHealth() error {
 				break
 			}
 			clus.logger.Info(
-				"successfully wrote health key",
+				"wrote health key",
 				zap.Int("retries", i),
 				zap.String("endpoint", m.EtcdClientEndpoint),
 			)
@@ -688,9 +686,9 @@ func (clus *Cluster) compactKV(rev int64, timeout time.Duration) (err error) {
 		kvc := pb.NewKVClient(conn)
 
 		clus.logger.Info(
-			"starting compaction",
+			"compacting",
 			zap.String("endpoint", m.EtcdClientEndpoint),
-			zap.Int64("revision", rev),
+			zap.Int64("compact-revision", rev),
 			zap.Duration("timeout", timeout),
 		)
 
@@ -706,14 +704,14 @@ func (clus *Cluster) compactKV(rev int64, timeout time.Duration) (err error) {
 				clus.logger.Info(
 					"compact error is ignored",
 					zap.String("endpoint", m.EtcdClientEndpoint),
-					zap.Int64("revision", rev),
+					zap.Int64("compact-revision", rev),
 					zap.Error(cerr),
 				)
 			} else {
 				clus.logger.Warn(
 					"compact failed",
 					zap.String("endpoint", m.EtcdClientEndpoint),
-					zap.Int64("revision", rev),
+					zap.Int64("compact-revision", rev),
 					zap.Error(cerr),
 				)
 				err = cerr
@@ -723,9 +721,9 @@ func (clus *Cluster) compactKV(rev int64, timeout time.Duration) (err error) {
 
 		if succeed {
 			clus.logger.Info(
-				"finished compaction",
+				"compacted",
 				zap.String("endpoint", m.EtcdClientEndpoint),
-				zap.Int64("revision", rev),
+				zap.Int64("compact-revision", rev),
 				zap.Duration("timeout", timeout),
 				zap.Duration("took", time.Since(now)),
 			)

tools/functional-tester/tester/cluster_tester.go

@@ -99,7 +99,7 @@ func (clus *Cluster) StartTester() {
 	}
 
 	clus.logger.Info(
-		"functional-tester is finished",
+		"functional-tester passed",
 		zap.Int("round", clus.rd),
 		zap.Int("case", clus.cs),
 	)
@@ -114,6 +114,7 @@ func (clus *Cluster) doRound(round int) error {
 
 		caseTotalCounter.WithLabelValues(f.Desc()).Inc()
 
+		clus.logger.Info("wait health before injecting failures")
 		if err := clus.WaitHealth(); err != nil {
 			return fmt.Errorf("wait full health error: %v", err)
 		}
@@ -134,6 +135,9 @@ func (clus *Cluster) doRound(round int) error {
 			zap.String("desc", f.Desc()),
 		)
 
+		// if run local, recovering server may conflict
+		// with stressing client ports
+		// TODO: use unix for local tests
 		clus.logger.Info(
 			"recovering failure",
 			zap.Int("round", clus.rd),
@@ -150,17 +154,20 @@ func (clus *Cluster) doRound(round int) error {
 			zap.String("desc", f.Desc()),
 		)
 
+		clus.logger.Info("pausing stresser after failure recovery, before wait health")
 		clus.pauseStresser()
 
+		clus.logger.Info("wait health after recovering failures")
 		if err := clus.WaitHealth(); err != nil {
 			return fmt.Errorf("wait full health error: %v", err)
 		}
+		clus.logger.Info("check consistency after recovering failures")
 		if err := clus.checkConsistency(); err != nil {
 			return fmt.Errorf("tt.checkConsistency error (%v)", err)
 		}
 
 		clus.logger.Info(
-			"success",
+			"failure case passed",
 			zap.Int("round", clus.rd),
 			zap.Int("case", clus.cs),
 			zap.String("desc", f.Desc()),
@@ -184,6 +191,7 @@ func (clus *Cluster) updateRevision() error {
 }
 
 func (clus *Cluster) compact(rev int64, timeout time.Duration) (err error) {
+	clus.logger.Info("pausing stresser before compact")
 	clus.pauseStresser()
 	defer func() {
 		if err == nil {
@@ -255,7 +263,7 @@ func (clus *Cluster) cleanup() error {
 	clus.closeStresser()
 	if err := clus.FailArchive(); err != nil {
 		clus.logger.Warn(
-			"Cleanup failed",
+			"cleanup failed",
 			zap.Int("round", clus.rd),
 			zap.Int("case", clus.cs),
 			zap.Error(err),
@@ -264,7 +272,7 @@ func (clus *Cluster) cleanup() error {
 	}
 	if err := clus.Restart(); err != nil {
 		clus.logger.Warn(
-			"Restart failed",
+			"restart failed",
 			zap.Int("round", clus.rd),
 			zap.Int("case", clus.cs),
 			zap.Error(err),

tools/functional-tester/tester/failure_case_kill.go

@@ -107,6 +107,7 @@ func (f *failureOne) Recover(clus *Cluster, round int) error {
 	if err := f.recoverMember(clus, round%len(clus.Members)); err != nil {
 		return err
 	}
+	clus.logger.Info("wait health after recovering failureOne")
 	return clus.WaitHealth()
 }
 
@@ -125,6 +126,7 @@ func (f *failureAll) Recover(clus *Cluster, round int) error {
 			return err
 		}
 	}
+	clus.logger.Info("wait health after recovering failureAll")
 	return clus.WaitHealth()
 }
 
@@ -159,6 +161,7 @@ func (f *failureLeader) Recover(clus *Cluster, round int) error {
 	if err := f.recoverMember(clus, f.idx); err != nil {
 		return err
 	}
+	clus.logger.Info("wait health after recovering failureLeader")
 	return clus.WaitHealth()
 }