Skip to content

Conversation

@orestisfl
Copy link
Contributor

Proposed commit message

The test was flaky because workerWg.Done() was called before the final log statement completed, allowing input.Stop() to return while the goroutine was still logging to the test's logger.

Fix by reordering defers so workerWg.Done() runs last (must be first defer due to LIFO ordering).

Also fix goroutine leak in the test itself by removing the unnecessary goroutine and using a select to check for unexpected events.

Checklist

  • My code follows the style guidelines of this project
  • I have commented my code, particularly in hard-to-understand areas
  • I have made corresponding changes to the documentation
  • I have made corresponding change to the default configuration files
  • I have added tests that prove my fix is effective or that my feature works. Where relevant, I have used the stresstest.sh script to run them under stress conditions and race detector to verify their stability.
  • I have added an entry in ./changelog/fragments using the changelog tool.

How to test this PR locally

Difficult to reproduce, run with:

GOMAXPROCS=1 go test -run TestNegativeCases -count=2000 -failfast ./x-pack/filebeat/input/cometd
panic: Log in goroutine after TestNegativeCases has completed: 2025-11-28T16:04:01.738+0100	INFO	cometd	Input worker has stopped.	{"pubsub_channel": "channel_name"}

goroutine 8352 [running]:
testing.(*common).log(0xc0002aa000, {0xc0003e9a40?, 0x65?})
	/usr/lib/go/src/testing/testing.go:1030 +0x1ac
testing.(*common).Logf(0xc0002aa000, {0x13f435e?, 0x400?}, {0xc00035ddb0?, 0x0?, 0x2?})
	/usr/lib/go/src/testing/testing.go:1191 +0x4f
go.uber.org/zap/zaptest.TestingWriter.Write({{0x75eedea33200?, 0xc0002aa000?}, 0x40?}, {0xc0005e5c00?, 0x66, 0xc0005e5c00?})
	/home/orestis/go/pkg/mod/go.uber.org/[email protected]/zaptest/logger.go:146 +0xdb
go.uber.org/zap/zapcore.(*ioCore).Write(0xc000136d80, {0x0, {0xc2428c586bfdd61c, 0xafdaba1f1, 0x1d14dc0}, {0x13f6038, 0x6}, {0x140a066, 0x19}, {0x0, ...}, ...}, ...)
	/home/orestis/go/pkg/mod/go.uber.org/[email protected]/zapcore/core.go:99 +0xb5
go.uber.org/zap/zapcore.(*CheckedEntry).Write(0xc000251790, {0x0, 0x0, 0x0})
	/home/orestis/go/pkg/mod/go.uber.org/[email protected]/zapcore/entry.go:253 +0x119
go.uber.org/zap.(*SugaredLogger).log(0xc000054a98, 0x0, {0x0?, 0x0?}, {0xc0000d5e18?, 0x1?, 0x1?}, {0x0, 0x0, 0x0})
	/home/orestis/go/pkg/mod/go.uber.org/[email protected]/sugar.go:355 +0xec
go.uber.org/zap.(*SugaredLogger).Info(...)
	/home/orestis/go/pkg/mod/go.uber.org/[email protected]/sugar.go:155
github.com/elastic/elastic-agent-libs/logp.(*Logger).Info(...)
	/home/orestis/go/pkg/mod/github.com/elastic/[email protected]/logp/logger.go:186
github.com/elastic/beats/v7/x-pack/filebeat/input/cometd.(*cometdInput).Run.func1.1()
	/home/orestis/src/beats/x-pack/filebeat/input/cometd/input.go:77 +0x56d
created by github.com/elastic/beats/v7/x-pack/filebeat/input/cometd.(*cometdInput).Run.func1 in goroutine 8343
	/home/orestis/src/beats/x-pack/filebeat/input/cometd/input.go:41 +0x87
FAIL	github.com/elastic/beats/v7/x-pack/filebeat/input/cometd	47.249s
FAIL

Related issues

The test was flaky because workerWg.Done() was called before the final
log statement completed, allowing input.Stop() to return while the
goroutine was still logging to the test's logger.

Fix by reordering defers so workerWg.Done() runs last (must be first
defer due to LIFO ordering).

Also fix goroutine leak in the test itself by removing the unnecessary
goroutine and using a select to check for unexpected events.

