Thread sanitizer finds issues

[bridger]

I tried running my server with thread sanitizer enabled and it flagged several data races in InconingSocketManager.swift. My server uses websockets, which might be related to these data races.

They are easy to repro for me, but here are some of them it found for reference:

WARNING: ThreadSanitizer: data race (pid=67210)
  Write of size 1 at 0x7b1c00068df0 by thread T14:
  * #0 WSSocketProcessor.inProgress.setter WSSocketProcessor.swift (KituraWebSocket:x86_64+0x10b89)
    #1 protocol witness for IncomingSocketProcessor.inProgress.setter in conformance WSSocketProcessor WSSocketProcessor.swift (KituraWebSocket:x86_64+0x1380c)
    #2 IncomingSocketHandler.handleCancel() IncomingSocketHandler.swift:398 (KituraNet:x86_64+0xbb14b)
    #3 partial apply IncomingSocketHandler.swift (KituraNet:x86_64+0xbcad4)
    #4 thunk for @callee_owned () -> () FastCGIServer.swift (KituraNet:x86_64+0x3d34c)
    #5 __tsan::dispatch_callback_wrap(void*) <null>:5353648 (libclang_rt.tsan_osx_dynamic.dylib:x86_64h+0x662e1)
    #6 _dispatch_call_block_and_release <null>:5353648 (libdispatch.dylib:x86_64+0x9c3c)

  Previous read of size 1 at 0x7b1c00068df0 by thread T1:
  * #0 WSSocketProcessor.inProgress.getter WSSocketProcessor.swift (KituraWebSocket:x86_64+0x10b0a)
    #1 protocol witness for IncomingSocketProcessor.inProgress.getter in conformance WSSocketProcessor WSSocketProcessor.swift (KituraWebSocket:x86_64+0x13763)
    #2 IncomingSocketManager.removeIdleSockets(removeAll:) IncomingSocketManager.swift:242 (KituraNet:x86_64+0xbf1c0)
    #3 IncomingSocketManager.handle(socket:processor:) IncomingSocketManager.swift:137 (KituraNet:x86_64+0xbde71)
    #4 HTTPServer.handleClientConnection(clientSocket:socketManager:) HTTPServer.swift:278 (KituraNet:x86_64+0x71183)
    #5 HTTPServer.listen(listenSocket:socketManager:) HTTPServer.swift:223 (KituraNet:x86_64+0x6c09c)
    #6 closure #1 in HTTPServer.listen(on:) HTTPServer.swift:133 (KituraNet:x86_64+0x69aee)
    #7 partial apply for closure #1 in HTTPServer.listen(on:) HTTPServer.swift (KituraNet:x86_64+0x69c8c)
    #8 thunk for @callee_owned () -> () FastCGIServer.swift (KituraNet:x86_64+0x3d34c)
    #9 _dispatch_client_callout <null>:5353648 (libdispatch.dylib:x86_64+0x1d1e)
    #10 _dispatch_client_callout <null>:5353648 (libdispatch.dylib:x86_64+0x1d1e)

  Issue is caused by frames marked with "*".

  Location is heap block of size 112 at 0x7b1c00068dd0 allocated by thread T5:
    #0 malloc <null>:5353680 (libclang_rt.tsan_osx_dynamic.dylib:x86_64h+0x48b3a)
    #1 swift_slowAlloc <null>:5353680 (libswiftCore.dylib:x86_64+0x344478)
    #2 WSSocketProcessor.__allocating_init(connection:) WSSocketProcessor.swift (KituraWebSocket:x86_64+0x11584)
    #3 WSConnectionUpgradeFactory.upgrade(handler:request:response:) WSConnectionUpgradeFactory.swift:73 (KituraWebSocket:x86_64+0x36f8)
    #4 protocol witness for ConnectionUpgradeFactory.upgrade(handler:request:response:) in conformance WSConnectionUpgradeFactory WSConnectionUpgradeFactory.swift (KituraWebSocket:x86_64+0x4e8b)
    #5 ConnectionUpgradeFactory.upgrade(handler:request:response:) ConnectionUpgradeFactory.swift:54 (KituraNet:x86_64+0x20185)
    #6 ConnectionUpgrader.upgradeConnection(handler:request:response:) ConnectionUpgrader.swift:77 (KituraNet:x86_64+0x22788)
    #7 IncomingHTTPSocketProcessor.parsingComplete() IncomingHTTPSocketProcessor.swift:245 (KituraNet:x86_64+0x8c9d0)
    #8 IncomingHTTPSocketProcessor.parse(_:) IncomingHTTPSocketProcessor.swift:222 (KituraNet:x86_64+0x8bcd0)
    #9 IncomingHTTPSocketProcessor.process(_:) IncomingHTTPSocketProcessor.swift:98 (KituraNet:x86_64+0x8a5b3)
    #10 protocol witness for IncomingSocketProcessor.process(_:) in conformance IncomingHTTPSocketProcessor IncomingHTTPSocketProcessor.swift (KituraNet:x86_64+0x8deec)
    #11 IncomingSocketHandler.handleReadHelper() IncomingSocketHandler.swift:167 (KituraNet:x86_64+0xb2d5d)
    #12 IncomingSocketHandler.handleRead() IncomingSocketHandler.swift:139 (KituraNet:x86_64+0xb0984)
    #13 closure #1 in IncomingSocketHandler.init(socket:using:) IncomingSocketHandler.swift:105 (KituraNet:x86_64+0xaff37)
    #14 partial apply for closure #1 in IncomingSocketHandler.init(socket:using:) IncomingSocketHandler.swift (KituraNet:x86_64+0xaff8d)
    #15 thunk for @callee_owned () -> () FastCGIServer.swift (KituraNet:x86_64+0x3d34c)
    #16 __tsan::dispatch_callback_wrap(void*) <null>:5353680 (libclang_rt.tsan_osx_dynamic.dylib:x86_64h+0x662e1)
    #17 _dispatch_client_callout <null>:5353680 (libdispatch.dylib:x86_64+0x1d1e)

  Thread T14 (tid=5477528, running) is a GCD worker thread

  Thread T1 (tid=5475065, running) is a GCD worker thread

  Thread T5 (tid=5475102, finished) is a GCD worker thread

