XCTest: Stdio not output at correct point #422

adam-fowler · 2022-09-22T14:00:29Z

Describe the bug
Stdio output appears to be buffered and not outputting at correct time. The easiest way to reproduce this is create a test which outputs a lot of text. You'll find that the text output appears after the TestSuite passed message. This only happens when running swift from the command line.

Steps To Reproduce
Steps to reproduce the behavior:

Create package which includes the following test

    func testPrint() {
        for i in 1..<100 {
            let string = (0..<i).map(\.description).joined()
            print(string)
        }
    }
}

Run swift test

Expected behavior
Print out of numbers should appear before TestSuite passed message.

Environment (please fill out the following information)

OS: macOS 12.4
Xcode: 13.4
swift-driver version: 1.45.2 Apple Swift version 5.6.1 (swiftlang-5.6.0.323.66 clang-1316.0.20.12)
Target: arm64-apple-macosx12.0

The text was updated successfully, but these errors were encountered:

weissi · 2022-11-10T10:14:00Z

This is a "bug" in xctest. The issue you're seeing here is that print(...) in Swift goes through the stdio buffering but the XCTest status prints do not.

Therefore even if a print(...) gets issues before the XCTest status prints, it might show up after it.

As a workaround, you can place a fflush(stdout) just before the end of the test as in

    func testPrint() {
        for i in 1..<100 {
            let string = (0..<i).map(\.description).joined()
            print(string)
        }
        fflush(stdout) // <<---
    }

and everything will look okay. Arguably, XCTest should flush all the stdio buffers fflush(stdout); fflush(stderr); once a test completes.

How can one debug this? For example with this dtrace.

The meaning of this dtrace is:

