Hooks run out of order when there is an error

[Johnlon]

@vearutop would you mind double checking this.
BUG #650

It looks like we've written tests that assert what I consider as broken behaviour.

Specifically if there has been an error then the AfterScenario runs prematurely and then the step level hooks run for any remaining scenarios.

Is there any logic to this - looks plain wrong to me.
I expect strict nesting as described in the bug ticket.

[Johnlon]

Here is a test that I believe verifies the correct logical behaviour...

package godog

import (
	"context"
	"errors"
	"fmt"
	"regexp"
	"strings"
	"testing"

	"github.com/stretchr/testify/assert"
)

func TestTestSuite_RunJL(t *testing.T) {
	for _, tc := range []struct {
		name          string
		body          string
		afterStepCnt  int
		beforeStepCnt int
		log           string
		noStrict      bool
		suitePasses   bool
	}{
		{
			name: "fail_then_pass_fails_scenario", afterStepCnt: 2, beforeStepCnt: 2,
			body: `
					When step passes
					When not defined
					When step missing args
					Then step passes`,
			log: `
					>>>> Before suite
					>> Before scenario "test"
					Before step "step passes"
					<step action>
					After step "step passes", error: <nil>, status: passed
					Before step "not defined"
					After step "not defined", error: step is undefined, status: undefined
					Before step "step missing args"
					After step "step missing args", error: <nil>, status: skipped
					Before step "step passes"
					After step "step passes", error: <nil>, status: skipped
					<< After scenario "test", error: step is undefined
					<<<< After suite`,
		},
	} {
		t.Run(tc.name, func(t *testing.T) {
			afterScenarioCnt := 0
			beforeScenarioCnt := 0

			afterStepCnt := 0
			beforeStepCnt := 0

			var log string

			suite := TestSuite{
				TestSuiteInitializer: func(suiteContext *TestSuiteContext) {
					suiteContext.BeforeSuite(func() {
						log += fmt.Sprintln(">>>> Before suite")
					})

					suiteContext.AfterSuite(func() {
						log += fmt.Sprintln("<<<< After suite")
					})
				},
				ScenarioInitializer: func(s *ScenarioContext) {
					s.Before(func(ctx context.Context, sc *Scenario) (context.Context, error) {
						log += fmt.Sprintf(">> Before scenario %q\n", sc.Name)
						beforeScenarioCnt++

						return ctx, nil
					})

					s.After(func(ctx context.Context, sc *Scenario, err error) (context.Context, error) {
						log += fmt.Sprintf("<< After scenario %q, error: %v\n", sc.Name, err)
						afterScenarioCnt++

						return ctx, nil
					})

					s.StepContext().Before(func(ctx context.Context, st *Step) (context.Context, error) {
						log += fmt.Sprintf("Before step %q\n", st.Text)
						beforeStepCnt++

						return ctx, nil
					})

					s.StepContext().After(func(ctx context.Context, st *Step, status StepResultStatus, err error) (context.Context, error) {
						log += fmt.Sprintf("After step %q, error: %v, status: %s\n", st.Text, err, status.String())
						afterStepCnt++

						return ctx, nil
					})

					s.Step("^step fails$", func() error {
						return errors.New("oops")
					})

					s.Step("^step skips scenario$", func() error {
						return errors.New("oops")
					})

					s.Step("^step passes$", func() {
						log += "<step action>\n"
					})

					s.Step("^multistep passes$", func() Steps {
						return Steps{"step passes", "step passes"}
					})

					s.Step("pending", func() error {
						return ErrPending
					})

					s.Step("^step missing args$", func(missingArg string) {

					})

					s.Step("^step is ambiguous$", func() {
						log += "<step action>\n"
					})
					s.Step("^step is ambiguous$", func() {
						log += "<step action>\n"
					})
					s.Step("^multistep has ambiguous$", func() Steps {
						return Steps{"step is ambiguous"}
					})

				},		Options: &Options{
					Format:   "pretty",
					Strict:   !tc.noStrict,
					NoColors: true,
					FeatureContents: []Feature{
						{
							Name: tc.name,
							Contents: []byte(trimAllLines(`
								Feature: test
								Scenario: test
								` + tc.body)),
						},
					},
				},
			}

			suitePasses := suite.Run() == 0
			assert.Equal(t, tc.suitePasses, suitePasses)
			assert.Equal(t, 1, afterScenarioCnt)
			assert.Equal(t, 1, beforeScenarioCnt)
			assert.Equal(t, tc.afterStepCnt, afterStepCnt)
			assert.Equal(t, tc.beforeStepCnt, beforeStepCnt)
			assert.Equal(t, trimAllLines(tc.log), trimAllLines(log), log)
		
			CompareLines(trimAllLines(tc.log), trimAllLines(log))
		})
	}
}


