Repository: cucumber/godog

Issue:
Running with concurrency shouldn't intermingle the test outputs
### 👓 What did you see?

Example output showing three different test's steps being mixed together
![image](https://github.com/user-attachments/assets/cbe09738-0e66-44c9-9a46-53d141497d8c)


### ✅ What did you expect to see?

It would be more readable and easier to debug to hold onto a test's output until it's complete and then write it all at once.

### 📦 Which tool/library version are you using?

_No response_

### 🔬 How could we reproduce it?

Set `Concurrency:  2` (or more) in the config

### 📚 Any additional context?

_No response_

Hints from issue comments:
@Johnlon: The suggestion is one possibility, but would result in silence for protracted periods.

The reality of the situation is that folk will use things like fmt.* and even the root println fn, and unlike the JVM sadly golang doesn't provide a reliable way to intercept stdout/stderr to capture that output to defer logging.
I tried it ages ago and it doesn't work and there is nothing the framework can really do to fix that.

What does work (for godog and other MT code) is to create a logger for each goroutine (eg in the before scenario), and to pass that logger to each step via the context object and then that logger can aggregate output until the after scenario where it could be logged en-masse.
This is something you can do yourself.

This approach also has advantages as you can attache the captured console to the steps as you go along so that it's available in HTML report and so on.
@tigh-latte: @Johnlon I've Implemented a possible approach to fix this without interrupting test execution in #645, if you have time to take a look/give feedback@Johnlon: does it only deal with the formatters or also ad-hoc console output from println, fmt* and loggers, which for me has been the main interest.
@tigh-latte: Just formatters. Should godog deal with adhoc printing to stdout outside of its domain? I don't think so myself. If I want ordered logging in a concurrent library, then I ought to learn how to use the logging of that library.@vearutop: It turned out this approach has a negative effect of hiding timestamps of operations from the formatter. For example, https://github.com/godogx/allure has stopped reporting correct test/steps durations.

I think we'll need to change the approach to allow timely calls of formatters that can handle concurrent scenarios.@tigh-latte: @vearutop that's fine, I'll have a think/look at this over the next wee while

Solution patch:
diff --git a/CHANGELOG.md b/CHANGELOG.md
index 11558f1..5d6c7e1 100644
--- a/CHANGELOG.md
+++ b/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))
diff --git a/formatters/fmt.go b/formatters/fmt.go
index fec9696..973cf11 100644
--- a/formatters/fmt.go
+++ b/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
diff --git a/internal/formatters/fmt_flushwrap.go b/internal/formatters/fmt_flushwrap.go
new file mode 100644
index 0000000..129b062
--- /dev/null
+++ b/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()
+	}
+}
diff --git a/internal/formatters/fmt_pretty.go b/internal/formatters/fmt_pretty.go
index 91dbc0c..76d7337 100644
--- a/internal/formatters/fmt_pretty.go
+++ b/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
 	}
 
diff --git a/internal/storage/storage.go b/internal/storage/storage.go
index 3fce8a8..72b7e86 100644
--- a/internal/storage/storage.go
+++ b/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)
diff --git a/run.go b/run.go
index 405aaff..7378b2f 100644
--- a/run.go
+++ b/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}



Test patch:
diff --git a/internal/formatters/fmt_flushwrap_test.go b/internal/formatters/fmt_flushwrap_test.go
new file mode 100644
index 0000000..408ff06
--- /dev/null
+++ b/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)
+}
diff --git a/internal/formatters/fmt_multi_test.go b/internal/formatters/fmt_multi_test.go
index b87e36d..be33b99 100644
--- a/internal/formatters/fmt_multi_test.go
+++ b/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++
+}
diff --git a/internal/storage/storage_test.go b/internal/storage/storage_test.go
index aa39d8c..47b8f7c 100644
--- a/internal/storage/storage_test.go
+++ b/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()