SUMMARY: ThreadSanitizer: data race WSSocketProcessor.swift in WSSocketProcessor.inProgress.setter

WARNING: ThreadSanitizer: data race (pid=67210)
  Write of size 8 at 0x7b2400009178 by thread T14:
  * #0 IncomingSocketHandler.processor.setter IncomingSocketHandler.swift (KituraNet:x86_64+0xadd4f)
    #1 IncomingSocketHandler.handleCancel() IncomingSocketHandler.swift:402 (KituraNet:x86_64+0xbb577)
    #2 partial apply IncomingSocketHandler.swift (KituraNet:x86_64+0xbcad4)
    #3 thunk for @callee_owned () -> () FastCGIServer.swift (KituraNet:x86_64+0x3d34c)
    #4 __tsan::dispatch_callback_wrap(void*) <null>:5353696 (libclang_rt.tsan_osx_dynamic.dylib:x86_64h+0x662e1)
    #5 _dispatch_call_block_and_release <null>:5353696 (libdispatch.dylib:x86_64+0x9c3c)

  Previous read of size 8 at 0x7b2400009178 by thread T1:
  * #0 IncomingSocketHandler.processor.getter IncomingSocketHandler.swift (KituraNet:x86_64+0xadc43)
    #1 IncomingSocketManager.removeIdleSockets(removeAll:) IncomingSocketManager.swift:242 (KituraNet:x86_64+0xbee0a)
    #2 IncomingSocketManager.handle(socket:processor:) IncomingSocketManager.swift:137 (KituraNet:x86_64+0xbde71)
    #3 HTTPServer.handleClientConnection(clientSocket:socketManager:) HTTPServer.swift:278 (KituraNet:x86_64+0x71183)
    #4 HTTPServer.listen(listenSocket:socketManager:) HTTPServer.swift:223 (KituraNet:x86_64+0x6c09c)
    #5 closure #1 in HTTPServer.listen(on:) HTTPServer.swift:133 (KituraNet:x86_64+0x69aee)
    #6 partial apply for closure #1 in HTTPServer.listen(on:) HTTPServer.swift (KituraNet:x86_64+0x69c8c)
    #7 thunk for @callee_owned () -> () FastCGIServer.swift (KituraNet:x86_64+0x3d34c)
    #8 _dispatch_client_callout <null>:5353696 (libdispatch.dylib:x86_64+0x1d1e)
    #9 _dispatch_client_callout <null>:5353696 (libdispatch.dylib:x86_64+0x1d1e)

  Issue is caused by frames marked with "*".

  Location is heap block of size 133 at 0x7b2400009120 allocated by thread T1:
    #0 malloc <null>:5353728 (libclang_rt.tsan_osx_dynamic.dylib:x86_64h+0x48b3a)
    #1 swift_slowAlloc <null>:5353728 (libswiftCore.dylib:x86_64+0x344478)
    #2 IncomingSocketHandler.__allocating_init(socket:using:) IncomingSocketHandler.swift (KituraNet:x86_64+0xaea3c)
    #3 IncomingSocketManager.handle(socket:processor:) IncomingSocketManager.swift:120 (KituraNet:x86_64+0xbdb8e)
    #4 HTTPServer.handleClientConnection(clientSocket:socketManager:) HTTPServer.swift:278 (KituraNet:x86_64+0x71183)
    #5 HTTPServer.listen(listenSocket:socketManager:) HTTPServer.swift:223 (KituraNet:x86_64+0x6c09c)
    #6 closure #1 in HTTPServer.listen(on:) HTTPServer.swift:133 (KituraNet:x86_64+0x69aee)
    #7 partial apply for closure #1 in HTTPServer.listen(on:) HTTPServer.swift (KituraNet:x86_64+0x69c8c)
    #8 thunk for @callee_owned () -> () FastCGIServer.swift (KituraNet:x86_64+0x3d34c)
    #9 _dispatch_client_callout <null>:5353728 (libdispatch.dylib:x86_64+0x1d1e)
    #10 _dispatch_client_callout <null>:5353728 (libdispatch.dylib:x86_64+0x1d1e)

  Thread T14 (tid=5477528, running) is a GCD worker thread

  Thread T1 (tid=5475065, running) is a GCD worker thread

