Add logs for debugging

main.go

@@ -10,6 +10,7 @@ import (
 	"net/http"
 	"os"
 	"path/filepath"
+	"sort"
 	"strconv"
 	"strings"
 	"text/tabwriter"
@@ -69,8 +70,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 +146,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 +184,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 +257,18 @@ 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{}
+
+		stepsToStartTime := map[string]map[string]time.Time{}
+		stepsToNames := map[string]string{}
+
 		for !finished {
 			url := configs.APIBaseURL + "/" + configs.AppSlug + "/" + configs.BuildSlug + "/" + configs.APIToken
 
@@ -296,6 +301,8 @@ func main() {
 				failf("Failed to unmarshal response body, error: %s, body: %s", err, string(body))
 			}
 
+			updateStepsStatesToStartTime(stepsToStartTime, stepsToNames, *responseModel)
+
 			finished = true
 			testsRunning := 0
 			for _, step := range responseModel.Steps {
@@ -319,20 +326,20 @@ func main() {
 			}
 
 			if finished {
-				log.Donef("=> Test finished")
+				log.TDonef("=> Test finished")
+				fmt.Println()
+
+				printStepsStatesToStartTime(stepsToStartTime, stepsToNames, 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 +409,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 +450,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 +556,88 @@ 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
+}
+
+func printStepsStatesToStartTime(stepsStatesToStartTime map[string]map[string]time.Time, stepsToNames map[string]string, currentTime time.Time, w io.Writer) {
+	var stepIDs []string
+	for stepID := range stepsToNames {
+		stepIDs = append(stepIDs, stepID)
+	}
+
+	sort.Strings(stepIDs)
+
+	for _, stepID := range stepIDs {
+		stepName := stepsToNames[stepID]
+		if _, err := fmt.Fprintln(w, stepName); err != nil {
+			fmt.Printf("Failed to print step status durations: %s", err)
+			return
+		}
+
+		statesToStartTime := stepsStatesToStartTime[stepID]
+
+		var states []string
+		for state := range statesToStartTime {
+			states = append(states, state)
+		}
+
+		sort.Slice(states, func(i, j int) bool {
+			stateI, stateJ := states[i], states[j]
+			startTimeI, startTimeJ := statesToStartTime[stateI], statesToStartTime[stateJ]
+
+			return startTimeI.Before(startTimeJ)
+		})
+
+		for i, state := range states {
+			startTime := statesToStartTime[state]
+
+			var endTime time.Time
+			if i == len(states)-1 {
+				endTime = currentTime
+			} else {
+				nextState := states[i+1]
+				endTime = statesToStartTime[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 updateStepsStatesToStartTime(stepsStatesToStartTime map[string]map[string]time.Time, stepsToNames map[string]string, response toolresults.ListStepsResponse) {
+	for _, step := range response.Steps {
+		_, ok := stepsToNames[step.StepId]
+		if !ok {
+			stepsToNames[step.StepId] = createStepNameWithDimensions(*step)
+		}
+
+		statesToStartTime, ok := stepsStatesToStartTime[step.StepId]
+		if !ok {
+			// Haven't seen this step yet
+			statesToStartTime = map[string]time.Time{}
+			stepsStatesToStartTime[step.StepId] = statesToStartTime
+		}
+
+		_, ok = statesToStartTime[step.State]
+		if !ok {
+			// Haven't seen this state yet -> set state start time
+			statesToStartTime[step.State] = time.Now()
+		}
+	}
+}

main_test.go

@@ -0,0 +1,60 @@
+package main
+
+import (
+	"bytes"
+	"testing"
+	"time"
+)
+
+func testRefTime() time.Time {
+	return time.Date(2022, 1, 1, 12, 30, 0, 0, time.UTC)
+}
+
+func Test_printStepsStatesToStartTime(t *testing.T) {
+	tests := []struct {
+		name                   string
+		stepsStatesToStartTime map[string]map[string]time.Time
+		stepsToNames           map[string]string
+		currentTime            time.Time
+	}{
+		{
+			name: "",
+			stepsStatesToStartTime: map[string]map[string]time.Time{
+				"ID_1": {
+					"pending":    testRefTime(),
+					"inProgress": testRefTime().Add(60 * time.Second),
+					"complete":   testRefTime().Add(90 * time.Second),
+				},
+				"ID_2": {
+					"pending":    testRefTime(),
+					"inProgress": testRefTime().Add(40 * time.Second),
+					"complete":   testRefTime().Add(90 * time.Second),
+				},
+			},
+			stepsToNames: map[string]string{
+				"ID_1": "iOS Tests",
+				"ID_2": "iOS Unit Tests",
+			},
+		},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			var b bytes.Buffer
+			printStepsStatesToStartTime(tt.stepsStatesToStartTime, tt.stepsToNames, 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)
+			}
+		})
+	}
+}