Improve debug logging and add tests that it is not evaluated when disabled

simonjbeaumont · simonjbeaumont · commit 1a90ef0513d9 · 2023-11-23T10:24:40.000Z
diff --git a/Sources/OpenAPIURLSession/URLSessionTransport.swift b/Sources/OpenAPIURLSession/URLSessionTransport.swift
@@ -230,10 +230,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
         }()
     )
diff --git a/Tests/OpenAPIURLSessionTests/AsyncBackpressuredStreamTests/AsyncBackpressuredStreamTests.swift b/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()
diff --git a/Tests/OpenAPIURLSessionTests/NIOAsyncHTTP1TestServer.swift b/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)") }
                         }
                     }
                 }
diff --git a/Tests/OpenAPIURLSessionTests/URLSessionBidirectionalStreamingTests/HTTPBodyOutputStreamTests.swift b/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
diff --git a/Tests/OpenAPIURLSessionTests/URLSessionBidirectionalStreamingTests/MockInputStreamDelegate.swift b/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 {
diff --git a/Tests/OpenAPIURLSessionTests/URLSessionBidirectionalStreamingTests/URLSessionBidirectionalStreamingTests.swift b/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))
                 }
             }
diff --git a/Tests/OpenAPIURLSessionTests/URLSessionTransportTests.swift b/Tests/OpenAPIURLSessionTests/URLSessionTransportTests.swift
@@ -24,7 +24,7 @@ import XCTest
 
 // swift-format-ignore: AllPublicDeclarationsHaveDocumentation
 class URLSessionTransportConverterTests: XCTestCase {
-    static override func setUp() { OpenAPIURLSession.debugLoggingEnabled = true }
+    static override func setUp() { OpenAPIURLSession.debugLoggingEnabled = false }
 
     func testRequestConversion() async throws {
         let request = HTTPRequest(
@@ -58,7 +58,7 @@ class URLSessionTransportConverterTests: XCTestCase {
 class URLSessionTransportBufferedTests: XCTestCase {
     var transport: (any ClientTransport)!
 
-    static override func setUp() { OpenAPIURLSession.debugLoggingEnabled = true }
+    static override func setUp() { OpenAPIURLSession.debugLoggingEnabled = false }
 
     override func setUp() async throws {
         transport = URLSessionTransport(configuration: .init(implementation: .buffering))
@@ -91,7 +91,7 @@ class URLSessionTransportBufferedTests: XCTestCase {
 class URLSessionTransportStreamingTests: XCTestCase {
     var transport: (any ClientTransport)!
 
-    static override func setUp() { OpenAPIURLSession.debugLoggingEnabled = true }
+    static override func setUp() { OpenAPIURLSession.debugLoggingEnabled = false }
 
     override func setUpWithError() throws {
         try XCTSkipUnless(URLSessionTransport.Configuration.Implementation.platformSupportsStreaming)
@@ -165,43 +165,43 @@ func testHTTPRedirect(
                 while let requestPart = try await requestPartIterator.next() {
                     switch requestPart {
                     case .head(let head):
-                        print("Server received head for \(head.uri)")
+                        debug("Server received head for \(head.uri)")
                         currentURI = head.uri
                     case .body(let buffer):
                         let currentURI = try XCTUnwrap(currentURI)
-                        print("Server received body bytes for \(currentURI) (numBytes: \(buffer.readableBytes))")
+                        debug("Server received body bytes for \(currentURI) (numBytes: \(buffer.readableBytes))")
                         accumulatedBody.writeImmutableBuffer(buffer)
                     case .end:
                         let currentURI = try XCTUnwrap(currentURI)
-                        print("Server received end for \(currentURI)")
+                        debug("Server received end for \(currentURI)")
                         XCTAssertEqual(accumulatedBody, ByteBuffer(string: requestBodyChunks.joined()))
                         switch currentURI {
                         case "/old":
-                            print("Server reseting body buffer")
+                            debug("Server reseting body buffer")
                             accumulatedBody = ByteBuffer()
                             try await outbound.write(
                                 .head(
                                     .init(version: .http1_1, status: .temporaryRedirect, headers: ["Location": "/new"])
                                 )
                             )
-                            print("Server sent head for \(currentURI)")
+                            debug("Server sent head for \(currentURI)")
                             try await outbound.write(.end(nil))
-                            print("Server sent end for \(currentURI)")
+                            debug("Server sent end for \(currentURI)")
                         case "/new":
                             try await outbound.write(.head(.init(version: .http1_1, status: .ok)))
-                            print("Server sent head for \(currentURI)")
+                            debug("Server sent head for \(currentURI)")
                             try await outbound.write(.end(nil))
-                            print("Server sent end for \(currentURI)")
+                            debug("Server sent end for \(currentURI)")
                         default: preconditionFailure()
                         }
                     }
                 }
             }
         }
-        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")
         if expectFailureDueToIterationBehavior {
             await XCTAssertThrowsError(
                 try await transport.send(
@@ -218,7 +218,7 @@ func testHTTPRedirect(
                 baseURL: URL(string: "http://127.0.0.1:\(serverPort)")!,
                 operationID: "unused"
             )
-            print("Client received response head: \(response)")
+            debug("Client received response head: \(response)")
             XCTAssertEqual(response.status, .ok)
         }
 
@@ -248,17 +248,17 @@ func testHTTPBasicGet(transport: any ClientTransport) async throws {
                 }
             }
         }
-        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, maybeResponseBody) = try await transport.send(
             HTTPRequest(method: .get, scheme: nil, authority: nil, path: requestPath),
             body: nil,
             baseURL: URL(string: "http://127.0.0.1:\(serverPort)")!,
             operationID: "unused"
         )
-        print("Client received response head: \(response)")
+        debug("Client received response head: \(response)")
         XCTAssertEqual(response.status, .ok)
         let receivedMessage = try await String(collecting: try XCTUnwrap(maybeResponseBody), upTo: .max)
         XCTAssertEqual(receivedMessage, responseBodyMessage)
@@ -292,21 +292,46 @@ func testHTTPBasicPost(transport: any ClientTransport) async throws {
                 }
             }
         }
-        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, maybeResponseBody) = try await transport.send(
             HTTPRequest(method: .post, scheme: nil, authority: nil, path: requestPath),
             body: HTTPBody(requestBodyMessage),
             baseURL: URL(string: "http://127.0.0.1:\(serverPort)")!,
             operationID: "unused"
         )
-        print("Client received response head: \(response)")
+        debug("Client received response head: \(response)")
         XCTAssertEqual(response.status, .ok)
         let receivedMessage = try await String(collecting: try XCTUnwrap(maybeResponseBody), upTo: .max)
         XCTAssertEqual(receivedMessage, responseBodyMessage)
 
         group.cancelAll()
     }
 }
+
+class URLSessionTransportDebugLoggingTests: XCTestCase {
+    func testDebugLoggingEnabled() async throws {
+        let expectation = expectation(description: "message autoclosure evaluated")
+        func message() -> String {
+            expectation.fulfill()
+            return "message"
+        }
+        OpenAPIURLSession.debugLoggingEnabled = true
+        debug(message())
+        await fulfillment(of: [expectation], timeout: 0)
+    }
+
+    func testDebugLoggingDisabled() async throws {
+        let expectation = expectation(description: "message autoclosure evaluated")
+        expectation.isInverted = true
+        func message() -> String {
+            expectation.fulfill()
+            return "message"
+        }
+        OpenAPIURLSession.debugLoggingEnabled = false
+        debug(message())
+        await fulfillment(of: [expectation], timeout: 0)
+    }
+}

Original file line number	Diff line number	Diff line change
`@@ -14,6 +14,7 @@`
`14`	`14`	`import NIOCore`
`15`	`15`	`import NIOPosix`
`16`	`16`	`import NIOHTTP1`
	`17`	`+@testable import OpenAPIURLSession`
`17`	`18`
`18`	`19`	`final class AsyncTestHTTP1Server {`
`19`	`20`
`@@ -58,10 +59,10 @@ final class AsyncTestHTTP1Server {`
`58`	`59`	`for try await connectionChannel in inbound {`
`59`	`60`	`group.addTask {`
`60`	`61`	`do {`
`61`		`- print("Sevrer handling new connection")`
	`62`	`+ debug("Sevrer handling new connection")`
`62`	`63`	`try await connectionHandler(connectionChannel)`
`63`		`- print("Server done handling connection")`
`64`		`- } catch { print("Server error handling connection: \(error)") }`
	`64`	`+ debug("Server done handling connection")`
	`65`	`+ } catch { debug("Server error handling connection: \(error)") }`
`65`	`66`	`}`
`66`	`67`	`}`
`67`	`68`	`}`