SUMMARY: ThreadSanitizer: data race IncomingSocketHandler.swift in IncomingSocketHandler.processor.setter

WARNING: ThreadSanitizer: data race (pid=67210)
  Write of size 4 at 0x7b440001a064 by thread T13:
  * #0 Socket.socketfd.setter Socket.swift (Socket:x86_64+0x1bcc6)
    #1 Socket.close(withSSLCleanup:) Socket.swift:3376 (Socket:x86_64+0x70f27)
    #2 Socket.close() Socket.swift:1557 (Socket:x86_64+0x38edc)
    #3 IncomingSocketHandler.handleCancel() IncomingSocketHandler.swift:395 (KituraNet:x86_64+0xbb034)
    #4 partial apply IncomingSocketHandler.swift (KituraNet:x86_64+0xbcad4)
    #5 thunk for @callee_owned () -> () FastCGIServer.swift (KituraNet:x86_64+0x3d34c)
    #6 __tsan::dispatch_callback_wrap(void*) <null>:1594000 (libclang_rt.tsan_osx_dynamic.dylib:x86_64h+0x662e1)
    #7 _dispatch_call_block_and_release <null>:1594000 (libdispatch.dylib:x86_64+0x9c3c)

  Previous read of size 4 at 0x7b440001a064 by thread T1:
  * #0 Socket.socketfd.getter Socket.swift (Socket:x86_64+0x1bc4a)
    #1 IncomingSocketManager.handle(socket:processor:) IncomingSocketManager.swift:121 (KituraNet:x86_64+0xbdbeb)
    #2 HTTPServer.handleClientConnection(clientSocket:socketManager:) HTTPServer.swift:278 (KituraNet:x86_64+0x71183)
    #3 HTTPServer.listen(listenSocket:socketManager:) HTTPServer.swift:223 (KituraNet:x86_64+0x6c09c)
    #4 closure #1 in HTTPServer.listen(on:) HTTPServer.swift:133 (KituraNet:x86_64+0x69aee)
    #5 partial apply for closure #1 in HTTPServer.listen(on:) HTTPServer.swift (KituraNet:x86_64+0x69c8c)
    #6 thunk for @callee_owned () -> () FastCGIServer.swift (KituraNet:x86_64+0x3d34c)
    #7 _dispatch_client_callout <null>:1594000 (libdispatch.dylib:x86_64+0x1d1e)
    #8 _dispatch_client_callout <null>:1594000 (libdispatch.dylib:x86_64+0x1d1e)

  Issue is caused by frames marked with "*".

  Location is heap block of size 292 at 0x7b440001a040 allocated by thread T1:
    #0 malloc <null>:1594032 (libclang_rt.tsan_osx_dynamic.dylib:x86_64h+0x48b3a)
    #1 swift_slowAlloc <null>:1594032 (libswiftCore.dylib:x86_64+0x344478)
    #2 Socket.__allocating_init(fd:remoteAddress:path:) Socket.swift (Socket:x86_64+0x24845)
    #3 Socket.acceptClientConnection(invokeDelegate:) Socket.swift:1402 (Socket:x86_64+0x33861)
    #4 HTTPServer.listen(listenSocket:socketManager:) HTTPServer.swift:196 (KituraNet:x86_64+0x6b2f4)
    #5 closure #1 in HTTPServer.listen(on:) HTTPServer.swift:133 (KituraNet:x86_64+0x69aee)
    #6 partial apply for closure #1 in HTTPServer.listen(on:) HTTPServer.swift (KituraNet:x86_64+0x69c8c)
    #7 thunk for @callee_owned () -> () FastCGIServer.swift (KituraNet:x86_64+0x3d34c)
    #8 _dispatch_client_callout <null>:1594032 (libdispatch.dylib:x86_64+0x1d1e)
    #9 _dispatch_client_callout <null>:1594032 (libdispatch.dylib:x86_64+0x1d1e)

  Thread T13 (tid=5475740, running) is a GCD worker thread

  Thread T1 (tid=5475065, running) is a GCD worker thread

