Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Parallel Logging #1457

Closed
2 tasks
dreadster3 opened this issue Oct 25, 2024 · 0 comments · Fixed by #1467
Closed
2 tasks

Parallel Logging #1457

dreadster3 opened this issue Oct 25, 2024 · 0 comments · Fixed by #1467

Comments

@dreadster3
Copy link

dreadster3 commented Oct 25, 2024

Describe the bug
When running tests in parallel with the JSON flag, for example, using go test -v -json ./..., the logs become mixed up between tests. For instance, logs intended for one test appear in the output of another, making it difficult to distinguish which logs belong to which test.

To Reproduce
Run the following tests, with the following command go test -json -v ./...

package something

import (
	"testing"

	"github.com/gruntwork-io/terratest/modules/logger"
)

func log(t *testing.T) {
	logger.Log(t, "This is a log")
}

func Test1(t *testing.T) {
	t.Parallel()

	for i := 0; i < 100; i++ {
		log(t)
	}
}

func Test2(t *testing.T) {
	t.Parallel()

	for i := 0; i < 100; i++ {
		log(t)
	}
}

Which will result in this:

...
{"Time":"2024-10-25T18:09:16.435283509+01:00","Action":"output","Package":"go_playground/pkg/something","Test":"Test2","Output":"Test1 2024-10-25T18:09:16+01:00 something_test.go:10: This
is a log
"}
{"Time":"2024-10-25T18:09:16.435295209+01:00","Action":"output","Package":"go_playground/pkg/something","Test":"Test1","Output":"--- PASS: Test1 (0.00s)
"}
{"Time":"2024-10-25T18:09:16.435312409+01:00","Action":"output","Package":"go_playground/pkg/something","Test":"Test1","Output":"Test2 2024-10-25T18:09:16+01:00 something_test.go:10: This
is a log
"}
{"Time":"2024-10-25T18:09:16.435322709+01:00","Action":"output","Package":"go_playground/pkg/something","Test":"Test1","Output":"Test2 2024-10-25T18:09:16+01:00 something_test.go:10: This
is a log
"}
{"Time":"2024-10-25T18:09:16.435332709+01:00","Action":"output","Package":"go_playground/pkg/something","Test":"Test1","Output":"Test2 2024-10-25T18:09:16+01:00 something_test.go:10: This
is a log
"}
{"Time":"2024-10-25T18:09:16.435349509+01:00","Action":"output","Package":"go_playground/pkg/something","Test":"Test1","Output":"Test2 2024-10-25T18:09:16+01:00 something_test.go:10: This
is a log
"}
{"Time":"2024-10-25T18:09:16.43541831+01:00","Action":"output","Package":"go_playground/pkg/something","Test":"Test1","Output":"Test2 2024-10-25T18:09:16+01:00 something_test.go:10: This i
s a log
"}
...

Where Test does not match the test name at the start of the line

Expected behavior
I am expecting the log that contains the test name to match the log in the json.

Nice to have

  • Terminal output
  • Screenshots

Versions

  • Terratest version: v0.47.2
  • Environment details:
    image

Additional context
After doing some digging I believe the issue comes from the logger package.
The DoLog method seems to use fmt.Fprintln instead of the t.Log provided by golang that is intended to be used during testing.
In the reproduce tests if I change the log function to use the t.Log() it works without issues.

func log(t *testing.T) {
	t.Log(t.Name(), "This is a log")
}
@dreadster3 dreadster3 added the bug Something isn't working label Oct 25, 2024
@ZachGoldberg ZachGoldberg added the terratest label Oct 25, 2024 — with Linear
@ZachGoldberg ZachGoldberg removed the bug Something isn't working label Oct 25, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants