Kitura-NIO calls syncShutdownGracefully of an EventLoopGroup ON an EventLoop

[weissi]

Kitura-NIO calls syncShutdownGracefully of an EventLoopGroup ON an EventLoop. That is very prone to deadlocking because it's attempting to shut down the EventLoop the synchronous call is running on. We now built in an automatic detection because people were hitting the deadlocks.

Test Suite 'ClientE2ETests' started at 2019-10-09 7:30:53.005 pm
Test Case '-[KituraNetTests.ClientE2ETests testEphemeralListeningPort]' started.
Test Case '-[KituraNetTests.ClientE2ETests testEphemeralListeningPort]' passed (0.007 seconds).
Test Case '-[KituraNetTests.ClientE2ETests testErrorRequests]' started.
Fatal error: BUG DETECTED: syncShutdownGracefully() must not be called when on an EventLoop.
Calling syncShutdownGracefully() on any EventLoop can lead to deadlocks.
Current eventLoop: SelectableEventLoop { selector = Selector { descriptor = 8 }, scheduledTasks = PriorityQueue(count: 0): [] }: file /tmp/.nio-release-tools_NoUBEx/swift-nio/Sources/NIO/EventLoop.swift, line 990
Exited with signal code 4

[harish1992]

Hi @weissi, I ran the tests with Swift-NIO master but was not able reproduce the issue. Can you please provide the steps to reproduce these issues? Thanks.

[weissi]

@harish1992 sorry about that, of course, here's a one line repro:

cd /tmp && rm -rf Kitura-NIO && git clone https://github.com/IBM-Swift/Kitura-NIO.git && cd Kitura-NIO && swift package edit swift-nio && cd Packages/swift-nio && git fetch origin && git reset --hard origin/master && cd ../.. && swift test

if you paste this, it'll clone a new Kitura-NIO into /tmp, use NIO master and run the tests, the output looks like

