test(zero-swift): show the test server's side when an app lifecycle test times out (#115)

The lifecycle tests' flake on the iOS Simulator (4 of about 60 macOS
runs) shows only the client's log: it sent the WebSocket upgrade and never
logged the socket opening, then timed out after 10 s, as the test did. The
local server's view, whether it accepted the connection and the upgrade
finished, wasn't recorded, so which side stalls is unknown. The server now
writes its listener and connection events to the same log the failure
prints.

Amp-Thread-ID: https://ampcode.com/threads/T-c513a037-a257-45e0-b9a9-15c15edfe859

Co-authored-by: Amp <amp@ampcode.com>

Author: tmm

swift/Tests/AppleTests/AppLifecycleTests.swift

@@ -30,15 +30,23 @@
       private var peers: [WebSocketServer.Peer] = []
       private var task: Task<Void, Never>?
 
-      init() async throws {
-        server = try WebSocketServer()
+      /// Its events go to `log`, with the client's, so a test that times out shows what the server saw.
+      init(_ log: RecordingLogSink) async throws {
+        server = try WebSocketServer(trace: {
+          log.log(level: .debug, message: "server: \($0)", context: [:])
+        })
         port = try await server.start()
-        task = Task { @MainActor [server] in
+        task = Task { @MainActor [server, log] in
           for await event in server.events {
             switch event {
             case .connected(let peer, _):
               self.connected += 1
               self.peers.append(peer)
+              log.log(
+                level: .debug,
+                message:
+                  "server: \(peer.connection.endpoint) open, acknowledging: \(self.acknowledge)",
+                context: [:])
               if self.acknowledge { peer.send(.text(#"["connected",{"wsid":"w"}]"#)) }
             case .message(let peer, .text(let text)):
               self.messages.append(text)
@@ -177,7 +185,7 @@
     }
 
     @Test func hiddenDisconnectsAndShownReconnects() async throws {
-      let server = try await Server()
+      let server = try await Server(log)
       defer { server.stop() }
       let zero = try makeZero(server)
       defer { zero.close() }
@@ -193,7 +201,7 @@
 
     /// Hidden while the socket is open but not yet acknowledged: the client ends up disconnected with no socket open, and connects when shown. If the attempt timed out first (`timedOutWhileStopped`), the client closed the socket and, hidden, waits to be shown, still connecting, as zero-client does.
     @Test func hiddenWhileConnecting() async throws {
-      let server = try await Server()
+      let server = try await Server(log)
       defer { server.stop() }
       server.acknowledge = false
       let zero = try makeZero(server)
@@ -218,7 +226,7 @@
 
     /// Many transitions in a row, without waiting between them: the client ends up in the state of the last one, with at most one socket open.
     @Test func rapidTransitionsSettleOnTheLast() async throws {
-      let server = try await Server()
+      let server = try await Server(log)
       defer { server.stop() }
       let zero = try makeZero(server)
       defer { zero.close() }
@@ -250,7 +258,7 @@
 
     /// Transitions after `close()` do nothing: no socket is opened and the client stays closed.
     @Test func transitionsAfterCloseDoNothing() async throws {
-      let server = try await Server()
+      let server = try await Server(log)
       defer { server.stop() }
       let zero = try makeZero(server)
       try await eventually("connected") { zero.connection.state == .connected }
@@ -268,7 +276,7 @@
 
     /// A `Zero` released without `close()`: its observers go with it, and later transitions don't reach it.
     @Test func releasedZeroStopsObserving() async throws {
-      let server = try await Server()
+      let server = try await Server(log)
       defer { server.stop() }
       weak var weakZero: Zero<Void>?
       do {
@@ -288,7 +296,7 @@
     #if canImport(UIKit)
       /// In the background, the client waits for the server to confirm the pending mutations before it disconnects, up to 10 seconds; back in the foreground before that, it stays connected.
       @Test func backgroundWaitsForPendingMutationsUntilTheForeground() async throws {
-        let server = try await Server()
+        let server = try await Server(log)
         defer { server.stop() }
         let zero = try makeZero(server)
         defer { zero.close() }
@@ -305,7 +313,7 @@
 
       /// The server never confirms: the client disconnects after the 10 seconds.
       @Test func backgroundGivesUpWaitingAfterTenSeconds() async throws {
-        let server = try await Server()
+        let server = try await Server(log)
         defer { server.stop() }
         let zero = try makeZero(server)
         defer { zero.close() }

swift/Tests/AppleTests/WebSocketServer.swift

@@ -64,8 +64,11 @@
     let events: AsyncStream<Event>
     private let continuation: AsyncStream<Event>.Continuation
     private let protocols = Locked<[String]>([])
+    /// Reports the listener's and the connections' state changes, for a test to show when it fails.
+    private let trace: (@Sendable (String) -> Void)?
 
-    init() throws {
+    init(trace: (@Sendable (String) -> Void)? = nil) throws {
+      self.trace = trace
       (events, continuation) = AsyncStream<Event>.makeStream()
       let parameters = NWParameters.tcp
       let options = NWProtocolWebSocket.Options()
@@ -86,15 +89,18 @@
       let continuation = self.continuation
       let protocols = self.protocols
       let queue = self.queue
+      let trace = self.trace
       listener.newConnectionHandler = { connection in
         let peer = Peer(connection)
+        trace?("accepted \(connection.endpoint)")
         connection.stateUpdateHandler = { state in
+          trace?("\(connection.endpoint) \(state)")
           if case .ready = state {
             continuation.yield(.connected(peer, protocols: protocols.withLock { $0 }))
           }
         }
         connection.start(queue: queue)
-        Self.receive(peer, continuation)
+        Self.receive(peer, continuation, trace)
       }
       return try await withCheckedThrowingContinuation {
         (c: CheckedContinuation<UInt16, any Error>) in
@@ -106,6 +112,7 @@
           }
         }
         listener.stateUpdateHandler = { [listener] state in
+          trace?("listener \(state)")
           switch state {
           case .ready: if first() { c.resume(returning: listener.port?.rawValue ?? 0) }
           case .failed(let error): if first() { c.resume(throwing: error) }
@@ -121,9 +128,13 @@
       continuation.finish()
     }
 
-    private static func receive(_ peer: Peer, _ events: AsyncStream<Event>.Continuation) {
+    private static func receive(
+      _ peer: Peer, _ events: AsyncStream<Event>.Continuation,
+      _ trace: (@Sendable (String) -> Void)?
+    ) {
       peer.connection.receiveMessage { data, context, _, error in
-        if error != nil {
+        if let error {
+          trace?("\(peer.connection.endpoint) receive failed: \(error)")
           events.yield(.closed(peer, code: 1006))
           return
         }
@@ -142,12 +153,13 @@
           case .applicationCode(let c)?, .privateCode(let c)?: code = Int(c)
           default: break
           }
+          trace?("\(peer.connection.endpoint) close frame \(code)")
           events.yield(.closed(peer, code: code))
           return
         default:
           break
         }
-        receive(peer, events)
+        receive(peer, events, trace)
       }
     }
   }