fix(formatter): On concurrent execution, execute formatter at end of Scenario (#645)

* fix(formatter): add onflush logger only print output at end of scenario when running concurrently

* add to changelog

* fix tests

* fix scenario outline output for the Pretty formatter

* fix casing for linter

* add coverage for new storage function

* relate suite back to where it was originally

* better type assertion on flush log

* var name for asserted formatter that doesn't clash with stdlib's fmt

* add coverage to summary

* only defer flush func when running concurrently

* much more concise way of deferring the flush

---------

Co-authored-by: Viacheslav Poturaev <[email protected]>

Author: tigh-latte

CHANGELOG.md

@@ -8,6 +8,8 @@ This document is formatted according to the principles of [Keep A CHANGELOG](htt
 
 ## Unreleased
 
+- fix(formatter): On concurrent execution, execute formatter at end of Scenario - ([645](https://github.com/cucumber/godog/pull/645) - [tigh-latte](https://github.com/tigh-latte))
+
 ## [v0.15.0]
 
 ### Added
@@ -39,7 +41,7 @@ This document is formatted according to the principles of [Keep A CHANGELOG](htt
 
 ### Changed
 - Update test.yml ([583](https://github.com/cucumber/godog/pull/583) - [vearutop](https://github.com/vearutop))
-  
+
 ## [v0.13.0]
 ### Added
 - Support for reading feature files from an `fs.FS` ([550](https://github.com/cucumber/godog/pull/550) - [tigh-latte](https://github.com/tigh-latte))

formatters/fmt.go

@@ -74,6 +74,12 @@ type Formatter interface {
 	Summary()
 }
 
+// FlushFormatter is a `Formatter` but can be flushed.
+type FlushFormatter interface {
+	Formatter
+	Flush()
+}
+
 // FormatterFunc builds a formatter with given
 // suite name and io.Writer to record output
 type FormatterFunc func(string, io.Writer) Formatter

internal/formatters/fmt_flushwrap.go

@@ -0,0 +1,108 @@
+package formatters
+
+import (
+	"sync"
+
+	"github.com/cucumber/godog/formatters"
+	messages "github.com/cucumber/messages/go/v21"
+)
+
+// WrapOnFlush wrap a `formatters.Formatter` in a `formatters.FlushFormatter`, which only
+// executes when `Flush` is called
+func WrapOnFlush(fmt formatters.Formatter) formatters.FlushFormatter {
+	return &onFlushFormatter{
+		fmt: fmt,
+		fns: make([]func(), 0),
+		mu:  &sync.Mutex{},
+	}
+}
+
+type onFlushFormatter struct {
+	fmt formatters.Formatter
+	fns []func()
+	mu  *sync.Mutex
+}
+
+func (o *onFlushFormatter) Pickle(pickle *messages.Pickle) {
+	o.fns = append(o.fns, func() {
+		o.fmt.Pickle(pickle)
+	})
+}
+
+func (o *onFlushFormatter) Passed(pickle *messages.Pickle, step *messages.PickleStep, definition *formatters.StepDefinition) {
+	o.fns = append(o.fns, func() {
+		o.fmt.Passed(pickle, step, definition)
+	})
+}
+
+// Ambiguous implements formatters.Formatter.
+func (o *onFlushFormatter) Ambiguous(pickle *messages.Pickle, step *messages.PickleStep, definition *formatters.StepDefinition, err error) {
+	o.fns = append(o.fns, func() {
+		o.fmt.Ambiguous(pickle, step, definition, err)
+	})
+}
+
+// Defined implements formatters.Formatter.
+func (o *onFlushFormatter) Defined(pickle *messages.Pickle, step *messages.PickleStep, definition *formatters.StepDefinition) {
+	o.fns = append(o.fns, func() {
+		o.fmt.Defined(pickle, step, definition)
+	})
+}
+
+// Failed implements formatters.Formatter.
+func (o *onFlushFormatter) Failed(pickle *messages.Pickle, step *messages.PickleStep, definition *formatters.StepDefinition, err error) {
+	o.fns = append(o.fns, func() {
+		o.fmt.Failed(pickle, step, definition, err)
+	})
+}
+
+// Feature implements formatters.Formatter.
+func (o *onFlushFormatter) Feature(pickle *messages.GherkinDocument, p string, c []byte) {
+	o.fns = append(o.fns, func() {
+		o.fmt.Feature(pickle, p, c)
+	})
+}
+
+// Pending implements formatters.Formatter.
+func (o *onFlushFormatter) Pending(pickle *messages.Pickle, step *messages.PickleStep, definition *formatters.StepDefinition) {
+	o.fns = append(o.fns, func() {
+		o.fmt.Pending(pickle, step, definition)
+	})
+}
+
+// Skipped implements formatters.Formatter.
+func (o *onFlushFormatter) Skipped(pickle *messages.Pickle, step *messages.PickleStep, definition *formatters.StepDefinition) {
+	o.fns = append(o.fns, func() {
+		o.fmt.Skipped(pickle, step, definition)
+	})
+}
+
+// Summary implements formatters.Formatter.
+func (o *onFlushFormatter) Summary() {
+	o.fns = append(o.fns, func() {
+		o.fmt.Summary()
+	})
+}
+
+// TestRunStarted implements formatters.Formatter.
+func (o *onFlushFormatter) TestRunStarted() {
+	o.fns = append(o.fns, func() {
+		o.fmt.TestRunStarted()
+	})
+}
+
+// Undefined implements formatters.Formatter.
+func (o *onFlushFormatter) Undefined(pickle *messages.Pickle, step *messages.PickleStep, definition *formatters.StepDefinition) {
+	o.fns = append(o.fns, func() {
+		o.fmt.Undefined(pickle, step, definition)
+	})
+}
+
+// Flush the logs.
+func (o *onFlushFormatter) Flush() {
+	o.mu.Lock()
+	defer o.mu.Unlock()
+	for _, fn := range o.fns {
+		fn()
+	}
+}

internal/formatters/fmt_flushwrap_test.go

@@ -0,0 +1,53 @@
+package formatters
+
+import (
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+var flushMock = DummyFormatter{}
+
+func TestFlushWrapOnFormatter(t *testing.T) {
+	flushMock.tt = t
+
+	fmt := WrapOnFlush(&flushMock)
+
+	fmt.Feature(document, str, byt)
+	fmt.TestRunStarted()
+	fmt.Pickle(pickle)
+	fmt.Defined(pickle, step, definition)
+	fmt.Passed(pickle, step, definition)
+	fmt.Skipped(pickle, step, definition)
+	fmt.Undefined(pickle, step, definition)
+	fmt.Failed(pickle, step, definition, err)
+	fmt.Pending(pickle, step, definition)
+	fmt.Ambiguous(pickle, step, definition, err)
+	fmt.Summary()
+
+	assert.Equal(t, 0, flushMock.CountFeature)
+	assert.Equal(t, 0, flushMock.CountTestRunStarted)
+	assert.Equal(t, 0, flushMock.CountPickle)
+	assert.Equal(t, 0, flushMock.CountDefined)
+	assert.Equal(t, 0, flushMock.CountPassed)
+	assert.Equal(t, 0, flushMock.CountSkipped)
+	assert.Equal(t, 0, flushMock.CountUndefined)
+	assert.Equal(t, 0, flushMock.CountFailed)
+	assert.Equal(t, 0, flushMock.CountPending)
+	assert.Equal(t, 0, flushMock.CountAmbiguous)
+	assert.Equal(t, 0, flushMock.CountSummary)
+
+	fmt.Flush()
+
+	assert.Equal(t, 1, flushMock.CountFeature)
+	assert.Equal(t, 1, flushMock.CountTestRunStarted)
+	assert.Equal(t, 1, flushMock.CountPickle)
+	assert.Equal(t, 1, flushMock.CountDefined)
+	assert.Equal(t, 1, flushMock.CountPassed)
+	assert.Equal(t, 1, flushMock.CountSkipped)
+	assert.Equal(t, 1, flushMock.CountUndefined)
+	assert.Equal(t, 1, flushMock.CountFailed)
+	assert.Equal(t, 1, flushMock.CountPending)
+	assert.Equal(t, 1, flushMock.CountAmbiguous)
+	assert.Equal(t, 1, flushMock.CountSummary)
+}

internal/formatters/fmt_multi_test.go

@@ -24,7 +24,6 @@ var (
 
 // TestRepeater tests the delegation of the repeater functions.
 func TestRepeater(t *testing.T) {
-
 	mock.tt = t
 	f := make(repeater, 0)
 	f = append(f, &mock)
@@ -52,7 +51,6 @@ func TestRepeater(t *testing.T) {
 	assert.Equal(t, 2, mock.CountFailed)
 	assert.Equal(t, 2, mock.CountPending)
 	assert.Equal(t, 2, mock.CountAmbiguous)
-
 }
 
 type BaseFormatter struct {
@@ -73,6 +71,7 @@ type DummyFormatter struct {
 	CountFailed         int
 	CountPending        int
 	CountAmbiguous      int
+	CountSummary        int
 }
 
 // SetStorage assigns gherkin data storage.
@@ -158,3 +157,8 @@ func (f *DummyFormatter) Ambiguous(p *messages.Pickle, s *messages.PickleStep, d
 	assert.Equal(f.tt, d, definition)
 	f.CountAmbiguous++
 }
+
+// Pickle receives scenario.
+func (f *DummyFormatter) Summary() {
+	f.CountSummary++
+}

internal/formatters/fmt_pretty.go

@@ -243,7 +243,7 @@ func (f *Pretty) Summary() {
 	f.Base.Summary()
 }
 
-func (f *Pretty) printOutlineExample(pickle *messages.Pickle, backgroundSteps int) {
+func (f *Pretty) printOutlineExample(pickle *messages.Pickle, step *messages.PickleStep, backgroundSteps int) {
 	var errorMsg string
 	var clr = green
 
@@ -255,7 +255,7 @@ func (f *Pretty) printOutlineExample(pickle *messages.Pickle, backgroundSteps in
 	printExampleHeader := exampleTable.TableBody[0].Id == exampleRow.Id
 	firstExamplesTable := astScenario.Examples[0].Location.Line == exampleTable.Location.Line
 
-	pickleStepResults := f.Storage.MustGetPickleStepResultsByPickleID(pickle.Id)
+	pickleStepResults := f.Storage.MustGetPickleStepResultsByPickleIDUntilStep(pickle.Id, step.Id)
 
 	firstExecutedScenarioStep := len(pickleStepResults) == backgroundSteps+1
 	if firstExamplesTable && printExampleHeader && firstExecutedScenarioStep {
@@ -419,7 +419,7 @@ func (f *Pretty) printStep(pickle *messages.Pickle, pickleStep *messages.PickleS
 	}
 
 	if !astBackgroundStep && len(astScenario.Examples) > 0 {
-		f.printOutlineExample(pickle, backgroundSteps)
+		f.printOutlineExample(pickle, pickleStep, backgroundSteps)
 		return
 	}
 

internal/storage/storage.go

@@ -223,7 +223,7 @@ func (s *Storage) MustGetPickleStepResult(id string) models.PickleStepResult {
 	return v.(models.PickleStepResult)
 }
 
-// MustGetPickleStepResultsByPickleID will retrieve pickle strep results by pickle id and panic on error.
+// MustGetPickleStepResultsByPickleID will retrieve pickle step results by pickle id and panic on error.
 func (s *Storage) MustGetPickleStepResultsByPickleID(pickleID string) (psrs []models.PickleStepResult) {
 	it := s.mustGet(tablePickleStepResult, tablePickleStepResultIndexPickleID, pickleID)
 	for v := it.Next(); v != nil; v = it.Next() {
@@ -233,6 +233,21 @@ func (s *Storage) MustGetPickleStepResultsByPickleID(pickleID string) (psrs []mo
 	return psrs
 }
 
+// MustGetPickleStepResultsByPickleIDUntilStep will retrieve pickle step results by pickle id
+// from 0..stepID for that pickle.
+func (s *Storage) MustGetPickleStepResultsByPickleIDUntilStep(pickleID string, untilStepID string) (psrs []models.PickleStepResult) {
+	it := s.mustGet(tablePickleStepResult, tablePickleStepResultIndexPickleID, pickleID)
+	for v := it.Next(); v != nil; v = it.Next() {
+		psr := v.(models.PickleStepResult)
+		psrs = append(psrs, psr)
+		if psr.PickleStepID == untilStepID {
+			break
+		}
+	}
+
+	return psrs
+}
+
 // MustGetPickleStepResultsByStatus will retrieve pickle strep results by status and panic on error.
 func (s *Storage) MustGetPickleStepResultsByStatus(status models.StepResultStatus) (psrs []models.PickleStepResult) {
 	it := s.mustGet(tablePickleStepResult, tablePickleStepResultIndexStatus, status)

internal/storage/storage_test.go

@@ -128,6 +128,40 @@ func Test_MustGetPickleStepResultsByPickleID(t *testing.T) {
 	assert.Equal(t, expected, actual)
 }
 
+func Test_MustGetPickleStepResultsByPickleIDUntilStep(t *testing.T) {
+	s := storage.NewStorage()
+
+	const pickleID = "p1"
+	const stepID = "s2"
+
+	store := []models.PickleStepResult{
+		{
+			Status:       models.Passed,
+			PickleID:     pickleID,
+			PickleStepID: "s1",
+		},
+		{
+			Status:       models.Passed,
+			PickleID:     pickleID,
+			PickleStepID: "s2",
+		},
+		{
+			Status:       models.Passed,
+			PickleID:     pickleID,
+			PickleStepID: "s3",
+		},
+	}
+
+	for _, psr := range store {
+		s.MustInsertPickleStepResult(psr)
+	}
+
+	expected := store[:2]
+
+	actual := s.MustGetPickleStepResultsByPickleIDUntilStep(pickleID, stepID)
+	assert.Equal(t, expected, actual)
+}
+
 func Test_MustGetPickleStepResultsByStatus(t *testing.T) {
 	s := storage.NewStorage()
 

run.go

@@ -33,8 +33,10 @@ const (
 	exitOptionError
 )
 
-type testSuiteInitializer func(*TestSuiteContext)
-type scenarioInitializer func(*ScenarioContext)
+type (
+	testSuiteInitializer func(*TestSuiteContext)
+	scenarioInitializer  func(*ScenarioContext)
+)
 
 type runner struct {
 	randomSeed            int64
@@ -115,6 +117,13 @@ func (r *runner) concurrent(rate int) (failed bool) {
 
 				// Copy base suite.
 				suite := *testSuiteContext.suite
+				if rate > 1 {
+					// if running concurrently, only print at end of scenario to keep
+					// scenario logs segregated
+					ffmt := ifmt.WrapOnFlush(testSuiteContext.suite.fmt)
+					suite.fmt = ffmt
+					defer ffmt.Flush()
+				}
 
 				if r.scenarioInitializer != nil {
 					sc := ScenarioContext{suite: &suite}