September 14th, 2022

Server Workgroup Updates
1

Attendees:

@adam-fowler @fabianfett @graskind @jdmcd @kmahar @ktoso @Patrick

Action Items

  • All to catch up on the SPM plugin thread
  • @graskind to work on updating the property wrapper proposal
  • @adam-fowler to write a bug report about stdout problems and CC @kmahar @Patrick
  • @graskind to chat with @tomerd about codecov problems and ping @0xTim
  • @graskind to post in SwiftPM plugin thread about Fluent code generation ideas
  • @ktoso to check on if GraphQL proposal needs security.md

Previous Action Items

  • @patrick to post Swiftly design doc to forums and make the repository public (carry over with some progress)
    • Patrick put up a PR to the repository, waiting on review
  • @0xTim to get into touch with the forum post author about filing an issue. (Tim did reach out, not sure if an issue was created)

Agenda

SwiftPM Plugin Thread

  • @ktoso: Mostly idea gathering, some comments about missing features
  • Want to let it simmer a bit more, see if any other feedback comes up
  • Some ideas:
    • swiftformat as a SPM plugin
    • ACTION: @graskind to post about Fluent generation
    • @adam-fowler thinks that he'll use it for Soto at some point

Publishing Previous Weeks Notes

  • Will attempt to start every meeting with working through the backlog
  • July 20th has been published
  • August 3rd will be published pending one outstanding review
  • August 17th to be published in order
  • August 31st to be published in order

GraphQL Proposal Discussion

  • Want to be in incubating, they meet all the basics
  • Proposal looks solid and has good community feedback
  • They use async and have CI and support latest versions of Swift
  • Have 2 devs
  • May need to drop in a security note (@ktoso to check)
  • Will vote on GraphQL and Graphiti together

GraphQL Vote

Problems with stdout

Zombie XCTest Processes

  • @kmahar: Mongo has own in-house CI and using Macstadium hosts. Other teams run Swift code on these machines as well as Objective-C code. Sometimes leave behind zombie processes. Gets right up to the test portion and then just hangs (XCTest is waiting for other zombie process to finish)
  • @adam-fowloer: Have seen something similar
  • @ktoso: Happening on all platforms?
  • @adam-fowler: Just on Mac. Has to do with listing all tests and needing to rebuild. Solved by telling it not to rebuild. Have forwarded bug to @tomerd

Codecov bug affecting Vapor CI

  • @graskind: Command no longer works if only trying to get path after the test suite is done. This was in 5.6
  • @graskind: Changes that could make it a bit worse do not appear to have landed in 5.7
  • ACTION: @graskind to reach out to @tomerd about this problem
3 Likes
2

@adam-fowler if you don't mind, please ping me once done. Happy to help look.
Do I understand this correctly that this is about buffering issues with print(...)? If yes, is it going to a pipe, a file or a terminal? If not, the remainder here is likely irrelevant.

Because print goes through stdio's buffering system which defaults to

  • stdout: line buffered if connected to terminal
  • stdout: buffered (up to a few kB) if not going to a terminal
  • stderr: unbuffered

The effects can be seen here (assuming all of these are run in a terminal):

With this, the hello will show up only after 10 seconds because stdout is line buffered by default when connected to a terminal (and because of terminator: "" we don't print a newline so the buffer doesn't get flushed).

$ echo 'import Darwin; print("hello", terminator: ""); sleep(10)' | swift -
[10 seconds wait]
hello

