Feature request: Indented output in the console for tests within a suite

[adammcarter]

Description

Currently the output to the console is flat:

For example, the below console output...

◇ Test run started.
↳ Testing Library Version: unknown (Swift 5.10 toolchain)
◇ Suite NotificationsDeepLinkUrl started.
◇ Test returnsAppPreferencesNotificationsUrl_wheniOS() started.
✔ Test returnsAppPreferencesNotificationsUrl_wheniOS() passed after 0.003 seconds.
✔ Suite NotificationsDeepLinkUrl passed after 0.003 seconds.
◇ Suite QueueNotificationsForRunChangesReturningBranchNames started.
◇ Test returnsEmptyArray_whenOldRunsHasARun_butNotificationsAreNotAvailable() started.
✔ Test returnsEmptyArray_whenOldRunsHasARun_butNotificationsAreNotAvailable() passed after 0.008 seconds.
◇ Test returnsEmptyArray_whenOldRunsIsEmpty() started.
✔ Test returnsEmptyArray_whenOldRunsIsEmpty() passed after 0.002 seconds.
◇ Test returnsNewRun_whenOldRunsHasANewRun_andNotificationsAreAvailable_andNotificationPreferenceIsEveryone() started.
✔ Test returnsNewRun_whenOldRunsHasANewRun_andNotificationsAreAvailable_andNotificationPreferenceIsEveryone() passed after 0.012 seconds.
✔ Suite QueueNotificationsForRunChangesReturningBranchNames passed after 0.023 seconds.
✔ Test run with 4 tests passed after 0.027 seconds.

This can be difficult to read both at a glance and with some time invested, especially when Suites are nested within other Suites.

Proposal

It would be nice if we could indent the tests/suites to a hierarchy like the below structure:

◇ Test run started.
↳ Testing Library Version: unknown (Swift 5.10 toolchain)
◇ Suite MySuite started.
  ↳ ◇ Suite MyChildSuite started.
      ◇ Test someTest() started.
      ✔ Test someTest() passed after 0.003 seconds.
      ↳ ◇ Suite MyGrandChildSuite started.
          ◇ Test someGrandChildTest() started.
           ✔ Test someGrandChildTest() passed after 0.003 seconds.
◇ Suite MyOtherSuite started.
  ↳ ◇ Suite MyOtherChildSuite started.
      ◇ Test someOtherTest() started.
      ✔ Test someOtherTest() passed after 0.003 seconds.

Benefits

The above output is easier to read at a glance and to see what tests and suites are a part of their parent - simplifying readability and seeing at a glance where a test might live to go and debug and ultimately fix it.

Potential issues

All the indenting

This could of course get a bit crazy if you have many nested Suites where the indentation could be so long that it becomes unreadable so we could either:

• Limit this indentation to A sensible level like 5 child indents
• Leave this down to the developer who ultimately controls their levels of nested Suits/Tests

Parallelised tests

As pointed out by @stmontgomery here https://github.com/apple/swift-testing/issues/296#issuecomment-2002027577 in my original post https://github.com/apple/swift-testing/issues/296, this could work badly with parallelised tests where the output is non-linear and indentation would cause the tests to be indented under a parent that it's not a part of, eg a parallelised test could appear under a suite it's not a part of because it just happened to run at the same time as the other test in the other suite.

However, this could be remedied simply by the parents being printed on the line above in the console if it hasn't already to make it explicit where the test came from.

Expected behavior

No response

Actual behavior

No response

Steps to reproduce

No response

swift-testing version/commit hash

0.6.0

Swift & OS version (output of swift --version && uname -a)

swift-driver version: 1.90.11.1 Apple Swift version 5.10 (swiftlang-5.10.0.13 clang-1500.3.9.4) Target: arm64-apple-macosx14.0 Darwin AT-ALK6L5VQ 23.3.0 Darwin Kernel Version 23.3.0: Wed Dec 20 21:30:44 PST 2023; root:xnu-10002.81.5~7/RELEASE_ARM64_T6000 arm64

[grynspan]

Output to stderr is currently unstructured, because tests can and do write to it too, so reordering the output from ConsoleOutputRecorder would be insufficient (you'd see the swift-testing output in the right order, but it would end up removed from direct test output.)

I think this becomes feasible once we have a supervisor process (similar to what XCTest has.) At that point, we'd be able to reorder events since all console output would be filtered through the supervisor.

I also want to explore how we can capture logging through mechanisms like os_log() and print() and see if we can't forward them as test events associated with a specific test: if we can do that, then we can include logged output in the correct position alongside other events like "test started" and "issue recorded."

[adammcarter]

Apologies for the delay, this sounds great re OS log and the direction for having a more complex/controlled output instead of stderr

Sounds like this one might be on hold for a while until the ground work is done for that above but all sounds good to me 👌🏻

[grynspan]

Tracked internally (more or less) as rdar://103374320.

[YOCKOW]

Couldn't we make a stopgap that adds @Suite names to each @Test name?

Given the following code:

import Testing

@Suite struct GuitarTests {
  @Test func chordTest() {}
}

@Suite struct BassTests {
  @Test func chordTest() {}
}

Current output:

◇ Test run started.
↳ Testing Library Version: 94 (arm64e-apple-macos13.0)
◇ Suite BassTests started.
◇ Suite GuitarTests started.
◇ Test chordTest() started.
◇ Test chordTest() started.
✔ Test chordTest() passed after 0.001 seconds.
✔ Test chordTest() passed after 0.001 seconds.
✔ Suite GuitarTests passed after 0.001 seconds.
✔ Suite BassTests passed after 0.001 seconds.
✔ Test run with 2 tests passed after 0.001 seconds.

After (ad-hoc) improvement:

◇ Test run started.
↳ Testing Library Version: 94 (arm64e-apple-macos13.0)
◇ Suite BassTests started.
◇ Suite GuitarTests started.
◇ Test BassTests.chordTest() started.
◇ Test GuitarTests.chordTest() started.
✔ Test GuitarTests.chordTest() passed after 0.001 seconds.
✔ Test BassTests.chordTest() passed after 0.001 seconds.
✔ Suite GuitarTests passed after 0.001 seconds.
✔ Suite BassTests passed after 0.001 seconds.
✔ Test run with 2 tests passed after 0.001 seconds.