refactor: log step start time and elapsed(ms)

hrp/internal/version/VERSION

@@ -1 +1 @@
-v5.0.0+2411100026
+v5.0.0+2411101040

hrp/pkg/uixt/action.go

@@ -82,6 +82,7 @@ func (ma MobileAction) GetOptions() []ActionOption {
 	var actionOptionList []ActionOption
 	if ma.Options != nil {
 		actionOptionList = append(actionOptionList, ma.Options.Options()...)
+		return actionOptionList
 	}
 	actionOptionList = append(actionOptionList, ma.ActionOptions.Options()...)
 	return actionOptionList

hrp/runner.go

@@ -559,72 +559,10 @@ func (r *SessionRunner) Start(givenVars map[string]interface{}) (summary *TestCa
 			log.Warn().Msg("interrupted in session runner")
 			return summary, errors.Wrap(code.InterruptError, "session runner interrupted")
 		default:
-			// parse step struct
-			err = r.parseStepStruct(step)
-			if err != nil {
-				log.Error().Err(err).Msg("parse step struct failed")
-				if r.caseRunner.hrpRunner.failfast {
-					return summary, errors.Wrap(err, "parse step struct failed")
-				}
-			}
-
-			stepName := step.Name()
-			stepType := string(step.Type())
-			log.Info().Str("step", stepName).Str("type", stepType).Msg("run step start")
-			stepStartTime := time.Now()
-
-			// run times of step
-			loopTimes := step.Config().Loops
-			if loopTimes < 0 {
-				log.Warn().Int("loops", loopTimes).Msg("loop times should be positive, set to 1")
-				loopTimes = 1
-			} else if loopTimes == 0 {
-				loopTimes = 1
-			} else if loopTimes > 1 {
-				log.Info().Int("loops", loopTimes).Msg("run step with specified loop times")
-			}
-
-			// run step with specified loop times
-			var stepResult *StepResult
-			for i := 1; i <= loopTimes; i++ {
-				var loopIndex string
-				if loopTimes > 1 {
-					log.Info().Int("index", i).Msg("start running step in loop")
-					loopIndex = fmt.Sprintf("_loop_%d", i)
-				}
-
-				// run step
-				startTime := time.Now().Unix()
-				stepResult, err = step.Run(r)
-				stepResult.Name = stepName + loopIndex
-				stepResult.StartTime = startTime
-
-				r.summary.AddStepResult(stepResult)
-			}
-
-			// update extracted variables
-			for k, v := range stepResult.ExportVars {
-				r.sessionVariables[k] = v
-			}
-
-			stepElapsed := time.Since(stepStartTime).Milliseconds()
+			_, err := r.RunStep(step)
 			if err == nil {
-				log.Info().Str("step", stepName).
-					Str("type", stepType).
-					Bool("success", true).
-					Int64("elapsed(ms)", stepElapsed).
-					Interface("exportVars", stepResult.ExportVars).
-					Msg("run step end")
 				continue
 			}
-
-			// failed
-			log.Error().Err(err).Str("step", stepName).
-				Str("type", stepType).
-				Bool("success", false).
-				Int64("elapsed(ms)", stepElapsed).
-				Msg("run step end")
-
 			// interrupted or timeout, abort running
 			if errors.Is(err, code.InterruptError) || errors.Is(err, code.TimeoutError) {
 				return summary, err
@@ -641,6 +579,72 @@ func (r *SessionRunner) Start(givenVars map[string]interface{}) (summary *TestCa
 	return summary, nil
 }
 
+func (r *SessionRunner) RunStep(step IStep) (stepResult *StepResult, err error) {
+	// parse step struct
+	if err = r.parseStepStruct(step); err != nil {
+		log.Error().Err(err).Msg("parse step struct failed")
+		if r.caseRunner.hrpRunner.failfast {
+			return nil, errors.Wrap(err, "parse step struct failed")
+		}
+	}
+
+	stepName := step.Name()
+	stepType := string(step.Type())
+	log.Info().Str("step", stepName).Str("type", stepType).Msg("run step start")
+
+	// run times of step
+	loopTimes := step.Config().Loops
+	if loopTimes < 0 {
+		log.Warn().Int("loops", loopTimes).Msg("loop times should be positive, set to 1")
+		loopTimes = 1
+	} else if loopTimes == 0 {
+		loopTimes = 1
+	} else if loopTimes > 1 {
+		log.Info().Int("loops", loopTimes).Msg("run step with specified loop times")
+	}
+
+	// run step with specified loop times
+	for i := 1; i <= loopTimes; i++ {
+		var loopIndex string
+		if loopTimes > 1 {
+			log.Info().Int("index", i).Msg("start running step in loop")
+			loopIndex = fmt.Sprintf("_loop_%d", i)
+		}
+
+		// run step
+		stepResult, err = step.Run(r)
+		stepResult.Name = stepName + loopIndex
+
+		// add step result to summary
+		r.summary.AddStepResult(stepResult)
+
+		// update extracted variables
+		for k, v := range stepResult.ExportVars {
+			r.sessionVariables[k] = v
+		}
+
+		// run step success
+		if err == nil {
+			log.Info().Str("step", stepName).
+				Str("type", stepType).
+				Bool("success", true).
+				Int64("elapsed(ms)", stepResult.Elapsed).
+				Interface("exportVars", stepResult.ExportVars).
+				Msg("run step end")
+			continue
+		}
+		// run step failed
+		log.Error().Err(err).Str("step", stepName).
+			Str("type", stepType).
+			Bool("success", false).
+			Int64("elapsed(ms)", stepResult.Elapsed).
+			Msg("run step end")
+		return stepResult, err
+	}
+
+	return stepResult, nil
+}
+
 func (r *SessionRunner) parseStepStruct(step IStep) error {
 	caseConfig := r.caseRunner.TestCase.Config.Get()
 	stepConfig := step.Config()

hrp/step_mobile_ui.go

@@ -3,6 +3,7 @@ package hrp
 import (
 	"fmt"
 	"strings"
+	"time"
 
 	"github.com/pkg/errors"
 	"github.com/rs/zerolog/log"
@@ -654,6 +655,13 @@ func runStepMobileUI(s *SessionRunner, step IStep) (stepResult *StepResult, err
 		"osType": mobileStep.OSType,
 	})
 
+	// init wda/uia/hdc driver
+	caseConfig := s.caseRunner.TestCase.Config.Get()
+	uiDriver, err := initUIClient(mobileStep.Serial, mobileStep.OSType, caseConfig)
+	if err != nil {
+		return
+	}
+
 	identifier := mobileStep.Identifier
 	if mobileStep.Options != nil && identifier == "" {
 		identifier = mobileStep.Options.Identifier
@@ -667,19 +675,14 @@ func runStepMobileUI(s *SessionRunner, step IStep) (stepResult *StepResult, err
 		}
 	}
 
+	start := time.Now()
 	stepResult = &StepResult{
 		Name:        step.Name(),
 		Identifier:  identifier,
 		StepType:    step.Type(),
 		Success:     false,
 		ContentSize: 0,
-	}
-
-	// init wda/uia/hdc driver
-	caseConfig := s.caseRunner.TestCase.Config.Get()
-	uiDriver, err := initUIClient(mobileStep.Serial, mobileStep.OSType, caseConfig)
-	if err != nil {
-		return
+		StartTime:   start.Unix(),
 	}
 
 	defer func() {
@@ -708,6 +711,7 @@ func runStepMobileUI(s *SessionRunner, step IStep) (stepResult *StepResult, err
 			attachments[key] = value
 		}
 		stepResult.Attachments = attachments
+		stepResult.Elapsed = time.Since(start).Milliseconds()
 	}()
 
 	// prepare actions

hrp/step_request.go

@@ -278,14 +278,17 @@ func prepareUpload(parser *Parser, stepRequest *StepRequest, stepVariables map[s
 
 func runStepRequest(r *SessionRunner, step IStep) (stepResult *StepResult, err error) {
 	stepRequest := step.(*StepRequestWithOptionalArgs)
+	start := time.Now()
 	stepResult = &StepResult{
 		Name:        stepRequest.StepName,
 		StepType:    stepTypeRequest,
 		Success:     false,
 		ContentSize: 0,
+		StartTime:   start.Unix(),
 	}
 
 	defer func() {
+		stepResult.Elapsed = time.Since(start).Milliseconds()
 		// update testcase summary
 		if err != nil {
 			stepResult.Attachments = err.Error()
@@ -360,7 +363,6 @@ func runStepRequest(r *SessionRunner, step IStep) (stepResult *StepResult, err e
 	}
 
 	// do request action
-	start := time.Now()
 	resp, err := client.Do(rb.req)
 	if err != nil {
 		return stepResult, errors.Wrap(err, "do request failed")
@@ -390,7 +392,6 @@ func runStepRequest(r *SessionRunner, step IStep) (stepResult *StepResult, err e
 		return
 	}
 
-	stepResult.Elapsed = time.Since(start).Milliseconds()
 	if r.caseRunner.hrpRunner.httpStatOn {
 		// resp.Body has been ReadAll
 		httpStat.Finish()

hrp/step_shell.go

@@ -95,22 +95,24 @@ func runStepShell(r *SessionRunner, step IStep) (stepResult *StepResult, err err
 		Str("content", shell.String).
 		Msg("run shell string")
 
+	start := time.Now()
 	stepResult = &StepResult{
 		Name:        step.Name(),
 		StepType:    stepTypeShell,
 		Success:     false,
-		Elapsed:     0,
 		ContentSize: 0,
+		StartTime:   start.Unix(),
 	}
+	defer func() {
+		stepResult.Elapsed = time.Since(start).Milliseconds()
+	}()
 
 	vars := r.caseRunner.Config.Get().Variables
 	for key, value := range vars {
 		os.Setenv(key, fmt.Sprintf("%v", value))
 	}
 
-	start := time.Now()
 	exitCode, err := myexec.RunShell(shell.String)
-	stepResult.Elapsed = time.Since(start).Milliseconds()
 	if err != nil {
 		if exitCode == shell.ExpectExitCode {
 			// get expected error

hrp/step_testcase.go

@@ -46,10 +46,12 @@ func (s *StepTestCaseWithOptionalArgs) Config() *StepConfig {
 }
 
 func (s *StepTestCaseWithOptionalArgs) Run(r *SessionRunner) (stepResult *StepResult, err error) {
+	start := time.Now()
 	stepResult = &StepResult{
-		Name:     s.StepName,
-		StepType: stepTypeTestCase,
-		Success:  false,
+		Name:      s.StepName,
+		StepType:  stepTypeTestCase,
+		Success:   false,
+		StartTime: start.Unix(),
 	}
 
 	defer func() {
@@ -57,6 +59,7 @@ func (s *StepTestCaseWithOptionalArgs) Run(r *SessionRunner) (stepResult *StepRe
 		if err != nil {
 			stepResult.Attachments = err.Error()
 		}
+		stepResult.Elapsed = time.Since(start).Milliseconds()
 	}()
 
 	stepTestCase := s.TestCase.(*TestCase)
@@ -84,11 +87,9 @@ func (s *StepTestCaseWithOptionalArgs) Run(r *SessionRunner) (stepResult *StepRe
 	}
 	sessionRunner := caseRunner.NewSession()
 
-	start := time.Now()
 	var summary *TestCaseSummary
 	// run referenced testcase with step variables
 	summary, err = sessionRunner.Start(s.Variables)
-	stepResult.Elapsed = time.Since(start).Milliseconds()
 
 	// update step names
 	for _, record := range summary.Records {

hrp/step_websocket.go

@@ -273,11 +273,13 @@ func runStepWebSocket(r *SessionRunner, step IStep) (stepResult *StepResult, err
 	stepWebSocket := step.(*StepWebSocket)
 	webSocket := stepWebSocket.WebSocket
 	variables := stepWebSocket.Variables
+	start := time.Now()
 	stepResult = &StepResult{
 		Name:        step.Name(),
 		StepType:    stepTypeWebSocket,
 		Success:     false,
 		ContentSize: 0,
+		StartTime:   start.Unix(),
 	}
 
 	defer func() {
@@ -285,6 +287,7 @@ func runStepWebSocket(r *SessionRunner, step IStep) (stepResult *StepResult, err
 		if err != nil {
 			stepResult.Attachments = err.Error()
 		}
+		stepResult.Elapsed = time.Since(start).Milliseconds()
 	}()
 
 	sessionData := newSessionData()
@@ -323,7 +326,6 @@ func runStepWebSocket(r *SessionRunner, step IStep) (stepResult *StepResult, err
 	}
 
 	var resp interface{}
-	start := time.Now()
 
 	// do websocket action
 	if r.caseRunner.hrpRunner.requestsLogOn {
@@ -396,7 +398,6 @@ func runStepWebSocket(r *SessionRunner, step IStep) (stepResult *StepResult, err
 		}
 	}
 
-	stepResult.Elapsed = time.Since(start).Milliseconds()
 	respObj, err := getResponseObject(r.caseRunner.hrpRunner.t, r.caseRunner.parser, resp)
 	if err != nil {
 		err = errors.Wrap(err, "get response object error")