change: move step logs to session runner

hrp/response.go

@@ -173,13 +173,13 @@ func (v *responseObject) Validate(iValidators []interface{}, variablesMapping ma
 			Msgf("validate %s", checkItem)
 		if !result {
 			v.t.Fail()
-			return errors.New(fmt.Sprintf(
+			log.Error().
-				"do assertion failed, checkExpr: %v, assertMethod: %v, checkValue: %v, expectValue: %v",
+				Str("checkExpr", validator.Check).
-				validator.Check,
+				Str("assertMethod", assertMethod).
-				assertMethod,
+				Interface("checkValue", checkValue).
-				checkValue,
+				Interface("expectValue", expectValue).
-				expectValue,
+				Msg("assert failed")
-			))
+			return errors.New("step validation failed")
 		}
 	}
 	return nil

hrp/session.go

@@ -69,24 +69,44 @@ func (r *SessionRunner) Start() error {
 	r.startTime = time.Now()
 	// run step in sequential order
 	for _, step := range r.testCase.TestSteps {
-		_, err := step.Run(r)
+		log.Info().Str("step", step.Name()).
+			Str("type", string(step.Type())).Msg("run step start")
+
+		stepResult, err := step.Run(r)
 		if err != nil && r.hrpRunner.failfast {
+			log.Error().
+				Str("step", stepResult.Name).
+				Str("type", string(stepResult.StepType)).
+				Bool("success", false).
+				Msg("run step end")
 			return errors.Wrap(err, "abort running due to failfast setting")
 		}
+
+		// update extracted variables
+		r.updateSession(stepResult.ExportVars)
+		// update testcase summary
+		r.updateSummary(stepResult)
+
+		log.Info().
+			Str("step", stepResult.Name).
+			Str("type", string(stepResult.StepType)).
+			Bool("success", stepResult.Success).
+			Interface("exportVars", stepResult.ExportVars).
+			Msg("run step end")
 	}
 
 	log.Info().Str("testcase", config.Name).Msg("run testcase end")
 	return nil
 }
 
-func (r *SessionRunner) UpdateSession(vars map[string]interface{}) {
+func (r *SessionRunner) updateSession(vars map[string]interface{}) {
 	for k, v := range vars {
 		r.sessionVariables[k] = v
 	}
 }
 
-// UpdateSummary appends step result to summary
+// updateSummary appends step result to summary
-func (r *SessionRunner) UpdateSummary(stepResult *StepResult) {
+func (r *SessionRunner) updateSummary(stepResult *StepResult) {
 	r.summary.Records = append(r.summary.Records, stepResult)
 	r.summary.Stat.Total += 1
 	if stepResult.Success {

hrp/step_api.go

@@ -3,8 +3,6 @@ package hrp
 import (
 	"fmt"
 
-	"github.com/rs/zerolog/log"
-
 	"github.com/httprunner/httprunner/hrp/internal/builtin"
 )
 
@@ -93,8 +91,6 @@ func (s *StepAPIWithOptionalArgs) Struct() *TStep {
 }
 
 func (s *StepAPIWithOptionalArgs) Run(r *SessionRunner) (*StepResult, error) {
-	log.Info().Str("api", s.step.Name).Msg("run referenced api")
-
 	// extend request with referenced API
 	api, _ := s.step.API.(*API)
 	extendWithAPI(s.step, api)

hrp/step_request.go

@@ -243,8 +243,6 @@ func (r *requestBuilder) prepareBody(stepVariables map[string]interface{}) error
 }
 
 func runStepRequest(r *SessionRunner, step *TStep) (stepResult *StepResult, err error) {
-	log.Info().Str("step", step.Name).Msg("run step start")
-
 	stepResult = &StepResult{
 		Name:        step.Name,
 		StepType:    stepTypeRequest,
@@ -255,18 +253,8 @@ func runStepRequest(r *SessionRunner, step *TStep) (stepResult *StepResult, err
 	defer func() {
 		// update testcase summary
 		if err != nil {
-			log.Error().Err(err).Msg("run request step failed")
 			stepResult.Attachment = err.Error()
-		} else {
-			// update extracted variables
-			r.UpdateSession(stepResult.ExportVars)
-			log.Info().
-				Str("step", step.Name).
-				Bool("success", stepResult.Success).
-				Interface("exportVars", stepResult.ExportVars).
-				Msg("run step end")
 		}
-		r.UpdateSummary(stepResult)
 	}()
 
 	sessionData := newSessionData()

hrp/step_testcase.go

@@ -50,7 +50,6 @@ func (s *StepTestCaseWithOptionalArgs) Run(r *SessionRunner) (*StepResult, error
 	}
 	s.step.Variables = stepVariables
 
-	log.Info().Str("testcase", s.step.Name).Msg("run referenced testcase")
 	stepResult := &StepResult{
 		Name:     s.step.Name,
 		StepType: stepTypeTestCase,
@@ -73,8 +72,6 @@ func (s *StepTestCaseWithOptionalArgs) Run(r *SessionRunner) (*StepResult, error
 	err = sessionRunner.Start()
 	stepResult.Elapsed = time.Since(start).Milliseconds()
 	if err != nil {
-		log.Error().Err(err).Msg("run referenced testcase step failed")
-		log.Info().Str("step", s.step.Name).Bool("success", false).Msg("run step end")
 		stepResult.Attachment = err.Error()
 		r.summary.Success = false
 		return stepResult, err
@@ -96,12 +93,6 @@ func (s *StepTestCaseWithOptionalArgs) Run(r *SessionRunner) (*StepResult, error
 	r.summary.Stat.Successes += summary.Stat.Successes
 	r.summary.Stat.Failures += summary.Stat.Failures
 
-	log.Info().
-		Str("step", s.step.Name).
-		Bool("success", true).
-		Interface("exportVars", stepResult.ExportVars).
-		Msg("run step end")
-
 	return stepResult, nil
 }
 

hrp/step_thinktime.go

@@ -30,8 +30,7 @@ func (s *StepThinkTime) Struct() *TStep {
 
 func (s *StepThinkTime) Run(r *SessionRunner) (*StepResult, error) {
 	thinkTime := s.step.ThinkTime
-	log.Info().Str("name", s.step.Name).
+	log.Info().Float64("time", thinkTime.Time).Msg("think time")
-		Float64("time", thinkTime.Time).Msg("think time")
 
 	stepResult := &StepResult{
 		Name:     s.step.Name,