Add logs for debugging

main.go

@@ -69,8 +69,8 @@ func createConfigsModelFromEnvs() ConfigsModel {
 func (configs ConfigsModel) print() {
 	log.Infof("Configs:")
 	log.Printf("- ZipPath: %s", configs.ZipPath)
-
 	log.Printf("- TestTimeout: %s", configs.TestTimeout)
+	log.Printf("- DownloadTestResults: %s", configs.DownloadTestResults)
 	log.Printf("- TestDevices:\n---")
 	w := tabwriter.NewWriter(os.Stdout, 0, 0, 3, ' ', 0)
 	if _, err := fmt.Fprintln(w, "Model\tOS version\tOrientation\tLocale\t"); err != nil {
@@ -145,7 +145,7 @@ func main() {
 
 	successful := true
 
-	log.Infof("Upload IPAs")
+	log.TInfof("Upload IPAs")
 	{
 		url := configs.APIBaseURL + "/assets/" + configs.AppSlug + "/" + configs.BuildSlug + "/" + configs.APIToken
 
@@ -183,11 +183,11 @@ func main() {
 			failf("Failed to upload file(%s) to (%s), error: %s", configs.ZipPath, responseModel.AppURL, err)
 		}
 
-		log.Donef("=> .xctestrun uploaded")
+		log.TDonef("=> .xctestrun uploaded")
 	}
 
 	fmt.Println()
-	log.Infof("Start test")
+	log.TInfof("Start test")
 	{
 		url := configs.APIBaseURL + "/" + configs.AppSlug + "/" + configs.BuildSlug + "/" + configs.APIToken
 
@@ -256,14 +256,17 @@ func main() {
 			failf("Failed to start test: %d, error: %s", resp.StatusCode, string(body))
 		}
 
-		log.Donef("=> Test started")
+		log.TDonef("=> Test started")
 	}
 
 	fmt.Println()
-	log.Infof("Waiting for test results")
+	log.TInfof("Waiting for test results")
 	{
 		finished := false
 		printedLogs := []string{}
+
+		stepIDToStepStates := map[string]stepStates{}
+
 		for !finished {
 			url := configs.APIBaseURL + "/" + configs.AppSlug + "/" + configs.BuildSlug + "/" + configs.APIToken
 
@@ -296,6 +299,8 @@ func main() {
 				failf("Failed to unmarshal response body, error: %s, body: %s", err, string(body))
 			}
 
+			updateStepsStates(stepIDToStepStates, *responseModel)
+
 			finished = true
 			testsRunning := 0
 			for _, step := range responseModel.Steps {
@@ -319,20 +324,20 @@ func main() {
 			}
 
 			if finished {
-				log.Donef("=> Test finished")
+				log.TDonef("=> Test finished")
+				fmt.Println()
+
+				printStepsStates(stepIDToStepStates, time.Now(), os.Stdout)
 				fmt.Println()
 
-				log.Infof("Test results:")
+				log.TInfof("Test results:")
 				w := tabwriter.NewWriter(os.Stdout, 0, 0, 3, ' ', 0)
 				if _, err := fmt.Fprintln(w, "Model\tOS version\tOrientation\tLocale\tOutcome\t"); err != nil {
 					failf("Failed to write in writer")
 				}
 
 				for _, step := range responseModel.Steps {
-					dimensions := map[string]string{}
-					for _, dimension := range step.DimensionValue {
-						dimensions[dimension.Key] = dimension.Value
-					}
+					dimensions := createDimensions(*step)
 
 					outcome := step.Outcome.Summary
 
@@ -402,7 +407,7 @@ func main() {
 
 	if configs.DownloadTestResults == "true" {
 		fmt.Println()
-		log.Infof("Downloading test assets")
+		log.TInfof("Downloading test assets")
 		{
 			url := configs.APIBaseURL + "/assets/" + configs.AppSlug + "/" + configs.BuildSlug + "/" + configs.APIToken
 
@@ -443,7 +448,7 @@ func main() {
 				}
 			}
 
-			log.Donef("=> Assets downloaded")
+			log.TDonef("=> Assets downloaded")
 			if err := tools.ExportEnvironmentWithEnvman("VDTESTING_DOWNLOADED_FILES_DIR", tempDir); err != nil {
 				log.Warnf("Failed to export environment (VDTESTING_DOWNLOADED_FILES_DIR), error: %s", err)
 			} else {
@@ -549,3 +554,11 @@ func uploadFile(uploadURL string, archiveFilePath string) error {
 
 	return nil
 }
+
+func createDimensions(step toolresults.Step) map[string]string {
+	dimensions := map[string]string{}
+	for _, dimension := range step.DimensionValue {
+		dimensions[dimension.Key] = dimension.Value
+	}
+	return dimensions
+}

step_states.go

@@ -0,0 +1,100 @@
+package main
+
+import (
+	"fmt"
+	"io"
+	"sort"
+	"time"
+
+	toolresults "google.golang.org/api/toolresults/v1beta3"
+)
+
+type stepStates struct {
+	name             string
+	stateToStartTime map[string]time.Time
+}
+
+func newStepStates(step toolresults.Step) stepStates {
+	return stepStates{
+		name:             createStepNameWithDimensions(step),
+		stateToStartTime: map[string]time.Time{},
+	}
+}
+
+func (s *stepStates) saveState(state string, startTime time.Time) {
+	if _, ok := s.stateToStartTime[state]; ok {
+		return
+	}
+
+	// Haven't seen this state yet -> set state start time
+	s.stateToStartTime[state] = startTime
+}
+
+func (s *stepStates) print(currentTime time.Time, w io.Writer) {
+	if _, err := fmt.Fprintln(w, s.name); err != nil {
+		fmt.Printf("Failed to print step status durations: %s", err)
+		return
+	}
+
+	var states []string
+	for state := range s.stateToStartTime {
+		states = append(states, state)
+	}
+
+	sort.Slice(states, func(i, j int) bool {
+		stateI, stateJ := states[i], states[j]
+		startTimeI, startTimeJ := s.stateToStartTime[stateI], s.stateToStartTime[stateJ]
+
+		return startTimeI.Before(startTimeJ)
+	})
+
+	for i, state := range states {
+		startTime := s.stateToStartTime[state]
+
+		var endTime time.Time
+		if i == len(states)-1 {
+			endTime = currentTime
+		} else {
+			nextState := states[i+1]
+			endTime = s.stateToStartTime[nextState]
+		}
+
+		duration := endTime.Sub(startTime)
+
+		if _, err := fmt.Fprintf(w, "- time spent in %s state: ~%s\n", state, duration.Round(time.Second).String()); err != nil {
+			fmt.Printf("Failed to print step status durations: %s", err)
+			return
+		}
+	}
+}
+
+func createStepNameWithDimensions(step toolresults.Step) string {
+	dimensions := createDimensions(step)
+	return fmt.Sprintf("%s (%s %s %s %s)", step.Name, dimensions["Model"], dimensions["Version"], dimensions["Orientation"], dimensions["Locale"])
+}
+
+func updateStepsStates(stepIDtoStates map[string]stepStates, response toolresults.ListStepsResponse) {
+	for _, step := range response.Steps {
+		stepStates, ok := stepIDtoStates[step.StepId]
+		if !ok {
+			stepStates = newStepStates(*step)
+			stepIDtoStates[step.StepId] = stepStates
+		}
+
+		stepStates.saveState(step.State, time.Now())
+	}
+}
+
+func printStepsStates(stepIDtoStates map[string]stepStates, currentTime time.Time, w io.Writer) {
+	var stepIDs []string
+	for stepID := range stepIDtoStates {
+		stepIDs = append(stepIDs, stepID)
+	}
+
+	sort.Strings(stepIDs)
+
+	for _, stepID := range stepIDs {
+		stepState := stepIDtoStates[stepID]
+		stepState.print(currentTime, w)
+	}
+}

step_states_test.go

@@ -0,0 +1,61 @@
+package main
+
+import (
+	"bytes"
+	"testing"
+	"time"
+)
+
+func testRefTime() time.Time {
+	return time.Date(2022, 1, 1, 12, 30, 0, 0, time.UTC)
+}
+
+func Test_printStepsStates(t *testing.T) {
+	tests := []struct {
+		name               string
+		stepIDToStepStates map[string]stepStates
+		currentTime        time.Time
+	}{
+		{
+			name: "",
+			stepIDToStepStates: map[string]stepStates{
+				"ID_1": {
+					name: "iOS Tests",
+					stateToStartTime: map[string]time.Time{
+						"pending":    testRefTime(),
+						"inProgress": testRefTime().Add(60 * time.Second),
+						"complete":   testRefTime().Add(90 * time.Second),
+					},
+				},
+				"ID_2": {
+					name: "iOS Unit Tests",
+					stateToStartTime: map[string]time.Time{
+						"pending":    testRefTime(),
+						"inProgress": testRefTime().Add(40 * time.Second),
+						"complete":   testRefTime().Add(90 * time.Second),
+					},
+				},
+			},
+		},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			var b bytes.Buffer
+			printStepsStates(tt.stepIDToStepStates, testRefTime().Add(90*time.Second), &b)
+
+			actual := b.String()
+			expected := `iOS Tests
+- time spent in pending state: ~1m0s
+- time spent in inProgress state: ~30s
+- time spent in complete state: ~0s
+iOS Unit Tests
+- time spent in pending state: ~40s
+- time spent in inProgress state: ~50s
+- time spent in complete state: ~0s
+`
+			if actual != expected {
+				t.Fatalf("%s != %s", actual, expected)
+			}
+		})
+	}
+}