// wrapString wraps a string into chunks of the given width.
func wrapString(s string, width int) []string {
	var result []string
	for len(s) > width {
		result = append(result, s[:width])
		s = s[width:]
	}
	result = append(result, s)
	return result
}

// CompareLines compares two lists of strings and prints them with wrapped text.
func CompareLines(expected, actual string) {
	tabRegex := regexp.MustCompile("\t")
	expected = string(tabRegex.ReplaceAll([]byte(expected), []byte("\\t")))
	actual = string(tabRegex.ReplaceAll([]byte(actual), []byte("\\t")))

	list1 := strings.Split(expected, "\n")
	list2 := strings.Split(actual, "\n")

	// Get the length of the longer list
	maxLength := len(list1)
	if len(list2) > maxLength {
		maxLength = len(list2)
	}

	colWid := 60
	fmtTitle := fmt.Sprintf("%%4s: %%-%ds | %%-%ds\n", colWid+2, colWid+2)
	fmtData := fmt.Sprintf("%%4d: %%-%ds | %%-%ds   %%s\n", colWid+2, colWid+2)

	fmt.Printf(fmtTitle, "#", "expected", "actual")

	for i := 0; i < maxLength; i++ {
		var val1, val2 string

		// Get the value from list1 if it exists
		if i < len(list1) {
			val1 = list1[i]
		} else {
			val1 = "N/A"
		}

		// Get the value from list2 if it exists
		if i < len(list2) {
			val2 = list2[i]
		} else {
			val2 = "N/A"
		}

		// Wrap both strings into slices of strings with fixed width
		wrapped1 := wrapString(val1, colWid)
		wrapped2 := wrapString(val2, colWid)

		// Find the number of wrapped lines needed for the current pair
		maxWrappedLines := len(wrapped1)
		if len(wrapped2) > maxWrappedLines {
			maxWrappedLines = len(wrapped2)
		}

		// Print the wrapped lines with alignment
		for j := 0; j < maxWrappedLines; j++ {
			var line1, line2 string

			// Get the wrapped line or use an empty string if it doesn't exist
			if j < len(wrapped1) {
				line1 = wrapped1[j]
			} else {
				line1 = ""
			}

			if j < len(wrapped2) {
				line2 = wrapped2[j]
			} else {
				line2 = ""
			}

			status := "same"
			// if val1 != val2 {
			if line1 != line2 {
				status = "different"
			}

			delim := "¬"
			// Print the wrapped lines with fixed-width column
			fmt.Printf(fmtData, i+1, delim+line1+delim, delim+line2+delim, status)
		}
	}
}

[nhv96]

I expanded your test case a little bit with another scenario test2 right after test, and it has steps that are expected to pass.
I found that the hooks for the test2 are running correctly, only the hook of test scenario is in wrong order.

   #: expected                                                       | actual
   1: ¬>>>> Before suite¬                                            | ¬>>>> Before suite¬                                              same
   2: ¬>> Before scenario "test1"¬                                   | ¬>> Before scenario "test1"¬                                     same
   3: ¬Before step "step passes"¬                                    | ¬Before step "step passes"¬                                      same
   4: ¬<step action>¬                                                | ¬<step action>¬                                                  same
   5: ¬After step "step passes", error: <nil>, status: passed¬       | ¬After step "step passes", error: <nil>, status: passed¬         same
   6: ¬Before step "not defined"¬                                    | ¬Before step "not defined"¬                                      same
   7: ¬After step "not defined", error: step is undefined, status: ¬ | ¬After step "not defined", error: step is undefined, status: ¬   same
   7: ¬undefined¬                                                    | ¬undefined¬                                                      same
   8: ¬Before step "step missing args"¬                              | ¬<< After scenario "test1", error: step is undefined¬            different
   9: ¬After step "step missing args", error: <nil>, status: skippe¬ | ¬Before step "step missing args"¬                                different
   9: ¬d¬                                                            | ¬¬                                                               different
  10: ¬Before step "step passes"¬                                    | ¬After step "step missing args", error: <nil>, status: skippe¬   different
  10: ¬¬                                                             | ¬d¬                                                              different
  11: ¬After step "step passes", error: <nil>, status: skipped¬      | ¬Before step "step passes"¬                                      different
  12: ¬<< After scenario "test1", error: step is undefined¬          | ¬After step "step passes", error: <nil>, status: skipped¬        different
  13: ¬>> Before scenario "test2"¬                                   | ¬>> Before scenario "test2"¬                                     same
  14: ¬Before step "step passes"¬                                    | ¬Before step "step passes"¬                                      same
  15: ¬<step action>¬                                                | ¬<step action>¬                                                  same
  16: ¬After step "step passes", error: <nil>, status: passed¬       | ¬After step "step passes", error: <nil>, status: passed¬         same
  17: ¬Before step "step passes"¬                                    | ¬Before step "step passes"¬                                      same
  18: ¬<step action>¬                                                | ¬<step action>¬                                                  same
  19: ¬After step "step passes", error: <nil>, status: passed¬       | ¬After step "step passes", error: <nil>, status: passed¬         same
  20: ¬<< After scenario "test2", error: <nil>¬                      | ¬<< After scenario "test2", error: <nil>¬                        same
  21: ¬<<<< After suite¬                                             | ¬<<<< After suite¬                                               same