SUMMARY: ThreadSanitizer: data race Socket.swift in Socket.socketfd.setter

WARNING: ThreadSanitizer: data race (pid=67210)
  Read of size 1 at 0x7b1c00010780 by thread T1:
  * #0 WSSocketProcessor.inProgress.getter WSSocketProcessor.swift (KituraWebSocket:x86_64+0x10b0a)
    #1 protocol witness for IncomingSocketProcessor.inProgress.getter in conformance WSSocketProcessor WSSocketProcessor.swift (KituraWebSocket:x86_64+0x13763)
    #2 IncomingSocketManager.removeIdleSockets(removeAll:) IncomingSocketManager.swift:242 (KituraNet:x86_64+0xbf1c0)
    #3 IncomingSocketManager.handle(socket:processor:) IncomingSocketManager.swift:137 (KituraNet:x86_64+0xbde71)
    #4 HTTPServer.handleClientConnection(clientSocket:socketManager:) HTTPServer.swift:278 (KituraNet:x86_64+0x71183)
    #5 HTTPServer.listen(listenSocket:socketManager:) HTTPServer.swift:223 (KituraNet:x86_64+0x6c09c)
    #6 closure #1 in HTTPServer.listen(on:) HTTPServer.swift:133 (KituraNet:x86_64+0x69aee)
    #7 partial apply for closure #1 in HTTPServer.listen(on:) HTTPServer.swift (KituraNet:x86_64+0x69c8c)
    #8 thunk for @callee_owned () -> () FastCGIServer.swift (KituraNet:x86_64+0x3d34c)
    #9 _dispatch_client_callout <null>:1058032 (libdispatch.dylib:x86_64+0x1d1e)
    #10 _dispatch_client_callout <null>:1058032 (libdispatch.dylib:x86_64+0x1d1e)

  Previous write of size 1 at 0x7b1c00010780 by thread T20:
    [failed to restore the stack]

  Issue is caused by frames marked with "*".

  Location is heap block of size 112 at 0x7b1c00010760 allocated by thread T20:
    #0 malloc <null>:1058064 (libclang_rt.tsan_osx_dynamic.dylib:x86_64h+0x48b3a)
    #1 swift_slowAlloc <null>:1058064 (libswiftCore.dylib:x86_64+0x344478)
    #2 WSSocketProcessor.__allocating_init(connection:) WSSocketProcessor.swift (KituraWebSocket:x86_64+0x11584)
    #3 WSConnectionUpgradeFactory.upgrade(handler:request:response:) WSConnectionUpgradeFactory.swift:73 (KituraWebSocket:x86_64+0x36f8)
    #4 protocol witness for ConnectionUpgradeFactory.upgrade(handler:request:response:) in conformance WSConnectionUpgradeFactory WSConnectionUpgradeFactory.swift (KituraWebSocket:x86_64+0x4e8b)
    #5 ConnectionUpgradeFactory.upgrade(handler:request:response:) ConnectionUpgradeFactory.swift:54 (KituraNet:x86_64+0x20185)
    #6 ConnectionUpgrader.upgradeConnection(handler:request:response:) ConnectionUpgrader.swift:77 (KituraNet:x86_64+0x22788)
    #7 IncomingHTTPSocketProcessor.parsingComplete() IncomingHTTPSocketProcessor.swift:245 (KituraNet:x86_64+0x8c9d0)
    #8 IncomingHTTPSocketProcessor.parse(_:) IncomingHTTPSocketProcessor.swift:222 (KituraNet:x86_64+0x8bcd0)
    #9 IncomingHTTPSocketProcessor.process(_:) IncomingHTTPSocketProcessor.swift:98 (KituraNet:x86_64+0x8a5b3)
    #10 protocol witness for IncomingSocketProcessor.process(_:) in conformance IncomingHTTPSocketProcessor IncomingHTTPSocketProcessor.swift (KituraNet:x86_64+0x8deec)
    #11 IncomingSocketHandler.handleReadHelper() IncomingSocketHandler.swift:167 (KituraNet:x86_64+0xb2d5d)
    #12 IncomingSocketHandler.handleRead() IncomingSocketHandler.swift:139 (KituraNet:x86_64+0xb0984)
    #13 closure #1 in IncomingSocketHandler.init(socket:using:) IncomingSocketHandler.swift:105 (KituraNet:x86_64+0xaff37)
    #14 partial apply for closure #1 in IncomingSocketHandler.init(socket:using:) IncomingSocketHandler.swift (KituraNet:x86_64+0xaff8d)
    #15 thunk for @callee_owned () -> () FastCGIServer.swift (KituraNet:x86_64+0x3d34c)
    #16 __tsan::dispatch_callback_wrap(void*) <null>:1058064 (libclang_rt.tsan_osx_dynamic.dylib:x86_64h+0x662e1)
    #17 _dispatch_client_callout <null>:1058064 (libdispatch.dylib:x86_64+0x1d1e)

  Thread T1 (tid=5475065, running) is a GCD worker thread

  Thread T20 (tid=5486776, finished) is a GCD worker thread

