Fix threading violation in KeyLogCallbackManager (#250)

Motivation:

The KeyLogCallbackManager belongs on an SSLContext, and so may be
invoked from multiple threads. However, it incorrectly cached a
ByteBuffer on its storage, leading to thread unsafety. This tends to
manifest in assertion failures, but could lead to arbitrary data
corruption or double frees.

Modifications:

- Remove the cached bytebuffer.
- Add probabilistic test.

Result:

No more thread-safety violations.

Sources/NIOSSL/SSLCallbacks.swift

@@ -106,31 +106,23 @@ public typealias NIOSSLKeyLogCallback = (ByteBuffer) -> Void
 internal struct KeyLogCallbackManager {
     private var callback: NIOSSLKeyLogCallback
 
-    private var scratchBuffer: ByteBuffer
-}
-
-extension KeyLogCallbackManager {
     init(callback: @escaping NIOSSLKeyLogCallback) {
         self.callback = callback
-
-        // We need to allocate a bytebuffer into which we can write the string. Normally we wouldn't just magic
-        // a ByteBufferAllocator into existence, but here it's just worthwhile doing, not least because a SSLContext doesn't
-        // necessarily belong to only one Channel anyway. As for 512: it seemed a reasonable guess that 512 bytes was about as long as this
-        // needed to be (most secrets won't be longer than 256 bits, which is 32 bytes, so even when base64 encoded we have loads of headroom).
-        self.scratchBuffer = ByteBufferAllocator().buffer(capacity: 512)
     }
 }
 
 extension KeyLogCallbackManager {
     /// Called to log a string to the user.
-    mutating func log(_ stringPointer: UnsafePointer<CChar>) {
-        self.scratchBuffer.clear()
-
+    func log(_ stringPointer: UnsafePointer<CChar>) {
         let len = strlen(stringPointer)
+
+        // We don't cache this because `log` can be called from arbitrary threads concurrently.
+        var scratchBuffer = ByteBufferAllocator().buffer(capacity: len + 1)
+
         let bufferPointer = UnsafeRawBufferPointer(start: stringPointer, count: Int(len))
-        self.scratchBuffer.writeBytes(bufferPointer)
-        self.scratchBuffer.writeInteger(UInt8(ascii: "\n"))
-        self.callback(self.scratchBuffer)
+        scratchBuffer.writeBytes(bufferPointer)
+        scratchBuffer.writeInteger(UInt8(ascii: "\n"))
+        self.callback(scratchBuffer)
     }
 }
 

Tests/NIOSSLTests/TLSConfigurationTest+XCTest.swift

@@ -40,6 +40,7 @@ extension TLSConfigurationTest {
                 ("testMatchingCompatibleSignatures", testMatchingCompatibleSignatures),
                 ("testNonexistentFileObject", testNonexistentFileObject),
                 ("testComputedApplicationProtocols", testComputedApplicationProtocols),
+                ("testKeyLogManagerOverlappingAccess", testKeyLogManagerOverlappingAccess),
            ]
    }
 }

Tests/NIOSSLTests/TLSConfigurationTest.swift

@@ -401,4 +401,44 @@ class TLSConfigurationTest: XCTestCase {
         XCTAssertEqual(config.applicationProtocols, ["h2", "http/1.1"])
         XCTAssertEqual(config.encodedApplicationProtocols, [[2, 104, 50], [8, 104, 116, 116, 112, 47, 49, 46, 49]])
     }
+
+    func testKeyLogManagerOverlappingAccess() throws {
+        // Tests that we can have overlapping calls to the log() function of the keylog manager.
+        // This test fails probabilistically! DO NOT IGNORE INTERMITTENT FAILURES OF THIS TEST.
+        let semaphore = DispatchSemaphore(value: 0)
+        let group = DispatchGroup()
+        let completionsQueue = DispatchQueue(label: "completionsQueue")
+        var completions: [Bool] = []
+
+        func keylogCallback(_ ign: ByteBuffer) {
+            completionsQueue.sync {
+                completions.append(true)
+                semaphore.wait()
+            }
+            group.leave()
+        }
+
+        let keylogManager = KeyLogCallbackManager(callback: keylogCallback(_:))
+
+        // Now we call log twice, from different threads. These will not complete right away so we
+        // do those on background threads. They should not both complete.
+        group.enter()
+        group.enter()
+        DispatchQueue(label: "first-thread").async {
+            keylogManager.log("hello!")
+        }
+        DispatchQueue(label: "second-thread").async {
+            keylogManager.log("world!")
+        }
+
+        // We now sleep a short time to let everything catch up and the runtime catch any exclusivity violation.
+        // 10ms is fine.
+        usleep(10_000)
+
+        // Great, signal the sempahore twice to un-wedge everything and wait for everything to exit.
+        semaphore.signal()
+        semaphore.signal()
+        group.wait()
+        XCTAssertEqual([true, true], completionsQueue.sync { completions })
+    }
 }