$ cd /tmp && rm -rf Kitura-NIO && git clone https://github.com/IBM-Swift/Kitura-NIO.git && cd Kitura-NIO && swift package edit swift-nio && cd Packages/swift-nio && git fetch origin && git reset --hard origin/master && cd ../.. && swift test
Cloning into 'Kitura-NIO'...
remote: Enumerating objects: 99, done.
remote: Counting objects: 100% (99/99), done.
remote: Compressing objects: 100% (87/87), done.
remote: Total 2373 (delta 45), reused 44 (delta 8), pack-reused 2274
Receiving objects: 100% (2373/2373), 1.16 MiB | 4.09 MiB/s, done.
Resolving deltas: 100% (1440/1440), done.
Fetching https://github.com/apple/swift-nio.git
Fetching https://github.com/apple/swift-nio-ssl.git
Fetching https://github.com/apple/swift-nio-extras.git
Fetching https://github.com/IBM-Swift/BlueSSLService.git
Fetching https://github.com/IBM-Swift/LoggerAPI.git
Fetching https://github.com/IBM-Swift/BlueSocket.git
Fetching https://github.com/apple/swift-log.git
Completed resolution in 12.49s
Cloning https://github.com/apple/swift-nio-ssl.git
Resolving https://github.com/apple/swift-nio-ssl.git at 2.4.1
Cloning https://github.com/apple/swift-nio-extras.git
Resolving https://github.com/apple/swift-nio-extras.git at 1.2.0
Cloning https://github.com/IBM-Swift/LoggerAPI.git
Resolving https://github.com/IBM-Swift/LoggerAPI.git at 1.9.0
Cloning https://github.com/apple/swift-nio.git
Resolving https://github.com/apple/swift-nio.git at 2.8.0
Cloning https://github.com/IBM-Swift/BlueSSLService.git
Resolving https://github.com/IBM-Swift/BlueSSLService.git at 1.0.50
Cloning https://github.com/apple/swift-log.git
Resolving https://github.com/apple/swift-log.git at 1.1.1
Cloning https://github.com/IBM-Swift/BlueSocket.git
Resolving https://github.com/IBM-Swift/BlueSocket.git at 1.0.50
HEAD is now at 23303e7c NIOHTTP1TestServer (#1152) ### JW: <<< using NIO master
[...]         ### JW: cut out lots of warnings
[620/620] Linking Kitura-NIOPackageTests
Test Suite 'All tests' started at 2019-10-10 9:15:25.863 am
Test Suite 'Kitura-NIOPackageTests.xctest' started at 2019-10-10 9:15:25.863 am
Test Suite 'BufferListTests' started at 2019-10-10 9:15:25.863 am
Test Case '-[KituraNetTests.BufferListTests testAppendData]' started.
Test Case '-[KituraNetTests.BufferListTests testAppendData]' passed (0.092 seconds).
Test Case '-[KituraNetTests.BufferListTests testAppendUnsafePointerLength]' started.
Test Case '-[KituraNetTests.BufferListTests testAppendUnsafePointerLength]' passed (0.000 seconds).
Test Case '-[KituraNetTests.BufferListTests testDataAndCount]' started.
Test Case '-[KituraNetTests.BufferListTests testDataAndCount]' passed (0.000 seconds).
Test Case '-[KituraNetTests.BufferListTests testFillArray]' started.
Test Case '-[KituraNetTests.BufferListTests testFillArray]' passed (0.001 seconds).
Test Case '-[KituraNetTests.BufferListTests testFillData]' started.
Test Case '-[KituraNetTests.BufferListTests testFillData]' passed (0.000 seconds).
Test Case '-[KituraNetTests.BufferListTests testFillMutableData]' started.
Test Case '-[KituraNetTests.BufferListTests testFillMutableData]' passed (0.000 seconds).
Test Case '-[KituraNetTests.BufferListTests testFillUnsafeMutablePointer]' started.
Test Case '-[KituraNetTests.BufferListTests testFillUnsafeMutablePointer]' passed (0.000 seconds).
Test Case '-[KituraNetTests.BufferListTests testRewind]' started.
Test Case '-[KituraNetTests.BufferListTests testRewind]' passed (0.000 seconds).
Test Suite 'BufferListTests' passed at 2019-10-10 9:15:25.957 am.
	 Executed 8 tests, with 0 failures (0 unexpected) in 0.094 (0.095) seconds
Test Suite 'ChannelQuiescingTests' started at 2019-10-10 9:15:25.958 am
Test Case '-[KituraNetTests.ChannelQuiescingTests testChannelQuiescing]' started.
Test Case '-[KituraNetTests.ChannelQuiescingTests testChannelQuiescing]' passed (2.023 seconds).
Test Suite 'ChannelQuiescingTests' passed at 2019-10-10 9:15:27.981 am.
	 Executed 1 test, with 0 failures (0 unexpected) in 2.023 (2.023) seconds
Test Suite 'ClientE2ETests' started at 2019-10-10 9:15:27.981 am
Test Case '-[KituraNetTests.ClientE2ETests testEphemeralListeningPort]' started.
Test Case '-[KituraNetTests.ClientE2ETests testEphemeralListeningPort]' passed (0.012 seconds).
Test Case '-[KituraNetTests.ClientE2ETests testErrorRequests]' started.
Fatal error: BUG DETECTED: syncShutdownGracefully() must not be called when on an EventLoop.
Calling syncShutdownGracefully() on any EventLoop can lead to deadlocks.
Current eventLoop: SelectableEventLoop { selector = Selector { descriptor = 8 }, scheduledTasks = PriorityQueue(count: 0): [] }: file /private/tmp/Kitura-NIO/Packages/swift-nio/Sources/NIO/EventLoop.swift, line 990
Exited with signal code 4

[djones6]

@weissi While working on SwiftyRequest, I created a global EventLoopGroup for all instances of SwiftyRequest to use. Do you think it would make sense for HTTPServer also?

At the moment, if we create multiple HTTPServers, they each have a MultiThreadedEventLoopGroup and they then try to shut this down during deinit. I guess that's the crux of the issue here.

If they all shared a global ELG, then presumably there would be no need to shut it down, as any future HTTPServer would make use of it again.

This would also avoid having to keep track of whether the ELG was user-supplied (via the upcoming API for #225) and avoid shutting down one that HTTPServer does not own.

[weissi]

@djones6 a global MTELG isn't ideal but better than shutting it down in deinit. Long-term I think these libraries should also adopt the anyway recommended explicit teardown pattern.

[harish1992]

@weissi This issue is fixed in PR #225