Test log output is no longer streamed as the test runs since CSAPI tests moved to tests/csapi (multiple packages in tests)

[MadLittleMods]

Before #171 and the csapi package was added, I was able to run Complement tests and see the log output as it runs. But nowadays, all of the test log output is buffered and only printed when all of the tests finish.

This is caused by Go deciding to not stream log output when there are multiple packages present (we have tests and csapi in the ./tests/... directory):

• cmd/go: go test -v does not stream logs when testing multiple packages golang/go#46959
• testing: testing a list of packages blocks the real-time output golang/go#27826

Related:

• Related https://dave.cheney.net/2020/03/10/go-test-v-streaming-output
• Go added the streaming behavior in https://go-review.googlesource.com/c/go/+/127120

---

I liked the streaming behavior before to see the test progress but it's also important when I try to hook up Element to the homeserver and rooms from Complement to be able to see the log output of room ID's, etc to join and inspect, https://github.com/matrix-org/complement/blob/master/ONBOARDING.md#how-do-i-hook-up-a-matrix-client-like-element-to-the-homeservers-spun-up-by-complement-after-a-test-runs

As a workaround, I can get the log streaming behavior I want by being very selective about the files to run: go test -v -run TestImportHistoricalMessages ./tests/main_test.go ./tests/msc2716_test.go but this is manual process adjusting our generic Synapse test runner every time.

Potential solutions

1. Move all tests to the tests package.
2. Just wait for upstream Go changes although there is a possibility this won't change and just the documentation will be updated with this caveat
3. Run each test package in their own process to still get parallel but still get stream output
4. Can we run tests in parallel without separate packages? Move CSAPI only tests to tests/csapi #171

[kegsay]

If you want streaming output, only specify a single package in go test - in other words don't use ... e.g:

go test -v -run TestOutboundFederationIgnoresMissingEventWithBadJSONForRoomVersion6 ./tests

[MadLittleMods]

Streaming log output seems like a great default benefit to have. It would be nice to just make it work without people having to know this random caveat.

We could modify the Synapse test runner for Complement to only run tests but I assume we do actually want to test the csapi things there as well. Is there another solution we could try?

[kegsay]

Streaming log output seems like a great default benefit to have.

Well, yes, but there are good reasons why this is not the default. If you are running tests under CI, most of the time you care more about the speed of the tests rather than having any kind of streamed output. If you are running tests locally then you care more for streamed output in which case just run a single package. They are conflicting features because in order to get large speedups (e.g 2x) you need to run tests in parallel. If this was streamed as it happened the output would be nonsensical and hard to follow, which is why it gets buffered in the first place.

[MadLittleMods]

Tests are currently only run sequentially, unless t.Parallel() is called in a subtest. This will not scale as we increase the number of tests.

-- #119

Do you mean that it isn't very practical/reasonable to add t.Parallel() to everything? Or that parallelism is different than having a separate package?

---

If you are running tests under CI, most of the time you care more about the speed of the tests rather than having any kind of streamed output. If you are running tests locally then you care more for streamed output in which case just run a single package. They are conflicting features because in order to get large speedups (e.g 2x) you need to run tests in parallel.

It seems like those can coexist, I'm not trying to be CI and developer at the same time. Make CI efficient however and have it work out of the box for a local developer seems achievable.

Ideal solution

I think ideally, Go could see that when I'm using -run and I only match tests in a single package, it would just start streaming.

Potential solutions

Split tests manually

But something we can do now, boils down to what you mentioned about specifying a package. We could have all of the tests in the tests package and keep the Synapse test runner defaulted to ./tests/... so it always streams for developers.

For CI .github/workflows/tests.yml#L377, it seems like we could run separate jobs for each package,

• go test -v -tags synapse_blacklist,msc2403,msc2946,msc3083 ./tests
• go test -v -tags synapse_blacklist,msc2403,msc2946,msc3083 ./tests/csapi

Systematically split tests across CI jobs

Or parallelize more systematically, https://docs.gitlab.com/ee/ci/yaml/#parallel. I don't see this exact option for GitHub actions but something of the sort is possible, https://rubyyagi.com/how-to-run-tests-in-parallel-in-github-actions/#configuring-github-actions-workflow-to-run-test-in-parallel

Write some shell script to do the same thing 🤷

go list - Use the built-in Go command go list ./... to glob Golang packages. This allows splitting package tests across multiple containers.

go test -v $(go list ./... | circleci tests split)

-- https://circleci.com/docs/2.0/parallelism-faster-jobs/#other-ways-to-split-tests

Even after renaming all of package csapi_tests to package tests, go list ./tests/... still lists two directories which are split-able.

go list ./tests/...
github.com/matrix-org/complement/tests
github.com/matrix-org/complement/tests/csapi

[kegsay]

The number of directories will increase as the number of tests increases, so your solution isn't very practical as it would mean having to constantly update callsites where Complement is invoked (GH actions, manually, READMEs, etc)

Using a shell script doesn't help because either:

• you run them sequentially -> slow
• you run them in parallel -> nonsense interleaved output

Splitting them across different processes would be useful but seems convoluted given GH actions doesn't support it and afaik the only benefit for doing this would be to allow concurrent streaming output (it wouldn't speed up test runs any more than what we do currently).

Overall, I'm not seeing any convincing argument for changing the current behaviour. By default, tests are run in parallel and output is buffered and emitted all at once at the end. If you want streaming output when debugging or creating new tests, then run a single package as outlined in #215 (comment) - this gives the best of both worlds, at the cost of needing to know how go test works.

I don't think it's worth wasting more time and effort on this so I'm closing this issue.

[MadLittleMods]

I've created golang/go#49195 to try to tackle this from the Go side so it just works out of the box.

[MadLittleMods]

This tip from @richvdh to change the parallelism works well,

Try sticking -p 1 on the complement.sh commandline.

-- @richvdh matrix-org/synapse#13204 (comment)

(relevant Go source code)