SUMMARY: ThreadSanitizer: data race WSSocketProcessor.swift in WSSocketProcessor.inProgress.getter

[djones6]

I can recreate this using the https://github.com/IBM-Swift-Sunset/Kitura-Chat-Server sample, and also with another simple project that does not use WebSockets.

Most of the reported races involve flags or state relating to the lifespan of a connection. After a new connection is accepted, we invoke IncomingSocketManager.removeIdleSockets() to clear any stale connections (Keep-Alive connections that have exceeded an idleness timeout). This involves checking the IncomingSocketProcessor.inProgress and keepAliveUntil flags of all connections, not just the set managed by the current thread, and so there is a theoretical problem with data consistency here. Also, while the race on the inProgress field is only between handler threads, a race on keepAliveUntil could involve handler threads, which update the keepalive state after sending a response.

Another race apparently exists when first handling an incoming connection: when the IncomingSocketManager creates the IncomingSocketHandler, the DispatchSourceRead is resumed from within the initializer. The IncomingSocketManager then reads socket.socketfd to register the handler in a dictionary, indexed by socketfd. However, in theory the handleCancel() handler could fire (clearing the socket.socketfd) before the initializer completes.

Regardless of whether either race is likely to manifest in a bug in practice, their presence could make it harder to use the thread sanitizer tool to find other more pressing problems. I'll look into what's involved in fixing these.

[djones6]

This may have been fixed by #284 - this required locking around the socketHandlers array to prevent concurrent access during mutation with Swift 5.

I'll try to confirm in the next week or so.

[djones6]

These are not fixed, I was confusing two different issues in my mind. Although TSan would have flagged up the socketHandlers concurrent access if it were available on Linux.

