Stream Complement progress and format logs in a separate step after all tests are done

[MadLittleMods]

Stream Complement progress and format logs in a separate step after all tests are done. This way we can see what's happening as the tests run instead of nothing until the end. Also useful to split the test output from the formatting so we can take the raw test output before formatting gobbles it all up.

Same thing I did in https://github.com/element-hq/synapse-rust-apps/pull/361

Todo

• Wait for Auto-formatting .github/workflows/tests.yml from VSCode #19327 to merge

Pull Request Checklist

• Pull request is based on the develop branch
• Pull request includes a changelog file. The entry should:
  • Be a short description of your change which makes sense to users. "Fixed a bug that prevented receiving messages from other servers." instead of "Moved X method from EventStore to EventWorkerStore.".
  • Use markdown where necessary, mostly for code blocks.
  • End with either a period (.) or an exclamation mark (!).
  • Start with a capital letter.
  • Feel free to credit yourself, by adding a sentence "Contributed by @github_username." or "Contributed by [Your Name]." to the end of the entry.
• Code style is correct (run the linters)

[anoadragon453]

Definitely nicer to see logs streamed instead of having to wait!

[anoadragon453]

Can we format the contents of the JSON log output so they're nicer to look at than:

{"Time":"2025-12-30T19:59:08.059181484Z","Action":"output","Package":"github.com/matrix-org/complement/tests/csapi","Test":"TestMessagesOverFederation","Output":"    client.go:845: [CSAPI] GET hs1/_matrix/client/v3/sync =\u003e 200 OK (250.682156ms)\n"}
{"Time":"2025-12-30T19:59:08.097480482Z","Action":"output","Package":"github.com/matrix-org/complement/tests/csapi","Test":"TestMessagesOverFederation","Output":"    client.go:845: [CSAPI] PUT hs1/_matrix/client/v3/rooms/!luJDjfDmGxAPyHHZVY:hs1/send/m.room.message/170 =\u003e 200 OK (37.967197ms)\n"}
{"Time":"2025-12-30T19:59:08.097518042Z","Action":"output","Package":"github.com/matrix-org/complement/tests/csapi","Test":"TestMessagesOverFederation/Visible_shared_history_after_joining_new_room_(backfill)/`messagesRequestLimit`_is_greater_than_the_number_of_messages_backfilled_(in_Synapse,_100)","Output":"    room_messages_test.go:411: SendEventSynced waiting for event ID $Wf0FmR_uW5SWIBNPtD04nqwq59Jexs86WoXXVnYsHxc\n"}
{"Time":"2025-12-30T19:59:08.237247319Z","Action":"output","Package":"github.com/matrix-org/complement/tests/csapi","Test":"TestMessagesOverFederation","Output":"    client.go:845: [CSAPI] GET hs1/_matrix/client/v3/sync =\u003e 200 OK (139.630783ms)\n"}
{"Time":"2025-12-30T19:59:08.275854022Z","Action":"output","Package":"github.com/matrix-org/complement/tests/csapi","Test":"TestMessagesOverFederation","Output":"    client.go:845: [CSAPI] PUT hs1/_matrix/client/v3/rooms/!luJDjfDmGxAPyHHZVY:hs1/send/m.room.message/171 =\u003e 200 OK (38.264142ms)\n"}

Or do you want the raw JSON output streamed for some reason?

We could use a jq filter pipeline:

COMPLEMENT_DIR=`pwd`/complement synapse/scripts-dev/complement.sh -p 1 -json 2>&1 \
  | tee /tmp/gotest.log \
  | jq -Rr --unbuffered '
    # If the line is JSON, assume Complement logs and parse.
    if (. | startswith("{") or startswith("[")) then
        # Parse as JSON
        (try fromjson catch empty) as $e
        | 
        # Note: .Time is an optional field.
        def ts:
          if $e.Time? then "\($e.Time) " else "" end;

        if $e.Action=="pass" then "\(ts)--- PASS: \($e.Test) (\($e.Elapsed)s)"
        elif $e.Action=="fail" then "\(ts)--- FAIL: \($e.Test) (\($e.Elapsed)s)"
        elif $e.Action=="skip" then "\(ts)--- SKIP: \($e.Test) (\($e.Elapsed)s)"
        elif $e.Action=="output" then "\(ts)\($e.Output | rtrimstr("\n"))"
        else empty end
      # Otherwise, assume script/docker build output and print directly.
      else
        .
      end
  '

which prints lines like:

2025-12-30T19:55:35.657310513Z 2025/12/30 19:55:35 config: &{BaseImageURI:complement-synapse DebugLoggingEnabled:false AlwaysPrintServerLogs:false EnvVarsPropagatePrefix:PASS_ SpawnHSTimeout:2m0s ContainerCPUCores:0 ContainerMemoryBytes:0 KeepBlueprints:[] HostMounts:[] BaseImageURIs:map[] PackageNamespace:csapi CACertificate:0xc00046e608 CAPrivateKey:0xc0004428c0 BestEffort:false HostnameRunningComplement:host.docker.internal EnableDirtyRuns:true HSPortBindingIP:127.0.0.1 PostTestScript:}
2025-12-30T19:55:35.660130161Z === RUN   TestChangePasswordPushers
2025-12-30T19:55:35.694392489Z 2025/12/30 19:55:35 Sharing [SERVER_NAME=hs1 SYNAPSE_WORKER_TYPES= SYNAPSE_LOG_TESTING=1 SYNAPSE_COMPLEMENT_USE_WORKERS=true SYNAPSE_COMPLEMENT_DATABASE=postgres] host environment variables with container
2025-12-30T19:55:48.977944267Z     client.go:845: [CSAPI] POST hs1/_matrix/client/v3/register => 200 OK (108.896905ms)
2025-12-30T19:55:48.978043462Z === RUN   TestChangePasswordPushers/Pushers_created_with_a_different_access_token_are_deleted_on_password_change
2025-12-30T19:55:49.016572468Z     client.go:845: [CSAPI] POST hs1/_matrix/client/v3/login => 200 OK (38.296022ms)

(likely worth putting the jq block into a script under .ci/scripts.)

[MadLittleMods]

I don't think it's worth it. I think it's easiest just to interpret the JSON information as-is.

The tests can run in parallel and the output will be mixed up with each other. The only reason it streams in the first place is because we're using the JSON output format (and because we use -p 1):

 	// If we're showing JSON output, then display output as soon as 
 	// possible even when multiple tests are being run: the JSON output 
 	// events are attributed to specific package tests, so interlacing them 
 	// is OK. 

-- cmd/go -> src/cmd/go/internal/test/test.go#L1196-L1224

We would need to include the same information about which test/package the log is attributed to, etc. While, it may be possible to come up with a better format, the JSON version is still workable in a sticky situation which is really the only time we'd be interpreting it anyway. And it also allows us to copy-paste it into whatever tool (like you did) for further processing.

If anything, could be a follow-up PR.

[MadLittleMods]

Thanks of the review @anoadragon453 🐇