With this however, the hello shows up immediately (because we're printing a newline):

$ echo 'import Darwin; print("hello"); sleep(10)' | swift -
hello

Lastly, this | cat will cause the hello to appear after the 10 seconds only because we're fully buffered when writing to a file.

$ echo 'import Darwin; print("hello"); sleep(10)' | swift - | cat
[10 seconds wait]
hello

Note that in most CI systems, stdout is normally connected to a pipe (for the orchestrator to capture the output), hence it might often appear to be stuck for a while.

Apart from the delays, there is one more issue: If we crash (or get killed) before the buffer gets flushed, we don't see anything. Nicely visible here:

If we're connected to a pipe, the hello is lost (because we never got to flush the buffer).

$ echo 'import Darwin; print("hello"); kill(getpid(), SIGKILL)' | swift - | cat
[the hello does not get printed]

Buf if we're connected to a terminal it prints because the buffer gets flushed on newline

$ echo 'import Darwin; print("hello"); kill(getpid(), SIGKILL)' | swift - 
hello
Killed: 9

FWIW, if you want to change the buffering, you have two options:

  1. fflush(stdout) to flush the buffer immediately
  2. set(v)buf to change the default buffering behaviour. With that it's possible to change stdout to be line-buffered even when connected to a pipe.
3

Hi @johannesweiss

The place I've seen this most frequently is when running swift test on macOS. Test results ie Test Case '-[MyLib.LibTests testArray]' passed (0.005 seconds). are output to stderr, for some inexplicable reason so can get out of sync with any stdout output. This is more likely to happen if you output a lot to stdout

eg the following test

    func testOutput() {
        for i in 0...5 {
            print(i)
        }
    }

produces

Test Suite 'Selected tests' started at 2022-11-10 10:07:03.891
Test Suite 'hummingbirdPackageTests.xctest' started at 2022-11-10 10:07:03.892
Test Suite 'ApplicationTests' started at 2022-11-10 10:07:03.892
Test Case '-[HummingbirdTests.ApplicationTests testOutput]' started.
Test Case '-[HummingbirdTests.ApplicationTests testOutput]' passed (0.002 seconds).
Test Suite 'ApplicationTests' passed at 2022-11-10 10:07:03.894.
         Executed 1 test, with 0 failures (0 unexpected) in 0.002 (0.002) seconds
Test Suite 'hummingbirdPackageTests.xctest' passed at 2022-11-10 10:07:03.894.
         Executed 1 test, with 0 failures (0 unexpected) in 0.002 (0.002) seconds
Test Suite 'Selected tests' passed at 2022-11-10 10:07:03.894.
         Executed 1 test, with 0 failures (0 unexpected) in 0.002 (0.004) seconds
0
1
2
3
4
5

When it makes more sense that it produce

Test Suite 'Selected tests' started at 2022-11-10 10:09:44.298
Test Suite 'hummingbirdPackageTests.xctest' started at 2022-11-10 10:09:44.299
Test Suite 'ApplicationTests' started at 2022-11-10 10:09:44.299
Test Case '-[HummingbirdTests.ApplicationTests testOutput]' started.
0
1
2
3
4
5
Test Case '-[HummingbirdTests.ApplicationTests testOutput]' passed (0.002 seconds).
Test Suite 'ApplicationTests' passed at 2022-11-10 10:09:44.301.
         Executed 1 test, with 0 failures (0 unexpected) in 0.002 (0.002) seconds
Test Suite 'hummingbirdPackageTests.xctest' passed at 2022-11-10 10:09:44.301.
         Executed 1 test, with 0 failures (0 unexpected) in 0.002 (0.002) seconds
Test Suite 'Selected tests' passed at 2022-11-10 10:09:44.301.
         Executed 1 test, with 0 failures (0 unexpected) in 0.002 (0.003) seconds

I'm pretty sure prior to swift 5.6 we got the second output.

I'm guessing this could actually just be a XCTest issue. Maybe some flushes were removed between tests.

4

Thanks @adam-fowler just saw the bug report at Stdio not output at correct point · Issue #61247 · apple/swift · GitHub

As expected a buffering issue where XCTest's status messages do not go through the buffer but print() does. Should be an easy fix in XCTest (and can be worked around manually by you if necessary in the interim).

5

By the way this is not an issue on linux because XCTest results go through stdout on linux.

6

Could be that, or maybe XCTest did go through the stdio buffer prior to 5.6? Many options, in any case I think XCTest should make sure that everything in the stdio buffers gets flushed and that its output is aligned to that.

This is especially true because I think it prints its status messages to stderr and print goes through stdout. Technically these are two totally separate output streams but for humans they usually appear merged in a file or a terminal. So I think it's reasonable to assume that XCTest flushes everything.

7

I'm pretty sure XCTest has always output to stderr on macOS. Well at least all the versions I have tested. I needed to know when developing VSCode extension.

1 Like
10

(Deleted some more posts, somehow misread what you said.)

Just FWIW, this reordering can still happen:

$ echo 'import Darwin; print("hello"); write(1, "world\n", 6)' | swift -
hello
world
$ echo 'import Darwin; print("hello"); write(1, "world\n", 6)' | swift - | cat
world
hello

See how we see hello first, then world when writing to a terminal (because then stdout is line-buffered so the buffer will be flushed immediately after print("hello")).
But world first and then hello when writing to a pipe (because the buffer is 'fully buffered' which means it's only flushed on exit (or if we were to print a lot of data)).