Improve debug logging and add tests that it is not evaluated when disabled (#26)

### Motivation

The transport code has some debug logging, which is compile-time omitted
in release builds, and only enabled in tests.

A number of tests produce an enormous amount of output (e.g. the
streaming tests that pull 10GB through 10MB buffers), which are unwieldy
in CI and locally.

Additionally, we found that the logging produced by these tests had
interleaved output, both because of the mixed use of `print` and `debug`
in tests and the lack of locking between multiple threads

Finally, even when running in debug mode with debug logging _disabled_,
the function arguments to the `debug` function were still evaluated
unnecessarily.

### Modifications

- Update the `debug` function to log to standard error (cf. standard
out).
- Pass an autoclosure as argument to `debug` so that it is only
evaluated when logging is enabled.
- Add a lock around the use of `FileHandle.standardError`.
- Replace all stray uses of `print` in tests with `debug`.

### Result

- No debug logging should appear in tests by default (you can enable
them locally when reproducing failures).
- When enabled, log lines should not be all jumbled up.
- When disabled, no string interpolation is performed.

### Test Plan

- Added tests that check that the log message is not interpolated when
disabled.

Author: simonjbeaumont

Sources/OpenAPIURLSession/URLSessionTransport.swift

@@ -20,6 +20,7 @@ import Foundation
 @preconcurrency import struct Foundation.URLComponents
 @preconcurrency import struct Foundation.Data
 @preconcurrency import protocol Foundation.LocalizedError
+@preconcurrency import class Foundation.FileHandle
 #if canImport(FoundationNetworking)
 @preconcurrency import struct FoundationNetworking.URLRequest
 @preconcurrency import class FoundationNetworking.URLSession
@@ -230,10 +231,17 @@ var debugLoggingEnabled: Bool {
     get { _debugLoggingEnabled.withLockedValue { $0 } }
     set { _debugLoggingEnabled.withLockedValue { $0 = newValue } }
 }
-func debug(_ items: Any..., separator: String = " ", terminator: String = "\n") {
+private let _standardErrorLock = LockStorage.create(value: FileHandle.standardError)
+func debug(_ message: @autoclosure () -> String, function: String = #function, file: String = #file, line: UInt = #line)
+{
     assert(
         {
-            if debugLoggingEnabled { print(items, separator: separator, terminator: terminator) }
+            if debugLoggingEnabled {
+                _standardErrorLock.withLockedValue {
+                    let logLine = "[\(function) \(file.split(separator: "/").last!):\(line)] \(message())\n"
+                    $0.write(Data((logLine).utf8))
+                }
+            }
             return true
         }()
     )

Tests/OpenAPIURLSessionTests/AsyncBackpressuredStreamTests/AsyncBackpressuredStreamTests.swift

@@ -51,7 +51,7 @@ final class AsyncBackpressuredStreamTests: XCTestCase {
             group.addTask {
                 while true {
                     backPressureEventContinuation.yield(())
-                    print("Yielding")
+                    debug("Yielding")
                     try await source.asyncWrite(contentsOf: [1])
                 }
             }
@@ -64,12 +64,12 @@ final class AsyncBackpressuredStreamTests: XCTestCase {
             await backPressureEventIterator.next()
             await backPressureEventIterator.next()
 
-            print("Waited 4 times")
+            debug("Waited 4 times")
 
             _ = try await iterator.next()
             _ = try await iterator.next()
             _ = try await iterator.next()
-            print("Consumed three")
+            debug("Consumed three")
 
             await backPressureEventIterator.next()
             await backPressureEventIterator.next()
@@ -91,12 +91,12 @@ final class AsyncBackpressuredStreamTests: XCTestCase {
             group.addTask {
                 @Sendable func yield() {
                     backPressureEventContinuation.yield(())
-                    print("Yielding")
+                    debug("Yielding")
                     source.write(contentsOf: [1]) { result in
                         switch result {
                         case .success: yield()
 
-                        case .failure: print("Stopping to yield")
+                        case .failure: debug("Stopping to yield")
                         }
                     }
                 }
@@ -112,12 +112,12 @@ final class AsyncBackpressuredStreamTests: XCTestCase {
             await backPressureEventIterator.next()
             await backPressureEventIterator.next()
 
-            print("Waited 4 times")
+            debug("Waited 4 times")
 
             _ = try await iterator.next()
             _ = try await iterator.next()
             _ = try await iterator.next()
-            print("Consumed three")
+            debug("Consumed three")
 
             await backPressureEventIterator.next()
             await backPressureEventIterator.next()

Tests/OpenAPIURLSessionTests/NIOAsyncHTTP1TestServer.swift

@@ -14,6 +14,7 @@
 import NIOCore
 import NIOPosix
 import NIOHTTP1
+@testable import OpenAPIURLSession
 
 final class AsyncTestHTTP1Server {
 
@@ -58,10 +59,10 @@ final class AsyncTestHTTP1Server {
                     for try await connectionChannel in inbound {
                         group.addTask {
                             do {
-                                print("Sevrer handling new connection")
+                                debug("Sevrer handling new connection")
                                 try await connectionHandler(connectionChannel)
-                                print("Server done handling connection")
-                            } catch { print("Server error handling connection: \(error)") }
+                                debug("Server done handling connection")
+                            } catch { debug("Server error handling connection: \(error)") }
                         }
                     }
                 }

Tests/OpenAPIURLSessionTests/URLSessionBidirectionalStreamingTests/HTTPBodyOutputStreamTests.swift

@@ -19,7 +19,7 @@ import XCTest
 
 // swift-format-ignore: AllPublicDeclarationsHaveDocumentation
 class HTTPBodyOutputStreamBridgeTests: XCTestCase {
-    static override func setUp() { OpenAPIURLSession.debugLoggingEnabled = true }
+    static override func setUp() { OpenAPIURLSession.debugLoggingEnabled = false }
 
     func testHTTPBodyOutputStreamInputOutput() async throws {
         let chunkSize = 71

Tests/OpenAPIURLSessionTests/URLSessionBidirectionalStreamingTests/MockInputStreamDelegate.swift

@@ -14,6 +14,7 @@
 #if canImport(Darwin)
 
 import Foundation
+@testable import OpenAPIURLSession
 
 /// Reads one byte at a time from the stream, regardless of how many bytes are available.
 ///
@@ -39,7 +40,7 @@ final class MockInputStreamDelegate: NSObject, StreamDelegate {
         self.inputStream.open()
     }
 
-    deinit { print("Input stream delegate deinit") }
+    deinit { debug("Input stream delegate deinit") }
 
     private func readAndResumeContinuation() {
         dispatchPrecondition(condition: .onQueue(Self.streamQueue))
@@ -52,15 +53,15 @@ final class MockInputStreamDelegate: NSObject, StreamDelegate {
         }
         switch buffer.count {
         case -1:
-            print("Input stream delegate error reading from stream: \(inputStream.streamError!)")
+            debug("Input stream delegate error reading from stream: \(inputStream.streamError!)")
             inputStream.close()
             continuation.resume(throwing: inputStream.streamError!)
         case 0:
-            print("Input stream delegate reached end of stream; will close stream")
+            debug("Input stream delegate reached end of stream; will close stream")
             self.close()
             continuation.resume(returning: nil)
         case let numBytesRead where numBytesRead > 0:
-            print("Input stream delegate read \(numBytesRead) bytes from stream: \(buffer)")
+            debug("Input stream delegate read \(numBytesRead) bytes from stream: \(buffer)")
             continuation.resume(returning: buffer)
         default: preconditionFailure()
         }
@@ -85,12 +86,12 @@ final class MockInputStreamDelegate: NSObject, StreamDelegate {
     func close(withError error: (any Error)? = nil) {
         self.inputStream.close()
         Self.streamQueue.async { self.state = .closed(error) }
-        print("Input stream delegate closed stream with error: \(String(describing: error))")
+        debug("Input stream delegate closed stream with error: \(String(describing: error))")
     }
 
     func stream(_ stream: Stream, handle event: Stream.Event) {
         dispatchPrecondition(condition: .onQueue(Self.streamQueue))
-        print("Input stream delegate received event: \(event)")
+        debug("Input stream delegate received event: \(event)")
         switch event {
         case .hasBytesAvailable:
             switch state {

Tests/OpenAPIURLSessionTests/URLSessionBidirectionalStreamingTests/URLSessionBidirectionalStreamingTests.swift

@@ -23,7 +23,7 @@ import XCTest
 
 class URLSessionBidirectionalStreamingTests: XCTestCase {
     // swift-format-ignore: AllPublicDeclarationsHaveDocumentation
-    static override func setUp() { OpenAPIURLSession.debugLoggingEnabled = true }
+    static override func setUp() { OpenAPIURLSession.debugLoggingEnabled = false }
 
     func testBidirectionalEcho_PerChunkRatchet_1BChunk_1Chunks_1BUploadBuffer_1BDownloadWatermark() async throws {
         try await testBidirectionalEchoPerChunkRatchet(
@@ -329,31 +329,31 @@ class URLSessionBidirectionalStreamingTests: XCTestCase {
                                     )
                                 )
                             )
-                            print("Server sent response head")
+                            debug("Server sent response head")
                             for i in 1...numResponseChunks {
                                 try await outbound.write(.body(ByteBuffer(bytes: responseChunk)))
-                                print("Server sent body chunk \(i)/\(numResponseChunks) of \(responseChunk.count)")
+                                debug("Server sent body chunk \(i)/\(numResponseChunks) of \(responseChunk.count)")
                             }
                         case .body: preconditionFailure()
                         case .end:
                             try await outbound.write(.end(nil))
-                            print("Server sent response end")
+                            debug("Server sent response end")
                         }
                     }
                 }
             }
-            print("Server running on 127.0.0.1:\(serverPort)")
+            debug("Server running on 127.0.0.1:\(serverPort)")
 
             // Send the request.
-            print("Client starting request")
+            debug("Client starting request")
             let (response, responseBody) = try await URLSession.shared.bidirectionalStreamingRequest(
                 for: HTTPRequest(method: .get, scheme: nil, authority: nil, path: "/"),
                 baseURL: URL(string: "http://127.0.0.1:\(serverPort)")!,
                 requestBody: nil,
                 requestStreamBufferSize: 16 * 1024 * 1024,
                 responseStreamWatermarks: responseStreamWatermarks
             )
-            print("Client received response head: \(response)")
+            debug("Client received response head: \(response)")
             XCTAssertEqual(response.status, .ok)
 
             switch verification {
@@ -362,10 +362,10 @@ class URLSessionBidirectionalStreamingTests: XCTestCase {
                 var unprocessedBytes = ByteBuffer()
                 var numProcessedChunks = 0
                 for try await receivedResponseChunk in responseBody! {
-                    print("Client received some response body bytes (numBytes: \(receivedResponseChunk.count))")
+                    debug("Client received some response body bytes (numBytes: \(receivedResponseChunk.count))")
                     unprocessedBytes.writeBytes(receivedResponseChunk)
                     while unprocessedBytes.readableBytes >= responseChunk.count {
-                        print("Client reconstructing and verifying chunk \(numProcessedChunks+1)/\(numResponseChunks)")
+                        debug("Client reconstructing and verifying chunk \(numProcessedChunks+1)/\(numResponseChunks)")
                         XCTAssertEqual(
                             ArraySlice(unprocessedBytes.readBytes(length: responseChunk.count)!),
                             responseChunk
@@ -379,14 +379,14 @@ class URLSessionBidirectionalStreamingTests: XCTestCase {
             case .count:
                 var numBytesReceived = 0
                 for try await receivedResponseChunk in responseBody! {
-                    print("Client received some response body bytes (numBytes: \(receivedResponseChunk.count))")
+                    debug("Client received some response body bytes (numBytes: \(receivedResponseChunk.count))")
                     numBytesReceived += receivedResponseChunk.count
                 }
                 XCTAssertEqual(numBytesReceived, responseChunk.count * numResponseChunks)
             case .delay(let delay):
                 for try await receivedResponseChunk in responseBody! {
-                    print("Client received some response body bytes (numBytes: \(receivedResponseChunk.count))")
-                    print("Client doing fake work for \(delay)s")
+                    debug("Client received some response body bytes (numBytes: \(receivedResponseChunk.count))")
+                    debug("Client doing fake work for \(delay)s")
                     try await Task.sleep(nanoseconds: UInt64(delay.nanoseconds))
                 }
             }