for every function matching *write, do
- print file descriptor (trace(arg0), length trace(arg2) as well as the first 10 bytes of the buffer (trace(substr(copyinstr(arg1), 0, 10)))
- record the user stack ustack() in an aggregation (@) which will be printed at the end.

sudo dtrace -n 'pid$target::write*:entry  { trace(arg0); trace(substr(copyinstr(arg1), 0, 10)); trace(arg2); @[ustack()] = count(); }' -c '/Applications/Xcode.app/Contents/Developer/usr/bin/xctest .build/debug/foofPackageTests.xctest'

the output is

[...]
              libsystem_kernel.dylib`write
              Foundation`_NSWriteToFileDescriptorWithProgress+0xc4
              Foundation`__34-[NSConcreteFileHandle writeData:]_block_invoke+0x50
              Foundation`-[NSData(NSData) enumerateByteRangesUsingBlock:]+0x78
              Foundation`-[NSConcreteFileHandle writeData:]+0xc4
              XCTestCore`-[XCTestLog logTestMessage:]+0x58
              XCTestCore`-[XCTestLog testLogWithFormat:arguments:]+0x5c
              XCTestCore`-[XCTestLog testLogWithFormat:]+0x20
              XCTestCore`-[XCTestLog testCaseWillStart:]+0x6c
              XCTestCore`__45-[XCTestObservationCenter _testCaseDidStart:]_block_invoke+0x40
              XCTestCore`-[XCTestObservationCenter _performBlockOnObserversWhichRespondToSelector:block:]+0xf0
              XCTestCore`-[XCTestObservationCenter _testCaseDidStart:]+0xf0
              XCTestCore`-[XCTestCaseRun start]+0x50
              XCTestCore`__26-[XCTestCase performTest:]_block_invoke.141+0x54
              XCTestCore`+[XCTContext _runInChildOfContext:forTestCase:markAsReportingBase:block:]+0xb4
              XCTestCore`+[XCTContext runInContextForTestCase:markAsReportingBase:block:]+0x90
              XCTestCore`-[XCTestCase performTest:]+0x134
              XCTestCore`-[XCTest runTest]+0x30
              XCTestCore`-[XCTestSuite runTestBasedOnRepetitionPolicy:testRun:]+0x44
              XCTestCore`__27-[XCTestSuite performTest:]_block_invoke+0xa4
                2

              libsystem_kernel.dylib`__write_nocancel
              libsystem_c.dylib`__swrite+0x18
              libsystem_c.dylib`_swrite+0x6c
              libsystem_c.dylib`__sflush+0xe8
              libsystem_c.dylib`__sfvwrite+0x318
              libsystem_c.dylib`fwrite+0x98
              libswiftCore.dylib`specialized _print<A>(_:separator:terminator:to:)+0xc8c
              foofPackageTests`foofTests.testPrint()+0x458
              foofPackageTests`@objc foofTests.testPrint()+0x24
              CoreFoundation`__invoking___+0x94
              CoreFoundation`-[NSInvocation invoke]+0x1ac
              XCTestCore`+[XCTFailableInvocation invokeStandardConventionInvocation:completion:]+0x44
              XCTestCore`__90+[XCTFailableInvocation invokeInvocation:withTestMethodConvention:lastObservedErrorIssue:]_block_invoke_3+0x1c
              XCTestCore`__81+[XCTFailableInvocation invokeWithAsynchronousWait:lastObservedErrorIssue:block:]_block_invoke.5+0x70
              XCTestCore`+[XCTSwiftErrorObservation observeErrorsInBlock:]+0x54
              XCTestCore`+[XCTFailableInvocation invokeWithAsynchronousWait:lastObservedErrorIssue:block:]+0x1cc
              XCTestCore`+[XCTFailableInvocation invokeInvocation:withTestMethodConvention:lastObservedErrorIssue:]+0x174
              XCTestCore`+[XCTFailableInvocation invokeInvocation:lastObservedErrorIssue:]+0x48
              XCTestCore`__24-[XCTestCase invokeTest]_block_invoke_2+0x58
              XCTestCore`-[XCTMemoryChecker _assertInvalidObjectsDeallocatedAfterScope:]+0x54
               99

The relevant parts here are that XCTest's logTestMessage goes straight to the kernel's write syscall. In other words, it does not go through the stdio buffer.

              libsystem_kernel.dylib`write
              Foundation`_NSWriteToFileDescriptorWithProgress+0xc4
              Foundation`__34-[NSConcreteFileHandle writeData:]_block_invoke+0x50
              Foundation`-[NSData(NSData) enumerateByteRangesUsingBlock:]+0x78
              Foundation`-[NSConcreteFileHandle writeData:]+0xc4
              XCTestCore`-[XCTestLog logTestMessage:]+0x58

On the other hand, Swift's print does go through the stdio buffer so it'll be written using the kernel's write system call when the buffer is flushed

              libsystem_kernel.dylib`__write_nocancel
              libsystem_c.dylib`__swrite+0x18
              libsystem_c.dylib`_swrite+0x6c
              libsystem_c.dylib`__sflush+0xe8
              libsystem_c.dylib`__sfvwrite+0x318
              libsystem_c.dylib`fwrite+0x98
              libswiftCore.dylib`specialized _print<A>(_:separator:terminator:to:)+0xc8c

(see how the __write_nocancel (which is kinda the same as write) happens out of a function called __sflush?)

adam-fowler · 2022-11-10T10:16:23Z

I pretty much came to the same conclusion while writing a response to your forum post

weissi · 2022-11-10T10:22:07Z

Awesome! Also: XCTest does (sometimes?) print its status messages to stderr. Given that stdout/fd 1 and stderr/fd 2 are two separate streams but usually appear merged on a terminal/file to humans, I think it's reasonable to assume that the test framework flushes everything before/after a test run.

This will also help with losing output in case of a crash/kill during a test when the stdio buffers can no longer be flushed and are lost.

tomerd · 2022-11-10T19:44:59Z

cc @stmontgomery @briancroom, should report be moved to XCTest repo and handled there?

stmontgomery · 2022-11-10T22:00:10Z

This symptom appears to be seen in the copy of XCTest included in Xcode, not in the "Corelibs" open source Swift version of XCTest contained in this repo. I have filed 102210347 to track the issue there. But we can keep this issue open to track fixing the same problem in this repo, even though I don't think that is where the bug was originally observed.

adam-fowler · 2022-11-11T08:26:58Z

Yes this is a macOS issue only. On macOS XCTest outputs all of its status updates to stderr, while the corelibs version outputs to stdout. This issue could be fixed by either

moving xctest outputs to stdout.
running fflush(stdout) and fflush(stderr) after each test has run

weissi · 2022-11-11T15:46:33Z

moving xctest outputs to stdout.

That alone won't be good enough. Unless XCTest starts going through stdio (i.e. fwrite, fputs, fprintf, ...) too. And even if that were changed that wouldn't fix potential weirdness because we would lose messages when the program crashes in CI.

My recommendation would be to flush everything right after the test has ended. That way we do as much as we can to make sure the printed data actually makes it into the output (terminal/pipe/file/...).

grynspan · 2023-06-28T20:15:55Z

I wonder if calling setbuf() to change the buffering of stdout and/or stderr would help here?

weissi · 2023-06-29T14:14:13Z

I wonder if calling setbuf() to change the buffering of stdout and/or stderr would help here?

It would if we assume that the user never touches it. I still think it can be expected from a test framework that it flushes all sorts of output buffers at the end of a test.

grynspan · 2023-06-29T14:25:13Z

Agreed, that seems like a reasonable thing to do as well.

grynspan · 2023-09-18T19:37:15Z

We've transferred this issue to Radar as rdar://102210347 and will track it as an improvement to the XCTest framework.

adam-fowler added the bug label Sep 22, 2022

stmontgomery transferred this issue from swiftlang/swift Nov 10, 2022

adam-fowler changed the title ~~Stdio not output at correct point~~ XCTest: Stdio not output at correct point Nov 11, 2022

grynspan closed this as not planned Won't fix, can't repro, duplicate, stale Sep 18, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

XCTest: Stdio not output at correct point #422

XCTest: Stdio not output at correct point #422

adam-fowler commented Sep 22, 2022

weissi commented Nov 10, 2022 •

edited

Loading

adam-fowler commented Nov 10, 2022 •

edited

Loading

weissi commented Nov 10, 2022

tomerd commented Nov 10, 2022 •

edited

Loading

stmontgomery commented Nov 10, 2022 •

edited

Loading

adam-fowler commented Nov 11, 2022

weissi commented Nov 11, 2022

grynspan commented Jun 28, 2023

weissi commented Jun 29, 2023

grynspan commented Jun 29, 2023

grynspan commented Sep 18, 2023

XCTest: Stdio not output at correct point #422

XCTest: Stdio not output at correct point #422

Comments

adam-fowler commented Sep 22, 2022

weissi commented Nov 10, 2022 • edited Loading

adam-fowler commented Nov 10, 2022 • edited Loading

weissi commented Nov 10, 2022

tomerd commented Nov 10, 2022 • edited Loading

stmontgomery commented Nov 10, 2022 • edited Loading

adam-fowler commented Nov 11, 2022

weissi commented Nov 11, 2022

grynspan commented Jun 28, 2023

weissi commented Jun 29, 2023

grynspan commented Jun 29, 2023

grynspan commented Sep 18, 2023

weissi commented Nov 10, 2022 •

edited

Loading

adam-fowler commented Nov 10, 2022 •

edited

Loading

tomerd commented Nov 10, 2022 •

edited

Loading

stmontgomery commented Nov 10, 2022 •

edited

Loading