--- FAIL: TestTestSuite_RunJL (0.00s)
    --- FAIL: TestTestSuite_RunJL/fail_then_pass_fails_scenario (0.00s)

and with this defer function return early when there's a scenarioErr, I believe this is by design, since right after the step not defined is detected, scenarioErr is not yet returned with error, and shouldFail or s.shouldFail(err) is valid with local variable err = ErrUndefined, so it trigger the condition.

// Trigger after scenario on failing or last step to attach possible hook error to step.
f !s.shouldFail(scenarioErr) && (isLast || shouldFail) {
	rctx, err = s.runAfterScenarioHooks(rctx, pickle, err)
}

[Johnlon]

With my present understanding that line "f !s.shouldFail(scenarioErr) && (isLast || shouldFail) {" is a causing the bug

It cannot make sense as a design that AfterScenario runs before the steps have run to completion.

[nhv96]

I see, should this be fixed, I think we should refactor that piece of logic so that it is easier to read and maintain. IMO we can move the before/after hooks to the outer loop of each step to make the code more straightforward, something like this

for i, step := range steps {
        isLast := i == len(steps)-1
        isFirst := i == 0
        if isFirst {
                s.runBeforeScenarioHooks(ctx, pickle)
                if err != nil {
                }
        }
        
        err = s.runBeforeStepHooks(ctx, step, err)
        ....
        err = s.runStep(ctx, pickle, step, scenarioErr, isFirst, isLast)
        ....
        err = s.runAfterStepHooks(ctx, step, status, err)
        ....
        err = s.runAfterScenarioHooks(rctx, pickle, err)
}

what do you think?

[Johnlon]

agree it's more like the cuke jvm that way.
I did make an edit like that but ...

I have a big edit on the go for this that includes a refresh the tests , as when I made a fix I found working with the existing tests was more challenging that it needed to be.

could you leave it with me for a bit

thanks

hopefully a PR this week

[Johnlon]

thanks for confirming

[nhv96]

I see, thank you very much.

[vearutop]

Good catch, I think there is no reasonable justification for current behavior, it is just an overlook or an implementation shortcut. Please feel free to fix this (or maybe I'll try once I have some time).

[Johnlon]

hi thanks. please leave it with me for a bit. I'm renovating the tests at the moment in prep to make that change and also dryrun which I need. John

…

On Thu, 24 Oct 2024, 12:00 pm Viacheslav Poturaev, ***@***.***> wrote: Good catch, I think there is no reasonable justification for current behavior, it is just an overlook or an implementation shortcut. Please feel free to fix this (or maybe I'll try once I have some time). — Reply to this email directly, view it on GitHub <#651 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAGMFGFBRC5MTWMWZ4MCBOTZ5DHODAVCNFSM6AAAAABQH6Q6PGVHI2DSMVQWIX3LMV43URDJONRXK43TNFXW4Q3PNVWWK3TUHMYTCMBTHE3TKMI> . You are receiving this because you authored the thread.Message ID: ***@***.***>

[Johnlon]

@vearutop
@nhv96

OK this is NOT the fix for the above problem but it's my first push of the renovation work as part of that fix.
This can be merged independently.

There are api changes.

• formatters.Formatter now carries Close() - which causes a lot of the changes.
• godog.TestSuite has additional method RunWitResults()

See : #659

This took a lot of disentanlging. Sadly suite_context_test was anoverhaul; as it wasn't really testing godog at all really but some kind of simulation of it. Eg take a look at 'iRunFeatureSuiteWithTagsAndFormatter' on trunk << that isn't godog being tested, and all the event stuff in that routine isn't right either. Many of the tests were overly complex with interdependencies between feature files that except for a few cases did nothing but make things more complex. (still work to be done there)

Anyway please take look.

Anyway - there is still redundancy in the tests - I removed it but put it back as this is big enough already.

[nhv96]

I'm trying to run the make test but got this error from staticcheck

$ make checks
check godog
go fmt ./...
go run honnef.co/go/tools/cmd/staticcheck@v0.5.1 ./...
go: honnef.co/go/tools/cmd/staticcheck@v0.5.1 (in honnef.co/go/tools@v0.5.1): go.mod:3: invalid go version '1.22.1': must match format 1.23
make: *** [Makefile:28: checks] Error 1

I'm using go1.19, it seems that I need to use the latest go version to run this branch right?

[Johnlon]

should be 1.16

not sure what going on there.
did I commit something I didn't intend to?

ah I upgraded honnef from 0.4.1 I think as it was crashing. will revert I guess

my local install is 1.22