From ecadb0fdf7d6db08cc7629da100a98d2229919c8 Mon Sep 17 00:00:00 2001
From: Gyuho Lee <gyuhox@gmail.com>
Date: Mon, 9 Apr 2018 11:28:11 -0700
Subject: [PATCH] functional/tester: improve logging

Signed-off-by: Gyuho Lee <gyuhox@gmail.com>
---
 functional/tester/cluster_run.go | 26 ++++++++++++++++++++++----
 functional/tester/failure.go     |  4 ----
 functional/tester/stress_key.go  |  4 +++-
 3 files changed, 25 insertions(+), 9 deletions(-)

diff --git a/functional/tester/cluster_run.go b/functional/tester/cluster_run.go
index 5cd601ac1..c29b81027 100644
--- a/functional/tester/cluster_run.go
+++ b/functional/tester/cluster_run.go
@@ -152,7 +152,7 @@ func (clus *Cluster) doRound() error {
 		fcase := fa.FailureCase()
 		if fcase != rpcpb.FailureCase_NO_FAIL_WITH_NO_STRESS_FOR_LIVENESS {
 			clus.lg.Info(
-				"stresser START",
+				"stress START",
 				zap.Int("round", clus.rd),
 				zap.Int("case", clus.cs),
 				zap.Int("case-total", len(clus.failures)),
@@ -190,7 +190,13 @@ func (clus *Cluster) doRound() error {
 		}
 
 		if stressStarted {
-			clus.lg.Info("stresser PAUSE")
+			clus.lg.Info(
+				"stress PAUSE",
+				zap.Int("round", clus.rd),
+				zap.Int("case", clus.cs),
+				zap.Int("case-total", len(clus.failures)),
+				zap.String("desc", fa.Desc()),
+			)
 			ems := clus.stresser.Pause()
 			if fcase == rpcpb.FailureCase_NO_FAIL_WITH_STRESS && len(ems) > 0 {
 				ess := make([]string, 0, len(ems))
@@ -213,12 +219,24 @@ func (clus *Cluster) doRound() error {
 			}
 		}
 
-		clus.lg.Info("health check START")
+		clus.lg.Info(
+			"health check START",
+			zap.Int("round", clus.rd),
+			zap.Int("case", clus.cs),
+			zap.Int("case-total", len(clus.failures)),
+			zap.String("desc", fa.Desc()),
+		)
 		if err := clus.WaitHealth(); err != nil {
 			return fmt.Errorf("wait full health error: %v", err)
 		}
 
-		clus.lg.Info("consistency check START")
+		clus.lg.Info(
+			"consistency check START",
+			zap.Int("round", clus.rd),
+			zap.Int("case", clus.cs),
+			zap.Int("case-total", len(clus.failures)),
+			zap.String("desc", fa.Desc()),
+		)
 		if err := clus.checkConsistency(); err != nil {
 			return fmt.Errorf("consistency check error (%v)", err)
 		}
diff --git a/functional/tester/failure.go b/functional/tester/failure.go
index cb1cef930..855cb7f4c 100644
--- a/functional/tester/failure.go
+++ b/functional/tester/failure.go
@@ -251,8 +251,6 @@ func (f *failureUntilSnapshot) Inject(clus *Cluster) error {
 	now := time.Now()
 	clus.lg.Info(
 		"trigger snapshot START",
-		zap.Int("round", clus.rd),
-		zap.Int("case", clus.cs),
 		zap.String("desc", f.Desc()),
 		zap.Int64("etcd-snapshot-count", snapshotCount),
 	)
@@ -283,8 +281,6 @@ func (f *failureUntilSnapshot) Inject(clus *Cluster) error {
 		if diff > snapshotCount {
 			clus.lg.Info(
 				"trigger snapshot PASS",
-				zap.Int("round", clus.rd),
-				zap.Int("case", clus.cs),
 				zap.Int("retries", i),
 				zap.String("desc", f.Desc()),
 				zap.Int64("committed-entries", diff),
diff --git a/functional/tester/stress_key.go b/functional/tester/stress_key.go
index 60c016e4d..509748b8a 100644
--- a/functional/tester/stress_key.go
+++ b/functional/tester/stress_key.go
@@ -18,6 +18,7 @@ import (
 	"context"
 	"fmt"
 	"math/rand"
+	"reflect"
 	"sync"
 	"sync/atomic"
 	"time"
@@ -158,9 +159,10 @@ func (s *keyStresser) run() {
 			return
 		default:
 			s.lg.Warn(
-				"stress stopped",
+				"stress run exiting",
 				zap.String("stress-type", s.stype.String()),
 				zap.String("endpoint", s.m.EtcdClientEndpoint),
+				zap.String("error-type", reflect.TypeOf(err).String()),
 				zap.Error(err),
 			)
 			return