A simple fix for these data races is to guard each of the state variables that could be accessed by two threads with a read/write lock, similar to the one I used in #284. However, a first pass at doing this tanked our Hello World performance by almost 50%. I'll continue experimenting to see if I can find an implementation that has a performance penalty that we can stomach.

[weissi]

These issues can manifest as arbitrary memory unsafety and therefore security vulnerabilities. I would very very much recommend fixing them asap.

Thread unsafety in Swift is especially troublesome because it breaks copy on write and make a usually memory safe language memory unsafe so users aren't prepared to look out for these things.

[djones6]

I experimented with fixing the thread sanitizer issues again, this time using NIOConcurrencyHelpers where possible (eg. dealing with simple Bool / Int values).

I addressed each property individually as a sequence of commits here: https://github.com/IBM-Swift/Kitura-net/compare/concurrencyFixes2

               | Throughput (req/s)      | CPU (%) | Mem (kb)     | Latency (ms)                   | good
Implementation | Average    | Max        | Average | Avg peak RSS | Average  | 99%      | Max      | iters
---------------|------------|------------|---------|--------------|----------|----------|----------|-------
          base |    79380.9 |    81892.3 |    97.8 |        28846 |      1.6 |      7.2 |    206.0 |    10
       a112af2 |    58718.4 |    59616.0 |    97.1 |        25761 |      2.2 |      8.9 |    198.8 |    10
       0aade36 |    56898.6 |    58211.7 |    97.5 |        25708 |      2.3 |      9.4 |    204.1 |    10
       b398b94 |    57189.8 |    58407.9 |    97.8 |        25778 |      2.2 |      8.4 |    203.4 |    10
       41f8924 |    56778.8 |    58137.5 |    97.7 |        25793 |      2.3 |      9.4 |    201.8 |    10
       e6e1ea3 |    56766.0 |    58430.7 |    97.7 |        25795 |      2.3 |      9.8 |    200.2 |    10
       04e1aa2 |    55656.2 |    57113.9 |    97.2 |        25730 |      2.4 |     11.7 |    199.7 |    10
       8ff6ba1 |    56984.9 |    58094.5 |    97.6 |        25724 |      2.2 |      8.4 |    202.7 |    10
       8fc62e3 |    55805.4 |    57282.9 |    97.5 |        25745 |      2.3 |     10.0 |    202.0 |    10
       df6eff5 |    56493.4 |    57700.2 |    97.7 |        25746 |      2.3 |      9.4 |    202.1 |    10  
       37303ef |    55490.9 |    57158.7 |    97.5 |        25816 |      2.3 |      9.3 |    201.0 |    10
       201600a |    51998.3 |    52794.8 |    97.0 |        25783 |      2.5 |     10.0 |    200.2 |    10
       732d65f |    51373.9 |    52947.3 |    97.3 |        25858 |      2.5 |      9.8 |    202.5 |    10

These are cumulative, so compare each line with the previous. Error margin is quite high (+/- 1% or so).
The biggest costs appear to be a112af2 and 201600a, which are using a DispatchQueue for synchronizing access to the Socket's file descriptor and the IncomingHTTPSocketProcessor's keepalive state, respectively.

I did a subsequent experiment focusing on just the Socket file descriptor where I modified BlueSocket to use a NIO Atomic for Socket.socketfd, and this was an improvement, though still much slower than base:

               | Throughput (req/s)      | CPU (%) | Mem (kb)     | Latency (ms)                   | good
Implementation | Average    | Max        | Average | Avg peak RSS | Average  | 99%      | Max      | iters
---------------|------------|------------|---------|--------------|----------|----------|----------|-------
    thread_1-p |    63615.2 |    65358.8 |    97.4 |        25815 |      2.0 |      7.5 |    201.7 |    10

Current thoughts are around the handling of the socketfd value and whether we could stash a constant value for it when creating the IncomingSocketHandler, rather than accessing the value on Socket, and determine whether the socket has been closed by some means other than checking socketfd > -1.

[hactar]

I have an app that also appears to crash "at random" with Thread 2: EXC_BAD_INSTRUCTION (code=EXC_I386_INVOP, subcode=0x0) - while trying to diagnose it I also stumbled across the thread sanitizer issue. Is there any way to work around the issue to rule out that this is causing my crashes?