Difficult to reproduce, run with:

```sh
GOMAXPROCS=1 go test -run TestNegativeCases -count=2000 -failfast ./x-pack/filebeat/input/cometd
```

```
panic: Log in goroutine after TestNegativeCases has completed: 2025-11-28T16:04:01.738+0100	INFO	cometd	Input worker has stopped.	{"pubsub_channel": "channel_name"}

goroutine 8352 [running]:
testing.(*common).log(0xc0002aa000, {0xc0003e9a40?, 0x65?})
	/usr/lib/go/src/testing/testing.go:1030 +0x1ac
testing.(*common).Logf(0xc0002aa000, {0x13f435e?, 0x400?}, {0xc00035ddb0?, 0x0?, 0x2?})
	/usr/lib/go/src/testing/testing.go:1191 +0x4f
go.uber.org/zap/zaptest.TestingWriter.Write({{0x75eedea33200?, 0xc0002aa000?}, 0x40?}, {0xc0005e5c00?, 0x66, 0xc0005e5c00?})
	/home/orestis/go/pkg/mod/go.uber.org/[email protected]/zaptest/logger.go:146 +0xdb
go.uber.org/zap/zapcore.(*ioCore).Write(0xc000136d80, {0x0, {0xc2428c586bfdd61c, 0xafdaba1f1, 0x1d14dc0}, {0x13f6038, 0x6}, {0x140a066, 0x19}, {0x0, ...}, ...}, ...)
	/home/orestis/go/pkg/mod/go.uber.org/[email protected]/zapcore/core.go:99 +0xb5
go.uber.org/zap/zapcore.(*CheckedEntry).Write(0xc000251790, {0x0, 0x0, 0x0})
	/home/orestis/go/pkg/mod/go.uber.org/[email protected]/zapcore/entry.go:253 +0x119
go.uber.org/zap.(*SugaredLogger).log(0xc000054a98, 0x0, {0x0?, 0x0?}, {0xc0000d5e18?, 0x1?, 0x1?}, {0x0, 0x0, 0x0})
	/home/orestis/go/pkg/mod/go.uber.org/[email protected]/sugar.go:355 +0xec
go.uber.org/zap.(*SugaredLogger).Info(...)
	/home/orestis/go/pkg/mod/go.uber.org/[email protected]/sugar.go:155
github.com/elastic/elastic-agent-libs/logp.(*Logger).Info(...)
	/home/orestis/go/pkg/mod/github.com/elastic/[email protected]/logp/logger.go:186
github.com/elastic/beats/v7/x-pack/filebeat/input/cometd.(*cometdInput).Run.func1.1()
	/home/orestis/src/beats/x-pack/filebeat/input/cometd/input.go:77 +0x56d
created by github.com/elastic/beats/v7/x-pack/filebeat/input/cometd.(*cometdInput).Run.func1 in goroutine 8343
	/home/orestis/src/beats/x-pack/filebeat/input/cometd/input.go:41 +0x87
FAIL	github.com/elastic/beats/v7/x-pack/filebeat/input/cometd	47.249s
FAIL
```

Closes elastic#47698
@orestisfl orestisfl requested a review from kruskall November 28, 2025 15:20
@orestisfl orestisfl self-assigned this Nov 28, 2025
@orestisfl orestisfl requested a review from a team as a code owner November 28, 2025 15:20
@orestisfl orestisfl added bug flaky-test Unstable or unreliable test cases. backport-active-all Automated backport with mergify to all the active branches skip-changelog labels Nov 28, 2025
@botelastic botelastic bot added the needs_team Indicates that the issue/PR needs a Team:* label label Nov 28, 2025
@botelastic
Copy link

botelastic bot commented Nov 28, 2025

This pull request doesn't have a Team:<team> label.

@github-actions
Copy link
Contributor

🤖 GitHub comments

Just comment with:

  • run docs-build : Re-trigger the docs validation. (use unformatted text in the comment!)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

backport-active-all Automated backport with mergify to all the active branches bug flaky-test Unstable or unreliable test cases. needs_team Indicates that the issue/PR needs a Team:* label skip-changelog

Projects

None yet

Development

Successfully merging this pull request may close these issues.

[Flaky test] TestNegativeCases - Log in goroutine after TestNegativeCases has completed

1 participant